core logger support multiple level + switch ixbots to user corelogger instead of spdlog

This commit is contained in:
Benjamin Sergeant 2020-04-24 15:17:50 -07:00
parent 0670954faf
commit 646b18bf28
13 changed files with 206 additions and 84 deletions

View File

@ -31,11 +31,6 @@ if (NOT JSONCPP_FOUND)
set(JSONCPP_INCLUDE_DIRS ../third_party/jsoncpp) set(JSONCPP_INCLUDE_DIRS ../third_party/jsoncpp)
endif() endif()
find_package(SpdLog)
if (NOT SPDLOG_FOUND)
set(SPDLOG_INCLUDE_DIRS ../third_party/spdlog/include)
endif()
set(IXBOTS_INCLUDE_DIRS set(IXBOTS_INCLUDE_DIRS
. .
.. ..

View File

@ -7,10 +7,11 @@
#include "IXCobraBot.h" #include "IXCobraBot.h"
#include "IXQueueManager.h" #include "IXQueueManager.h"
#include <ixcobra/IXCobraConnection.h>
#include <ixcore/utils/IXCoreLogger.h>
#include <algorithm> #include <algorithm>
#include <chrono> #include <chrono>
#include <ixcobra/IXCobraConnection.h>
#include <spdlog/spdlog.h>
#include <sstream> #include <sstream>
#include <thread> #include <thread>
#include <vector> #include <vector>
@ -34,10 +35,10 @@ namespace ix
Json::FastWriter jsonWriter; Json::FastWriter jsonWriter;
std::atomic<uint64_t> sentCount(0); std::atomic<uint64_t> sentCount(0);
std::atomic<uint64_t> receivedCount(0); std::atomic<uint64_t> receivedCount(0);
std::atomic<uint64_t> sentCountTotal(0); uint64_t sentCountTotal(0);
std::atomic<uint64_t> receivedCountTotal(0); uint64_t receivedCountTotal(0);
std::atomic<uint64_t> sentCountPerSecs(0); uint64_t sentCountPerSecs(0);
std::atomic<uint64_t> receivedCountPerSecs(0); uint64_t receivedCountPerSecs(0);
std::atomic<bool> stop(false); std::atomic<bool> stop(false);
std::atomic<bool> throttled(false); std::atomic<bool> throttled(false);
std::atomic<bool> fatalCobraError(false); std::atomic<bool> fatalCobraError(false);
@ -58,11 +59,17 @@ namespace ix
// as those are used externally, so we need to introduce // as those are used externally, so we need to introduce
// our own counters // our own counters
// //
spdlog::info("messages received {} {} sent {} {}", std::stringstream ss;
receivedCountPerSecs, ss << "messages received "
receivedCountTotal, << receivedCountPerSecs
sentCountPerSecs, << " "
sentCountTotal); << receivedCountTotal
<< " sent "
<< sentCountPerSecs
<< " "
<< sentCountTotal;
CoreLogger::info(ss.str());
receivedCountPerSecs = receivedCount - receivedCountTotal; receivedCountPerSecs = receivedCount - receivedCountTotal;
sentCountPerSecs = sentCount - receivedCountTotal; sentCountPerSecs = sentCount - receivedCountTotal;
@ -73,7 +80,7 @@ namespace ix
std::this_thread::sleep_for(duration); std::this_thread::sleep_for(duration);
} }
spdlog::info("timer thread done"); CoreLogger::info("timer thread done");
}; };
std::thread t1(timer); std::thread t1(timer);
@ -93,7 +100,7 @@ namespace ix
if (currentState == state) 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); exit(1);
} }
state = currentState; state = currentState;
@ -102,7 +109,7 @@ namespace ix
std::this_thread::sleep_for(duration); std::this_thread::sleep_for(duration);
} }
spdlog::info("heartbeat thread done"); CoreLogger::info("heartbeat thread done");
}; };
std::thread t2(heartbeat); std::thread t2(heartbeat);
@ -124,19 +131,19 @@ namespace ix
// That might be too noisy // That might be too noisy
if (verbose) if (verbose)
{ {
spdlog::info("cobra bot: sending succesfull"); CoreLogger::info("cobra bot: sending succesfull");
} }
++sentCount; ++sentCount;
} }
else else
{ {
spdlog::error("cobra bot: error sending"); CoreLogger::error("cobra bot: error sending");
} }
if (stop) break; if (stop) break;
} }
spdlog::info("sender thread done"); CoreLogger::info("sender thread done");
}; };
std::thread t3(sender); std::thread t3(sender);
@ -158,22 +165,23 @@ namespace ix
&sentCount](const CobraEventPtr& event) { &sentCount](const CobraEventPtr& event) {
if (event->type == ix::CobraEventType::Open) if (event->type == ix::CobraEventType::Open)
{ {
spdlog::info("Subscriber connected"); CoreLogger::info("Subscriber connected");
for (auto&& it : event->headers) for (auto&& it : event->headers)
{ {
spdlog::info("{}: {}", it.first, it.second); CoreLogger::info(it.first + "::" + it.second);
} }
} }
else if (event->type == ix::CobraEventType::Closed) 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) else if (event->type == ix::CobraEventType::Authenticated)
{ {
spdlog::info("Subscriber authenticated"); CoreLogger::info("Subscriber authenticated");
spdlog::info("Subscribing to {} at position {}", channel, subscriptionPosition); CoreLogger::info("Subscribing to " + channel);
spdlog::info("Using filter: {}", filter); CoreLogger::info("Subscribing at position " + subscriptionPosition);
CoreLogger::info("Subscribing with filter " + filter);
conn.subscribe(channel, conn.subscribe(channel,
filter, filter,
subscriptionPosition, subscriptionPosition,
@ -189,9 +197,8 @@ namespace ix
&sentCount](const Json::Value& msg, const std::string& position) { &sentCount](const Json::Value& msg, const std::string& position) {
if (verbose) if (verbose)
{ {
spdlog::info("Subscriber received message {} -> {}", CoreLogger::info("Subscriber received message "
position, + position + " -> " + jsonWriter.write(msg));
jsonWriter.write(msg));
} }
subscriptionPosition = position; subscriptionPosition = position;
@ -217,50 +224,50 @@ namespace ix
// That might be too noisy // That might be too noisy
if (verbose) if (verbose)
{ {
spdlog::info("cobra bot: sending succesfull"); CoreLogger::info("cobra bot: sending succesfull");
} }
++sentCount; ++sentCount;
} }
else else
{ {
spdlog::error("cobra bot: error sending"); CoreLogger::error("cobra bot: error sending");
} }
} }
}); });
} }
else if (event->type == ix::CobraEventType::Subscribed) 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) 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) 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) 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) 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) else if (event->type == ix::CobraEventType::HandshakeError)
{ {
spdlog::error("Subscriber: Handshake error: {}", event->errMsg); CoreLogger::error("Subscriber: Handshake error: " + event->errMsg);
fatalCobraError = true; fatalCobraError = true;
} }
else if (event->type == ix::CobraEventType::AuthenticationError) else if (event->type == ix::CobraEventType::AuthenticationError)
{ {
spdlog::error("Subscriber: Authentication error: {}", event->errMsg); CoreLogger::error("Subscriber: Authentication error: " + event->errMsg);
fatalCobraError = true; fatalCobraError = true;
} }
else if (event->type == ix::CobraEventType::SubscriptionError) else if (event->type == ix::CobraEventType::SubscriptionError)
{ {
spdlog::error("Subscriber: Subscription error: {}", event->errMsg); CoreLogger::error("Subscriber: Subscription error: " + event->errMsg);
fatalCobraError = true; fatalCobraError = true;
} }
}); });

