logging: Add severity level to logs

[klementtan]

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]

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

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

[jnewbery]

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]

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

[laanwj]

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.

[jonatack]

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

[jonatack]

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]

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]

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

[klementtan]

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]

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]

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.

[klementtan]

@jonatack @MarcoFalke thanks for the detailed review!

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

[laanwj]

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]

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]

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]

Code review and lightly tested ACK e11cdc9