logging: Add severity level to logs

klementtan commented at 5:27 pm on March 2, 2022: contributor

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:

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

0$ grep "net:debug" debug.log
1
22022-03-04T16:41:15Z [opencon] [net:debug] trying connection XXX:YYY lastseen=2.7hrs
32022-03-04T16:41:16Z [opencon] [net:debug] trying connection XXX:YYY lastseen=16.9hrs
42022-03-04T16:41:17Z [opencon] [net:debug] trying connection XXX:YYY lastseen=93.2hrs
52022-03-04T16:41:18Z [opencon] [net:debug] trying connection XXX:YYY lastseen=2.7hrs

klementtan force-pushed on Mar 2, 2022

DrahtBot added the label Tests on Mar 2, 2022

klementtan force-pushed on Mar 3, 2022

DrahtBot commented at 2:45 am on March 3, 2022: contributor

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.

klementtan force-pushed on Mar 3, 2022

klementtan force-pushed on Mar 4, 2022

luke-jr commented at 1:41 am on March 8, 2022: member

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 commented at 12:01 pm on March 9, 2022: member

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 force-pushed on Mar 9, 2022

klementtan commented at 3:36 pm on March 9, 2022: contributor

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

in doc/release-notes.md:63 in a0b8904767 outdated

56@@ -57,6 +57,11 @@ Notable changes
57 Example item
58 ------------
59 
60+Tools and Utilities
61+-------------------
62+
63+- Allow logging with severity level and display it with the category name. (#24464)

MarcoFalke commented at 4:37 pm on March 16, 2022:

As it is not clear that this pull will be merged quickly, maybe move the 5 lines to a separate file, per the instructions in https://github.com/bitcoin/bitcoin/blob/master/doc/developer-notes.md#release-notes ?

klementtan commented at 5:09 pm on March 16, 2022:

Done 👍🏻

klementtan force-pushed on Mar 16, 2022

laanwj commented at 2:27 pm on April 5, 2022: member

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.

laanwj added the label Utils/log/libs on Apr 14, 2022

laanwj removed the label Tests on Apr 14, 2022

in src/logging.h:69 in 4444a6ba3d outdated

64@@ -65,6 +65,13 @@ namespace BCLog {
65         BLOCKSTORE  = (1 << 26),
66         ALL         = ~(uint32_t)0,
67     };
68+    enum class Level {
69+        None = 0,

laanwj commented at 7:03 am on April 14, 2022:

What does level “None” mean? Is it the highest or lowest log level? This ordering will matter when we want to add, say, a priority floor per category.

klementtan commented at 10:10 am on April 18, 2022:

What does level “None” mean?

I used None to signify that the log is an existing log that does not have any severity level.

Is it the highest or lowest log level? This ordering will matter when we want to add, say, a priority floor per category.

Yup, you’re right! Setting None to the lowest level will cause problems when we want to implement a priority floor.

Updated the severity level of None to just above Debug. None is currently set to level 1 (second lowest level).

laanwj commented at 11:44 am on May 4, 2022:

Thanks. I guess it’s a temporary worry until all log messages have an explicit level.

klementtan force-pushed on Apr 18, 2022

in src/logging.cpp:134 in df62ac8f49 outdated

131@@ -131,7 +132,6 @@ struct CLogCategoryDesc {
132     BCLog::LogFlags flag;
133     std::string category;
134 };
135-

MarcoFalke commented at 10:11 am on May 3, 2022:

nit?

klementtan commented at 9:03 am on May 4, 2022:

Done 👍🏻

in src/logging.cpp:314 in df62ac8f49 outdated

310+            s += ":";
311+        }
312+
313+        if (level != Level::None) {
314+            auto it = LevelStr.find(level);
315+            if (it != LevelStr.end()) s += it->second;

MarcoFalke commented at 10:15 am on May 3, 2022:

Wouldn’t it be better to do the enum-class -> string conversion with a compile-time checked switch-case instead of an unordered map?

klementtan commented at 9:05 am on May 4, 2022:

Yup, you’re right. Updated the PR to replace the unordered map with a helper function that uses a switch-case to return the string conversion.

in src/logging.cpp:195 in df62ac8f49 outdated

190+    {BCLog::Level::Debug, "debug"},
191+    {BCLog::Level::Warning, "warning"},
192+    {BCLog::Level::Error, "error"},
193+};
194+
195+const std::unordered_map<BCLog::LogFlags, std::string> LogFlagStr{

MarcoFalke commented at 10:21 am on May 3, 2022:

nit: Maybe name this LogCategoryStr, as flags (combined categories) are ignored?

klementtan commented at 9:05 am on May 4, 2022:

Done 👍🏻 . Replaced this unordered map with a helper function and named it LogCategoryToStr

in src/logging.cpp:329 in df62ac8f49 outdated

325@@ -262,6 +326,7 @@ void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& loggi
326         str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] ");
327     }
328 
329+

