logging: Add severity level to logs #24464

klementtan · 2022-03-02T17:27:25Z

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 #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:

Code

$ 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

DrahtBot · 2022-03-03T02:45:37Z

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

#24827 (net: Fix undefined behavior in socket address handling by Adlai-Holler)
#24697 (refactor address relay time by MarcoFalke)
#24662 (addrman: Use system time instead of adjusted network time by MarcoFalke)
#21878 (Make all networking code mockable by vasild)
#21603 (log: Mitigate disk filling attacks by rate limiting LogPrintf by dergoegge)
#16673 (Relog configuration args on debug.log rotation by LarryRuane)

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.

luke-jr

Concept ACK, but

Category shouldn't be optional.
Severity should be a parameter, not part of the function name. Often, severity can vary based on the specifics.

jnewbery · 2022-03-09T12:01:53Z

Concept ACK. I agree with @luke-jr that it'd be better for severity to be a parameter rather than part of the macro name

klementtan · 2022-03-09T15:36:03Z

@jnewbery @luke-jr thanks for the feedback. Updated the PR to use log severity as a parameter instead of macro name.

doc/release-notes.md

laanwj · 2022-04-05T14:27:44Z

Concept ACK. I've always liked this idea because it allows moving all "global" log messages to a category, eventually, just with a higher priority than debug.

src/logging.cpp

klementtan · 2022-05-06T05:14:51Z

@jonatack @MarcoFalke thanks for the detailed review!

a62d157 to 2f83557: Updated the PR to address the review comments

laanwj · 2022-05-09T14:30:38Z

src/logging.cpp

