Log: Add debug log category tag #21102

pull ghost wants to merge 3 commits into bitcoin:master from changing 10 files +82 −41
  1. ghost commented at 4:16 pm on February 7, 2021: none

    Fixes #21058

    As the LogPrint macro takes the debug log category as parameter, I think it would be nice to have that debug log category also shown together with the according debug log message, to have clear transparency what debug message belongs to what debug category. In the past, people inserted the same debug log category name in the message itself, e.g. torcontrol.cpp: LogPrint(BCLog::TOR, "tor: SAFECOOKIE authentication challenge successful\n"); With this patch, this would be obsolete, and I would be willing to create a follow-up PR to cleanup that redundancy those then-redundant in-message categories are removed. Here is a log example how the log looks with this patch and debug=1:

     02021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=index, before=0.0MiB, after=0.0MiB
     12021-02-07T15:45:55Z [bench] FlushStateToDisk: write block index to disk completed (12.27ms)
     22021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (69 coins, 11kB) started
     32021-02-07T15:45:55Z [coindb] Writing final batch of 0.00 MiB
     42021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=chainstate, before=0.0MiB, after=0.0MiB
     52021-02-07T15:45:55Z [coindb] Committed 0 changed transaction outputs (out of 69) to coin database...
     62021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (69 coins, 11kB) completed (0.00s)
     72021-02-07T15:45:55Z [validation] Enqueuing ChainStateFlushed: block hash=0000000000000025d3499369d144977b6266bac92837748dc452e84cd05bc007
     82021-02-07T15:45:55Z [validation] ChainStateFlushed: block hash=0000000000000025d3499369d144977b6266bac92837748dc452e84cd05bc007
     92021-02-07T15:45:55Z [bench] FlushStateToDisk: write block and undo data to disk started
    102021-02-07T15:45:55Z [bench] FlushStateToDisk: write block and undo data to disk completed (15.44ms)
    112021-02-07T15:45:55Z [bench] FlushStateToDisk: write block index to disk started
    122021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=index, before=0.0MiB, after=0.0MiB
    132021-02-07T15:45:55Z [bench] FlushStateToDisk: write block index to disk completed (8.10ms)
    142021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
    152021-02-07T15:45:55Z [coindb] Writing final batch of 0.00 MiB
    162021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=chainstate, before=0.0MiB, after=0.0MiB
    172021-02-07T15:45:55Z [coindb] Committed 0 changed transaction outputs (out of 0) to coin database...
    182021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
    192021-02-07T15:45:55Z [validation] Enqueuing ChainStateFlushed: block hash=0000000000000025d3499369d144977b6266bac92837748dc452e84cd05bc007
    202021-02-07T15:45:55Z Shutdown: done
    212021-02-07T15:45:55Z [qt] GUI: shutdown : Shutdown finished
    

    I tested also with setting debug=addrman and it works, only debug log messages of category addrman are logged then, with the prefix. I think this is a step for the better and there is no drawback. I think there should be a better logging with pairing of log category and log level (e.g. like in Tor log), but that should be out of the scope of this PR. I have read the developer notes, and because of section “Source code organization” I extra included the #include <map> in logging.cpp allthough it was not needed to successfully compile.

    Unfortunately, I am no C++ expert and I guess there are chances that the places/scope of the definitions may be not optimal. Any help for doing better is appreciated. I saw the need to clone the function LogCategoryPrintf because I had not seen a way to change __VA_ARGS__ to insert the log category string in the beginning of the first (format string) parameter. I have allowed edits by maintainers, too, your are welcome to edit.

  2. Log debug log category 48ddbfd839
  3. fanquake added the label Utils/log/libs on Feb 8, 2021
  4. fanquake commented at 3:30 am on February 8, 2021: member

    and there is no drawback.

    Things to consider:

    If on by default this will likely break some existing log parsing tools.

    Our wallet logs it’s name using [], which means we can already have log output like the following:

    02021-02-08T02:55:14Z [test] Wallet File Version = 169900
    12021-02-08T02:55:14Z [test] Keys: 2018 plaintext, 0 encrypted, 2018 w/ metadata, 2018 total. Unknown wallet records: 0
    

    With this change, wallet names can be misinterpreted as a logging category.

    and I would be willing to create a follow-up PR to cleanup that redundancy.

    I think those changes should just be part of this PR. For anyone running with logthreadnames this change is going to result in output like the following:

    02021-02-08T02:34:43Z [init] [http] Starting HTTP server
    12021-02-08T02:34:43Z [init] HTTP: starting 4 worker threads
    22021-02-08T02:34:43Z [http] [http] Entering http event loop
    3...
    42021-02-08T02:34:54Z [torcontrol] [tor] tor: Error connecting to Tor control socket
    52021-02-08T02:34:54Z [torcontrol] [tor] tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
    
  5. DrahtBot commented at 5:59 am on February 8, 2021: 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:

    • #19809 (log: Prefix log messages with function name and source code location if -logsourcelocations is set by practicalswift)
    • #19358 (torcontrol : avoid to set wrong outbound proxy and network settings when creating an inbound onion service. by Saibato)

    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.

  6. ghost commented at 8:20 am on February 8, 2021: none

    and I would be willing to create a follow-up PR to cleanup that redundancy.

    I think those changes should just be part of this PR.

    Done, added a scripted-diff commit.

  7. ghost commented at 10:14 am on February 8, 2021: none

    Thanks, I was not aware of logthreadnames and that after the log category prefix there can be inserted another prefix afterwards at the beginning. When #19809 would be merged, there could be a third prefix as I understand, and the position of a “prefix” would not be predictable. I wonder if “prefix” would then be the right word anymore. Maybe this could be seen more like a “log tag” then? Then the log tag which this PR is about could be [lc:<log category>] (lc as abbreviation for log category), e.g.

    2021-02-07T15:45:55Z [lc:coindb] Writing final batch of 0.00 MiB

    and with logthreadnames=1 e.g.

    2021-02-08T02:34:54Z [torcontrol] [lc:tor] Error connecting to Tor control socket

    I would be fine with that.

    Offtopic of this PR, just an idea: Learning that there are more tags, I came to the idea if maybe the logged thread name and function name(as of #19809) could have also a log tag prefix, e.g. [tn:<thread name>] and [fn:<function name>], [fl:<file name+line>].

  8. scripted-diff: Remove debug log category prefix from log messages
    -BEGIN VERIFY SCRIPT-
    sed -i --regexp-extended -e 's/(BCLog::(NET|TOR|MEMPOOL|HTTP|BENCH|ZMQ|WALLETDB|RPC|ESTIMATEFEE|ADDRMAN|SELECTCOINS|REINDEX|CMPCTBLOCK|RAND|PRUNE|PROXY|MEMPOOLREJ|LIBEVENT|COINDB|QT|LEVELDB|VALIDATION)\s*,\s*")\s*\2\s*:\s*(.*)/\1\3/gi' $(git ls-files src/)
    -END VERIFY SCRIPT-
    c586cabd7a
  9. unknown renamed this:
    Log debug log category
    Log: Add debug log category tag
    on Feb 8, 2021
  10. tag [lc:category] instead of [category] 555dbfbfa7
  11. ghost commented at 10:25 pm on February 8, 2021: none

    Log looks now like this with logthreadnames=1:

    02021-02-08T22:22:30Z [torcontrol] [lc:tor] Error connecting to Tor control socket
    12021-02-08T22:22:30Z [torcontrol] [lc:tor] Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
    22021-02-08T22:22:31Z [msghand] [lc:addrman] Added 58 addresses from 209.166.10.82: 88 tried, 31277 new
    
  12. DrahtBot added the label Needs rebase on Feb 18, 2021
  13. DrahtBot commented at 2:15 pm on February 18, 2021: member

    🐙 This pull request conflicts with the target branch and needs rebase.

    Want to unsubscribe from rebase notifications on this pull request? Just convert this pull request to a “draft”.

  14. ghost commented at 6:24 pm on February 18, 2021: none
    Closing due to need for rebase and no further feedback.
  15. unknown closed this on Feb 18, 2021

  16. DrahtBot locked this on Aug 16, 2022

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-07-03 13:13 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me