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

laanwj · 2022-05-24T18:21:06Z

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

Example of messages before:

2022-05-24T18:11:57Z [libevent] libevent: event_add: event: 0x55da963fcc10 (fd 10), EV_READ    call 0x7f1c7a254620
2022-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)
2022-05-24T18:12:08Z leveldb: Generated table #609127@1: 6445 keys, 312916 bytes
2022-05-24T18:12:08Z leveldb: Generated table #609128@1: 5607 keys, 268548 bytes
2022-05-24T18:12:08Z leveldb: Generated table #609129@1: 189 keys, 9384 bytes
2022-05-24T18:12:08Z leveldb: Generated table #609130@1: 293 keys, 13818 bytes

Example of messages after:

2022-05-24T17:59:52Z [libevent:debug] event_add: event: 0x5652f44dac10 (fd 10), EV_READ    call 0x7f210f2e6620
2022-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)
2022-05-24T17:59:53Z [leveldb:debug] Recovering log #1072
2022-05-24T17:59:53Z [leveldb:debug] Level-0 table #1082: started
2022-05-24T17:59:53Z [leveldb:debug] Level-0 table #1082: 193 bytes OK
2022-05-24T17:59:53Z [leveldb:debug] Delete type=3 #1070
2022-05-24T17:59:53Z [leveldb:debug] Delete type=0 #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.

src/logging.h

DrahtBot · 2022-05-25T03:48:36Z

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.

src/logging.h

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.

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

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 · 2022-05-25T09:36:34Z

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.

jonatack

Tested ACK c4e7717

jonatack · 2022-05-25T13:28:08Z

src/dbwrapper.cpp

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


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

18ec120 same for src/httpserver.cpp

c4e7717 same for src/net.cpp

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.

…vent messages, reverse LogPrintLevel order c4e7717 refactor: Change LogPrintLevel order to category, severity (laanwj) ce92071 leveldb: Log messages from leveldb with category and debug level (laanwj) 18ec120 http: Use severity-based logging for messages from libevent (laanwj) bd971bf logging: Unconditionally log levels >= WARN (laanwj) Pull request description: Log messages from leveldb and libevent libraries in the severity+level based log format introduced in bitcoin#24464. Example of messages before: ``` 2022-05-24T18:11:57Z [libevent] libevent: event_add: event: 0x55da963fcc10 (fd 10), EV_READ call 0x7f1c7a254620 2022-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) 2022-05-24T18:12:08Z leveldb: Generated table #609127@1: 6445 keys, 312916 bytes 2022-05-24T18:12:08Z leveldb: Generated table #609128@1: 5607 keys, 268548 bytes 2022-05-24T18:12:08Z leveldb: Generated table #609129@1: 189 keys, 9384 bytes 2022-05-24T18:12:08Z leveldb: Generated table #609130@1: 293 keys, 13818 bytes ``` Example of messages after: ``` 2022-05-24T17:59:52Z [libevent:debug] event_add: event: 0x5652f44dac10 (fd 10), EV_READ call 0x7f210f2e6620 2022-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) 2022-05-24T17:59:53Z [leveldb:debug] Recovering log bitcoin#1072 2022-05-24T17:59:53Z [leveldb:debug] Level-0 table bitcoin#1082: started 2022-05-24T17:59:53Z [leveldb:debug] Level-0 table bitcoin#1082: 193 bytes OK 2022-05-24T17:59:53Z [leveldb:debug] Delete type=3 bitcoin#1070 2022-05-24T17:59:53Z [leveldb:debug] Delete type=0 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. ACKs for top commit: jonatack: Tested ACK c4e7717 Tree-SHA512: ea48a1517f8c1b23760e59933bbd64ebf09c32eb947e31b8c2696b4630ac1f4303b126720183e2de052bcede3a17e475bbf3fbb6378a12b0fa8f3582d610930d

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

laanwj force-pushed the 2022-05-logging-improved branch from ff55e92 to cdd3d8d Compare May 24, 2022 18:42

jonatack reviewed May 24, 2022

View reviewed changes

src/logging.h Outdated Show resolved Hide resolved

laanwj force-pushed the 2022-05-logging-improved branch from cdd3d8d to d2a8887 Compare May 24, 2022 19:21

laanwj mentioned this pull request May 24, 2022

Severity-based logging -- parent PR #25203

Closed

6 tasks

DrahtBot mentioned this pull request May 25, 2022

Isolate the storage abstraction layer from the application/serialization layer #24922

Closed

maflcko reviewed May 25, 2022

View reviewed changes

src/logging.h Outdated Show resolved Hide resolved

maflcko approved these changes May 25, 2022

View reviewed changes

laanwj added 4 commits May 25, 2022 11:26

logging: Unconditionally log levels >= WARN

bd971bf

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.

http: Use severity-based logging for messages from libevent

18ec120

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

leveldb: Log messages from leveldb with category and debug level

ce92071

refactor: Change LogPrintLevel order to category, severity

c4e7717

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 force-pushed the 2022-05-logging-improved branch from d2a8887 to c4e7717 Compare May 25, 2022 09:33

laanwj changed the title ~~log: Use severity-based logging for leveldb/libevent messages~~ log: Use severity-based logging for leveldb/libevent messages, reverse LogPrintLevel order May 25, 2022

jonatack reviewed May 25, 2022

View reviewed changes

DrahtBot mentioned this pull request May 25, 2022

refactor address relay time #24697

Merged

laanwj merged commit 4901631 into bitcoin:master May 26, 2022

mzumsande mentioned this pull request Jun 22, 2022

log: Mitigate disk filling attacks by rate limiting LogPrintf #21603

Closed

bitcoin locked and limited conversation to collaborators May 26, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

laanwj commented May 24, 2022 •

edited

Loading

DrahtBot commented May 25, 2022 •

edited

Loading

laanwj commented May 25, 2022

jonatack left a comment

jonatack May 25, 2022 •

edited

Loading

laanwj May 25, 2022

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

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

Conversation

laanwj commented May 24, 2022 • edited Loading

DrahtBot commented May 25, 2022 • edited Loading

Conflicts

laanwj commented May 25, 2022

jonatack left a comment

Choose a reason for hiding this comment

jonatack May 25, 2022 • edited Loading

Choose a reason for hiding this comment

laanwj May 25, 2022

Choose a reason for hiding this comment

laanwj commented May 24, 2022 •

edited

Loading

DrahtBot commented May 25, 2022 •

edited

Loading

jonatack May 25, 2022 •

edited

Loading