diff --git a/CHANGELOG.md b/CHANGELOG.md index 2203852..596c59f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,12 @@ ## XX.XX.XX +- Added the health check feature. The SDK now sends a health check request once after `start()`. Like any request, it updates the user's last seen time on the server. - Added the SDK name and version (`sdk_name` and `sdk_version`) to every request, including the remote config and SDK Behavior Settings fetches. Before, only the begin session request carried them. - Added `multiplyCustomUserDetail` for multiplying the numeric value of a custom user property on the server. +- Added `disableHealthCheck()` for turning off the health check request. +- Added `status_code` and `body` to `HTTPResponse`. A custom HTTP client can fill them so that the health check reports the last request the server refused; a client that leaves them empty works as before. +- Calls made before `start()`, a second `start()`, beginning a session that already runs and ending one that does not are now logged at warning level. Failed and non-JSON server answers, and session calls ignored because the SDK Behavior Settings turned session tracking off, are now logged at debug level. + +- Mitigated an issue where reaching the event queue threshold logged a warning that events were dropped, although they were sent. ## 26.8.1 - ! Minor breaking change ! Builds now stop with a clear error when the SDK headers find a nlohmann/json older than 3.11 first on the include path, instead of mixing two versions of the library. diff --git a/CMakeLists.txt b/CMakeLists.txt index 9eabe57..622bd4b 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -37,6 +37,7 @@ set(COUNTLY_PUBLIC_HEADERS ${CMAKE_CURRENT_SOURCE_DIR}/include/countly/crash_module.hpp ${CMAKE_CURRENT_SOURCE_DIR}/include/countly/event.hpp ${CMAKE_CURRENT_SOURCE_DIR}/include/countly/logger_module.hpp + ${CMAKE_CURRENT_SOURCE_DIR}/include/countly/health_check_module.hpp ${CMAKE_CURRENT_SOURCE_DIR}/include/countly/remote_config_store.hpp ${CMAKE_CURRENT_SOURCE_DIR}/include/countly/request_builder.hpp ${CMAKE_CURRENT_SOURCE_DIR}/include/countly/request_module.hpp @@ -55,7 +56,8 @@ add_library(countly ${CMAKE_CURRENT_SOURCE_DIR}/src/storage_module_db.cpp ${CMAKE_CURRENT_SOURCE_DIR}/src/storage_module_memory.cpp ${CMAKE_CURRENT_SOURCE_DIR}/src/event.cpp - ${CMAKE_CURRENT_SOURCE_DIR}/src/configuration_module.cpp) + ${CMAKE_CURRENT_SOURCE_DIR}/src/configuration_module.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/src/health_check_module.cpp) add_library(countly::countly ALIAS countly) target_include_directories(countly @@ -153,7 +155,8 @@ if(COUNTLY_BUILD_TESTS) ${CMAKE_CURRENT_SOURCE_DIR}/tests/internal_limits.cpp ${CMAKE_CURRENT_SOURCE_DIR}/tests/internal_limits_integration.cpp ${CMAKE_CURRENT_SOURCE_DIR}/tests/multi_instance.cpp - ${CMAKE_CURRENT_SOURCE_DIR}/tests/user_details.cpp) + ${CMAKE_CURRENT_SOURCE_DIR}/tests/user_details.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/tests/health_check.cpp) target_compile_options(countly-tests PRIVATE $<$>:-g>) target_compile_definitions(countly-tests PRIVATE COUNTLY_BUILD_TESTS) diff --git a/include/countly.hpp b/include/countly.hpp index 6750b11..4d73167 100644 --- a/include/countly.hpp +++ b/include/countly.hpp @@ -24,6 +24,7 @@ #undef ERROR #endif #include "countly/event.hpp" +#include "countly/health_check_module.hpp" #include "countly/logger_module.hpp" #include "countly/storage_module_base.hpp" #include "countly/views_module.hpp" @@ -359,6 +360,15 @@ class Countly : public cly::CountlyDelegates { configuration->sessionDuration = updateInterval; } + /** + * Disables the SDK health check. Once after start the SDK sends the server a short report about its own state: + * how many warnings and errors it logged, the last request the server refused, how often its session, event, + * view and crash methods were called, and which known problems occurred. It carries no data the app recorded, + * and the server shows it in SDK Manager. With this option the report is not sent; the SDK keeps counting. + * Call it before start(). + */ + void disableHealthCheck(); + /** * Disable SDK behavior settings updates that SDK performs periodically from the server. */ @@ -431,6 +441,12 @@ class Countly : public cly::CountlyDelegates { inline const CountlyConfiguration &getConfiguration() { return *configuration.get(); } + /** + * The health check counters of this instance. + * Warning: This method is for debugging purposes, and it is going to be removed in the future. + */ + inline std::shared_ptr debugHealthCheck() { return health_check; } + static void halt(); static size_t debugClaimedPathCount(); @@ -496,6 +512,38 @@ class Countly : public cly::CountlyDelegates { void updateLoop(); void packEvents(); + + /** + * Begins a session, counted in the health check as a call of the app or, with 'automatic', of the SDK. + * A call of the app while a session runs is reported as log code w760. + */ + bool beginSessionInternal(bool automatic); + + /** + * Updates the session, counted in the health check as a call of the app or, with 'automatic', of the SDK. + * A call of the app in manual session control without a running session is reported as log code w760. + */ + bool updateSessionInternal(bool automatic); + + /** + * Ends the session, counted in the health check as a call of the app or, with 'automatic', of the SDK. + * A call of the app without a running session is reported as log code w760. + */ + bool endSessionInternal(bool automatic); + + /** + * Sends the health check once, as an immediate request to /i, unless it is disabled, the SDK behavior settings + * turn networking off, or it was sent already. It carries the base request parameters, the app version as + * metrics and the counters. Only what it reported is taken away from the counters, and only once the server + * accepted it with a 2xx answer that is a JSON object with a "result". Runs on the update thread, so the + * request never holds up start() and finishes before the instance is destroyed. + */ + void sendHealthCheck(); + + /** + * Stores the health check counters when a session update interval passed since they were last stored. + */ + void saveHealthCheckOnTimer(); bool began_session = false; std::atomic is_being_disposed{false}; std::atomic is_sdk_initialized{false}; @@ -517,6 +565,11 @@ class Countly : public cly::CountlyDelegates { std::unique_ptr crash_module; std::unique_ptr views_module; + // Health check counters; created with the instance, so warnings logged before start() are counted too. + std::shared_ptr health_check = std::make_shared(); + std::atomic health_check_sent{false}; + std::chrono::steady_clock::time_point last_health_check_save = std::chrono::steady_clock::now(); + std::shared_ptr configuration; std::shared_ptr logger; std::shared_ptr requestBuilder; diff --git a/include/countly/constants.hpp b/include/countly/constants.hpp index 01eb1e7..261a350 100644 --- a/include/countly/constants.hpp +++ b/include/countly/constants.hpp @@ -37,6 +37,15 @@ namespace cly { struct HTTPResponse { bool success; nlohmann::json data; + /** + * HTTP status code of the answer, 0 when no answer arrived or the HTTP client did not set it. + * The health check reports the code and the body of the last answer that refused a request. + */ + long status_code = 0; + /** + * Body of the answer as text, empty when there was none or the HTTP client did not set it. + */ + std::string body; }; using HTTPClientFunction = std::function; diff --git a/include/countly/countly_configuration.hpp b/include/countly/countly_configuration.hpp index 37b80b0..916ed49 100644 --- a/include/countly/countly_configuration.hpp +++ b/include/countly/countly_configuration.hpp @@ -92,6 +92,11 @@ struct CountlyConfiguration { bool sdkBehaviorSettingsUpdatesDisabled = false; + /** + * Whether the SDK sends its health check after start. + */ + bool healthCheckEnabled = true; + std::string sdkBehaviorSettings; CountlyConfiguration(const std::string appKey, std::string serverUrl) { diff --git a/include/countly/health_check_module.hpp b/include/countly/health_check_module.hpp new file mode 100644 index 0000000..37663b3 --- /dev/null +++ b/include/countly/health_check_module.hpp @@ -0,0 +1,112 @@ +#ifndef HEALTH_CHECK_MODULE_HPP_ +#define HEALTH_CHECK_MODULE_HPP_ + +#include +#include +#include +#include + +#include "nlohmann/json.hpp" + +namespace cly { +class LoggerModule; +class StorageModuleBase; + +/** + * The counters of the SDK health check: warnings and errors logged, the last request the server + * refused, backoffs, method usage ("fu") and log codes ("lc"), kept since the last health check + * the server accepted. Logs at debug level only, as every warning and error the SDK logs is + * counted here. + */ +class HealthCheckModule { +public: + static const int COUNT_CAP = 65535; + static const size_t MAX_ERROR_MESSAGE_LENGTH = 1000; + + HealthCheckModule(); + ~HealthCheckModule(); + + /** + * Sets the logger the module writes its debug lines to. Held weakly, as the logger holds this module. + */ + void setLogger(std::weak_ptr logger); + + /** + * Sets the storage the counters are kept in and adds the counters a previous run stored to the + * current ones. A stored state that is not valid JSON is cleared and reported as log code e503. + * Held weakly, as the storage holds the logger, which holds this module. + */ + void setStorage(std::shared_ptr storage); + + /** Counts one warning the SDK logged. */ + void logWarning(); + + /** Counts one error the SDK logged. */ + void logError(); + + /** + * Keeps the answer of the server to a queued request it did not accept. Only the most recent one + * is kept. A status code outside 1..999 is ignored, and the body is cut to 1000 characters. + */ + void logFailedNetworkRequest(long statusCode, const std::string &errorResponse); + + /** + * Counts a backoff of the request queue and extends the current run of backoffs in a row. "cbom" + * holds the longest run right away. Records log code w320, and w321 when the backoff continues a run. + */ + void logBackoffRequest(); + + /** Ends the current run of backoffs in a row, when a queued request was answered in time. */ + void logConsecutiveBackoffRequest(); + + /** + * Counts one call of a method for the "fu" map. A call the SDK made by itself carries ":a", a + * deprecated method ":d". Empty names are ignored, and every count stops at 65535. + */ + void recordUsage(const std::string &area, const std::string &method); + + /** Counts occurrences of a log code for the "lc" map, a level letter and three digits such as "w740". */ + void recordLogCode(const std::string &code, int count = 1); + + /** + * The health check parameter as it is sent. "fu" and "lc" are always present, empty when nothing + * was counted, so the server can tell an SDK that reports them from one that does not. + */ + nlohmann::json snapshot(); + + /** + * Takes away what an accepted health check reported, so what was counted while it was on its way + * is reported next time. The last failed request and the longest backoff run are cleared only + * when they did not change since. Stores what is left. + */ + void clearSentValues(const nlohmann::json &sent); + + /** Stores the counters, when a storage is set. */ + void saveState(); + + /** Resets every counter to its default and clears the stored state. */ + void clearAndSave(); + +private: + void setupInitialCounters(const std::string &initialState); + void addUsage(const std::string &area, const std::string &method, long long count); + void addLogCode(const std::string &code, long long count); + nlohmann::json toJson(bool forStorage); + void debugLog(const std::string &message); + + std::mutex _mutex; + std::weak_ptr _logger; + std::weak_ptr _storage; + + long long _countLogWarning = 0; + long long _countLogError = 0; + long _statusCode = -1; + std::string _errorMessage; + long long _countBackoffRequest = 0; + long long _consecutiveBackoffRequest = 0; + long long _consecutiveBackoffRequestCounter = 0; + std::map> _methodUsage; + std::map _logCodes; +}; +} // namespace cly +#endif diff --git a/include/countly/logger_module.hpp b/include/countly/logger_module.hpp index bd6ba43..b2d1edd 100644 --- a/include/countly/logger_module.hpp +++ b/include/countly/logger_module.hpp @@ -7,6 +7,7 @@ namespace cly { enum class LogLevel { DEBUG = 1, INFO = 2, WARNING = 3, ERROR = 4, FATAL = 5 }; using LoggerFunction = std::function; +class HealthCheckModule; class LoggerModule { public: @@ -45,6 +46,35 @@ class LoggerModule { */ static bool isInsideCallback(); + /** + * Hands the health check counters to the logger. From then on every WARNING is counted as a + * warning and every ERROR or FATAL as an error, whether or not a log callback is set. + * + * @param healthCheck the counters of this instance + */ + void setHealthCheck(std::shared_ptr healthCheck); + + /** + * @return the health check counters of this instance, empty before they are set + */ + std::shared_ptr healthCheck() const; + + /** + * Records a health check log code, such as "w740", next to the log line of its condition. + * + * @param code the log code + * @param count how many times the condition occurred + */ + void recordLogCode(const std::string &code, int count = 1); + + /** + * Counts one call of a method for the health check method usage. + * + * @param area the feature area: "sessions", "events", "views" or "crashes" + * @param method the method name, with ":a" for a call the SDK made by itself + */ + void recordUsage(const std::string &area, const std::string &method); + private: class LoggerModuleImpl; std::unique_ptr impl; diff --git a/include/countly/storage_module_base.hpp b/include/countly/storage_module_base.hpp index 507a35e..23b4c35 100644 --- a/include/countly/storage_module_base.hpp +++ b/include/countly/storage_module_base.hpp @@ -98,6 +98,18 @@ class StorageModuleBase { virtual void storeSDKBehaviorSettings(const std::string &sdk_behavior_settings) = 0; virtual std::string getSDKBehaviorSettings() = 0; + + /** + * Store the health check counters. + * @param state: the counters as JSON text, empty to clear them + */ + virtual void storeHealthCheckState(const std::string &state) { (void)state; } + + /** + * Read the stored health check counters. + * @return the counters as JSON text, empty when none are stored + */ + virtual std::string getHealthCheckState() { return std::string(); } }; } // namespace cly diff --git a/include/countly/storage_module_db.hpp b/include/countly/storage_module_db.hpp index a57022c..540b303 100644 --- a/include/countly/storage_module_db.hpp +++ b/include/countly/storage_module_db.hpp @@ -26,6 +26,8 @@ class StorageModuleDB : public StorageModuleBase { void RQInsertAtEnd(const std::string &request) override; void storeSDKBehaviorSettings(const std::string &sdk_behavior_settings) override; std::string getSDKBehaviorSettings() override; + void storeHealthCheckState(const std::string &state) override; + std::string getHealthCheckState() override; }; } // namespace cly #endif \ No newline at end of file diff --git a/src/configuration_module.cpp b/src/configuration_module.cpp index f086650..e0189cd 100644 --- a/src/configuration_module.cpp +++ b/src/configuration_module.cpp @@ -382,7 +382,7 @@ class ConfigurationModule::ConfigurationModuleImpl { } void _stopTimer() { - _logger->log(LogLevel::WARNING, "[Countly] [ConfigurationModule] stopTimer, stopping server config update timer thread."); + _logger->log(LogLevel::DEBUG, "[Countly] [ConfigurationModule] stopTimer, stopping server config update timer thread."); { // The flag has to be mutated under the same mutex the waiter evaluates it diff --git a/src/countly.cpp b/src/countly.cpp index 9a84566..96f22d8 100644 --- a/src/countly.cpp +++ b/src/countly.cpp @@ -25,6 +25,11 @@ #endif namespace cly { +namespace { +const char *const HEALTH_CHECK_AREA_SESSIONS = "sessions"; +const char *const HEALTH_CHECK_AREA_EVENTS = "events"; +} // namespace + namespace { /** @@ -129,6 +134,8 @@ Countly::Countly() { crash_module = nullptr; views_module = nullptr; logger.reset(new cly::LoggerModule()); + health_check->setLogger(logger); + logger->setHealthCheck(health_check); configuration.reset(new cly::CountlyConfiguration("", "")); } @@ -616,7 +623,8 @@ void Countly::setUserDetails(const std::map &value) { session_params["user_details"] = limitedDetails; if (!is_sdk_initialized) { - log(LogLevel::ERROR, "[Countly] setUserDetails, This method can't be called before SDK initialization. Returning."); + log(LogLevel::WARNING, "[Countly] setUserDetails, This method can't be called before SDK initialization. Returning."); + logger->recordLogCode("w101"); return; } @@ -662,7 +670,8 @@ void Countly::setCustomUserDetails(const std::map &val session_params["user_details"]["custom"] = limitedCustom; if (!is_sdk_initialized) { - log(LogLevel::ERROR, "[Countly] setCustomUserDetails, This method can't be called before SDK initialization. Returning."); + log(LogLevel::WARNING, "[Countly] setCustomUserDetails, This method can't be called before SDK initialization. Returning."); + logger->recordLogCode("w101"); return; } @@ -678,15 +687,18 @@ void Countly::setCustomUserDetails(const std::map &val void Countly::multiplyCustomUserDetail(const std::string &key, double value) { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] multiplyCustomUserDetail, SDK is not initialized."); + logger->recordLogCode("w101"); return; } if (!std::isfinite(value)) { log(LogLevel::WARNING, "[Countly] multiplyCustomUserDetail, The parameter 'value' must be a finite number. Returning."); + logger->recordLogCode("w700"); return; } const std::string truncatedKey = cly::limits::truncateString(key, configurationModule->getLimits().maxKeyLength); if (truncatedKey.empty()) { log(LogLevel::WARNING, "[Countly] multiplyCustomUserDetail, The parameter 'key' can't be empty. Returning."); + logger->recordLogCode("w700"); return; } if (!isAllowedByFilter(configurationModule->getUserPropertyFilterList(), key)) { @@ -720,16 +732,19 @@ void Countly::queueUserDetails(const nlohmann::json &userDetails) { void Countly::setCountry(const std::string &country_code) { log(LogLevel::WARNING, "[Countly] setCountry, 'setCountry' is deprecated, please use 'setLocation(countryCode, city, gpsCoordinates, ipAddress)' method instead."); + logger->recordLogCode("w120"); setLocation(country_code, "", "", ""); } void Countly::setCity(const std::string &city_name) { log(LogLevel::WARNING, "[Countly] setCity, 'setCity' is deprecated, please use 'setLocation(countryCode, city, gpsCoordinates, ipAddress)' method instead."); + logger->recordLogCode("w120"); setLocation("", city_name, "", ""); } void Countly::setLocation(double lattitude, double longitude) { log(LogLevel::WARNING, "[Countly] setLocation, 'setLocation(latitude, longitude)' is deprecated, please use 'setLocation(countryCode, city, gpsCoordinates, ipAddress)' method instead."); + logger->recordLogCode("w120"); std::ostringstream location_stream; location_stream << lattitude << ',' << longitude; @@ -739,6 +754,7 @@ void Countly::setLocation(double lattitude, double longitude) { void Countly::setLocation(const std::string &countryCode, const std::string &city, const std::string &gpsCoordinates, const std::string &ipAddress) { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] setLocation, SDK is not initialized."); + logger->recordLogCode("w101"); return; } bool isClearingLocation = countryCode.empty() && city.empty() && gpsCoordinates.empty() && ipAddress.empty(); @@ -753,6 +769,7 @@ void Countly::setLocation(const std::string &countryCode, const std::string &cit if ((!countryCode.empty() && city.empty()) || (!city.empty() && countryCode.empty())) { log(LogLevel::WARNING, "[Countly] setLocation, It's required that both 'country_code' and 'city' should be set together"); + logger->recordLogCode("w700"); } session_params["city"] = city; @@ -831,7 +848,8 @@ void Countly::setDeviceID(const std::string &value, bool same_user) { lk.unlock(); if (!is_sdk_initialized) { - log(LogLevel::ERROR, "[Countly] setDeviceID, Device id can't be changed while the SDK has not been initialized."); + log(LogLevel::WARNING, "[Countly] setDeviceID, Device id can't be changed while the SDK has not been initialized."); + logger->recordLogCode("w101"); return; } @@ -871,7 +889,7 @@ void Countly::_changeDeviceIdWithoutMerge(const std::string &value) { // send all event to server and end current session of old user flushEvents(); if (configuration->manualSessionControl == false) { - endSession(); + endSessionInternal(true); } { @@ -885,7 +903,7 @@ void Countly::_changeDeviceIdWithoutMerge(const std::string &value) { // start a new session for new user if (configuration->manualSessionControl == false) { - beginSession(); + beginSessionInternal(true); } } #pragma endregion Device Id @@ -896,7 +914,8 @@ void Countly::start(const std::string &app_key, const std::string &host, int por // configurationModule->fetch*/beginSession() calls below. std::unique_lock lk(*mutex); if (is_sdk_initialized) { - log(LogLevel::ERROR, "[Countly] start, SDK has already been initialized, 'start' should not be called a second time!"); + log(LogLevel::WARNING, "[Countly] start, SDK has already been initialized, 'start' should not be called a second time!"); + logger->recordLogCode("w110"); return; } @@ -950,6 +969,7 @@ void Countly::start(const std::string &app_key, const std::string &host, int por if (port < 0 || port > 65535) { log(LogLevel::WARNING, "[Countly] start, Port number is out of valid boundaries. Setting it to 0."); + logger->recordLogCode("w121"); port = 0; } @@ -982,6 +1002,7 @@ void Countly::start(const std::string &app_key, const std::string &host, int por requestModule->setConfigurationProvider(configurationModule); views_module->setConfigurationProvider(configurationModule); crash_module->setConfigurationProvider(configurationModule); + health_check->setStorage(storageModule); is_sdk_initialized = true; // after this point SDK is initialized. @@ -995,7 +1016,7 @@ void Countly::start(const std::string &app_key, const std::string &host, int por if (configuration->manualSessionControl == false) { lk.unlock(); - beginSession(); + beginSessionInternal(true); lk.lock(); } @@ -1018,6 +1039,7 @@ void Countly::start(const std::string &app_key, const std::string &host, int por */ void Countly::startOnCloud(const std::string &app_key) { log(LogLevel::WARNING, "[Countly] startOnCloud, 'startOnCloud' is deprecated, this is going to be removed in the future."); + logger->recordLogCode("w120"); this->start(app_key, "https://cloud.count.ly", 443); } @@ -1066,8 +1088,9 @@ void Countly::stop() { // ~Countly, which is where the lifetime problem they solve actually arises. _deleteThread(); if (configuration->manualSessionControl == false) { - endSession(); + endSessionInternal(true); } + health_check->saveState(); } void Countly::_deleteThread() { @@ -1099,11 +1122,15 @@ void Countly::setUpdateInterval(size_t milliseconds) { void Countly::addEvent(const cly::Event &event) { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] addEvent, SDK is not initialized."); + logger->recordLogCode("w101"); return; } std::string eventKey = event.getKey(); bool isInternalEvent = eventKey.find("[CLY]_") == 0; + if (!isInternalEvent) { + logger->recordUsage(HEALTH_CHECK_AREA_EVENTS, "record"); + } // Check custom event tracking (only blocks custom events) if (!configurationModule->isCustomEventTrackingEnabled() && !isInternalEvent) { @@ -1202,7 +1229,7 @@ void Countly::checkAndSendEventToRQ() { } } else { if (queueSize >= configurationModule->getEventQueueSizeLimit()) { - log(LogLevel::WARNING, "[Countly] checkAndSendEventToRQ, Event queue is full, dropping the oldest event to insert a new one"); + log(LogLevel::DEBUG, "[Countly] checkAndSendEventToRQ, Event queue threshold is reached, sending the events to the request queue"); for (const auto &event_json : event_queue) { events.push_back(nlohmann::json::parse(event_json)); } @@ -1214,6 +1241,7 @@ void Countly::checkAndSendEventToRQ() { void Countly::setMaxEvents(size_t value) { log(LogLevel::WARNING, "[Countly] setMaxEvents, 'setMaxEvents' and 'SetMaxEventsPerMessage' are deprecated. Use 'setEventsToRQThreshold' instead."); + logger->recordLogCode("w120"); setEventsToRQThreshold(static_cast(value)); } @@ -1222,9 +1250,11 @@ void Countly::setEventsToRQThreshold(int value) { std::unique_lock lk(*mutex); if (value < 1) { log(LogLevel::WARNING, "[Countly] setEventsToRQThreshold, Threshold can not be less than 1. Setting it to 1 instead of:[" + std::to_string(value) + "]"); + logger->recordLogCode("w121"); value = 1; } else if (value > 10000) { log(LogLevel::WARNING, "[Countly] setEventsToRQThreshold, Threshold can not be greater than 10000. Setting it to 10000 instead of:[" + std::to_string(value) + "]"); + logger->recordLogCode("w121"); value = 10000; } @@ -1269,6 +1299,7 @@ void Countly::flushEvents(std::chrono::seconds timeout) { std::ostringstream log_message; log_message << "[Countly] flushEvents, error: " << e.what(); log(LogLevel::FATAL, log_message.str()); + logger->recordLogCode("e901"); } } @@ -1286,7 +1317,7 @@ bool Countly::attemptSessionUpdateEQ() { } } if (configuration->manualSessionControl == false) { - return !updateSession(); + return !updateSessionInternal(true); } else { packEvents(); return false; @@ -1363,22 +1394,33 @@ void Countly::debugInjectRawEvent(const std::string &raw) { } #endif -bool Countly::beginSession() { +bool Countly::beginSession() { return beginSessionInternal(false); } + +bool Countly::beginSessionInternal(bool automatic) { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] beginSession, SDK is not initialized."); + logger->recordLogCode("w101"); return false; } + if (!automatic) { + logger->recordUsage(HEALTH_CHECK_AREA_SESSIONS, "begin"); + } // unique_lock so the mutex is always released on scope exit, including the // early returns below and any exception (e.g. a json type_error from a // session_params access, or addRequestToQueue) thrown while it is held. std::unique_lock lk(*mutex); log(LogLevel::INFO, "[Countly] beginSession, Starting session"); if (configurationModule->isSessionTrackingEnabled() == false) { - log(LogLevel::ERROR, "[Countly] beginSession, Session tracking is disabled in server configuration, can not begin session."); + log(LogLevel::DEBUG, "[Countly] beginSession, Session tracking is disabled in server configuration, can not begin session."); return false; } if (began_session == true) { - log(LogLevel::DEBUG, "[Countly] beginSession, Session is already active."); + if (automatic) { + log(LogLevel::DEBUG, "[Countly] beginSession, Session is already active."); + } else { + log(LogLevel::WARNING, "[Countly] beginSession, Session is already active, the call is ignored."); + logger->recordLogCode("w760"); + } return true; } @@ -1416,6 +1458,9 @@ bool Countly::beginSession() { session_params.erase("user_details"); last_sent_session_request = std::chrono::steady_clock::now(); began_session = true; + if (automatic) { + logger->recordUsage(HEALTH_CHECK_AREA_SESSIONS, "begin:a"); + } // snapshot guarded state before releasing the lock bool shouldUpdateRemoteConfig = remote_config_enabled; lk.unlock(); @@ -1429,11 +1474,17 @@ bool Countly::beginSession() { /** * @brief Update session */ -bool Countly::updateSession() { +bool Countly::updateSession() { return updateSessionInternal(false); } + +bool Countly::updateSessionInternal(bool automatic) { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] updateSession, SDK is not initialized."); + logger->recordLogCode("w101"); return false; } + if (!automatic) { + logger->recordUsage(HEALTH_CHECK_AREA_SESSIONS, "update"); + } // unique_lock so the mutex is always released on scope exit, including when an // exception propagates out of a call made while the lock is held. std::unique_lock lk(*mutex, std::defer_lock); @@ -1441,7 +1492,7 @@ bool Countly::updateSession() { // Check if there was a session, if not try to start one lk.lock(); if (configurationModule->isSessionTrackingEnabled() == false) { - log(LogLevel::ERROR, "[Countly] updateSession, Session tracking is disabled in server configuration, can not update session."); + log(LogLevel::DEBUG, "[Countly] updateSession, Session tracking is disabled in server configuration, can not update session."); lk.unlock(); return false; } @@ -1449,9 +1500,10 @@ bool Countly::updateSession() { lk.unlock(); if (configuration->manualSessionControl == true) { log(LogLevel::WARNING, "[Countly] updateSession, SDK is in manual session control mode and there is no active session. Please start a session first."); + logger->recordLogCode("w760"); return false; } - if (!beginSession()) { + if (!beginSessionInternal(true)) { log(LogLevel::DEBUG, "[Countly] updateSession, Failed to begin session."); // if beginSession fails, we should not try to update session return false; @@ -1489,6 +1541,9 @@ bool Countly::updateSession() { log(LogLevel::DEBUG, "[Countly] updateSession, Sending session update."); std::map data = {{"app_key", session_params["app_key"].get()}, {"device_id", session_params["device_id"].get()}, {"session_duration", std::to_string(duration.count())}}; requestModule->addRequestToQueue(data); + if (automatic) { + logger->recordUsage(HEALTH_CHECK_AREA_SESSIONS, "update:a"); + } last_sent_session_request += duration; } @@ -1512,6 +1567,7 @@ bool Countly::updateSession() { std::ostringstream log_message; log_message << "[Countly] updateSession, error: " << e.what(); log(LogLevel::FATAL, log_message.str()); + logger->recordLogCode("e901"); } // lk releases the mutex on scope exit if it is still held. return true; @@ -1581,14 +1637,20 @@ void Countly::sendEventsToRQ(const nlohmann::json &events) { requestModule->addRequestToQueue(data); } -bool Countly::endSession() { +bool Countly::endSession() { return endSessionInternal(false); } + +bool Countly::endSessionInternal(bool automatic) { if (!is_sdk_initialized && !is_being_disposed) { log(LogLevel::WARNING, "[Countly] endSession, SDK is not initialized."); + logger->recordLogCode("w101"); return false; } + if (!automatic) { + logger->recordUsage(HEALTH_CHECK_AREA_SESSIONS, "end"); + } log(LogLevel::INFO, "[Countly] endSession, Ending session"); if (is_being_disposed == false && configurationModule->isSessionTrackingEnabled() == false) { - log(LogLevel::ERROR, "[Countly] endSession, Session tracking is disabled in server configuration, can not end session."); + log(LogLevel::DEBUG, "[Countly] endSession, Session tracking is disabled in server configuration, can not end session."); return false; } const auto timestamp = std::chrono::duration_cast(Countly::getTimestamp().time_since_epoch()); @@ -1602,9 +1664,14 @@ bool Countly::endSession() { // that clears it: read outside, two concurrent calls could both see an active // session and both queue an end_session request. stop() on one thread and a // device id change on another is enough to get there. - std::lock_guard lk(*mutex); + std::unique_lock lk(*mutex); if (began_session == false) { - log(LogLevel::DEBUG, "[Countly] endSession, There is no active session to end."); + if (automatic || is_being_disposed) { + log(LogLevel::DEBUG, "[Countly] endSession, There is no active session to end."); + } else { + log(LogLevel::WARNING, "[Countly] endSession, There is no active session to end, the call is ignored."); + logger->recordLogCode("w760"); + } return true; } @@ -1622,6 +1689,11 @@ bool Countly::endSession() { last_sent_session_request = now; began_session = false; + lk.unlock(); + if (automatic) { + logger->recordUsage(HEALTH_CHECK_AREA_SESSIONS, "end:a"); + } + health_check->saveState(); return true; } @@ -1834,6 +1906,7 @@ void Countly::addEventToSqlite(const cly::Event &event) { // Say which operation failed: this event is being dropped, and a bare // "database is locked" gives no hint of what was lost. log(LogLevel::ERROR, "[Countly] addEventToSqlite, Event was not stored, SQLite error: " + std::string(sqlite3_errmsg(database))); + logger->recordLogCode("e501"); } sqlite3_finalize(statement); } @@ -1986,6 +2059,7 @@ void Countly::updateLoop() { running = true; } try { + sendHealthCheck(); if (configuration->immediateRequestOnStop) { while (true) { { @@ -2000,11 +2074,12 @@ void Countly::updateLoop() { } } if (enable_automatic_session == true && configuration->manualSessionControl == false) { - updateSession(); + updateSessionInternal(true); } else if (configuration->manualSessionControl == true) { packEvents(); } requestModule->processQueue(mutex); + saveHealthCheckOnTimer(); } } else { while (true) { @@ -2019,11 +2094,12 @@ void Countly::updateLoop() { } std::this_thread::sleep_for(std::chrono::milliseconds(last_wait_milliseconds)); if (enable_automatic_session == true && configuration->manualSessionControl == false) { - updateSession(); + updateSessionInternal(true); } else if (configuration->manualSessionControl == true) { packEvents(); } requestModule->processQueue(mutex); + saveHealthCheckOnTimer(); } std::lock_guard lk(*mutex); running = false; @@ -2037,6 +2113,61 @@ void Countly::updateLoop() { } } +void Countly::disableHealthCheck() { + if (is_sdk_initialized) { + log(LogLevel::WARNING, "[Countly] disableHealthCheck, You can not disable the health check after SDK initialization."); + return; + } + + configuration->healthCheckEnabled = false; +} + +void Countly::sendHealthCheck() { + if (!configuration->healthCheckEnabled) { + log(LogLevel::DEBUG, "[Countly] sendHealthCheck, the health check is disabled, nothing is sent"); + return; + } + + if (configurationModule == nullptr || !configurationModule->isNetworkingEnabled()) { + log(LogLevel::DEBUG, "[Countly] sendHealthCheck, networking is disabled by the SDK behavior settings, the counters wait for the next start"); + return; + } + + if (health_check_sent.exchange(true)) { + log(LogLevel::DEBUG, "[Countly] sendHealthCheck, the health check was already sent"); + return; + } + + try { + const nlohmann::json snapshot = health_check->snapshot(); + std::map data = {{"hc", snapshot.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace)}}; + + nlohmann::json::const_iterator appVersion = configuration->metrics.find("_app_version"); + if (appVersion != configuration->metrics.end() && appVersion->is_string() && !appVersion->get().empty()) { + data["metrics"] = nlohmann::json({{"_app_version", appVersion->get()}}).dump(-1, ' ', false, nlohmann::json::error_handler_t::replace); + } + + log(LogLevel::DEBUG, "[Countly] sendHealthCheck, sending the health check"); + const HTTPResponse response = requestModule->sendHTTP("/i", requestBuilder->buildRequest(data)); + if (response.success && response.data.is_object() && response.data.contains("result")) { + log(LogLevel::DEBUG, "[Countly] sendHealthCheck, the server accepted the health check"); + health_check->clearSentValues(snapshot); + } else { + log(LogLevel::DEBUG, "[Countly] sendHealthCheck, the server did not accept the health check, the counters are kept for the next start"); + } + } catch (const std::exception &e) { + log(LogLevel::DEBUG, std::string("[Countly] sendHealthCheck, the health check could not be sent: ") + e.what()); + } +} + +void Countly::saveHealthCheckOnTimer() { + const std::chrono::steady_clock::time_point now = std::chrono::steady_clock::now(); + if (configurationModule != nullptr && now - last_health_check_save >= std::chrono::seconds(configurationModule->getSessionUpdateInterval())) { + last_health_check_save = now; + health_check->saveState(); + } +} + void Countly::enableRemoteConfig() { std::lock_guard lk(*mutex); remote_config_enabled = true; @@ -2045,6 +2176,7 @@ void Countly::enableRemoteConfig() { void Countly::updateRemoteConfig() { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] updateRemoteConfig, SDK is not initialized."); + logger->recordLogCode("w101"); return; } std::unique_lock lk(*mutex); @@ -2073,6 +2205,7 @@ nlohmann::json Countly::getRemoteConfigValue(const std::string &key) { void Countly::updateRemoteConfigFor(std::string *keys, size_t key_count) { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] updateRemoteConfigFor, SDK is not initialized."); + logger->recordLogCode("w101"); return; } std::unique_lock lk(*mutex); @@ -2095,6 +2228,7 @@ void Countly::updateRemoteConfigFor(std::string *keys, size_t key_count) { void Countly::updateRemoteConfigExcept(std::string *keys, size_t key_count) { if (!is_sdk_initialized) { log(LogLevel::WARNING, "[Countly] updateRemoteConfigExcept, SDK is not initialized."); + logger->recordLogCode("w101"); return; } std::unique_lock lk(*mutex); diff --git a/src/crash_module.cpp b/src/crash_module.cpp index be45b8c..3b5d66a 100644 --- a/src/crash_module.cpp +++ b/src/crash_module.cpp @@ -42,6 +42,7 @@ void CrashModule::addBreadcrumb(const std::string &value) { std::string limited = cly::limits::truncateString(value, lim.maxValueSize); impl->_logger->log(LogLevel::INFO, "[Countly] [CrashModule] addBreadcrumb, value = [" + limited + "]"); + impl->_logger->recordUsage("crashes", "log"); std::lock_guard lk(*impl->_mutex); // if breadcrumb count limit is reached, remove oldest breadcrumb @@ -56,6 +57,7 @@ void CrashModule::addBreadcrumb(const std::string &value) { void CrashModule::recordException(const std::string &title, const std::string &stackTrace, const bool fatal, const std::map &crashMetrics, const std::map &segmentation) { impl->_logger->log(LogLevel::INFO, cly::utils::format_string("[Countly] [CrashModule] recordException, title = [%s], stackTrace = [%s]", title.c_str(), stackTrace.c_str())); + impl->_logger->recordUsage("crashes", "record"); SDKLimits lim{COUNTLY_MAX_KEY_LENGTH_DEFAULT, COUNTLY_MAX_VALUE_SIZE_DEFAULT, COUNTLY_MAX_SEGMENTATION_VALUES_DEFAULT, COUNTLY_MAX_BREADCRUMB_COUNT_DEFAULT, COUNTLY_MAX_STACK_TRACE_LINES_PER_THREAD_DEFAULT, COUNTLY_MAX_STACK_TRACE_LINE_LENGTH_DEFAULT}; if (std::shared_ptr config = impl->_configProvider.lock()) { @@ -75,22 +77,26 @@ void CrashModule::recordException(const std::string &title, const std::string &s if (title.empty()) { impl->_logger->log(LogLevel::WARNING, "[Countly] [CrashModule] recordException, The parameter 'title' can't be empty"); + impl->_logger->recordLogCode("w700"); } if (stackTrace.empty()) { - impl->_logger->log(LogLevel::ERROR, "[Countly] [CrashModule] recordException, The parameter 'stackTrace' can't be empty"); + impl->_logger->log(LogLevel::WARNING, "[Countly] [CrashModule] recordException, The parameter 'stackTrace' can't be empty"); + impl->_logger->recordLogCode("w700"); } // check if the crash metric '_os' exists and is not empty auto it = crashMetrics.find("_os"); if (it == crashMetrics.end() || it->second.empty()) { - impl->_logger->log(LogLevel::ERROR, "[Countly] [CrashModule] recordException, The crash metric '_os' can't be empty"); + impl->_logger->log(LogLevel::WARNING, "[Countly] [CrashModule] recordException, The crash metric '_os' can't be empty"); + impl->_logger->recordLogCode("w700"); } // check if the crash metric '_app_version' exists and is not empty it = crashMetrics.find("_app_version"); if (it == crashMetrics.end() || it->second.empty()) { - impl->_logger->log(LogLevel::ERROR, "[Countly] [CrashModule] recordException, The crash metric '_app_version' can't be empty"); + impl->_logger->log(LogLevel::WARNING, "[Countly] [CrashModule] recordException, The crash metric '_app_version' can't be empty"); + impl->_logger->recordLogCode("w700"); } // lock mutex to avoid concurrent access; lock_guard releases on scope exit, diff --git a/src/health_check_module.cpp b/src/health_check_module.cpp new file mode 100644 index 0000000..34c5360 --- /dev/null +++ b/src/health_check_module.cpp @@ -0,0 +1,343 @@ +#include "countly/health_check_module.hpp" +#include "countly/logger_module.hpp" +#include "countly/storage_module_base.hpp" + +#include + +namespace cly { +namespace { +const char KEY_LOG_ERROR[] = "LErr"; +const char KEY_LOG_WARNING[] = "LWar"; +const char KEY_STATUS_CODE[] = "RStatC"; +const char KEY_ERROR_MESSAGE[] = "REMsg"; +const char KEY_BACKOFF_REQUEST[] = "BReq"; +const char KEY_CONSECUTIVE_BACKOFF_REQUEST[] = "CBReq"; +const char KEY_METHOD_USAGE[] = "MU"; +const char KEY_LOG_CODES[] = "LC"; + +const char REQUEST_KEY_ERROR_COUNT[] = "el"; +const char REQUEST_KEY_WARNING_COUNT[] = "wl"; +const char REQUEST_KEY_STATUS_CODE[] = "sc"; +const char REQUEST_KEY_ERROR_MESSAGE[] = "em"; +const char REQUEST_KEY_BACKOFF_REQUEST[] = "bom"; +const char REQUEST_KEY_CONSECUTIVE_BACKOFF_REQUEST[] = "cbom"; +const char REQUEST_KEY_METHOD_USAGE[] = "fu"; +const char REQUEST_KEY_LOG_CODES[] = "lc"; + +/** + * A non-negative whole number stored under 'key', or 0 when the entry is missing or of another type. + */ +long long storedCount(const nlohmann::json &stored, const char *key) { + nlohmann::json::const_iterator it = stored.find(key); + if (it == stored.end() || !it->is_number()) { + return 0; + } + return std::max(0LL, it->get()); +} + +/** + * The number reported under 'key' in a sent snapshot, or 'fallback' when it is missing. + */ +long long sentNumber(const nlohmann::json &sent, const char *key, long long fallback) { + nlohmann::json::const_iterator it = sent.find(key); + if (it == sent.end() || !it->is_number()) { + return fallback; + } + return it->get(); +} + +/** + * Takes a reported amount away from a count, removing the count when nothing is left. + */ +void subtract(std::map &counts, const std::string &key, long long reported) { + std::map::iterator it = counts.find(key); + if (it == counts.end()) { + return; + } + it->second -= reported; + if (it->second <= 0) { + counts.erase(it); + } +} +} // namespace + +const int HealthCheckModule::COUNT_CAP; +const size_t HealthCheckModule::MAX_ERROR_MESSAGE_LENGTH; + +HealthCheckModule::HealthCheckModule() {} + +HealthCheckModule::~HealthCheckModule() {} + +void HealthCheckModule::setLogger(std::weak_ptr logger) { + std::lock_guard lk(_mutex); + _logger = logger; +} + +void HealthCheckModule::debugLog(const std::string &message) { + std::shared_ptr logger; + { + std::lock_guard lk(_mutex); + logger = _logger.lock(); + } + if (logger) { + logger->log(LogLevel::DEBUG, "[Countly] [HealthCheckModule] " + message); + } +} + +void HealthCheckModule::setStorage(std::shared_ptr storage) { + { + std::lock_guard lk(_mutex); + _storage = storage; + } + // read outside the lock: the storage logs, and a warning it logs is counted here + std::string stored = storage ? storage->getHealthCheckState() : std::string(); + setupInitialCounters(stored); +} + +void HealthCheckModule::setupInitialCounters(const std::string &initialState) { + if (initialState.empty()) { + return; + } + + const nlohmann::json stored = nlohmann::json::parse(initialState, nullptr, false); + if (stored.is_discarded() || !stored.is_object()) { + clearAndSave(); + { + std::lock_guard lk(_mutex); + addLogCode("e503", 1); + } + debugLog("setupInitialCounters, the stored health check state could not be read and is reset"); + return; + } + + { + std::lock_guard lk(_mutex); + _countLogWarning += storedCount(stored, KEY_LOG_WARNING); + _countLogError += storedCount(stored, KEY_LOG_ERROR); + nlohmann::json::const_iterator statusCode = stored.find(KEY_STATUS_CODE); + if (_statusCode == -1 && statusCode != stored.end() && statusCode->is_number()) { + _statusCode = statusCode->get(); + } + nlohmann::json::const_iterator errorMessage = stored.find(KEY_ERROR_MESSAGE); + if (_errorMessage.empty() && errorMessage != stored.end() && errorMessage->is_string()) { + _errorMessage = errorMessage->get(); + } + _countBackoffRequest += storedCount(stored, KEY_BACKOFF_REQUEST); + _consecutiveBackoffRequest = std::max(_consecutiveBackoffRequest, storedCount(stored, KEY_CONSECUTIVE_BACKOFF_REQUEST)); + + nlohmann::json::const_iterator usage = stored.find(KEY_METHOD_USAGE); + if (usage != stored.end() && usage->is_object()) { + for (nlohmann::json::const_iterator area = usage->begin(); area != usage->end(); ++area) { + if (!area->is_object()) { + continue; + } + for (nlohmann::json::const_iterator method = area->begin(); method != area->end(); ++method) { + if (method->is_number()) { + addUsage(area.key(), method.key(), method->get()); + } + } + } + } + + nlohmann::json::const_iterator codes = stored.find(KEY_LOG_CODES); + if (codes != stored.end() && codes->is_object()) { + for (nlohmann::json::const_iterator code = codes->begin(); code != codes->end(); ++code) { + if (code->is_number()) { + addLogCode(code.key(), code->get()); + } + } + } + } + + debugLog("setupInitialCounters, loaded the stored health check state"); +} + +void HealthCheckModule::logWarning() { + std::lock_guard lk(_mutex); + _countLogWarning++; +} + +void HealthCheckModule::logError() { + std::lock_guard lk(_mutex); + _countLogError++; +} + +void HealthCheckModule::logFailedNetworkRequest(long statusCode, const std::string &errorResponse) { + if (statusCode <= 0 || statusCode >= 1000) { + return; + } + + std::lock_guard lk(_mutex); + _statusCode = statusCode; + _errorMessage = errorResponse.size() > MAX_ERROR_MESSAGE_LENGTH ? errorResponse.substr(0, MAX_ERROR_MESSAGE_LENGTH) : errorResponse; +} + +void HealthCheckModule::logBackoffRequest() { + std::lock_guard lk(_mutex); + bool continuesRun = _consecutiveBackoffRequestCounter > 0; + _countBackoffRequest++; + _consecutiveBackoffRequestCounter++; + _consecutiveBackoffRequest = std::max(_consecutiveBackoffRequest, _consecutiveBackoffRequestCounter); + addLogCode("w320", 1); + if (continuesRun) { + addLogCode("w321", 1); + } +} + +void HealthCheckModule::logConsecutiveBackoffRequest() { + std::lock_guard lk(_mutex); + _consecutiveBackoffRequestCounter = 0; +} + +void HealthCheckModule::recordUsage(const std::string &area, const std::string &method) { + if (area.empty() || method.empty()) { + return; + } + + std::lock_guard lk(_mutex); + addUsage(area, method, 1); +} + +void HealthCheckModule::recordLogCode(const std::string &code, int count) { + if (code.empty() || count <= 0) { + return; + } + + std::lock_guard lk(_mutex); + addLogCode(code, count); +} + +void HealthCheckModule::addUsage(const std::string &area, const std::string &method, long long count) { + if (count <= 0) { + return; + } + + long long ¤t = _methodUsage[area][method]; + current = std::min(current + count, static_cast(COUNT_CAP)); +} + +void HealthCheckModule::addLogCode(const std::string &code, long long count) { + if (count <= 0) { + return; + } + + long long ¤t = _logCodes[code]; + current = std::min(current + count, static_cast(COUNT_CAP)); +} + +nlohmann::json HealthCheckModule::toJson(bool forStorage) { + nlohmann::json usage = nlohmann::json::object(); + for (std::map>::const_iterator area = _methodUsage.begin(); area != _methodUsage.end(); ++area) { + nlohmann::json methods = nlohmann::json::object(); + for (std::map::const_iterator method = area->second.begin(); method != area->second.end(); ++method) { + methods[method->first] = method->second; + } + usage[area->first] = methods; + } + + nlohmann::json codes = nlohmann::json::object(); + for (std::map::const_iterator code = _logCodes.begin(); code != _logCodes.end(); ++code) { + codes[code->first] = code->second; + } + + nlohmann::json json = nlohmann::json::object(); + json[forStorage ? KEY_LOG_ERROR : REQUEST_KEY_ERROR_COUNT] = _countLogError; + json[forStorage ? KEY_LOG_WARNING : REQUEST_KEY_WARNING_COUNT] = _countLogWarning; + json[forStorage ? KEY_STATUS_CODE : REQUEST_KEY_STATUS_CODE] = _statusCode; + json[forStorage ? KEY_ERROR_MESSAGE : REQUEST_KEY_ERROR_MESSAGE] = _errorMessage; + json[forStorage ? KEY_BACKOFF_REQUEST : REQUEST_KEY_BACKOFF_REQUEST] = _countBackoffRequest; + json[forStorage ? KEY_CONSECUTIVE_BACKOFF_REQUEST : REQUEST_KEY_CONSECUTIVE_BACKOFF_REQUEST] = _consecutiveBackoffRequest; + json[forStorage ? KEY_METHOD_USAGE : REQUEST_KEY_METHOD_USAGE] = usage; + json[forStorage ? KEY_LOG_CODES : REQUEST_KEY_LOG_CODES] = codes; + return json; +} + +nlohmann::json HealthCheckModule::snapshot() { + std::lock_guard lk(_mutex); + return toJson(false); +} + +void HealthCheckModule::clearSentValues(const nlohmann::json &sent) { + { + std::lock_guard lk(_mutex); + _countLogError = std::max(0LL, _countLogError - sentNumber(sent, REQUEST_KEY_ERROR_COUNT, 0)); + _countLogWarning = std::max(0LL, _countLogWarning - sentNumber(sent, REQUEST_KEY_WARNING_COUNT, 0)); + _countBackoffRequest = std::max(0LL, _countBackoffRequest - sentNumber(sent, REQUEST_KEY_BACKOFF_REQUEST, 0)); + + if (_consecutiveBackoffRequest == sentNumber(sent, REQUEST_KEY_CONSECUTIVE_BACKOFF_REQUEST, -1)) { + _consecutiveBackoffRequest = 0; + } + + nlohmann::json::const_iterator sentMessage = sent.find(REQUEST_KEY_ERROR_MESSAGE); + std::string reportedMessage = (sentMessage != sent.end() && sentMessage->is_string()) ? sentMessage->get() : std::string(); + if (_statusCode == sentNumber(sent, REQUEST_KEY_STATUS_CODE, -2) && _errorMessage == reportedMessage) { + _statusCode = -1; + _errorMessage.clear(); + } + + nlohmann::json::const_iterator sentUsage = sent.find(REQUEST_KEY_METHOD_USAGE); + if (sentUsage != sent.end() && sentUsage->is_object()) { + for (nlohmann::json::const_iterator area = sentUsage->begin(); area != sentUsage->end(); ++area) { + std::map>::iterator counted = _methodUsage.find(area.key()); + if (counted == _methodUsage.end() || !area->is_object()) { + continue; + } + for (nlohmann::json::const_iterator method = area->begin(); method != area->end(); ++method) { + if (method->is_number()) { + subtract(counted->second, method.key(), method->get()); + } + } + if (counted->second.empty()) { + _methodUsage.erase(counted); + } + } + } + + nlohmann::json::const_iterator sentCodes = sent.find(REQUEST_KEY_LOG_CODES); + if (sentCodes != sent.end() && sentCodes->is_object()) { + for (nlohmann::json::const_iterator code = sentCodes->begin(); code != sentCodes->end(); ++code) { + if (code->is_number()) { + subtract(_logCodes, code.key(), code->get()); + } + } + } + } + + saveState(); +} + +void HealthCheckModule::saveState() { + std::shared_ptr storage; + std::string state; + { + std::lock_guard lk(_mutex); + storage = _storage.lock(); + if (!storage) { + return; + } + state = toJson(true).dump(-1, ' ', false, nlohmann::json::error_handler_t::replace); + } + // written outside the lock: the storage logs, and a warning it logs is counted here + storage->storeHealthCheckState(state); +} + +void HealthCheckModule::clearAndSave() { + std::shared_ptr storage; + { + std::lock_guard lk(_mutex); + _countLogWarning = 0; + _countLogError = 0; + _statusCode = -1; + _errorMessage.clear(); + _countBackoffRequest = 0; + _consecutiveBackoffRequest = 0; + _consecutiveBackoffRequestCounter = 0; + _methodUsage.clear(); + _logCodes.clear(); + storage = _storage.lock(); + } + if (storage) { + storage->storeHealthCheckState(""); + } +} +} // namespace cly diff --git a/src/logger_module.cpp b/src/logger_module.cpp index 131a25e..3ba708c 100644 --- a/src/logger_module.cpp +++ b/src/logger_module.cpp @@ -1,4 +1,5 @@ #include "countly/logger_module.hpp" +#include "countly/health_check_module.hpp" #include #include #include @@ -24,6 +25,9 @@ class LoggerModule::LoggerModuleImpl { // logs at DEBUG level on per-event paths. std::atomic has_logger{false}; LoggerFunction logger_function; + // Set once, before the instance logs from other threads, and never cleared. + std::shared_ptr health_check; + std::atomic has_health_check{false}; }; LoggerModule::LoggerModule() { impl = std::make_unique(); } @@ -42,6 +46,14 @@ const LoggerFunction LoggerModule::getLogger() { } void LoggerModule::log(LogLevel level, const std::string &message) { + if (level >= LogLevel::WARNING && impl->has_health_check.load(std::memory_order_acquire)) { + if (level == LogLevel::WARNING) { + impl->health_check->logWarning(); + } else { + impl->health_check->logError(); + } + } + // Fast path for the common case of no registered callback: one atomic load and // out, no lock. Without this, adding the mutex would have made every DEBUG log // site on the per-event paths more expensive than before it existed. @@ -78,4 +90,31 @@ void LoggerModule::log(LogLevel level, const std::string &message) { } bool LoggerModule::isInsideCallback() { return inside_log_callback; } + +void LoggerModule::setHealthCheck(std::shared_ptr healthCheck) { + if (!healthCheck || impl->has_health_check.load(std::memory_order_acquire)) { + return; + } + impl->health_check = healthCheck; + impl->has_health_check.store(true, std::memory_order_release); +} + +std::shared_ptr LoggerModule::healthCheck() const { + if (!impl->has_health_check.load(std::memory_order_acquire)) { + return nullptr; + } + return impl->health_check; +} + +void LoggerModule::recordLogCode(const std::string &code, int count) { + if (impl->has_health_check.load(std::memory_order_acquire)) { + impl->health_check->recordLogCode(code, count); + } +} + +void LoggerModule::recordUsage(const std::string &area, const std::string &method) { + if (impl->has_health_check.load(std::memory_order_acquire)) { + impl->health_check->recordUsage(area, method); + } +} } // namespace cly diff --git a/src/request_module.cpp b/src/request_module.cpp index 005c700..ad91110 100644 --- a/src/request_module.cpp +++ b/src/request_module.cpp @@ -1,4 +1,5 @@ #include "countly/request_module.hpp" +#include "countly/health_check_module.hpp" #include "countly/request_builder.hpp" #include @@ -188,6 +189,7 @@ void RequestModule::addRequestToQueue(const std::map & if (config->getRequestQueueSizeLimit() <= impl->_storageModule->RQCount()) { impl->_logger->log(LogLevel::WARNING, cly::utils::format_string("[Countly] [RequestModule] addRequestToQueue: Request Queue is full. Dropping the oldest request.")); + impl->_logger->recordLogCode("w310"); impl->_storageModule->RQRemoveFront(); } @@ -255,6 +257,10 @@ void RequestModule::processQueue(std::shared_ptr mutex) { std::lock_guard lk(*mutex); if (!response.success) { impl->_logger->log(LogLevel::DEBUG, cly::utils::format_string("[Countly] [RequestModule] processQueue: Failed to deliver to server, will try again later.")); + std::shared_ptr healthCheck = impl->_logger->healthCheck(); + if (healthCheck && response.status_code > 0) { + healthCheck->logFailedNetworkRequest(response.status_code, !response.body.empty() || response.data.is_null() ? response.body : response.data.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace)); + } // if the request was not a success, abort sending and try again in the future break; } @@ -358,7 +364,8 @@ HTTPResponse RequestModule::sendHTTP(std::string path, std::string data) { DWORD dwSize = static_cast(sizeof(dwStatusCode)); WinHttpQueryHeaders(hRequest, WINHTTP_QUERY_STATUS_CODE | WINHTTP_QUERY_FLAG_NUMBER, WINHTTP_HEADER_NAME_BY_INDEX, &dwStatusCode, &dwSize, WINHTTP_NO_HEADER_INDEX); response.success = (dwStatusCode >= 200 && dwStatusCode < 300); - if (response.success) { + response.status_code = static_cast(dwStatusCode); + { DWORD n_bytes_available; bool error_reading_body = false; std::string body; @@ -387,10 +394,11 @@ HTTPResponse RequestModule::sendHTTP(std::string path, std::string data) { delete[] body_part; } while (n_bytes_available > 0); - if (!body.empty()) { + response.body = body; + if (response.success && !body.empty()) { const nlohmann::json &parseResult = nlohmann::json::parse(body, nullptr, false); if (parseResult.is_discarded()) { - impl->_logger->log(LogLevel::WARNING, "[Countly] [RequestModule] sendHTTP, Returned response from the server was not a valid JSON."); + impl->_logger->log(LogLevel::DEBUG, "[Countly] [RequestModule] sendHTTP, Returned response from the server was not a valid JSON."); } else { response.data = parseResult; } @@ -442,11 +450,13 @@ HTTPResponse RequestModule::sendHTTP(std::string path, std::string data) { long status_code; curl_easy_getinfo(curl, CURLINFO_RESPONSE_CODE, &status_code); response.success = (status_code >= 200 && status_code < 300); + response.status_code = status_code; + response.body = body; if (!body.empty()) { const nlohmann::json &parseResult = nlohmann::json::parse(body, nullptr, false); if (parseResult.is_discarded()) { - impl->_logger->log(LogLevel::WARNING, "[Countly] [RequestModule] sendHTTP, Returned response from the server was not a valid JSON."); + impl->_logger->log(LogLevel::DEBUG, "[Countly] [RequestModule] sendHTTP, Returned response from the server was not a valid JSON."); } else { response.data = parseResult; } diff --git a/src/storage_module_db.cpp b/src/storage_module_db.cpp index e0175e1..3f11938 100644 --- a/src/storage_module_db.cpp +++ b/src/storage_module_db.cpp @@ -15,6 +15,10 @@ const char REQUESTS_TABLE_REQUEST_DATA[] = "RequestData"; #define SDK_BEHAVIOR_SETTINGS_KEY_COLUMN_NAME "Key" #define SDK_BEHAVIOR_SETTINGS_DATA_COLUMN_NAME "SettingsData" #define SDK_BEHAVIOR_SETTINGS_KEY_VALUE 1 +#define HEALTH_CHECK_TABLE_NAME "HealthCheck" +#define HEALTH_CHECK_KEY_COLUMN_NAME "Key" +#define HEALTH_CHECK_DATA_COLUMN_NAME "StateData" +#define HEALTH_CHECK_KEY_VALUE 1 namespace cly { StorageModuleDB::StorageModuleDB(std::shared_ptr config, std::shared_ptr logger) : StorageModuleBase(config, logger) {} @@ -33,8 +37,9 @@ void StorageModuleDB::init() { } #endif - // Create schema for the requests table and the SDK behavior settings table - _is_initialized = createSchema(REQUESTS_TABLE_NAME, REQUESTS_TABLE_REQUEST_ID, REQUESTS_TABLE_REQUEST_DATA) && createSchema(SDK_BEHAVIOR_SETTINGS_TABLE_NAME, SDK_BEHAVIOR_SETTINGS_KEY_COLUMN_NAME, SDK_BEHAVIOR_SETTINGS_DATA_COLUMN_NAME); + // Create schema for the requests table, the SDK behavior settings table and the health check table + _is_initialized = createSchema(REQUESTS_TABLE_NAME, REQUESTS_TABLE_REQUEST_ID, REQUESTS_TABLE_REQUEST_DATA) && createSchema(SDK_BEHAVIOR_SETTINGS_TABLE_NAME, SDK_BEHAVIOR_SETTINGS_KEY_COLUMN_NAME, SDK_BEHAVIOR_SETTINGS_DATA_COLUMN_NAME) && + createSchema(HEALTH_CHECK_TABLE_NAME, HEALTH_CHECK_KEY_COLUMN_NAME, HEALTH_CHECK_DATA_COLUMN_NAME); if (_is_initialized) { vacuumDatabase(); @@ -559,4 +564,97 @@ std::string StorageModuleDB::getSDKBehaviorSettings() { } } +void StorageModuleDB::storeHealthCheckState(const std::string &state) { + try { + if (!_is_initialized) { + _logger->log(LogLevel::DEBUG, "[Countly] [StorageModuleDB] storeHealthCheckState, Module is not initialized"); + return; + } + +#ifdef COUNTLY_USE_SQLITE + sqlite3 *db = nullptr; + sqlite3_stmt *stmt = nullptr; + + if (cly::utils::openDatabase(_configuration->databasePath, &db) != SQLITE_OK) { + _logger->log(LogLevel::ERROR, "[Countly] [StorageModuleDB] storeHealthCheckState, Failed to open database"); + _logger->recordLogCode("e501"); + return; + } + + const char *sql = "INSERT OR REPLACE INTO " HEALTH_CHECK_TABLE_NAME " (" HEALTH_CHECK_KEY_COLUMN_NAME ", " HEALTH_CHECK_DATA_COLUMN_NAME ") " + "VALUES (?, ?);"; + + if (sqlite3_prepare_v2(db, sql, -1, &stmt, nullptr) != SQLITE_OK) { + _logger->log(LogLevel::ERROR, "[Countly] [StorageModuleDB] storeHealthCheckState, Failed to prepare statement"); + _logger->recordLogCode("e501"); + sqlite3_close(db); + return; + } + + sqlite3_bind_int(stmt, 1, HEALTH_CHECK_KEY_VALUE); + sqlite3_bind_text(stmt, 2, state.c_str(), -1, SQLITE_TRANSIENT); + + if (sqlite3_step(stmt) != SQLITE_DONE) { + const char *err = sqlite3_errmsg(db); + _logger->log(LogLevel::ERROR, std::string("[Countly] [StorageModuleDB] storeHealthCheckState, failed: [") + err + "]"); + _logger->recordLogCode("e501"); + } + + sqlite3_finalize(stmt); + sqlite3_close(db); +#else + (void)state; +#endif + } catch (const std::exception &e) { + _logger->log(LogLevel::ERROR, std::string("[Countly] [StorageModuleDB] storeHealthCheckState, exception: [") + e.what() + "]"); + _logger->recordLogCode("e501"); + } +} + +std::string StorageModuleDB::getHealthCheckState() { + try { + if (!_is_initialized) { + _logger->log(LogLevel::DEBUG, "[Countly] [StorageModuleDB] getHealthCheckState, Module is not initialized"); + return ""; + } + +#ifdef COUNTLY_USE_SQLITE + sqlite3 *db = nullptr; + sqlite3_stmt *stmt = nullptr; + std::string result; + + if (cly::utils::openDatabase(_configuration->databasePath, &db) != SQLITE_OK) { + _logger->log(LogLevel::ERROR, "[Countly] [StorageModuleDB] getHealthCheckState, Failed to open database"); + return ""; + } + + const char *sql = "SELECT " HEALTH_CHECK_DATA_COLUMN_NAME " FROM " HEALTH_CHECK_TABLE_NAME " WHERE " HEALTH_CHECK_KEY_COLUMN_NAME " = ?;"; + + if (sqlite3_prepare_v2(db, sql, -1, &stmt, nullptr) == SQLITE_OK) { + sqlite3_bind_int(stmt, 1, HEALTH_CHECK_KEY_VALUE); + if (sqlite3_step(stmt) == SQLITE_ROW) { + const unsigned char *text = sqlite3_column_text(stmt, 0); + if (text) { + result = reinterpret_cast(text); + } + } + } else { + _logger->log(LogLevel::ERROR, "[Countly] [StorageModuleDB] getHealthCheckState, Failed to prepare statement"); + } + + if (stmt) { + sqlite3_finalize(stmt); + } + sqlite3_close(db); + + return result; +#else + return ""; +#endif + } catch (const std::exception &e) { + _logger->log(LogLevel::ERROR, std::string("[Countly] [StorageModuleDB] getHealthCheckState, exception: [") + e.what() + "]"); + return ""; + } +} + }; // namespace cly \ No newline at end of file diff --git a/src/views_module.cpp b/src/views_module.cpp index a06f5b8..b97acc7 100644 --- a/src/views_module.cpp +++ b/src/views_module.cpp @@ -150,6 +150,7 @@ class ViewsModule::ViewModuleImpl { _logger->log(cly::LogLevel::WARNING, cly::utils::format_string("[Countly] [ViewsModule] _closeViewWithName, Couldn't find " "view with name = [%s]", name.c_str())); + _logger->recordLogCode("w730"); return; } _recordView(v, {}, false); @@ -180,6 +181,7 @@ class ViewsModule::ViewModuleImpl { _logger->log(cly::LogLevel::WARNING, cly::utils::format_string("[Countly] [ViewsModule] _closeViewWithID, Couldn't find " "view with viewId = [%s]", viewId.c_str())); + _logger->recordLogCode("w730"); return; } @@ -199,8 +201,10 @@ std::string ViewsModule::openView(const std::string &name, const std::map_logger->log(cly::LogLevel::INFO, cly::utils::format_string("[Countly] [ViewsModule] openView, name = [%s], segmentation = [%s]", name.c_str(), utils::mapToString(segmentation).c_str())); + impl->_logger->recordUsage("views", "start"); if (name.empty()) { impl->_logger->log(cly::LogLevel::WARNING, "[Countly] [ViewsModule] openView, view name can not be null or empty!"); + impl->_logger->recordLogCode("w710"); return {}; } @@ -210,8 +214,10 @@ std::string ViewsModule::openView(const std::string &name, const std::map_logger->log(cly::LogLevel::INFO, cly::utils::format_string("[Countly] [ViewsModule] closeViewWithName, name = [%s]", name.c_str())); + impl->_logger->recordUsage("views", "stop"); if (name.empty()) { impl->_logger->log(cly::LogLevel::WARNING, "[Countly] [ViewsModule] closeViewWithName, view name can not be null or empty!"); + impl->_logger->recordLogCode("w700"); return; } impl->_closeViewWithName(name); @@ -220,8 +226,10 @@ void ViewsModule::closeViewWithName(const std::string &name) { void ViewsModule::closeViewWithID(const std::string &viewId) { impl->_logger->log(cly::LogLevel::INFO, cly::utils::format_string("[Countly] [ViewsModule] closeViewWithID, viewId = [%s]", viewId.c_str())); + impl->_logger->recordUsage("views", "stop"); if (viewId.empty()) { impl->_logger->log(cly::LogLevel::WARNING, "[Countly] [ViewsModule] closeViewWithID, viewId can not be null or empty!"); + impl->_logger->recordLogCode("w700"); return; } diff --git a/tests/health_check.cpp b/tests/health_check.cpp new file mode 100644 index 0000000..272263e --- /dev/null +++ b/tests/health_check.cpp @@ -0,0 +1,412 @@ +#include +#include +#include +#include +#include + +#include "doctest.h" + +#include "countly/health_check_module.hpp" +#include "nlohmann/json.hpp" +#include "test_utils.hpp" + +using namespace cly; +using namespace test_utils; +using json = nlohmann::json; + +namespace { +/** + * A storage that keeps only the health check state, for the counter tests. + */ +class HealthCheckStateStorage : public StorageModuleBase { +public: + std::string state; + + HealthCheckStateStorage() : StorageModuleBase(nullptr, nullptr) {} + void init() override {} + long long RQCount() override { return 0; } + void RQClearAll() override {} + void RQRemoveFront() override {} + const std::shared_ptr RQPeekFront() override { return std::make_shared(-1, ""); } + std::vector> RQPeekAll() override { return {}; } + void RQRemoveFront(std::shared_ptr request) override { (void)request; } + void RQInsertAtEnd(const std::string &request) override { (void)request; } + void storeSDKBehaviorSettings(const std::string &sdk_behavior_settings) override { (void)sdk_behavior_settings; } + std::string getSDKBehaviorSettings() override { return ""; } + void storeHealthCheckState(const std::string &value) override { state = value; } + std::string getHealthCheckState() override { return state; } +}; + +/** + * The count of a method in a health check, 0 when it was not counted. + */ +long long usage(const json &hc, const std::string &area, const std::string &method) { + if (!hc["fu"].contains(area) || !hc["fu"][area].contains(method)) { + return 0; + } + return hc["fu"][area][method].get(); +} + +/** + * The count of a log code in a health check, 0 when it was not recorded. + */ +long long code(const json &hc, const std::string &logCode) { + if (!hc["lc"].contains(logCode)) { + return 0; + } + return hc["lc"][logCode].get(); +} + +/** + * Waits until the fake HTTP client received a health check, at most two seconds. + */ +bool waitForHealthCheck(size_t count = 1) { + for (int attempt = 0; attempt < 200; attempt++) { + if (health_check_call_queue.size() >= count) { + return true; + } + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + } + return false; +} + +/** + * Starts the default instance with the fake HTTP client and manual session control, so no session + * request is queued unless a test makes one. + */ +void startWithHealthCheck(Countly &countly) { + countly.setHTTPClient(test_utils::fakeSendHTTP); + countly.setDeviceID(COUNTLY_TEST_DEVICE_ID); + countly.SetPath(TEST_DATABASE_NAME); + countly.disableSDKBehaviorSettingsUpdates(); + countly.enableManualSessionControl(); + countly.setMetrics("Windows", "10", "PC", "1920x1080", "", "2.4.1"); + countly.start(COUNTLY_TEST_APP_KEY, COUNTLY_TEST_HOST, COUNTLY_TEST_PORT, false); +} +} // namespace + +TEST_CASE("health check counters") { + SUBCASE("a new counter reports the defaults, with empty method usage and log codes") { + HealthCheckModule module; + json hc = module.snapshot(); + CHECK(hc["el"] == 0); + CHECK(hc["wl"] == 0); + CHECK(hc["sc"] == -1); + CHECK(hc["em"] == ""); + CHECK(hc["bom"] == 0); + CHECK(hc["cbom"] == 0); + CHECK(hc["fu"].is_object()); + CHECK(hc["fu"].empty()); + CHECK(hc["lc"].is_object()); + CHECK(hc["lc"].empty()); + } + + SUBCASE("only the last refused request is kept, status codes outside 1..999 are ignored, the message is cut") { + HealthCheckModule module; + module.logFailedNetworkRequest(500, "first"); + module.logFailedNetworkRequest(0, "ignored"); + module.logFailedNetworkRequest(1000, "ignored"); + module.logFailedNetworkRequest(400, std::string(1200, 'x')); + json hc = module.snapshot(); + CHECK(hc["sc"] == 400); + CHECK(hc["em"].get().size() == 1000); + } + + SUBCASE("cbom keeps the longest run of backoffs, w320 counts every backoff and w321 every one that continues a run") { + HealthCheckModule module; + module.logBackoffRequest(); + module.logBackoffRequest(); + module.logBackoffRequest(); + module.saveState(); + module.logConsecutiveBackoffRequest(); + module.logBackoffRequest(); + module.logBackoffRequest(); + json hc = module.snapshot(); + CHECK(hc["bom"] == 5); + CHECK(hc["cbom"] == 3); + CHECK(code(hc, "w320") == 5); + CHECK(code(hc, "w321") == 3); + } + + SUBCASE("counts stop at 65535 and empty names are ignored") { + HealthCheckModule module; + module.recordLogCode("w101", 70000); + module.recordLogCode("w101"); + module.recordUsage("events", ""); + module.recordUsage("", "record"); + json hc = module.snapshot(); + CHECK(code(hc, "w101") == 65535); + CHECK(hc["fu"].empty()); + } + + SUBCASE("an accepted health check takes away only what it reported") { + std::shared_ptr storage = std::make_shared(); + HealthCheckModule module; + module.setStorage(storage); + module.logWarning(); + module.logWarning(); + module.logFailedNetworkRequest(500, "down"); + module.logBackoffRequest(); + module.recordUsage("events", "record"); + module.recordLogCode("w720"); + + json sent = module.snapshot(); + + module.logWarning(); + module.logFailedNetworkRequest(400, "bad"); + module.logBackoffRequest(); + module.recordUsage("events", "record"); + module.recordUsage("views", "start"); + + module.clearSentValues(sent); + json left = module.snapshot(); + CHECK(left["wl"] == 1); + CHECK(left["sc"] == 400); + CHECK(left["em"] == "bad"); + CHECK(left["bom"] == 1); + CHECK(left["cbom"] == 2); + CHECK(usage(left, "events", "record") == 1); + CHECK(usage(left, "views", "start") == 1); + CHECK(code(left, "w720") == 0); + CHECK(json::parse(storage->state)["LWar"] == 1); + + module.clearSentValues(module.snapshot()); + json empty = module.snapshot(); + CHECK(empty["sc"] == -1); + CHECK(empty["em"] == ""); + CHECK(empty["cbom"] == 0); + CHECK(empty["fu"].empty()); + } + + SUBCASE("a stored state is restored and added to what was counted before, with the storage keys of the guide") { + std::shared_ptr storage = std::make_shared(); + storage->state = R"({"LErr":2,"LWar":3,"RStatC":503,"REMsg":"Service Unavailable","BReq":4,"CBReq":2,)" + R"("MU":{"events":{"record":5,"start":"x"},"views":7},"LC":{"w740":1,"w720":"y"}})"; + HealthCheckModule module; + module.logWarning(); + module.setStorage(storage); + + json hc = module.snapshot(); + CHECK(hc["el"] == 2); + CHECK(hc["wl"] == 4); + CHECK(hc["sc"] == 503); + CHECK(hc["em"] == "Service Unavailable"); + CHECK(hc["bom"] == 4); + CHECK(hc["cbom"] == 2); + CHECK(usage(hc, "events", "record") == 5); + CHECK(usage(hc, "events", "start") == 0); + CHECK(!hc["fu"].contains("views")); + CHECK(code(hc, "w740") == 1); + CHECK(!hc["lc"].contains("w720")); + + module.saveState(); + json stored = json::parse(storage->state); + for (const char *key : {"LErr", "LWar", "RStatC", "REMsg", "BReq", "CBReq", "MU", "LC"}) { + CHECK(stored.contains(key)); + } + } + + SUBCASE("a stored state that is not valid JSON is cleared and reported as e503") { + std::shared_ptr storage = std::make_shared(); + storage->state = "{not json"; + HealthCheckModule module; + module.setStorage(storage); + + json hc = module.snapshot(); + CHECK(storage->state.empty()); + CHECK(hc["el"] == 0); + CHECK(code(hc, "e503") == 1); + } +} + +TEST_CASE("health check requests") { + SUBCASE("sent once after start as a request to /i, with the base parameters, the app version and the counters") { + clearSDK(); + Countly &countly = Countly::getInstance(); + countly.setEventsToRQThreshold(0); + startWithHealthCheck(countly); + + REQUIRE(waitForHealthCheck()); + HTTPCall call = health_check_call_queue.front(); + CHECK(call.url == "/i"); + CHECK(call.data["app_key"] == COUNTLY_TEST_APP_KEY); + CHECK(call.data["device_id"] == COUNTLY_TEST_DEVICE_ID); + CHECK(!call.data["timestamp"].empty()); + CHECK(call.data["sdk_name"] == COUNTLY_SDK_NAME); + CHECK(call.data["sdk_version"] == COUNTLY_SDK_VERSION); + CHECK(json::parse(call.data["metrics"]) == json({{"_app_version", "2.4.1"}})); + + json hc = json::parse(call.data["hc"]); + for (const char *key : {"el", "wl", "sc", "em", "bom", "cbom", "fu", "lc"}) { + CHECK(hc.contains(key)); + } + CHECK(hc["wl"].get() >= 1); + CHECK(code(hc, "w121") == 1); + + // the fake client accepts it, so what it reported is taken away once the answer is handled + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + CHECK(code(countly.debugHealthCheck()->snapshot(), "w121") == 0); + + countly.updateSession(); + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + CHECK(health_check_call_queue.size() == 1); + clearSDK(); + } + + SUBCASE("disabled, nothing is sent, but warnings are still counted") { + clearSDK(); + Countly &countly = Countly::getInstance(); + countly.disableHealthCheck(); + startWithHealthCheck(countly); + std::this_thread::sleep_for(std::chrono::milliseconds(300)); + CHECK(health_check_call_queue.empty()); + + long long before = countly.debugHealthCheck()->snapshot()["wl"].get(); + countly.endSession(); + CHECK(countly.debugHealthCheck()->snapshot()["wl"].get() == before + 1); + clearSDK(); + } + + SUBCASE("networking turned off by the SDK behavior settings, nothing is sent") { + clearSDK(); + Countly &countly = Countly::getInstance(); + std::string settings = json({{"networking", false}}).dump(); + countly.setSDKBehaviorSettings(settings); + startWithHealthCheck(countly); + std::this_thread::sleep_for(std::chrono::milliseconds(300)); + CHECK(health_check_call_queue.empty()); + clearSDK(); + } + + SUBCASE("a refused health check leaves the counters for the next start") { + clearSDK(); + Countly &countly = Countly::getInstance(); + countly.setHTTPClient([](bool use_post, const std::string &url, const std::string &data) { + HTTPResponse response = fakeSendHTTP(use_post, url, data); + if (data.find("hc=") != std::string::npos) { + return HTTPResponse{false, json::object(), 400, R"({"result":"App does not exist"})"}; + } + return response; + }); + countly.setDeviceID(COUNTLY_TEST_DEVICE_ID); + countly.SetPath(TEST_DATABASE_NAME); + countly.disableSDKBehaviorSettingsUpdates(); + countly.enableManualSessionControl(); + countly.setEventsToRQThreshold(0); + countly.start(COUNTLY_TEST_APP_KEY, COUNTLY_TEST_HOST, COUNTLY_TEST_PORT, false); + + REQUIRE(waitForHealthCheck()); + std::this_thread::sleep_for(std::chrono::milliseconds(100)); + CHECK(code(countly.debugHealthCheck()->snapshot(), "w121") == 1); + clearSDK(); + } +} + +TEST_CASE("health check method usage and log codes") { + SUBCASE("the app's session, event, view and crash calls are counted under the names of the guide") { + clearSDK(); + Countly &countly = Countly::getInstance(); + startWithHealthCheck(countly); + REQUIRE(waitForHealthCheck()); + + countly.beginSession(); + countly.updateSession(); + countly.endSession(); + + countly.addEvent(Event("click", 1)); + countly.RecordEvent("purchase", 2); + + std::string viewId = countly.views().openView("first"); + countly.views().closeViewWithID(viewId); + countly.views().openView("second"); + countly.views().closeViewWithName("second"); + + countly.crash().addBreadcrumb("crumb"); + countly.crash().recordException("title", "trace", false, {{"_os", "Windows"}, {"_app_version", "2.4.1"}}); + + json hc = countly.debugHealthCheck()->snapshot(); + CHECK(usage(hc, "sessions", "begin") == 1); + CHECK(usage(hc, "sessions", "update") == 1); + CHECK(usage(hc, "sessions", "end") == 1); + CHECK(usage(hc, "events", "record") == 2); + CHECK(usage(hc, "views", "start") == 2); + CHECK(usage(hc, "views", "stop") == 2); + CHECK(usage(hc, "crashes", "log") == 1); + CHECK(usage(hc, "crashes", "record") == 1); + clearSDK(); + } + + SUBCASE("sessions the SDK begins and ends by itself carry :a") { + clearSDK(); + Countly &countly = Countly::getInstance(); + countly.setHTTPClient(test_utils::fakeSendHTTP); + countly.setDeviceID(COUNTLY_TEST_DEVICE_ID); + countly.SetPath(TEST_DATABASE_NAME); + countly.disableSDKBehaviorSettingsUpdates(); + countly.start(COUNTLY_TEST_APP_KEY, COUNTLY_TEST_HOST, COUNTLY_TEST_PORT, true); + REQUIRE(waitForHealthCheck()); + std::shared_ptr healthCheck = countly.debugHealthCheck(); + + // the session begun at start is in the first health check, which the fake client accepts + CHECK(usage(json::parse(health_check_call_queue.front().data["hc"]), "sessions", "begin:a") == 1); + countly.stop(); + json hc = healthCheck->snapshot(); + CHECK(usage(hc, "sessions", "end:a") == 1); + CHECK(usage(hc, "sessions", "begin") == 0); + clearSDK(); + } + + SUBCASE("misuse of the session and view methods records the codes of the guide") { + clearSDK(); + Countly &countly = Countly::getInstance(); + countly.addEvent(Event("too early", 1)); + startWithHealthCheck(countly); + REQUIRE(waitForHealthCheck()); + + countly.start(COUNTLY_TEST_APP_KEY, COUNTLY_TEST_HOST, COUNTLY_TEST_PORT, false); + countly.beginSession(); + countly.beginSession(); + countly.endSession(); + countly.endSession(); + countly.views().openView(""); + countly.views().closeViewWithID("unknown"); + countly.setCountry("TR"); + + json sent = json::parse(health_check_call_queue.front().data["hc"]); + CHECK(code(sent, "w101") == 1); + + json hc = countly.debugHealthCheck()->snapshot(); + CHECK(code(hc, "w110") == 1); + CHECK(code(hc, "w760") == 2); + CHECK(code(hc, "w710") == 1); + CHECK(code(hc, "w730") == 1); + CHECK(code(hc, "w120") == 1); + clearSDK(); + } + + SUBCASE("a queued request the server refuses is reported in sc and em") { + clearSDK(); + Countly &countly = Countly::getInstance(); + countly.setHTTPClient([](bool use_post, const std::string &url, const std::string &data) { + HTTPResponse response = fakeSendHTTP(use_post, url, data); + if (data.find("hc=") == std::string::npos && url == "/i") { + return HTTPResponse{false, json::object(), 400, R"({"result":"App does not exist"})"}; + } + return response; + }); + countly.setDeviceID(COUNTLY_TEST_DEVICE_ID); + countly.SetPath(TEST_DATABASE_NAME); + countly.disableSDKBehaviorSettingsUpdates(); + countly.enableManualSessionControl(); + countly.start(COUNTLY_TEST_APP_KEY, COUNTLY_TEST_HOST, COUNTLY_TEST_PORT, false); + REQUIRE(waitForHealthCheck()); + + countly.beginSession(); + countly.processRQDebug(); + + json hc = countly.debugHealthCheck()->snapshot(); + CHECK(hc["sc"] == 400); + CHECK(hc["em"] == R"({"result":"App does not exist"})"); + clearSDK(); + } +} diff --git a/tests/request.cpp b/tests/request.cpp index 445a079..2ffeb38 100644 --- a/tests/request.cpp +++ b/tests/request.cpp @@ -270,7 +270,7 @@ static bool waitForRequestWith(const std::string &key, const std::string &value) } /** - * What a request is for: the method of a fetch from /o/sdk, otherwise the type of queued request it carries. + * What a request is for: the method of a fetch from /o/sdk, otherwise the type of queued request it carries, or "hc" for the health check. */ static std::string requestKind(const test_utils::HTTPCall &call) { if (call.url == "/o/sdk") { @@ -281,7 +281,7 @@ static std::string requestKind(const test_utils::HTTPCall &call) { return method->second; } // end_session comes before session_duration because an end_session request carries both - for (const char *kind : {"begin_session", "end_session", "session_duration", "events", "user_details", "location", "crash", "old_device_id"}) { + for (const char *kind : {"begin_session", "end_session", "session_duration", "events", "user_details", "location", "crash", "old_device_id", "hc"}) { if (call.data.count(kind) > 0) { return kind; } @@ -599,7 +599,7 @@ TEST_CASE("Built-in HTTP client") { while (std::chrono::steady_clock::now() < deadline) { countly->processRQDebug(); request_lines = server.requestLines(); - if (request_lines.size() >= 4 && countly->checkRQSize() == 0) { + if (request_lines.size() >= 5 && countly->checkRQSize() == 0) { break; } std::this_thread::sleep_for(std::chrono::milliseconds(100)); @@ -624,7 +624,7 @@ TEST_CASE("Built-in HTTP client") { CHECK(call.data["sdk_name"] == EXPECTED_SDK_NAME); CHECK(call.data["sdk_version"] == COUNTLY_SDK_VERSION); } - CHECK(kinds == std::multiset{"sc", "fetch_remote_config", "begin_session", "events"}); + CHECK(kinds == std::multiset{"sc", "fetch_remote_config", "begin_session", "events", "hc"}); } SUBCASE("a request to a server that never answers is given up after the request timeout") { diff --git a/tests/test_utils.hpp b/tests/test_utils.hpp index 1dc799e..300a18b 100644 --- a/tests/test_utils.hpp +++ b/tests/test_utils.hpp @@ -42,6 +42,10 @@ struct ThreadSafeHTTPCallQueue { static ThreadSafeHTTPCallQueue http_call_queue; +// Health check requests the fake client received. Kept apart from http_call_queue, so the tests that +// assert the order of the queued requests do not see the health check sent at start. +static ThreadSafeHTTPCallQueue health_check_call_queue; + // Countly::setLogger takes a plain function pointer, so captured messages live in these statics. static std::mutex captured_log_mutex; static std::vector captured_log_messages; @@ -80,6 +84,7 @@ static void clearSDK() { cly::Countly::halt(); remove(TEST_DATABASE_NAME); http_call_queue.clear(); + health_check_call_queue.clear(); } /** @@ -171,6 +176,11 @@ static HTTPResponse fakeSendHTTPInto(ThreadSafeHTTPCallQueue &queue, bool use_po } } + if (http_call.data.find("hc") != http_call.data.end()) { + health_check_call_queue.push_back(http_call); + return HTTPResponse{true, nlohmann::json({{"result", "Success"}}), 200}; + } + queue.push_back(http_call); HTTPResponse response{false, nlohmann::json::object()};