Skip to content

Commit

Permalink
Merge bitcoin#24464: logging: Add severity level to logs
Browse files Browse the repository at this point in the history 
e11cdc9  logging: Add log severity level to net.cpp (klementtan)
a829064 logging: Add severity level to logs. (klementtan)

Pull request description:

  **Overview**: This PR introduces a new macro, `LogPrintLevel`, that allows developers to add logs with the severity level. Additionally, it will also print the log category if it is specified.

  Sample log:
  ```
  2022-03-04T16:41:15Z [opencon] [net:debug] trying connection XX.XX.XXX.XXX:YYYYY lastseen=2.7hrs
  ```

  **Motivation**: This feature was suggested in bitcoin#20576 and I believe that it will bring the following benefits:
  * Allow for easier filtering of logs in `debug.log`
  * Can be extended to allow users to select the minimum level of logs they would like to view (not in the scope of this PR)

  **Details**:
  * New log format. `... [category:level]...`. ie:
    * Do not print category if `category == NONE`
    * Do not print level if `level == NONE`
    * If `category == NONE` and `level == NONE`, do not print any fields (current behaviour)
  * Previous logging functions:
    * `LogPrintf`:  no changes in log as it calls `LogPrintf_` with `category = NONE` and `level = NONE`
    * `LogPrint`: prints additional `[category]` field as it calls `LogPrintf_` with `category = category` and `level = NONE`
  * `net.cpp`: As a proof of concept, updated logs with obvious severity (ie prefixed with `Warning/Error:..`) to use the new logging with severity.

  **Testing**:
  * Compiling and running `bitcoind` with this PR should instantly display logs with the category name (ie `net/tor/...`)
  * Grepping for `net:debug` in `debug.log` should display the updated logs with severity level:
    <details>
    <summary>Code</summary>

    ```
    $ grep "net:debug" debug.log

    2022-03-04T16:41:15Z [opencon] [net:debug] trying connection XXX:YYY lastseen=2.7hrs
    2022-03-04T16:41:16Z [opencon] [net:debug] trying connection XXX:YYY lastseen=16.9hrs
    2022-03-04T16:41:17Z [opencon] [net:debug] trying connection XXX:YYY lastseen=93.2hrs
    2022-03-04T16:41:18Z [opencon] [net:debug] trying connection XXX:YYY lastseen=2.7hrs
    ```
    </details>

ACKs for top commit:
  laanwj:
    Code review and lightly tested ACK e11cdc9

Tree-SHA512: 89a8c86667ccc0688e5acfdbd399aac1f5bec9f978a160e40b0210b0d9b8fdc338479583fc5bd2e2bc785821363f174f578d52136d228e8f638a20abbf0a568f
  • Loading branch information
@laanwj
laanwj committed May 24, 2022
2 parents 7008087 + e11cdc9 commit 90e49c1
Show file tree
Hide file tree
Showing 4 changed files with 265 additions and 23 deletions.
109 changes: 107 additions & 2 deletions src/logging.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -171,7 +171,7 @@ const CLogCategoryDesc LogCategories[] =

bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
{
if (str == "") {
if (str.empty()) {
flag = BCLog::ALL;
return true;
}
Expand All @@ -184,6 +184,91 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
return false;
}

std::string LogLevelToStr(BCLog::Level level)
{
switch (level) {
case BCLog::Level::None:
return "none";
case BCLog::Level::Debug:
return "debug";
case BCLog::Level::Info:
return "info";
case BCLog::Level::Warning:
return "warning";
case BCLog::Level::Error:
return "error";
}
assert(false);
}

std::string LogCategoryToStr(BCLog::LogFlags category)
{
// Each log category string representation should sync with LogCategories
switch (category) {
case BCLog::LogFlags::NONE:
return "none";
case BCLog::LogFlags::NET:
return "net";
case BCLog::LogFlags::TOR:
return "tor";
case BCLog::LogFlags::MEMPOOL:
return "mempool";
case BCLog::LogFlags::HTTP:
return "http";
case BCLog::LogFlags::BENCH:
return "bench";
case BCLog::LogFlags::ZMQ:
return "zmq";
case BCLog::LogFlags::WALLETDB:
return "walletdb";
case BCLog::LogFlags::RPC:
return "rpc";
case BCLog::LogFlags::ESTIMATEFEE:
return "estimatefee";
case BCLog::LogFlags::ADDRMAN:
return "addrman";
case BCLog::LogFlags::SELECTCOINS:
return "selectcoins";
case BCLog::LogFlags::REINDEX:
return "reindex";
case BCLog::LogFlags::CMPCTBLOCK:
return "cmpctblock";
case BCLog::LogFlags::RAND:
return "rand";
case BCLog::LogFlags::PRUNE:
return "prune";
case BCLog::LogFlags::PROXY:
return "proxy";
case BCLog::LogFlags::MEMPOOLREJ:
return "mempoolrej";
case BCLog::LogFlags::LIBEVENT:
return "libevent";
case BCLog::LogFlags::COINDB:
return "coindb";
case BCLog::LogFlags::QT:
return "qt";
case BCLog::LogFlags::LEVELDB:
return "leveldb";
case BCLog::LogFlags::VALIDATION:
return "validation";
case BCLog::LogFlags::I2P:
return "i2p";
case BCLog::LogFlags::IPC:
return "ipc";
#ifdef DEBUG_LOCKCONTENTION
case BCLog::LogFlags::LOCK:
return "lock";
#endif
case BCLog::LogFlags::UTIL:
return "util";
case BCLog::LogFlags::BLOCKSTORE:
return "blockstorage";
case BCLog::LogFlags::ALL:
return "all";
}
assert(false);
}

std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
{
// Sort log categories by alphabetical order.
Expand Down Expand Up @@ -249,11 +334,31 @@ namespace BCLog {
}
} // namespace BCLog

void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line)
void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags category, const BCLog::Level level)
{
StdLockGuard scoped_lock(m_cs);
std::string str_prefixed = LogEscapeMessage(str);

if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) {
std::string s{"["};

if (category != LogFlags::NONE) {
s += LogCategoryToStr(category);
}

if (category != LogFlags::NONE && level != Level::None) {
// Only add separator if both flag and level are not NONE
s += ":";
}

if (level != Level::None) {
s += LogLevelToStr(level);
}

s += "] ";
str_prefixed.insert(0, s);
}

if (m_log_sourcelocations && m_started_new_line) {
str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
}
Expand Down
35 changes: 26 additions & 9 deletions src/logging.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,13 @@ namespace BCLog {
BLOCKSTORE = (1 << 26),
ALL = ~(uint32_t)0,
};
enum class Level {
Debug = 0,
None = 1,
Info = 2,
Warning = 3,
Error = 4,
};

class Logger
{
Expand Down Expand Up @@ -105,7 +112,7 @@ namespace BCLog {
std::atomic<bool> m_reopen_file{false};

/** Send a string to the log output */
void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line);
void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags category, const BCLog::Level level);

/** Returns whether logs will be written to any output */
bool Enabled() const
Expand Down Expand Up @@ -173,7 +180,7 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str);
// peer can fill up a user's disk with debug.log entries.

template <typename... Args>
static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const char* fmt, const Args&... args)
static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, const char* fmt, const Args&... args)
{
if (LogInstance().Enabled()) {
std::string log_msg;
Expand All @@ -183,19 +190,29 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st
/* Original format string will have newline so don't add one here */
log_msg = "Error \"" + std::string(fmterr.what()) + "\" while formatting log message: " + fmt;
}
LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line);
LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line, flag, level);
}
}

#define LogPrintf(...) LogPrintf_(__func__, __FILE__, __LINE__, __VA_ARGS__)

#define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__)

#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::NONE, BCLog::Level::None, __VA_ARGS__)