+std::string LogCategoryToStr(BCLog::LogFlags category)
+{
+    switch (category) {
+    case BCLog::LogFlags::NONE:


It seems there's an overlap here with CLogCategoryDesc LogCategories[]. I think it would be best to use that? If not, at the least it would be good to add comments in both places (or even a test) to keep the lists in sync.

Done, added a comment to state that the LogCategoryToStr should sync with LogCategories and added tests to ensure that both are in sync.

I think it would be best to use that

I am not really sure how to do that as we cannot simply map the enum values of LogFlags to indexes on LogCategories. This is due to most of the enum values of LogCategories being bit flags (ie 1 << i) but LogCategories::NONE and LogCategories::ALL are not bit flags.

This is due to most of the enum values of LogCategories being bit flags (ie 1 << i) but LogCategories::NONE and LogCategories::ALL are not bit flags.

One way to do it would be to introduce a third "source data" structure, and build both LogCategories and the one used for LogCategoryToStr from that.

That said, I think this is ok for now.

laanwj · 2022-05-24T17:28:45Z

Code review and lightly tested ACK e11cdc9

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

…ldb/libevent 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/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 #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. ACKs for top commit: jonatack: Tested ACK c4e7717 Tree-SHA512: ea48a1517f8c1b23760e59933bbd64ebf09c32eb947e31b8c2696b4630ac1f4303b126720183e2de052bcede3a17e475bbf3fbb6378a12b0fa8f3582d610930d

…ntLevel, mention WalletLogPrintf 75848ec scripts and tools: update lint-logs.py to detect LogPrintLevel() (Jon Atack) Pull request description: Follow-up to #24464 that added the `LogPrintLevel()` macro. - update the `lint-logs.py` script to detect `LogPrintLevel()` - add `WalletLogPrintf()` (already detected but not mentioned) to the linter suggestion Example output: ``` $ test/lint/lint-logs.py All calls to LogPrintf(), LogPrint(), LogPrintLevel(), and WalletLogPrintf() should be terminated with "\n". src/addrdb.cpp:147: LogPrintf("banlist.dat ignored because it can only be read by " PACKAGE_NAME " version 22.x. Remove %s to silence this warning.", fs::quoted(fs::PathToString(m_banlist_dat))); src/addrman.cpp:388: LogPrint(BCLog::ADDRMAN, "addrman lost %i new and %i tried addresses due to collisions or invalid addresses", nLostUnk, nLost); src/banman.cpp:41: LogPrintf("Recreating the banlist database"); src/banman.cpp:66: LogPrint(BCLog::NET, "Flushed %d banned node addresses/subnets to disk %dms", banmap.size(), src/banman.cpp:194: LogPrint(BCLog::NET, "Removed banned node address/subnet: %s", sub_net.ToString()); src/net.cpp:2092: LogPrint(BCLog::NET, "Trying to make an anchor connection to %s", addrConnect.ToString()); src/net.cpp:2408: LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s", strError.original); src/net.cpp:2416: LogPrintf("%s", strError.original); src/net.cpp:2432: LogPrintf("%s", strError.original); src/net.cpp:2453: LogPrintLevel(BCLog::Level::Error, BCLog::NET, "%s", strError.original); src/netbase.cpp:573: LogPrintf("wait for connect to %s failed: %s", src/netbase.cpp:578: LogPrint(BCLog::NET, "connection attempt to %s timed out", addrConnect.ToString()); src/netbase.cpp:590: LogPrintf("getsockopt() for %s failed: %s", addrConnect.ToString(), NetworkErrorString(WSAGetLastError())); src/wallet/wallet.cpp:186: wallet->WalletLogPrintf("Releasing wallet"); src/wallet/wallet.cpp:1809: WalletLogPrintf("Rescan completed in %15dms", duration_milliseconds.count()); ``` ACKs for top commit: laanwj: ACK 75848ec Tree-SHA512: 78b3bc4428aaec2d198e1ff1c44b614fa2f2a228feb6303d97765136e4796171928d341c6e55a1d4e9e5a82ab099b14fee562b878dcf7bd2276f87bd9a8d323e

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

…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

…t output d40550d scripted-diff: remove duplicate categories from LogPrint output (Jon Atack) Pull request description: This is the first commit from #25203. - Scripted-diff: de-duplicate logging category output for the tor, i2p, net, zmq, and prune messages (e.g. where I found duplicates), as these category prefixes are now printed automatically since #24464 examples before ``` [tor] tor: Successfully connected! [i2p] I2P: Creating SAM session with 127.0.0.1:7656 [zmq] zmq: Initialize notification interface [net] net: enabling extra block-relay-only peers ``` after ``` [tor] Successfully connected! [i2p] Creating SAM session with 127.0.0.1:7656 [zmq] Initialize notification interface [net] enabling extra block-relay-only peers ``` ACKs for top commit: klementtan: crACK d40550d MarcoFalke: cr ACK d40550d Tree-SHA512: 63b799f2f899f0597981dd1acb91ef4439cd00b257a9eb19d67c4ce2c4dc72a95ac5761cb78f2a19090a10be74f23ea1db6929ed942ba0d008b4be563f0d5e7e

klementtan force-pushed the log_level branch 2 times, most recently from 4e9880d to b6875b4 Compare March 2, 2022 18:00

DrahtBot added the Tests label Mar 2, 2022

klementtan force-pushed the log_level branch from b6875b4 to 2c051e6 Compare March 3, 2022 02:22

klementtan force-pushed the log_level branch from 2c051e6 to 637b357 Compare March 3, 2022 02:51

klementtan mentioned this pull request Mar 3, 2022

RFC on logging improvements #20576

Closed

This was referenced Mar 3, 2022

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

Closed

Relog configuration args on debug.log rotation #16673

Closed

klementtan force-pushed the log_level branch from 637b357 to e3b88b8 Compare March 4, 2022 16:43

This was referenced Mar 5, 2022

util: Add -shutdownnotify option #23395

Merged

Make all networking code mockable #21878

Closed

luke-jr reviewed Mar 8, 2022

View reviewed changes

klementtan force-pushed the log_level branch from e3b88b8 to a0b8904 Compare March 9, 2022 15:32

DrahtBot mentioned this pull request Mar 16, 2022

doc: Add template for empty release notes #24583

Merged

maflcko reviewed Mar 16, 2022

View reviewed changes

doc/release-notes.md Outdated Show resolved Hide resolved

klementtan force-pushed the log_level branch 3 times, most recently from 6820e9b to 4444a6b Compare March 16, 2022 17:14

This was referenced Mar 25, 2022

addrman: Use system time instead of adjusted network time #24662

Merged

refactor address relay time #24697

Merged

This was referenced Apr 8, 2022

refactor: only use explicit reinterpret/const casts, not implicit #24185

Closed

net: Fix undefined behavior in socket address handling #24827

Closed

This was referenced Apr 14, 2022

More granular net logging #12219

Closed

p2p: Split network logging into two categories #24247 #24273

Closed

laanwj added Utils/log/libs and removed Tests labels Apr 14, 2022

maflcko reviewed May 5, 2022

View reviewed changes

src/logging.cpp Outdated Show resolved Hide resolved

maflcko reviewed May 5, 2022

View reviewed changes

src/logging.cpp Outdated Show resolved Hide resolved

klementtan force-pushed the log_level branch 2 times, most recently from a62d157 to 2f83557 Compare May 6, 2022 04:23

maflcko added this to the 24.0 milestone May 6, 2022

laanwj reviewed May 9, 2022

View reviewed changes

klementtan force-pushed the log_level branch from 2f83557 to 0d709b8 Compare May 19, 2022 12:56

klementtan added 2 commits May 19, 2022 21:05

logging: Add severity level to logs.

a829064

logging: Add log severity level to net.cpp

e11cdc9

klementtan force-pushed the log_level branch from 0d709b8 to e11cdc9 Compare May 19, 2022 13:05

laanwj merged commit 90e49c1 into bitcoin:master May 24, 2022

laanwj mentioned this pull request May 24, 2022

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

Merged

jonatack mentioned this pull request May 24, 2022

Severity-based logging -- parent PR #25203

Closed

6 tasks

klementtan deleted the log_level branch May 25, 2022 00:18

jonatack mentioned this pull request May 25, 2022

scripts and tools: update lint-logs.py to detect LogPrintLevel, mention WalletLogPrintf #25217

Merged

This was referenced May 31, 2022

log: Add debug log category prefix #21058

Closed

scripted-diff: remove duplicate categories from LogPrint output #25286

Merged

klementtan mentioned this pull request Jun 6, 2022

logging: threshold log level #25287

Closed

ghost mentioned this pull request Jun 7, 2022

logging: remove duplicate categories from LogPrint output #25293

Closed

jonatack mentioned this pull request Jul 11, 2022

bench: add logging benchmarks for LogPrintLevel and LogPrintfCategory #25586

Closed

jonatack mentioned this pull request Aug 22, 2022

Severity-based logging, step 2 #25614

Merged

bitcoin locked and limited conversation to collaborators Aug 13, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logging: Add severity level to logs #24464

logging: Add severity level to logs #24464

klementtan commented Mar 2, 2022 •

edited

Loading

DrahtBot commented Mar 3, 2022 •

edited

Loading

luke-jr left a comment

jnewbery commented Mar 9, 2022

klementtan commented Mar 9, 2022

laanwj commented Apr 5, 2022

klementtan commented May 6, 2022 •

edited

Loading

laanwj May 9, 2022 •

edited

Loading

klementtan May 19, 2022

laanwj May 24, 2022 •

edited

Loading

laanwj commented May 24, 2022 •

edited

Loading

logging: Add severity level to logs #24464

logging: Add severity level to logs #24464

Conversation

klementtan commented Mar 2, 2022 • edited Loading

DrahtBot commented Mar 3, 2022 • edited Loading

Conflicts

luke-jr left a comment

Choose a reason for hiding this comment

jnewbery commented Mar 9, 2022

klementtan commented Mar 9, 2022

laanwj commented Apr 5, 2022

klementtan commented May 6, 2022 • edited Loading

laanwj May 9, 2022 • edited Loading

Choose a reason for hiding this comment

klementtan May 19, 2022

Choose a reason for hiding this comment

laanwj May 24, 2022 • edited Loading

Choose a reason for hiding this comment

laanwj commented May 24, 2022 • edited Loading

klementtan commented Mar 2, 2022 •

edited

Loading

DrahtBot commented Mar 3, 2022 •

edited

Loading

klementtan commented May 6, 2022 •

edited

Loading

laanwj May 9, 2022 •

edited

Loading

laanwj May 24, 2022 •

edited

Loading

laanwj commented May 24, 2022 •

edited

Loading