log: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order

laanwj commented at 6:21 pm on May 24, 2022: member

Log messages from leveldb and libevent libraries in the severity+level based log format introduced in bitcoin/bitcoin#24464.

Example of messages before:

02022-05-24T18:11:57Z [libevent] libevent: event_add: event: 0x55da963fcc10 (fd 10), EV_READ    call 0x7f1c7a254620
12022-05-24T18:11:57Z [libevent] libevent: Epoll ADD(1) on fd 10 okay. Old events were 0; read change was 1 (add); write change was 0 (none); close change was 0 (none)
22022-05-24T18:12:08Z leveldb: Generated table [#609127](/bitcoin-bitcoin/609127/)@1: 6445 keys, 312916 bytes
32022-05-24T18:12:08Z leveldb: Generated table [#609128](/bitcoin-bitcoin/609128/)@1: 5607 keys, 268548 bytes
42022-05-24T18:12:08Z leveldb: Generated table [#609129](/bitcoin-bitcoin/609129/)@1: 189 keys, 9384 bytes
52022-05-24T18:12:08Z leveldb: Generated table [#609130](/bitcoin-bitcoin/609130/)@1: 293 keys, 13818 bytes

Example of messages after:

02022-05-24T17:59:52Z [libevent:debug] event_add: event: 0x5652f44dac10 (fd 10), EV_READ    call 0x7f210f2e6620
12022-05-24T17:59:52Z [libevent:debug] Epoll ADD(1) on fd 10 okay. Old events were 0; read change was 1 (add); write change was 0 (none); close change was 0 (none)
22022-05-24T17:59:53Z [leveldb:debug] Recovering log [#1072](/bitcoin-bitcoin/1072/)
32022-05-24T17:59:53Z [leveldb:debug] Level-0 table [#1082](/bitcoin-bitcoin/1082/): started
42022-05-24T17:59:53Z [leveldb:debug] Level-0 table [#1082](/bitcoin-bitcoin/1082/): 193 bytes OK
52022-05-24T17:59:53Z [leveldb:debug] Delete type=3 [#1070](/bitcoin-bitcoin/1070/)
62022-05-24T17:59:53Z [leveldb:debug] Delete type=0 [#1072](/bitcoin-bitcoin/1072/)

The first commit changes it so that messages with level Warning and Error are always logged independent of the -debug setting. I think this is useful to make sure warnings and errors, which tend to be important, are not lost. In the future this should be made more configurable.

Last commit changes LogPrintLevel argument order to category, severity: This is more consistent with the other functions, as well as with the logging output itself. If we want to make this change, we should do it before it’s all over the place.

laanwj added the label Utils/log/libs on May 24, 2022

laanwj force-pushed on May 24, 2022

in src/logging.h:218 in cdd3d8d4b1 outdated

214@@ -210,7 +215,7 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st
215 
216 #define LogPrintLevel(level, category, ...)               \
217     do {                                                  \
218-        if (LogAcceptCategory((category))) {              \
219+        if (LogAcceptCategory((category, level))) {       \

jonatack commented at 6:59 pm on May 24, 2022:

At first glance it looks like the updated callers are using an inverted parameters order (level, category) compared to here. Edit: I’m probably confused here though.

laanwj commented at 7:08 pm on May 24, 2022:

I thought about that, and I’m fine with putting level first, but that means updating all callers of LogAcceptCategory. It’s not that many, though.

Edit: note that the arguments are type-safe so you cannot actually make the mistake of swapping them.

Edit.2: Wait, you’re right, I must have done something wrong in the last push. Let me see.

laanwj commented at 7:21 pm on May 24, 2022:

It should build correctly now, the problem wasn’t the order of arguments but invalid () nesting.

laanwj commented at 7:24 pm on May 24, 2022:

I agree it’s strange that LogPrintLevel and LogPrintLevel_/LogAcceptCategory have opposite order of level, category arguments, but not sure it’s in scope to fix here (nor in which direction to resolve it, I think that needs a separate discussion).

laanwj force-pushed on May 24, 2022

DrahtBot commented at 3:48 am on May 25, 2022: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#24922 (Isolate the storage abstraction layer from the application/serialization layer by TheQuantumPhysicist)
#24697 (refactor address relay time by MarcoFalke)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

in src/logging.h:170 in d2a8887ace outdated

165@@ -166,9 +166,14 @@ namespace BCLog {
166 
167 BCLog::Logger& LogInstance();
168 
169-/** Return true if log accepts specified category */
170-static inline bool LogAcceptCategory(BCLog::LogFlags category)
171+/** Return true if log accepts specified category, at the specified level. */
172+static inline bool LogAcceptCategory(BCLog::LogFlags category, const BCLog::Level level = BCLog::Level::Debug)

MarcoFalke commented at 8:00 am on May 25, 2022:

Wouldn’t it be better to not have a default value and just inline the value once where it is needed?

laanwj commented at 9:02 am on May 25, 2022:

Sure, will do.

MarcoFalke approved

logging: Unconditionally log levels >= WARN

Messages with level `WARN` or higher should be logged even when
the category is not provided with `-debug=`, to make sure important
warnings are not lost.

bd971bffb0

http: Use severity-based logging for messages from libevent

Map libevent's severity to our own severity level for logging.

18ec120bb9

leveldb: Log messages from leveldb with category and debug level ce920713bf

refactor: Change LogPrintLevel order to category, severity

This is more consistent with the other functions, as well as with the
logging output itself. If we want to make this change, we should do it
before it's all over the place.

c4e7717727

laanwj force-pushed on May 25, 2022

laanwj commented at 9:36 am on May 25, 2022: member

Re-pushed d2a8887→c4e7717:

Remove default argument from LogAcceptCategory
Add commit to change LogPrintLevel argument order to category, severity: This is more consistent with the other functions, as well as with the logging output itself. If we want to make this change, we should do it before it’s all over the place.

laanwj renamed this:
~~log: Use severity-based logging for leveldb/libevent messages~~
log: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order
on May 25, 2022

in src/dbwrapper.cpp:22 in c4e7717727

18@@ -19,7 +19,7 @@ class CBitcoinLevelDBLogger : public leveldb::Logger {
19     // This code is adapted from posix_logger.h, which is why it is using vsprintf.
20     // Please do not do this in normal code
21     void Logv(const char * format, va_list ap) override {
22-            if (!LogAcceptCategory(BCLog::LEVELDB)) {
23+            if (!LogAcceptCategory(BCLog::LEVELDB, BCLog::Level::Debug)) {

jonatack commented at 1:28 pm on May 25, 2022:

It was already the case before this PR, so feel free to ignore, just noting that

bd971bf there is a missing #include <logging.h> in src/dbwrapper.cpp, src/timedata.cpp, src/wallet/coinselection.cpp

18ec120bb9e1fc9d27d2419da4c580bd3cde7e86 same for src/httpserver.cpp

c4e77177276ea2b79c4675cb2678ee2cc757b743 same for src/net.cpp

laanwj commented at 3:08 pm on May 25, 2022:

I agree, but as you say, this was the case before this PR, and is not introduced with category/severity based logging. There’s probably tons of source files that, besides these ones, need logging.h included.

jonatack commented at 2:05 pm on May 25, 2022: member

Tested ACK c4e77177276ea2b79c4675cb2678ee2cc757b743

laanwj merged this on May 26, 2022

laanwj closed this on May 26, 2022

sidhujag referenced this in commit a29dd98719 on May 28, 2022

DrahtBot locked this on May 26, 2023

log: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order #25202

Conflicts