View File

@ -8,9 +8,10 @@
#include "IXCobraBot.h" #include "IXCobraBot.h"
#include "IXQueueManager.h" #include "IXQueueManager.h"
#include <chrono>
#include <ixcobra/IXCobraConnection.h> #include <ixcobra/IXCobraConnection.h>
#include <spdlog/spdlog.h> #include <ixcore/utils/IXCoreLogger.h>
#include <chrono>
#include <sstream> #include <sstream>
#include <vector> #include <vector>
@ -38,7 +39,7 @@ namespace ix
if (!response) if (!response)
{ {
spdlog::warn("Null HTTP Response"); CoreLogger::warn("Null HTTP Response");
return false; return false;
} }
@ -46,21 +47,21 @@ namespace ix
{ {
for (auto it : response->headers) for (auto it : response->headers)
{ {
spdlog::info("{}: {}", it.first, it.second); CoreLogger::info(it.first + ": " + it.second);
} }
spdlog::info("Upload size: {}", response->uploadSize); CoreLogger::info("Upload size: " + std::to_string(response->uploadSize));
spdlog::info("Download size: {}", response->downloadSize); 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) 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") 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) if (!success)
{ {
spdlog::error("Error sending data to sentry: {}", response->statusCode); CoreLogger::error("Error sending data to sentry: " + std::to_string(response->statusCode));
spdlog::error("Body: {}", ret.second); CoreLogger::error("Body: " + ret.second);
spdlog::error("Response: {}", response->payload); CoreLogger::error("Response: " + response->payload);
// Error 429 Too Many Requests // Error 429 Too Many Requests
if (response->statusCode == 429) if (response->statusCode == 429)
@ -84,14 +85,12 @@ namespace ix
if (!ss.eof() || ss.fail()) if (!ss.eof() || ss.fail())
{ {
seconds = 30; seconds = 30;
spdlog::warn("Error parsing Retry-After header. " CoreLogger::warn("Error parsing Retry-After header. "
"Using {} for the sleep duration", "Using " + retryAfter + " for the sleep duration");
seconds);
} }
spdlog::warn("Error 429 - Too Many Requests. ws will sleep " CoreLogger::warn("Error 429 - Too Many Requests. ws will sleep "
"and retry after {} seconds", "and retry after " + retryAfter + " seconds");
retryAfter);
throttled = true; throttled = true;
auto duration = std::chrono::seconds(seconds); auto duration = std::chrono::seconds(seconds);

View File

@ -11,7 +11,7 @@
#include "IXStatsdClient.h" #include "IXStatsdClient.h"
#include <chrono> #include <chrono>
#include <ixcobra/IXCobraConnection.h> #include <ixcobra/IXCobraConnection.h>
#include <spdlog/spdlog.h> #include <ixcore/utils/IXCoreLogger.h>
#include <sstream> #include <sstream>
#include <vector> #include <vector>
@ -120,14 +120,14 @@ namespace ix
} }
else else
{ {
spdlog::error("Gauge {} is not a numeric type", gauge); CoreLogger::error("Gauge " + gauge + " is not a numeric type");
fatalCobraError = true; fatalCobraError = true;
return false; return false;
} }
if (verbose) if (verbose)
{ {
spdlog::info("{} - {} -> {}", id, attrName, x); CoreLogger::info(id + " - " + attrName + " -> " + std::to_string(x));
} }
if (!gauge.empty()) if (!gauge.empty())

View File

@ -10,7 +10,6 @@
#include "IXQueueManager.h" #include "IXQueueManager.h"
#include <chrono> #include <chrono>
#include <iostream> #include <iostream>
#include <spdlog/spdlog.h>
#include <sstream> #include <sstream>
namespace ix namespace ix

View File

@ -75,7 +75,7 @@ namespace ix
ss << "Subscription error: " << event->errMsg; 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, void CobraMetricsThreadedPublisher::configure(const CobraConfig& config,
const std::string& channel) const std::string& channel)
{ {
ix::IXCoreLogger::Log(config.socketTLSOptions.getDescription().c_str()); CoreLogger::log(config.socketTLSOptions.getDescription().c_str());
_channel = channel; _channel = channel;
_cobra_connection.configure(config); _cobra_connection.configure(config);

View File

@ -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 namespace ix
{ {
// Default do nothing logger // Default do a no-op logger
IXCoreLogger::LogFunc IXCoreLogger::_currentLogger = [](const char* /*msg*/) {}; 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 } // namespace ix

View File

@ -1,13 +1,36 @@
/*
* IXCoreLogger.h
* Author: Thomas Wells, Benjamin Sergeant
* Copyright (c) 2019-2020 Machine Zone, Inc. All rights reserved.
*/
#pragma once #pragma once
#include <functional> #include <functional>
#include <string>
namespace ix namespace ix
{ {
class IXCoreLogger enum class LogLevel
{
Debug = 0,
Info = 1,
Warning = 2,
Error = 3,
Critical = 4
};
class CoreLogger
{ {
public: public:
using LogFunc = std::function<void(const char*)>; using LogFunc = std::function<void(const char*, LogLevel level)>;
static void Log(const char* msg);
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) static void setLogFunction(LogFunc& func)
{ {

View File

@ -234,7 +234,7 @@ namespace ix
args->transferTimeout = 5 * 60; args->transferTimeout = 5 * 60;
args->followRedirects = true; args->followRedirects = true;
args->verbose = verbose; 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); std::string body = computePayload(msg);
HttpResponsePtr response = _httpClient->post(_url, body, args); HttpResponsePtr response = _httpClient->post(_url, body, args);
@ -271,7 +271,7 @@ namespace ix
args->followRedirects = true; args->followRedirects = true;
args->verbose = verbose; args->verbose = verbose;
args->multipartBoundary = multipartBoundary; 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 httpFormDataParameters;
httpFormDataParameters["upload_file_minidump"] = minidumpBytes; httpFormDataParameters["upload_file_minidump"] = minidumpBytes;
@ -297,7 +297,7 @@ namespace ix
args->transferTimeout = 5 * 60; args->transferTimeout = 5 * 60;
args->followRedirects = true; args->followRedirects = true;
args->verbose = verbose; 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->url = _url;
args->body = _jsonWriter.write(payload); args->body = _jsonWriter.write(payload);

View File

@ -198,7 +198,7 @@ namespace snake
auto responseCallback = [ws, pdu, &subscriptionId](const std::string& redisResponse) { auto responseCallback = [ws, pdu, &subscriptionId](const std::string& redisResponse) {
std::stringstream ss; std::stringstream ss;
ss << "Redis Response: " << redisResponse << "..."; ss << "Redis Response: " << redisResponse << "...";
ix::IXCoreLogger::Log(ss.str().c_str()); ix::CoreLogger::log(ss.str().c_str());
// Success // Success
nlohmann::json response = {{"action", "rtm/subscribe/ok"}, nlohmann::json response = {{"action", "rtm/subscribe/ok"},
@ -210,7 +210,7 @@ namespace snake
{ {
std::stringstream ss; std::stringstream ss;
ss << "Subscribing to " << appChannel << "..."; ss << "Subscribing to " << appChannel << "...";
ix::IXCoreLogger::Log(ss.str().c_str()); ix::CoreLogger::log(ss.str().c_str());
} }
if (!redisClient.subscribe(appChannel, responseCallback, callback)) if (!redisClient.subscribe(appChannel, responseCallback, callback))

View File

@ -29,7 +29,7 @@ namespace snake
std::stringstream ss; std::stringstream ss;
ss << "Listening on " << appConfig.hostname << ":" << appConfig.port; 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( webSocket->setOnMessageCallback(
[this, webSocket, state](const ix::WebSocketMessagePtr& msg) { [this, webSocket, state](const ix::WebSocketMessagePtr& msg) {
std::stringstream ss; std::stringstream ss;
ix::LogLevel logLevel = ix::LogLevel::Debug;
if (msg->type == ix::WebSocketMessageType::Open) if (msg->type == ix::WebSocketMessageType::Open)
{ {
ss << "New connection" << std::endl; ss << "New connection" << std::endl;
@ -86,6 +87,7 @@ namespace snake
_appConfig.redisPort)) _appConfig.redisPort))
{ {
ss << "Cannot connect to redis host" << std::endl; ss << "Cannot connect to redis host" << std::endl;
logLevel = ix::LogLevel::Error;
} }
} }
else if (msg->type == ix::WebSocketMessageType::Close) else if (msg->type == ix::WebSocketMessageType::Close)
@ -101,6 +103,7 @@ namespace snake
ss << "#retries: " << msg->errorInfo.retries << std::endl; ss << "#retries: " << msg->errorInfo.retries << std::endl;
ss << "Wait time(ms): " << msg->errorInfo.wait_time << std::endl; ss << "Wait time(ms): " << msg->errorInfo.wait_time << std::endl;
ss << "HTTP Status: " << msg->errorInfo.http_status << std::endl; ss << "HTTP Status: " << msg->errorInfo.http_status << std::endl;
logLevel = ix::LogLevel::Error;
} }
else if (msg->type == ix::WebSocketMessageType::Fragment) else if (msg->type == ix::WebSocketMessageType::Fragment)
{ {
@ -112,7 +115,7 @@ namespace snake
processCobraMessage(state, webSocket, _appConfig, msg->str); processCobraMessage(state, webSocket, _appConfig, msg->str);
} }
ix::IXCoreLogger::Log(ss.str().c_str()); ix::CoreLogger::log(ss.str().c_str(), logLevel);
}); });
}); });

View File

@ -14,8 +14,41 @@ int main(int argc, char* argv[])
{ {
ix::initNetSystem(); ix::initNetSystem();
ix::IXCoreLogger::LogFunc logFunc = [](const char* msg) { spdlog::info(msg); }; ix::CoreLogger::LogFunc logFunc = [](const char* msg, ix::LogLevel level) {
ix::IXCoreLogger::setLogFunction(logFunc); 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); int result = Catch::Session().run(argc, argv);

View File

@ -36,8 +36,41 @@ int main(int argc, char** argv)
{ {
ix::initNetSystem(); ix::initNetSystem();
ix::IXCoreLogger::LogFunc logFunc = [](const char* msg) { spdlog::info(msg); }; ix::CoreLogger::LogFunc logFunc = [](const char* msg, ix::LogLevel level) {
ix::IXCoreLogger::setLogFunction(logFunc); 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 #ifndef _WIN32
signal(SIGPIPE, SIG_IGN); signal(SIGPIPE, SIG_IGN);