From 646b18bf28a4d3619180813775fc9f536cb422a7 Mon Sep 17 00:00:00 2001 From: Benjamin Sergeant Date: Fri, 24 Apr 2020 15:17:50 -0700 Subject: [PATCH] core logger support multiple level + switch ixbots to user corelogger instead of spdlog --- ixbots/CMakeLists.txt | 5 -- ixbots/ixbots/IXCobraBot.cpp | 79 ++++++++++--------- ixbots/ixbots/IXCobraToSentryBot.cpp | 35 ++++---- ixbots/ixbots/IXCobraToStatsdBot.cpp | 6 +- ixbots/ixbots/IXCobraToStdoutBot.cpp | 1 - .../IXCobraMetricsThreadedPublisher.cpp | 4 +- ixcore/ixcore/utils/IXCoreLogger.cpp | 40 ++++++++-- ixcore/ixcore/utils/IXCoreLogger.h | 29 ++++++- ixsentry/ixsentry/IXSentryClient.cpp | 6 +- ixsnake/ixsnake/IXSnakeProtocol.cpp | 4 +- ixsnake/ixsnake/IXSnakeServer.cpp | 7 +- test/test_runner.cpp | 37 ++++++++- ws/ws.cpp | 37 ++++++++- 13 files changed, 206 insertions(+), 84 deletions(-) diff --git a/ixbots/CMakeLists.txt b/ixbots/CMakeLists.txt index 2bf3a2f9..dd73a586 100644 --- a/ixbots/CMakeLists.txt +++ b/ixbots/CMakeLists.txt @@ -31,11 +31,6 @@ if (NOT JSONCPP_FOUND) set(JSONCPP_INCLUDE_DIRS ../third_party/jsoncpp) endif() -find_package(SpdLog) -if (NOT SPDLOG_FOUND) - set(SPDLOG_INCLUDE_DIRS ../third_party/spdlog/include) -endif() - set(IXBOTS_INCLUDE_DIRS . .. diff --git a/ixbots/ixbots/IXCobraBot.cpp b/ixbots/ixbots/IXCobraBot.cpp index 45bb1c89..7b265f43 100644 --- a/ixbots/ixbots/IXCobraBot.cpp +++ b/ixbots/ixbots/IXCobraBot.cpp @@ -7,10 +7,11 @@ #include "IXCobraBot.h" #include "IXQueueManager.h" +#include +#include + #include #include -#include -#include #include #include #include @@ -34,10 +35,10 @@ namespace ix Json::FastWriter jsonWriter; std::atomic sentCount(0); std::atomic receivedCount(0); - std::atomic sentCountTotal(0); - std::atomic receivedCountTotal(0); - std::atomic sentCountPerSecs(0); - std::atomic receivedCountPerSecs(0); + uint64_t sentCountTotal(0); + uint64_t receivedCountTotal(0); + uint64_t sentCountPerSecs(0); + uint64_t receivedCountPerSecs(0); std::atomic stop(false); std::atomic throttled(false); std::atomic fatalCobraError(false); @@ -58,11 +59,17 @@ namespace ix // as those are used externally, so we need to introduce // our own counters // - spdlog::info("messages received {} {} sent {} {}", - receivedCountPerSecs, - receivedCountTotal, - sentCountPerSecs, - sentCountTotal); + std::stringstream ss; + ss << "messages received " + << receivedCountPerSecs + << " " + << receivedCountTotal + << " sent " + << sentCountPerSecs + << " " + << sentCountTotal; + CoreLogger::info(ss.str()); + receivedCountPerSecs = receivedCount - receivedCountTotal; sentCountPerSecs = sentCount - receivedCountTotal; @@ -73,7 +80,7 @@ namespace ix std::this_thread::sleep_for(duration); } - spdlog::info("timer thread done"); + CoreLogger::info("timer thread done"); }; std::thread t1(timer); @@ -93,7 +100,7 @@ namespace ix if (currentState == state) { - spdlog::error("no messages received or sent for 1 minute, exiting"); + CoreLogger::error("no messages received or sent for 1 minute, exiting"); exit(1); } state = currentState; @@ -102,7 +109,7 @@ namespace ix std::this_thread::sleep_for(duration); } - spdlog::info("heartbeat thread done"); + CoreLogger::info("heartbeat thread done"); }; std::thread t2(heartbeat); @@ -124,19 +131,19 @@ namespace ix // That might be too noisy if (verbose) { - spdlog::info("cobra bot: sending succesfull"); + CoreLogger::info("cobra bot: sending succesfull"); } ++sentCount; } else { - spdlog::error("cobra bot: error sending"); + CoreLogger::error("cobra bot: error sending"); } if (stop) break; } - spdlog::info("sender thread done"); + CoreLogger::info("sender thread done"); }; std::thread t3(sender); @@ -158,22 +165,23 @@ namespace ix &sentCount](const CobraEventPtr& event) { if (event->type == ix::CobraEventType::Open) { - spdlog::info("Subscriber connected"); + CoreLogger::info("Subscriber connected"); for (auto&& it : event->headers) { - spdlog::info("{}: {}", it.first, it.second); + CoreLogger::info(it.first + "::" + it.second); } } else if (event->type == ix::CobraEventType::Closed) { - spdlog::info("Subscriber closed: {}", event->errMsg); + CoreLogger::info("Subscriber closed: {}" + event->errMsg); } else if (event->type == ix::CobraEventType::Authenticated) { - spdlog::info("Subscriber authenticated"); - spdlog::info("Subscribing to {} at position {}", channel, subscriptionPosition); - spdlog::info("Using filter: {}", filter); + CoreLogger::info("Subscriber authenticated"); + CoreLogger::info("Subscribing to " + channel); + CoreLogger::info("Subscribing at position " + subscriptionPosition); + CoreLogger::info("Subscribing with filter " + filter); conn.subscribe(channel, filter, subscriptionPosition, @@ -189,9 +197,8 @@ namespace ix &sentCount](const Json::Value& msg, const std::string& position) { if (verbose) { - spdlog::info("Subscriber received message {} -> {}", - position, - jsonWriter.write(msg)); + CoreLogger::info("Subscriber received message " + + position + " -> " + jsonWriter.write(msg)); } subscriptionPosition = position; @@ -217,50 +224,50 @@ namespace ix // That might be too noisy if (verbose) { - spdlog::info("cobra bot: sending succesfull"); + CoreLogger::info("cobra bot: sending succesfull"); } ++sentCount; } else { - spdlog::error("cobra bot: error sending"); + CoreLogger::error("cobra bot: error sending"); } } }); } else if (event->type == ix::CobraEventType::Subscribed) { - spdlog::info("Subscriber: subscribed to channel {}", event->subscriptionId); + CoreLogger::info("Subscriber: subscribed to channel " + event->subscriptionId); } else if (event->type == ix::CobraEventType::UnSubscribed) { - spdlog::info("Subscriber: unsubscribed from channel {}", event->subscriptionId); + CoreLogger::info("Subscriber: unsubscribed from channel " + event->subscriptionId); } else if (event->type == ix::CobraEventType::Error) { - spdlog::error("Subscriber: error {}", event->errMsg); + CoreLogger::error("Subscriber: error " + event->errMsg); } else if (event->type == ix::CobraEventType::Published) { - spdlog::error("Published message hacked: {}", event->msgId); + CoreLogger::error("Published message hacked: " + std::to_string(event->msgId)); } else if (event->type == ix::CobraEventType::Pong) { - spdlog::info("Received websocket pong: {}", event->errMsg); + CoreLogger::info("Received websocket pong: " + event->errMsg); } else if (event->type == ix::CobraEventType::HandshakeError) { - spdlog::error("Subscriber: Handshake error: {}", event->errMsg); + CoreLogger::error("Subscriber: Handshake error: " + event->errMsg); fatalCobraError = true; } else if (event->type == ix::CobraEventType::AuthenticationError) { - spdlog::error("Subscriber: Authentication error: {}", event->errMsg); + CoreLogger::error("Subscriber: Authentication error: " + event->errMsg); fatalCobraError = true; } else if (event->type == ix::CobraEventType::SubscriptionError) { - spdlog::error("Subscriber: Subscription error: {}", event->errMsg); + CoreLogger::error("Subscriber: Subscription error: " + event->errMsg); fatalCobraError = true; } }); diff --git a/ixbots/ixbots/IXCobraToSentryBot.cpp b/ixbots/ixbots/IXCobraToSentryBot.cpp index 9247a63d..d8a4ca71 100644 --- a/ixbots/ixbots/IXCobraToSentryBot.cpp +++ b/ixbots/ixbots/IXCobraToSentryBot.cpp @@ -8,9 +8,10 @@ #include "IXCobraBot.h" #include "IXQueueManager.h" -#include #include -#include +#include + +#include #include #include @@ -38,7 +39,7 @@ namespace ix if (!response) { - spdlog::warn("Null HTTP Response"); + CoreLogger::warn("Null HTTP Response"); return false; } @@ -46,21 +47,21 @@ namespace ix { for (auto it : response->headers) { - spdlog::info("{}: {}", it.first, it.second); + CoreLogger::info(it.first + ": " + it.second); } - spdlog::info("Upload size: {}", response->uploadSize); - spdlog::info("Download size: {}", response->downloadSize); + CoreLogger::info("Upload size: " + std::to_string(response->uploadSize)); + CoreLogger::info("Download size: " + std::to_string(response->downloadSize)); - spdlog::info("Status: {}", response->statusCode); + CoreLogger::info("Status: " + std::to_string(response->statusCode)); if (response->errorCode != HttpErrorCode::Ok) { - spdlog::info("error message: {}", response->errorMsg); + CoreLogger::info("error message: " + response->errorMsg); } if (response->headers["Content-Type"] != "application/octet-stream") { - spdlog::info("payload: {}", response->payload); + CoreLogger::info("payload: " + response->payload); } } @@ -68,9 +69,9 @@ namespace ix if (!success) { - spdlog::error("Error sending data to sentry: {}", response->statusCode); - spdlog::error("Body: {}", ret.second); - spdlog::error("Response: {}", response->payload); + CoreLogger::error("Error sending data to sentry: " + std::to_string(response->statusCode)); + CoreLogger::error("Body: " + ret.second); + CoreLogger::error("Response: " + response->payload); // Error 429 Too Many Requests if (response->statusCode == 429) @@ -84,14 +85,12 @@ namespace ix if (!ss.eof() || ss.fail()) { seconds = 30; - spdlog::warn("Error parsing Retry-After header. " - "Using {} for the sleep duration", - seconds); + CoreLogger::warn("Error parsing Retry-After header. " + "Using " + retryAfter + " for the sleep duration"); } - spdlog::warn("Error 429 - Too Many Requests. ws will sleep " - "and retry after {} seconds", - retryAfter); + CoreLogger::warn("Error 429 - Too Many Requests. ws will sleep " + "and retry after " + retryAfter + " seconds"); throttled = true; auto duration = std::chrono::seconds(seconds); diff --git a/ixbots/ixbots/IXCobraToStatsdBot.cpp b/ixbots/ixbots/IXCobraToStatsdBot.cpp index d6c0a5dc..3a1bc88c 100644 --- a/ixbots/ixbots/IXCobraToStatsdBot.cpp +++ b/ixbots/ixbots/IXCobraToStatsdBot.cpp @@ -11,7 +11,7 @@ #include "IXStatsdClient.h" #include #include -#include +#include #include #include @@ -120,14 +120,14 @@ namespace ix } else { - spdlog::error("Gauge {} is not a numeric type", gauge); + CoreLogger::error("Gauge " + gauge + " is not a numeric type"); fatalCobraError = true; return false; } if (verbose) { - spdlog::info("{} - {} -> {}", id, attrName, x); + CoreLogger::info(id + " - " + attrName + " -> " + std::to_string(x)); } if (!gauge.empty()) diff --git a/ixbots/ixbots/IXCobraToStdoutBot.cpp b/ixbots/ixbots/IXCobraToStdoutBot.cpp index 0c0635a3..c0442dba 100644 --- a/ixbots/ixbots/IXCobraToStdoutBot.cpp +++ b/ixbots/ixbots/IXCobraToStdoutBot.cpp @@ -10,7 +10,6 @@ #include "IXQueueManager.h" #include #include -#include #include namespace ix diff --git a/ixcobra/ixcobra/IXCobraMetricsThreadedPublisher.cpp b/ixcobra/ixcobra/IXCobraMetricsThreadedPublisher.cpp index 6b79a46f..86ddb220 100644 --- a/ixcobra/ixcobra/IXCobraMetricsThreadedPublisher.cpp +++ b/ixcobra/ixcobra/IXCobraMetricsThreadedPublisher.cpp @@ -75,7 +75,7 @@ namespace ix ss << "Subscription error: " << event->errMsg; } - ix::IXCoreLogger::Log(ss.str().c_str()); + CoreLogger::log(ss.str().c_str()); }); } @@ -100,7 +100,7 @@ namespace ix void CobraMetricsThreadedPublisher::configure(const CobraConfig& config, const std::string& channel) { - ix::IXCoreLogger::Log(config.socketTLSOptions.getDescription().c_str()); + CoreLogger::log(config.socketTLSOptions.getDescription().c_str()); _channel = channel; _cobra_connection.configure(config); diff --git a/ixcore/ixcore/utils/IXCoreLogger.cpp b/ixcore/ixcore/utils/IXCoreLogger.cpp index 2463dbde..89159d54 100644 --- a/ixcore/ixcore/utils/IXCoreLogger.cpp +++ b/ixcore/ixcore/utils/IXCoreLogger.cpp @@ -1,14 +1,44 @@ -#include "ixcore/utils/IXCoreLogger.h" +/* + * IXCoreLogger.cpp + * Author: Thomas Wells, Benjamin Sergeant + * Copyright (c) 2019-2020 Machine Zone, Inc. All rights reserved. + */ +#include "ixcore/utils/IXCoreLogger.h" namespace ix { - // Default do nothing logger - IXCoreLogger::LogFunc IXCoreLogger::_currentLogger = [](const char* /*msg*/) {}; + // Default do a no-op logger + CoreLogger::LogFunc CoreLogger::_currentLogger = [](const char*, LogLevel) {}; - void IXCoreLogger::Log(const char* msg) + void CoreLogger::log(const char* msg, LogLevel level) { - _currentLogger(msg); + _currentLogger(msg, level); + } + + void CoreLogger::debug(const std::string& msg) + { + _currentLogger(msg.c_str(), LogLevel::Debug); + } + + void CoreLogger::info(const std::string& msg) + { + _currentLogger(msg.c_str(), LogLevel::Info); + } + + void CoreLogger::warn(const std::string& msg) + { + _currentLogger(msg.c_str(), LogLevel::Warning); + } + + void CoreLogger::error(const std::string& msg) + { + _currentLogger(msg.c_str(), LogLevel::Error); + } + + void CoreLogger::critical(const std::string& msg) + { + _currentLogger(msg.c_str(), LogLevel::Critical); } } // namespace ix diff --git a/ixcore/ixcore/utils/IXCoreLogger.h b/ixcore/ixcore/utils/IXCoreLogger.h index e140dfc3..18a23883 100644 --- a/ixcore/ixcore/utils/IXCoreLogger.h +++ b/ixcore/ixcore/utils/IXCoreLogger.h @@ -1,13 +1,36 @@ +/* + * IXCoreLogger.h + * Author: Thomas Wells, Benjamin Sergeant + * Copyright (c) 2019-2020 Machine Zone, Inc. All rights reserved. + */ + #pragma once #include +#include namespace ix { - class IXCoreLogger + enum class LogLevel + { + Debug = 0, + Info = 1, + Warning = 2, + Error = 3, + Critical = 4 + }; + + class CoreLogger { public: - using LogFunc = std::function; - static void Log(const char* msg); + using LogFunc = std::function; + + static void log(const char* msg, LogLevel level = LogLevel::Debug); + + static void debug(const std::string& msg); + static void info(const std::string& msg); + static void warn(const std::string& msg); + static void error(const std::string& msg); + static void critical(const std::string& msg); static void setLogFunction(LogFunc& func) { diff --git a/ixsentry/ixsentry/IXSentryClient.cpp b/ixsentry/ixsentry/IXSentryClient.cpp index d0a2d99a..944dce08 100644 --- a/ixsentry/ixsentry/IXSentryClient.cpp +++ b/ixsentry/ixsentry/IXSentryClient.cpp @@ -234,7 +234,7 @@ namespace ix args->transferTimeout = 5 * 60; args->followRedirects = true; args->verbose = verbose; - args->logger = [](const std::string& msg) { ix::IXCoreLogger::Log(msg.c_str()); }; + args->logger = [](const std::string& msg) { CoreLogger::log(msg.c_str()); }; std::string body = computePayload(msg); HttpResponsePtr response = _httpClient->post(_url, body, args); @@ -271,7 +271,7 @@ namespace ix args->followRedirects = true; args->verbose = verbose; args->multipartBoundary = multipartBoundary; - args->logger = [](const std::string& msg) { ix::IXCoreLogger::Log(msg.c_str()); }; + args->logger = [](const std::string& msg) { CoreLogger::log(msg.c_str()); }; HttpFormDataParameters httpFormDataParameters; httpFormDataParameters["upload_file_minidump"] = minidumpBytes; @@ -297,7 +297,7 @@ namespace ix args->transferTimeout = 5 * 60; args->followRedirects = true; args->verbose = verbose; - args->logger = [](const std::string& msg) { ix::IXCoreLogger::Log(msg.c_str()); }; + args->logger = [](const std::string& msg) { CoreLogger::log(msg.c_str()); }; args->url = _url; args->body = _jsonWriter.write(payload); diff --git a/ixsnake/ixsnake/IXSnakeProtocol.cpp b/ixsnake/ixsnake/IXSnakeProtocol.cpp index 1642519f..d1941261 100644 --- a/ixsnake/ixsnake/IXSnakeProtocol.cpp +++ b/ixsnake/ixsnake/IXSnakeProtocol.cpp @@ -198,7 +198,7 @@ namespace snake auto responseCallback = [ws, pdu, &subscriptionId](const std::string& redisResponse) { std::stringstream ss; ss << "Redis Response: " << redisResponse << "..."; - ix::IXCoreLogger::Log(ss.str().c_str()); + ix::CoreLogger::log(ss.str().c_str()); // Success nlohmann::json response = {{"action", "rtm/subscribe/ok"}, @@ -210,7 +210,7 @@ namespace snake { std::stringstream ss; ss << "Subscribing to " << appChannel << "..."; - ix::IXCoreLogger::Log(ss.str().c_str()); + ix::CoreLogger::log(ss.str().c_str()); } if (!redisClient.subscribe(appChannel, responseCallback, callback)) diff --git a/ixsnake/ixsnake/IXSnakeServer.cpp b/ixsnake/ixsnake/IXSnakeServer.cpp index 0875d0c3..49b2625c 100644 --- a/ixsnake/ixsnake/IXSnakeServer.cpp +++ b/ixsnake/ixsnake/IXSnakeServer.cpp @@ -29,7 +29,7 @@ namespace snake std::stringstream ss; ss << "Listening on " << appConfig.hostname << ":" << appConfig.port; - ix::IXCoreLogger::Log(ss.str().c_str()); + ix::CoreLogger::log(ss.str().c_str()); } // @@ -67,6 +67,7 @@ namespace snake webSocket->setOnMessageCallback( [this, webSocket, state](const ix::WebSocketMessagePtr& msg) { std::stringstream ss; + ix::LogLevel logLevel = ix::LogLevel::Debug; if (msg->type == ix::WebSocketMessageType::Open) { ss << "New connection" << std::endl; @@ -86,6 +87,7 @@ namespace snake _appConfig.redisPort)) { ss << "Cannot connect to redis host" << std::endl; + logLevel = ix::LogLevel::Error; } } else if (msg->type == ix::WebSocketMessageType::Close) @@ -101,6 +103,7 @@ namespace snake ss << "#retries: " << msg->errorInfo.retries << std::endl; ss << "Wait time(ms): " << msg->errorInfo.wait_time << std::endl; ss << "HTTP Status: " << msg->errorInfo.http_status << std::endl; + logLevel = ix::LogLevel::Error; } else if (msg->type == ix::WebSocketMessageType::Fragment) { @@ -112,7 +115,7 @@ namespace snake processCobraMessage(state, webSocket, _appConfig, msg->str); } - ix::IXCoreLogger::Log(ss.str().c_str()); + ix::CoreLogger::log(ss.str().c_str(), logLevel); }); }); diff --git a/test/test_runner.cpp b/test/test_runner.cpp index 350c2733..351708a7 100644 --- a/test/test_runner.cpp +++ b/test/test_runner.cpp @@ -14,8 +14,41 @@ int main(int argc, char* argv[]) { ix::initNetSystem(); - ix::IXCoreLogger::LogFunc logFunc = [](const char* msg) { spdlog::info(msg); }; - ix::IXCoreLogger::setLogFunction(logFunc); + ix::CoreLogger::LogFunc logFunc = [](const char* msg, ix::LogLevel level) { + switch (level) + { + case ix::LogLevel::Debug: + { + spdlog::debug(msg); + } + break; + + case ix::LogLevel::Info: + { + spdlog::info(msg); + } + break; + + case ix::LogLevel::Warning: + { + spdlog::warn(msg); + } + break; + + case ix::LogLevel::Error: + { + spdlog::error(msg); + } + break; + + case ix::LogLevel::Critical: + { + spdlog::critical(msg); + } + break; + } + }; + ix::CoreLogger::setLogFunction(logFunc); int result = Catch::Session().run(argc, argv); diff --git a/ws/ws.cpp b/ws/ws.cpp index e3d714e2..1c4b6536 100644 --- a/ws/ws.cpp +++ b/ws/ws.cpp @@ -36,8 +36,41 @@ int main(int argc, char** argv) { ix::initNetSystem(); - ix::IXCoreLogger::LogFunc logFunc = [](const char* msg) { spdlog::info(msg); }; - ix::IXCoreLogger::setLogFunction(logFunc); + ix::CoreLogger::LogFunc logFunc = [](const char* msg, ix::LogLevel level) { + switch (level) + { + case ix::LogLevel::Debug: + { + spdlog::debug(msg); + } + break; + + case ix::LogLevel::Info: + { + spdlog::info(msg); + } + break; + + case ix::LogLevel::Warning: + { + spdlog::warn(msg); + } + break; + + case ix::LogLevel::Error: + { + spdlog::error(msg); + } + break; + + case ix::LogLevel::Critical: + { + spdlog::critical(msg); + } + break; + } + }; + ix::CoreLogger::setLogFunction(logFunc); #ifndef _WIN32 signal(SIGPIPE, SIG_IGN);