// Use a macro instead of a function for conditional logging to prevent
// evaluating arguments when logging for the category is not enabled.
#define LogPrint(category, ...) \
do { \
if (LogAcceptCategory((category))) { \
LogPrintf(__VA_ARGS__); \
} \
#define LogPrint(category, ...) \
do { \
if (LogAcceptCategory((category))) { \
LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \
} \
} while (0)

#define LogPrintLevel(level, category, ...) \
do { \
if (LogAcceptCategory((category))) { \
LogPrintLevel_(category, level, __VA_ARGS__); \
} \
} while (0)

#endif // BITCOIN_LOGGING_H
24 changes: 12 additions & 12 deletions src/net.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -430,7 +430,7 @@ static CAddress GetBindAddress(SOCKET sock)
if (!getsockname(sock, (struct sockaddr*)&sockaddr_bind, &sockaddr_bind_len)) {
addr_bind.SetSockAddr((const struct sockaddr*)&sockaddr_bind);
} else {
LogPrint(BCLog::NET, "Warning: getsockname failed\n");
LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "getsockname failed\n");
}
}
return addr_bind;
Expand All @@ -454,9 +454,9 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo
}

/// debug print
LogPrint(BCLog::NET, "trying connection %s lastseen=%.1fhrs\n",
pszDest ? pszDest : addrConnect.ToString(),
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime)/3600.0);
LogPrintLevel(BCLog::Level::Debug, BCLog::NET, "trying connection %s lastseen=%.1fhrs\n",
pszDest ? pszDest : addrConnect.ToString(),
pszDest ? 0.0 : (double)(GetAdjustedTime() - addrConnect.nTime) / 3600.0);

// Resolve
const uint16_t default_port{pszDest != nullptr ? Params().GetDefaultPort(pszDest) :
Expand Down Expand Up @@ -1140,7 +1140,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) {
}

if (!addr.SetSockAddr((const struct sockaddr*)&sockaddr)) {
LogPrintf("Warning: Unknown socket family\n");
LogPrintLevel(BCLog::Level::Warning, BCLog::NET, "Unknown socket family\n");
} else {
addr = CAddress{MaybeFlipIPv6toCJDNS(addr), NODE_NONE};
}
Expand Down Expand Up @@ -2397,15 +2397,15 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
socklen_t len = sizeof(sockaddr);
if (!addrBind.GetSockAddr((struct sockaddr*)&sockaddr, &len))
{
strError = strprintf(Untranslated("Error: Bind address family for %s not supported"), addrBind.ToString());
LogPrintf("%s\n", strError.original);
strError = strprintf(Untranslated("Bind address family for %s not supported"), addrBind.ToString());
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
return false;
}

std::unique_ptr<Sock> sock = CreateSock(addrBind);
if (!sock) {
strError = strprintf(Untranslated("Error: Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintf("%s\n", strError.original);
strError = strprintf(Untranslated("Couldn't open socket for incoming connections (socket returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
return false;
}

Expand Down Expand Up @@ -2441,16 +2441,16 @@ bool CConnman::BindListenPort(const CService& addrBind, bilingual_str& strError,
strError = strprintf(_("Unable to bind to %s on this computer. %s is probably already running."), addrBind.ToString(), PACKAGE_NAME);
else
strError = strprintf(_("Unable to bind to %s on this computer (bind returned error %s)"), addrBind.ToString(), NetworkErrorString(nErr));
LogPrintf("%s\n", strError.original);
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
return false;
}
LogPrintf("Bound to %s\n", addrBind.ToString());

// Listen for incoming connections
if (listen(sock->Get(), SOMAXCONN) == SOCKET_ERROR)
{
strError = strprintf(_("Error: Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintf("%s\n", strError.original);
strError = strprintf(_("Listening for incoming connections failed (listen returned error %s)"), NetworkErrorString(WSAGetLastError()));
LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s\n", strError.original);
return false;
}

Expand Down
Loading

0 comments on commit 90e49c1

Please sign in to comment.