MarcoFalke commented at 10:21 am on May 3, 2022:

nit?

klementtan commented at 9:06 am on May 4, 2022:

Done 👍🏻

in src/logging.h:115 in df62ac8f49 outdated

111@@ -105,7 +112,7 @@ namespace BCLog {
112         std::atomic<bool> m_reopen_file{false};
113 
114         /** Send a string to the log output */
115-        void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line);
116+        void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level);

MarcoFalke commented at 10:22 am on May 3, 2022:

Maybe name flag->category to clarify that flags can’t be set?

klementtan commented at 9:07 am on May 4, 2022:

Done 👍🏻

in src/test/logging_tests.cpp:5 in df62ac8f49 outdated

1@@ -2,16 +2,55 @@
2 // Distributed under the MIT software license, see the accompanying
3 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
4 
5+#include <chrono>

MarcoFalke commented at 10:23 am on May 3, 2022:

Why move this include?

klementtan commented at 9:07 am on May 4, 2022:

My bad! Reverted this move of #include <chrono>

MarcoFalke approved

klementtan force-pushed on May 4, 2022

in src/logging.cpp:346 in 3a355136cf outdated

342     StdLockGuard scoped_lock(m_cs);
343     std::string str_prefixed = LogEscapeMessage(str);
344 
345+    if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) {
346+        std::string s;
347+        s += "[";

jonatack commented at 11:03 am on May 5, 2022:

suggestion

0-        std::string s;
1-        s += "[";
2+        std::string s{"["};

and if you feel like touching it:

0 bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
1 {
2-    if (str == "") {
3+    if (str.empty()) {

klementtan commented at 4:14 am on May 6, 2022:

Done 👍🏻

in src/logging.cpp:206 in 3a355136cf outdated

201+        return "none";
202+    }
203+
204+}
205+
206+std::string LogCategoryToStr(const BCLog::LogFlags& category)

jonatack commented at 11:04 am on May 5, 2022:

It would be good to consistently pass both LogFlags and Level in this pull either by (non-const) value or by reference to const, but not both. See https://isocpp.github.io/CppCoreGuidelines/CppCoreGuidelines#Rf-in.

jonatack commented at 1:45 pm on May 5, 2022:

I wonder at what point it makes sense to have an array of category strings and use a size_t cast of LogFlags as an index (i.e. like static constexpr std::array NETWORKS{"ipv4", "ipv6", "onion", "i2p", "cjdns"}; in bitcoin-cli.cpp)

klementtan commented at 4:27 am on May 6, 2022:

Thanks for the reference! Updated this pull to pass both LogFlags and Level by value.

klementtan commented at 5:13 am on May 6, 2022:

I wonder at what point it makes sense to have an array of category strings and use a size_t cast of LogFlags as an index @jonatack We chose switch-case as it provides us with a compile-time warning. Additionally, IMO for large enums, switch-cases are easier to review as compared to checking the index of the elements against the enum value.

However, I do agree that this function could easily become bloated but I am not sure what is the best solution for it.

jonatack commented at 3:07 pm on May 9, 2022:

Yes, I was musing more about performance as this code can be called frequently and an array lookup is constant time; maybe you can use the existing CLogCategoryDesc.

klementtan commented at 1:03 pm on May 19, 2022:

Do you have any suggestions on how we should map the enums to the index on the array? Currently, the majority enums values of LogFlags are bit flags (ie 1<<i) and the enum values of LogFlags::NONE and LogFlags::ALL are 0 and all bits sets respectively.

in doc/release-notes-24464.md:7 in 3a355136cf outdated

0@@ -0,0 +1,8 @@
1+Notable changes
2+===============
3+
4+Tools and Utilities
5+-------------------
6+
7+- Allow logging with severity level and display it with the category name. (#24464)

jonatack commented at 11:09 am on May 5, 2022:

Not sure, but a release note doesn’t seem needed until severity level is a user-facing choice.

klementtan commented at 4:27 am on May 6, 2022:

Agreed, removed this commit 👍🏻

in src/logging.cpp:342 in 3a355136cf outdated

340+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)
341 {
342     StdLockGuard scoped_lock(m_cs);
343     std::string str_prefixed = LogEscapeMessage(str);
344 
345+    if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) {

jonatack commented at 11:18 am on May 5, 2022:

pico-nit, maybe something like

 0     StdLockGuard scoped_lock(m_cs);
 1     std::string str_prefixed = LogEscapeMessage(str);
 2+    const bool both_not_none{category != LogFlags::NONE && level != Level::None};
 3 
 4-    if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) {
 5+    if (both_not_none && m_started_new_line) {
 6 
 7         if (category != LogFlags::NONE) {
 8             s += LogCategoryToStr(category);
 9         }
10 
11-        if (category != LogFlags::NONE && level != Level::None) {
12+        if (both_not_none) {
13             // Only add separator if both flag and level are not NONE
14             s += ":";
15         }

klementtan commented at 4:34 am on May 6, 2022:

I don’t think I can cleanly refractor the conditions as they are different. The first if checks that either category is not none or level is not none but the second if checks that both category and level are not none.

jonatack commented at 4:54 am on May 6, 2022:

Oops! was blind there, sorry 👓

jonatack commented at 11:32 am on May 5, 2022: contributor

Lightly tested approach ACK, this seems like a good base.

in src/logging.cpp:200 in 3a355136cf outdated

195+        return "info";
196+    case BCLog::Level::Warning:
197+        return "warning";
198+    case BCLog::Level::Error:
199+        return "error";
200+    default:

MarcoFalke commented at 1:48 pm on May 5, 2022:

the default case will disable the compiler warning (see dev notes)

klementtan commented at 4:35 am on May 6, 2022:

Thanks for catching it! Replaced the default case with an assert(false)

in src/logging.cpp:270 in 3a355136cf outdated

265+    case BCLog::LogFlags::BLOCKSTORE:
266+        return "blockstore";
267+    case BCLog::LogFlags::ALL:
268+        return "all";
269+    default:
270+        return "none";

MarcoFalke commented at 1:49 pm on May 5, 2022:

I don’t think this is true. UTIL | BLOCKSTORE isn’t "none".

klementtan commented at 5:00 am on May 6, 2022:

Replaced the default case with assert(false) 👍🏻

klementtan force-pushed on May 6, 2022

klementtan commented at 5:14 am on May 6, 2022: contributor

@jonatack @MarcoFalke thanks for the detailed review!

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

MarcoFalke added this to the milestone 24.0 on May 6, 2022

in src/logging.cpp:208 in 2f83557953 outdated

202+}
203+
204+std::string LogCategoryToStr(BCLog::LogFlags category)
205+{
206+    switch (category) {
207+    case BCLog::LogFlags::NONE:

laanwj commented at 2:30 pm on May 9, 2022:

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.

klementtan commented at 1:00 pm on May 19, 2022:

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.

laanwj commented at 3:32 pm on May 24, 2022:

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.

klementtan force-pushed on May 19, 2022

logging: Add severity level to logs. a8290649a6

logging: Add log severity level to net.cpp e11cdc9303

klementtan force-pushed on May 19, 2022

laanwj commented at 5:28 pm on May 24, 2022: member

Code review and lightly tested ACK e11cdc930375eaec8d737e116138b2f2018c099f

laanwj merged this on May 24, 2022

laanwj closed this on May 24, 2022

jonatack referenced this in commit 73d430d2b9 on May 24, 2022

klementtan deleted the branch on May 25, 2022

laanwj referenced this in commit 4901631dac on May 26, 2022

MarcoFalke referenced this in commit 77e125c486 on May 27, 2022

sidhujag referenced this in commit 2f111e0cd8 on May 28, 2022

sidhujag referenced this in commit a29dd98719 on May 28, 2022

MarcoFalke referenced this in commit 45d8b1e94a on Jun 7, 2022

bitcoin locked this on Aug 13, 2023

logging: Add severity level to logs #24464

Conflicts