Skip to content

Conversation

ghost
Copy link

@ghost ghost commented Feb 7, 2021

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:

2021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=index, before=0.0MiB, after=0.0MiB
2021-02-07T15:45:55Z [bench] FlushStateToDisk: write block index to disk completed (12.27ms)
2021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (69 coins, 11kB) started
2021-02-07T15:45:55Z [coindb] Writing final batch of 0.00 MiB
2021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=chainstate, before=0.0MiB, after=0.0MiB
2021-02-07T15:45:55Z [coindb] Committed 0 changed transaction outputs (out of 69) to coin database...
2021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (69 coins, 11kB) completed (0.00s)
2021-02-07T15:45:55Z [validation] Enqueuing ChainStateFlushed: block hash=0000000000000025d3499369d144977b6266bac92837748dc452e84cd05bc007
2021-02-07T15:45:55Z [validation] ChainStateFlushed: block hash=0000000000000025d3499369d144977b6266bac92837748dc452e84cd05bc007
2021-02-07T15:45:55Z [bench] FlushStateToDisk: write block and undo data to disk started
2021-02-07T15:45:55Z [bench] FlushStateToDisk: write block and undo data to disk completed (15.44ms)
2021-02-07T15:45:55Z [bench] FlushStateToDisk: write block index to disk started
2021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=index, before=0.0MiB, after=0.0MiB
2021-02-07T15:45:55Z [bench] FlushStateToDisk: write block index to disk completed (8.10ms)
2021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
2021-02-07T15:45:55Z [coindb] Writing final batch of 0.00 MiB
2021-02-07T15:45:55Z [leveldb] WriteBatch memory usage: db=chainstate, before=0.0MiB, after=0.0MiB
2021-02-07T15:45:55Z [coindb] Committed 0 changed transaction outputs (out of 0) to coin database...
2021-02-07T15:45:55Z FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
2021-02-07T15:45:55Z [validation] Enqueuing ChainStateFlushed: block hash=0000000000000025d3499369d144977b6266bac92837748dc452e84cd05bc007
2021-02-07T15:45:55Z Shutdown: done
2021-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.

@fanquake
Copy link
Member

fanquake commented Feb 8, 2021

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:

2021-02-08T02:55:14Z [test] Wallet File Version = 169900
2021-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:

2021-02-08T02:34:43Z [init] [http] Starting HTTP server
2021-02-08T02:34:43Z [init] HTTP: starting 4 worker threads
2021-02-08T02:34:43Z [http] [http] Entering http event loop
...
2021-02-08T02:34:54Z [torcontrol] [tor] tor: Error connecting to Tor control socket
2021-02-08T02:34:54Z [torcontrol] [tor] tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect

@DrahtBot
Copy link
Contributor

DrahtBot commented Feb 8, 2021

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

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.

@ghost
Copy link
Author

ghost commented Feb 8, 2021

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.

@ghost
Copy link
Author

ghost commented Feb 8, 2021

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>].

-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-
@ghost ghost changed the title Log debug log category Log: Add debug log category tag Feb 8, 2021
@ghost
Copy link
Author

ghost commented Feb 8, 2021

Log looks now like this with logthreadnames=1:

2021-02-08T22:22:30Z [torcontrol] [lc:tor] Error connecting to Tor control socket
2021-02-08T22:22:30Z [torcontrol] [lc:tor] Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
2021-02-08T22:22:31Z [msghand] [lc:addrman] Added 58 addresses from 209.166.10.82: 88 tried, 31277 new

@DrahtBot
Copy link
Contributor

🐙 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".

@ghost
Copy link
Author

ghost commented Feb 18, 2021

Closing due to need for rebase and no further feedback.

@ghost ghost closed this Feb 18, 2021
@bitcoin bitcoin locked as resolved and limited conversation to collaborators Aug 16, 2022
This pull request was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

log: Add debug log category prefix
2 participants