Refactor logging :)

This commit is contained in:
Joshua Ashton 2020-08-07 06:23:12 +01:00
parent 68a8c22c03
commit 79c277a440
13 changed files with 198 additions and 174 deletions

3
.gitmodules vendored
View File

@ -11,3 +11,6 @@
[submodule "subprojects/zlib"] [submodule "subprojects/zlib"]
path = subprojects/zlib path = subprojects/zlib
url = https://github.com/madler/zlib url = https://github.com/madler/zlib
[submodule "subprojects/fmt"]
path = subprojects/fmt
url = https://github.com/fmtlib/fmt

View File

@ -71,7 +71,7 @@ namespace Feather
void DedicatedServer::OnClientConnect(Network::TCPClientHandle&& client) void DedicatedServer::OnClientConnect(Network::TCPClientHandle&& client)
{ {
const auto& address = client->GetAddress(); const auto& address = client->GetAddress();
Log_Info("New connection from %s:%hu", address.ip, address.port); Log::Info("New connection from {}:{}", address.ip, address.port);
auto [clients, lock] = m_clients.borrow(); auto [clients, lock] = m_clients.borrow();
clients.emplace_back(std::move(client)); clients.emplace_back(std::move(client));
@ -80,7 +80,7 @@ namespace Feather
void DedicatedServer::OnClientDisconnect(const Network::TCPClient* client) void DedicatedServer::OnClientDisconnect(const Network::TCPClient* client)
{ {
const auto& address = client->GetAddress(); const auto& address = client->GetAddress();
Log_Info("Disconnected from %s:%hu", address.ip, address.port); Log::Info("Disconnected from {}:{}", address.ip, address.port);
auto [clients, lock] = m_clients.borrow(); auto [clients, lock] = m_clients.borrow();
clients.remove_if([&](MinecraftClient& other) { return other.GetTCPClient().get() == client; }); clients.remove_if([&](MinecraftClient& other) { return other.GetTCPClient().get() == client; });
@ -90,12 +90,12 @@ namespace Feather
void DedicatedServer::HandleUnknownPacket(MinecraftClient &client, int32_t id, const PacketReader &packet) void DedicatedServer::HandleUnknownPacket(MinecraftClient &client, int32_t id, const PacketReader &packet)
{ {
Log_Trace("Got unknown packet with ID %d from client.", id); Log::Trace("Got unknown packet with ID {} from client.", id);
} }
void DedicatedServer::HandleLegacyPing(MinecraftClient& client) void DedicatedServer::HandleLegacyPing(MinecraftClient& client)
{ {
Log_Info("Got legacy server list ping."); Log::Info("Got legacy server list ping.");
} }
#pragma region Handshake & Status #pragma region Handshake & Status
@ -103,7 +103,7 @@ namespace Feather
template <> template <>
void DedicatedServer::HandlePacket(MinecraftClient& client, const Handholding::ServerboundHandshake& handshake) void DedicatedServer::HandlePacket(MinecraftClient& client, const Handholding::ServerboundHandshake& handshake)
{ {
Log_Info("Client Intention Packet: version=%d, serverIp=%s, port=%u, intention=%d\n", Log::Info("Client Intention Packet: version={}, serverIp={}, port={}, intention={}\n",
handshake.protocolVersion, handshake.protocolVersion,
handshake.serverIP.c_str(), handshake.serverIP.c_str(),
handshake.port, handshake.port,
@ -116,7 +116,7 @@ namespace Feather
template <> template <>
void DedicatedServer::HandlePacket(MinecraftClient& client, const Status::ServerboundRequest& request) void DedicatedServer::HandlePacket(MinecraftClient& client, const Status::ServerboundRequest& request)
{ {
Log_Info("Client sent STATUS_PING_REQUEST"); Log::Info("Client sent STATUS_PING_REQUEST");
Status::ClientboundResponse message = Status::ClientboundResponse message =
{ {
@ -129,7 +129,7 @@ namespace Feather
template <> template <>
void DedicatedServer::HandlePacket(MinecraftClient& client, const Status::ServerboundPing& ping) void DedicatedServer::HandlePacket(MinecraftClient& client, const Status::ServerboundPing& ping)
{ {
Log_Info("Client sent STATUS_PING: %llu", ping.timestamp); Log::Info("Client sent STATUS_PING: {}", ping.timestamp);
Status::ClientboundPong message = Status::ClientboundPong message =
{ {

View File

@ -10,7 +10,7 @@ int main()
{ {
ServerProperties properties("server.properties"); ServerProperties properties("server.properties");
properties.Save(); properties.Save();
Log_Info("Starting server on port %d", properties.serverPort.GetValue()); Log::Info("Starting server on port {}", properties.serverPort.GetValue());
auto server = DedicatedServer(&properties); auto server = DedicatedServer(&properties);
return 1; return 1;

View File

@ -17,7 +17,7 @@ namespace Feather
std::ifstream file; std::ifstream file;
file.open(path); file.open(path);
Log_Info("Reading %s...", path); Log::Info("Reading {}...", path);
if (file.is_open()) if (file.is_open())
{ {
string line; string line;
@ -50,7 +50,7 @@ namespace Feather
} }
else else
{ {
Log_Warn("Could not find %s", path); Log::Warn("Could not find {}", path);
} }
} }

View File

@ -3,99 +3,6 @@
#include <cstdio> #include <cstdio>
#include <cstdarg> #include <cstdarg>
// Platform-dependent console initialization
static void InitPlatformConsole();
namespace Feather::Logging
{
Logger GlobalLogger;
ChannelID LOG_GENERAL = REGISTER_LOGGING_CHANNEL("General");
ChannelID LOG_LOGGING = REGISTER_LOGGING_CHANNEL("Logging");
// Since min and max are inclusive we have to add 1 here
// This assumes max > min (they better be)
static constexpr int NUM_LEVELS = ((int)Level::MaxLevel - (int)Level::MinLevel) + 1;
// Temporary solution while we don't have named enums
static const char *s_levelNames[NUM_LEVELS] = {"ERROR", "WARNING", "INFO", "DEBUG", "TRACE"};
// Shifts an enum value to be a positive index in s_levelNames
static constexpr int LEVEL_NAME_OFFSET = 0 - (int)Level::MinLevel;
Logger::Logger()
{
InitPlatformConsole();
}
void Logger::LogDirect(ChannelID channel, Level level, const char *message, ...)
{
char buffer[MAX_LOG_MESSAGE_LENGTH];
int offset = 0;
// All color escape sequences follow the following ANSI format:
// ESC (\x1B) CSI ([) <COLOR CODES> SGR (m)
switch (level)
{
case Level::Warning:
// 1 BRIGHT, 33 YELLOW
offset += snprintf(buffer + offset, MAX_LOG_MESSAGE_LENGTH - offset, "\x1B[1;33m");
break;
case Level::Error:
// 1 BRIGHT, 31 RED
offset += snprintf(buffer + offset, MAX_LOG_MESSAGE_LENGTH - offset, "\x1B[1;31m");
break;
default:
case Level::Info:
break;
}
const char* levelName = s_levelNames[(int)level + LEVEL_NAME_OFFSET];
if (channel == LOG_GENERAL) {
// Print only severity level
offset += snprintf(buffer + offset, MAX_LOG_MESSAGE_LENGTH - offset, "[%s] ", levelName);
} else {
// Print channel name and severity level
const char *channelName = m_channels[channel]->GetName();
offset += snprintf(buffer + offset, MAX_LOG_MESSAGE_LENGTH - offset, "[%s] [%s] ", channelName, levelName);
}
// Write our message
va_list args;
va_start(args, message);
offset += vsnprintf(buffer + offset, MAX_LOG_MESSAGE_LENGTH - offset, message, args);
va_end(args);
// Ignore any terminal newline
if (buffer[offset - 1] == '\n') offset--;
// Append ANSI style reset code 0 and newline
offset += snprintf(buffer + offset, MAX_LOG_MESSAGE_LENGTH - offset, "\x1b[0m\n");
if (level >= Level::Info) {
// Info and above go to stdout
printf(buffer);
} else {
// Error and warn go to stderr
fprintf(stderr, buffer);
}
}
ChannelID Logger::RegisterChannel(const char* name)
{
if (m_channelCount >= MAX_LOGGING_CHANNEL_COUNT) {
Log_Msg( LOG_LOGGING, Error, "Cannot register new logging channel '%s' because the maximum of %d channels has been exceeded.", name, MAX_LOGGING_CHANNEL_COUNT );
return LOG_GENERAL;
}
Channel *channel = new Channel(name);
m_channels[m_channelCount] = channel;
int id = m_channelCount++;
return id;
}
}
#ifdef _WIN32 #ifdef _WIN32
#ifndef WIN32_LEAN_AND_MEAN #ifndef WIN32_LEAN_AND_MEAN
@ -107,25 +14,52 @@ namespace Feather::Logging
#endif #endif
static void InitPlatformConsole() namespace Feather::Log
{ {
static bool s_initialized = false; namespace Channels
if (s_initialized)
return;
#ifdef _WIN32
HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);
if (handle != INVALID_HANDLE_VALUE)
{ {
DWORD mode = 0; ChannelID General = Logger::Instance().RegisterChannel("General");
if (GetConsoleMode(handle, &mode))
{
// To enable ANSI escape sequences on Windows 10 we need to set this flag
mode |= ENABLE_VIRTUAL_TERMINAL_PROCESSING;
SetConsoleMode(handle, mode);
}
} }
#endif
s_initialized = true; ChannelID Logger::RegisterChannel(const char* name)
} {
size_t id = m_channels.size();
m_channels.emplace_back(name);
return id;
}
Logger& Logger::Instance()
{
static std::unique_ptr<Logger> s_logger = nullptr;
if (s_logger == nullptr)
s_logger = std::make_unique<Logger>();
return *s_logger;
}
namespace
{
class LoggingManager
{
public:
LoggingManager()
{
#ifdef _WIN32
HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);
if (handle != INVALID_HANDLE_VALUE)
{
DWORD mode = 0;
if (GetConsoleMode(handle, &mode))
{
// To enable ANSI escape sequences on Windows 10 we need to set this flag
mode |= ENABLE_VIRTUAL_TERMINAL_PROCESSING;
SetConsoleMode(handle, mode);
}
}
#endif
}
};
static LoggingManager s_networkManager;
}
}

View File

@ -1,12 +1,18 @@
#pragma once #pragma once
namespace Feather::Logging #include <event2/event.h>
#define FMT_HEADER_ONLY
#include <fmt/core.h>
#include <fmt/color.h>
#include <ostream>
#include <vector>
#include <array>
//#define FEATHER_Log::COLUMNS
namespace Feather::Log
{ {
const int MAX_LOG_MESSAGE_LENGTH = 2048;
const int MAX_LOGGING_CHANNEL_COUNT = 256;
/*==== Severity Levels ==============================*/
enum class Level enum class Level
{ {
// Serious problems // Serious problems
@ -23,61 +29,134 @@ namespace Feather::Logging
// Fine grained spew // Fine grained spew
Trace = 2, Trace = 2,
// These are an inclusve interval
MinLevel = Error,
MaxLevel = Trace,
}; };
/*==== Channels ==============================*/ constexpr std::string_view GetLevelStringView(Level level)
{
switch (level)
{
case Level::Error: return "Error";
case Level::Warning: return "Warning";
case Level::Info: return "Info";
case Level::Debug: return "Debug";
case Level::Trace: return "Trace";
default: return "Unknown";
}
}
typedef int ChannelID; constexpr size_t MaxLevelLength = 7;
constexpr size_t MaxChannelLength = 15;
inline std::ostream& operator << (std::ostream& os, Level level)
{
os << GetLevelStringView(level);
return os;
}
constexpr fmt::text_style GetLevelTextStyle(Level level)
{
switch (level)
{
default:
case Level::Info: return fmt::fg(fmt::color::white);
case Level::Error: return fmt::fg(fmt::color::crimson);
case Level::Warning: return fmt::fg(fmt::color::yellow);
case Level::Debug: return fmt::fg(fmt::color::rebecca_purple);
case Level::Trace: return fmt::fg(fmt::color::aquamarine);
}
}
using ChannelID = size_t;
class Channel class Channel
{ {
const char* m_name;
public: public:
Channel(const char* name) : m_name(name) {} Channel(std::string_view name) : m_name(name) {}
inline const char* GetName() { return m_name; } inline std::string_view GetName() { return m_name; }
private:
std::string_view m_name;
}; };
extern ChannelID LOG_GENERAL; namespace Channels
{
/*==== Logger ==============================*/ extern ChannelID General;
}
class Logger class Logger
{ {
public: public:
Logger(); template <class S, typename... Args>
void LogDirect(ChannelID channel, Level level, const char* message, ...); void LogRaw(const fmt::text_style& style, const S& fmt, Args... args)
{
fmt::print(style, fmt, args...);
}
template <class S, typename... Args>
void LogRaw(const S& fmt, Args... args)
{
constexpr fmt::text_style white = fmt::fg(fmt::color::white);
LogRaw(white, fmt, args...);
}
template <class S, typename... Args>
void Log(ChannelID channel, Level level, const S& fmt, Args... args)
{
std::string_view levelString = GetLevelStringView(level);
std::string_view channelString = m_channels[channel].GetName();
#ifdef FEATHER_Log::COLUMNS
std::array<char, MaxLevelLength + 1> levelSpaces = {};
std::fill_n(levelSpaces.data(), MaxLevelLength - levelString.size(), ' ');
std::array<char, MaxChannelLength> channelSpaces = {};
std::fill_n(channelSpaces.data(), MaxChannelLength - channelString.size(), ' ');
LogRaw(GetLevelTextStyle(level), levelString);
LogRaw("{}|", levelSpaces.data());
LogRaw(channelString);
LogRaw("{}|", channelSpaces.data());
LogRaw(fmt, args...);
LogRaw("\n");
#else
if (channel != Channels::General)
LogRaw("[{}] ", channelString);
LogRaw("[");
LogRaw(GetLevelTextStyle(level), levelString);
LogRaw("] ");
LogRaw(fmt, args...);
LogRaw("\n");
#endif
}
ChannelID RegisterChannel(const char* name); ChannelID RegisterChannel(const char* name);
static Logger& Instance();
private: private:
Channel* m_channels[MAX_LOGGING_CHANNEL_COUNT]; std::vector<Channel> m_channels;
ChannelID m_channelCount = 0;
}; };
extern Logger GlobalLogger; template <class S, typename... Args>
} void Msg(ChannelID channel, Level level, const S& fmt, Args... args)
{
Logger::Instance().Log(channel, level, fmt, args...);
}
#define REGISTER_LOGGING_CHANNEL(Name) ::Feather::Logging::GlobalLogger.RegisterChannel(Name); template <class S, typename... Args>
void Info(const S& fmt, Args... args) { Msg(Channels::General, Level::Info, fmt, args...); }
// Logs a message, specifying a channel and log level template <class S, typename... Args>
#define Log_Msg(_Channel, _Level, _Message, ...) ::Feather::Logging::GlobalLogger.LogDirect(::Feather::Logging::_Channel, ::Feather::Logging::Level::_Level, _Message, ##__VA_ARGS__) void Warn(const S& fmt, Args... args) { Msg(Channels::General, Level::Warning, fmt, args...); }
// Logs a general message for end-users template <class S, typename... Args>
#define Log_Info(Message, ...) Log_Msg(LOG_GENERAL, Info, Message, ##__VA_ARGS__) void Error(const S& fmt, Args... args) { Msg(Channels::General, Level::Error, fmt, args...); }
// Logs a potential problem of note template <class S, typename... Args>
#define Log_Warn(Message, ...) Log_Msg(LOG_GENERAL, Warning, Message, ##__VA_ARGS__) void Debug(const S& fmt, Args... args) { Msg(Channels::General, Level::Debug, fmt, args...); }
// Logs a serious problem template <class S, typename... Args>
#define Log_Error(Message, ...) Log_Msg(LOG_GENERAL, Error, Message, ##__VA_ARGS__) void Trace(const S& fmt, Args... args) { Msg(Channels::General, Level::Trace, fmt, args...); }
}
// Logs debug information for developers
#define Log_Debug(Message, ...) Log_Msg(LOG_GENERAL, Debug, Message, ##__VA_ARGS__)
// Logs fine grained debug information
#define Log_Trace(Message, ...) Log_Msg(LOG_GENERAL, Trace, Message, ##__VA_ARGS__)

View File

@ -30,6 +30,7 @@ executable('FeatherMC', feather_src, protocol_headers,
include_directories : include_directories( include_directories : include_directories(
'.', '.',
'../subprojects/rapidjson/include', '../subprojects/rapidjson/include',
'../subprojects/fmt/include',
'../subprojects' # for zlib and cNBT, which have no include dir '../subprojects' # for zlib and cNBT, which have no include dir
), ),
install : true, install : true,

View File

@ -1,15 +1,21 @@
#include "NetworkManager.h" #include "NetworkManager.h"
#include "logging/Logger.h"
#include <event2/event.h> #include <event2/event.h>
#include <event2/thread.h> #include <event2/thread.h>
namespace Feather::Log::Channels
{
Log::ChannelID LibEvent = Log::Logger::Instance().RegisterChannel("libevent");
}
namespace Feather::Network namespace Feather::Network
{ {
namespace namespace
{ {
void LogCallback(int severity, const char* msg) void LogCallback(int severity, const char* msg)
{ {
printf("libevent: %s\n", msg); Log::Msg(Log::Channels::LibEvent, Log::Level::Info, msg);
} }
} }

View File

@ -2,12 +2,12 @@
#include "TCPListener.h" #include "TCPListener.h"
#include "NetworkManager.h" #include "NetworkManager.h"
#include "logging/Logger.h"
#include <event2/event.h> #include <event2/event.h>
#include <event2/buffer.h> #include <event2/buffer.h>
#include <event2/bufferevent.h> #include <event2/bufferevent.h>
#include "logging/Logger.h"
#include <cinttypes> #include <cinttypes>
namespace Feather::Network namespace Feather::Network
@ -39,7 +39,7 @@ namespace Feather::Network
data.resize(offset + size); data.resize(offset + size);
if (evbuffer_remove(buffer, &data[offset], size) != size) if (evbuffer_remove(buffer, &data[offset], size) != size)
{ {
Log_Error("Failed to remove data from buffer."); Log::Error("Failed to remove data from buffer.");
return; return;
} }
} }
@ -53,7 +53,7 @@ namespace Feather::Network
if (event & BEV_EVENT_ERROR) if (event & BEV_EVENT_ERROR)
{ {
const char* errorString = evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR()); const char* errorString = evutil_socket_error_to_string(EVUTIL_SOCKET_ERROR());
Log_Error("TCPClient: %s", errorString); Log::Error("TCPClient: {}", errorString);
} }
if (event & BEV_EVENT_EOF) if (event & BEV_EVENT_EOF)
@ -63,6 +63,6 @@ namespace Feather::Network
void TCPClient::Write(const uint8_t* data, size_t size) void TCPClient::Write(const uint8_t* data, size_t size)
{ {
if (bufferevent_write(m_bufferEvent, data, size) != 0) if (bufferevent_write(m_bufferEvent, data, size) != 0)
Log_Error("Failed to write to socket, size: " PRIuPTR ".", size); Log::Error("Failed to write to socket, size: " PRIuPTR ".", size);
} }
} }

View File

@ -15,31 +15,31 @@ namespace Feather::Network
if (!socket->IsValid()) if (!socket->IsValid())
{ {
Log_Error("Socket failed to be created."); Log::Error("Socket failed to be created.");
return; return;
} }
if (!socket->MarkReusable()) if (!socket->MarkReusable())
{ {
Log_Error("Failed to mark socket as resuable."); Log::Error("Failed to mark socket as resuable.");
return; return;
} }
if (socket->IsIPV6() && !socket->MarkDualBind()) if (socket->IsIPV6() && !socket->MarkDualBind())
{ {
Log_Error("Failed to mark IPv6 socket as dual-bind."); Log::Error("Failed to mark IPv6 socket as dual-bind.");
return; return;
} }
if (!socket->Bind(port)) if (!socket->Bind(port))
{ {
Log_Error("Failed to bind socket to port %hu.", port); Log::Error("Failed to bind socket to port {}.", port);
return; return;
} }
if (!socket->MarkNonBlocking()) if (!socket->MarkNonBlocking())
{ {
Log_Error("Failed to mark socket as non-blocking."); Log::Error("Failed to mark socket as non-blocking.");
return; return;
} }
@ -51,7 +51,7 @@ namespace Feather::Network
if (!socket->Listen(ListenerCallback, this)) if (!socket->Listen(ListenerCallback, this))
{ {
Log_Error("Failed to start listening on socket."); Log::Error("Failed to start listening on socket.");
return; return;
} }

View File

@ -15,7 +15,7 @@ namespace Feather::Network
// Can't create IPv6 socket? Create an IPv4 one. // Can't create IPv6 socket? Create an IPv4 one.
if (!(m_ipv6 = IsValid())) if (!(m_ipv6 = IsValid()))
{ {
Log_Info("Failed to create IPv6 socket, falling back to IPv4."); Log::Info("Failed to create IPv6 socket, falling back to IPv4.");
m_socket = socket(AF_INET, SOCK_STREAM, IPPROTO_TCP); m_socket = socket(AF_INET, SOCK_STREAM, IPPROTO_TCP);
} }
} }

View File

@ -25,7 +25,7 @@ namespace Feather::Protocol
inline void SetState(ProtocolState state) inline void SetState(ProtocolState state)
{ {
Log_Info("Setting state: %d", (int)state); Log::Info("Setting state: {}", (int)state);
m_state = state; m_state = state;
} }
private: private:

1
subprojects/fmt Submodule

@ -0,0 +1 @@
Subproject commit d7921d649a5bbd212f9983588b7af90dfc23f02c