log: Prefix log messages with function name and source code location if -logsourcelocations is set #19809

practicalswift · 2020-08-25T20:50:38Z

Prefix log messages with function name if -logfunctionnames is set.

Yes, exactly like -logthreadnames but for function names instead of thread names :)

This is a small developer ergonomics improvement: I've found this to be a cheap/simple way to correlate log output and originating function.

For me it beats the ordinary cycle of 1.) try to figure out a regexp matching the static part of the dynamic log message, 2.) git grep -E 'Using .* MiB out of .* requested for signature cache', 3.) mcedit filename.cpp (openemacs filename.cpp works too!) and 4.) search for log message and scroll up to find the function name :)

Without any logging parameters:

$ src/bitcoind -regtest
2020-08-25T03:29:04Z Using RdRand as an additional entropy source
2020-08-25T03:29:04Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2020-08-25T03:29:04Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2020-08-25T03:29:04Z Loaded best chain: hashBestChain=0fff88f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e22ff height=0 date=2011-02-02T23:16:42Z progress=1.000000
2020-08-25T03:29:04Z block tree size = 1
2020-08-25T03:29:04Z nBestHeight = 0
2020-08-25T03:29:04Z Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast
2020-08-25T03:29:04Z 0 addresses found from DNS seeds

With -logthreadnames and -logfunctionnames:

$ src/bitcoind -regtest -logthreadnames -logfunctionnames
2020-08-25T03:29:04Z [init] [ReportHardwareRand] Using RdRand as an additional entropy source
2020-08-25T03:29:04Z [init] [InitSignatureCache] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2020-08-25T03:29:04Z [init] [InitScriptExecutionCache] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2020-08-25T03:29:04Z [init] [LoadChainTip] Loaded best chain: hashBestChain=0fff88f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e22ff height=0 date=2011-02-02T23:16:42Z progress=1.000000
2020-08-25T03:29:04Z [init] [AppInitMain] block tree size = 1
2020-08-25T03:29:04Z [init] [AppInitMain] nBestHeight = 0
2020-08-25T03:29:04Z [loadblk] [LoadMempool] Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast
2020-08-25T03:29:04Z [dnsseed] [ThreadDNSAddressSeed] 0 addresses found from DNS seeds

DrahtBot · 2020-08-26T01:07:25Z

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

Log: Add debug log category tag #21102 (Log: Add debug log category tag by wodry)
Relog configuration args on debug.log rotation #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.

theStack · 2020-08-26T03:53:49Z

Concept ACK
(although I would suggest improving the PR description with s/mcedit/vim 😜)
Nice time-saving idea -- I think many core devs are familiar with your described cycle and could benefit from this.
After this gets into master, I suggest also passing it by default to nodes in the test framework.

laanwj · 2020-08-27T09:03:32Z

Concept ACK. After this we can start removing the explicit __func__ in logging calls, I guess, which is very inconsistently used.

promag

Concept ACK.

Use in test framework?

jamesob · 2020-09-01T01:16:48Z

Concept ACK, will review in the next few days

laanwj · 2020-09-01T12:54:29Z

Code review and tested ACK bd71653bfc312b10ca6b578b7c3accd0155b1a20
I think this is great for developers, but for the sake of not making default logging too wide / spammy I would prefer not to enable it by default (but it isn't in this PR).

Edit: I somewhat wonder how much larger this makes the executable. This adds a string for every function that has logging. I don't think it's too bad, but will test.
edit.2: the difference is negligible, these are stripped sizes:

-rwxrwxr-x 1 7.3M Sep  1 15:15 src/bitcoind
-rwxrwxr-x 1 7.4M Sep  1 14:59 src/bitcoind.19809

instagibbs · 2020-09-03T19:08:21Z

Ooh, concept ACK

instagibbs · 2020-09-03T19:11:14Z

Wouldn't hurt I think to have this active for a single test at least?

theStack

Tested ACK bd71653bfc312b10ca6b578b7c3accd0155b1a20 🧪
Note that in some cases the showed function name is quite generic and doesn't prevent the need for grepping contents of the message (as elaborated in the PR description), that is when LogPrint{f} is called in another logging wrapper function (e.g. WalletLogPrintf(...), Timer::Log(...) or ArgsManager::logArgsPrefix(...)).
Still an incredibly useful feature though that will save devs plenty of time in the future for sure!

sipa · 2020-09-15T21:34:33Z

It seems I'll be in a minority here, but I don't think this is very useful in the current form.

If the goal is to avoid the need for searching the source code to find where a message originated, it would be better to include file/line number instead of (or at least in addition to) the function name. Function names can be ambiguous, and do occasionally move from one file to another, so just that still means you need to grep the source code to find where the function is.

theStack · 2020-09-15T22:27:33Z

@sipa: Agreed that the PR doesn't eliminate the need to grep completely, but I think the main focus is to get rid of the burdensome part of figuring out what to grep in the first place (as expressed in the PR description "try to figure out a regexp matching the static part of the dynamic log message"). That can sometimes take quite some iterations or is not even possible at all of the log message is assembled in a highly dynamic way (i.e. lots of %s in the log format string).

Also, the function name grep is more effective as it not only shows you in which function the log is printed (single result), but also already at which places this function is declared/defined and called. For my purposes thats quite a lot of useful information about the causes of a log message after a single no-brainer grep considering I didn't even need to open a file yet at this point :)

That said, also showing file and line number can for sure also be helpful. Maybe via verbosity levels?

sipa · 2020-09-16T00:40:28Z

"try to figure out a regexp matching the static part of the dynamic log message"

That's a good point, I had missed this. I think it can be partially addressed with just better log messages, but this PR is a useful catch-all improvement with little code changes.

practicalswift · 2020-09-29T18:01:25Z

@instagibbs

Wouldn't hurt I think to have this active for a single test at least?

Now enabled for the unit tests and the functional tests.

@theStack

That said, also showing file and line number can for sure also be helpful. Maybe via verbosity levels?

I think that should be a separate option (-logsourcelocation perhaps?). However, that is out of scope for this PR.

test/functional/test_framework/test_node.py

theStack

ACK b0287dc4fa83e5d3c95edbf9bc120e222f9e1a22
Verified that since my last tested ACK, another commit has been added that activates the feature for unit tests, and for functional tests starting with 0.21.0 (minimum is set to 0.20.99 to also enable it on the master branch before the 0.21.0 release) 👌

practicalswift · 2020-12-01T12:53:16Z

Anything left to do here? :)

test/functional/test_framework/test_node.py

practicalswift · 2020-12-01T14:58:46Z

Rebased and bumped version check :)

jonasschnelli · 2020-12-01T19:18:33Z

Concept ACK

theStack

re-ACK 8cbeb9ec8650d6fe25afaae8b2a5f91aab00f2f7 🏞️

jnewbery · 2020-12-29T16:04:41Z

Concept ACK, if only to remove the __func__ and explicit function names in existing logs.

maflcko

ACK 8cbeb9ec8650d6fe25afaae8b2a5f91aab00f2f7

src/logging.h

src/init.cpp

ajtowns · 2021-01-14T09:32:05Z

This is a small developer ergonomics improvement: I've found this to be a cheap/simple way to correlate log output and originating function.

Wouldn't it be slightly better to also include the line number (or filename and line) as well then?

maflcko · 2021-01-14T09:59:53Z

@practicalswift Mind replying to the open questions in any way? Would be good to make progress here.

practicalswift · 2021-01-14T11:08:24Z

This is a small developer ergonomics improvement: I've found this to be a cheap/simple way to correlate log output and originating function.

Wouldn't it be slightly better to also include the line number (or filename and line) as well then?

Sure, that's a good idea but that would be out of scope for -logfunctionnames which this PR adds.

A follow-up PR can add say -logsourcelocation: I'd be glad to Concept ACK and review that :)

ajtowns · 2021-01-14T11:18:56Z

This is a small developer ergonomics improvement: I've found this to be a cheap/simple way to correlate log output and originating function.

Wouldn't it be slightly better to also include the line number (or filename and line) as well then?

Sure, that's a good idea but that would be out of scope for -logfunctionnames which this PR adds.

A follow-up PR can add say -logsourcelocation: I'd be glad to Concept ACK and review that :)

Having two options seems like overkill; why not make this one introduce -logsourcelocation which adds file/line/func to the logs? Don't feel particularly strongly either way, but grepping for "foo.cpp:123" does seem super easy.

maflcko · 2021-01-14T11:33:41Z

review ACK 9f5fc7eb55f8a19f6002f4cfe92e76c574ee8749

I am also ok with printing the file:line as well when -logfunctionnames is set.

practicalswift · 2021-01-14T12:04:23Z

@ajtowns

Having two options seems like overkill; why not make this one introduce -logsourcelocation which adds file/line/func to the logs

@MarcoFalke

I am also ok with printing the file:line as well when -logfunctionnames is set.

Being the very flexible person I am I have now added the file:line feature to satisfy the overwhelming public demand :)

Live demo:

$ src/bitcoind -regtest -logthreadnames -logfunctionnames
…
2021-01-14T12:34:56Z [init] [validation.cpp:4174] [LoadChainTip] Loaded best chain: hashBestChain=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 height=0 date=2011-02-02T23:16:42Z progress=1.000000

Please re-review! :)

maflcko · 2021-01-14T12:43:10Z

review ACK 09b974587ff90834c3559c15b3ab7d9489c65d65

ajtowns

ACK 09b974587ff90834c3559c15b3ab7d9489c65d65 -- minimal testing only

For functions defined in header files, I'm seeing these logged as

2021-01-15T06:44:32Z [./util/system.h:449] [TraceThread] torcontrol thread start

with a leading "./" -- might be due to us using #include <> which implies an include path search?

src/init.cpp

src/logging.cpp

btcslade

ACK 09b974587ff90834c3559c15b3ab7d9489c65d65

src/logging.cpp

… set

practicalswift · 2021-01-15T10:29:37Z

@ajtowns

Thanks for reviewing!

2021-01-15T06:44:32Z [./util/system.h:449] [TraceThread] torcontrol thread start

with a leading "./" -- might be due to us using #include <> which implies an include path search?

Now removing leading ./ which gives us:

2021-01-15T06:44:32Z [util/system.h:449] [TraceThread] torcontrol thread start

Please re-review :)

maflcko

review ACK b4511e2 🌃

Show signature and timestamp

Signature:

Timestamp of file with hash 1aea386739b0674d3af7837475dd6afb7545a269fc384634b14a41a5d3a0d80d -

laanwj · 2021-02-18T13:25:48Z

Code review ACK b4511e2

…source code location if -logsourcelocations is set b4511e2 log: Prefix log messages with function name if -logsourcelocations is set (practicalswift) Pull request description: Prefix log messages with function name if `-logfunctionnames` is set. Yes, exactly like `-logthreadnames` but for function names instead of thread names :) This is a small developer ergonomics improvement: I've found this to be a cheap/simple way to correlate log output and originating function. For me it beats the ordinary cycle of 1.) try to figure out a regexp matching the static part of the dynamic log message, 2.) `git grep -E 'Using .* MiB out of .* requested for signature cache'`, 3.) `mcedit filename.cpp` (`openemacs filename.cpp` works too!) and 4.) search for log message and scroll up to find the function name :) Without any logging parameters: ``` $ src/bitcoind -regtest 2020-08-25T03:29:04Z Using RdRand as an additional entropy source 2020-08-25T03:29:04Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 2020-08-25T03:29:04Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 2020-08-25T03:29:04Z Loaded best chain: hashBestChain=0fff88f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e22ff height=0 date=2011-02-02T23:16:42Z progress=1.000000 2020-08-25T03:29:04Z block tree size = 1 2020-08-25T03:29:04Z nBestHeight = 0 2020-08-25T03:29:04Z Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast 2020-08-25T03:29:04Z 0 addresses found from DNS seeds ``` With `-logthreadnames` and `-logfunctionnames`: ``` $ src/bitcoind -regtest -logthreadnames -logfunctionnames 2020-08-25T03:29:04Z [init] [ReportHardwareRand] Using RdRand as an additional entropy source 2020-08-25T03:29:04Z [init] [InitSignatureCache] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 2020-08-25T03:29:04Z [init] [InitScriptExecutionCache] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 2020-08-25T03:29:04Z [init] [LoadChainTip] Loaded best chain: hashBestChain=0fff88f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e22ff height=0 date=2011-02-02T23:16:42Z progress=1.000000 2020-08-25T03:29:04Z [init] [AppInitMain] block tree size = 1 2020-08-25T03:29:04Z [init] [AppInitMain] nBestHeight = 0 2020-08-25T03:29:04Z [loadblk] [LoadMempool] Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast 2020-08-25T03:29:04Z [dnsseed] [ThreadDNSAddressSeed] 0 addresses found from DNS seeds ``` ACKs for top commit: laanwj: Code review ACK b4511e2 MarcoFalke: review ACK b4511e2 🌃 Tree-SHA512: d100f5364630c323f31d275259864c597f7725e462d5f4bdedcc7033ea616d7fc0d16ef1b2af557e692f4deea73c6773ccfc681589e7bf6ba970b9ec169040c7

… set Summary: > Prefix log messages with function name if `-logfunctionnames` is set, exactly like `-logthreadnames but for function names instead of thread names. > > This is a small developer ergonomics improvement: I've found this to be a cheap/simple way to correlate log output and originating function. This is a backport of [[bitcoin/bitcoin#19809 | core#19809]] Test Plan: `ninja all check-all` Reviewers: #bitcoin_abc, Fabien Reviewed By: #bitcoin_abc, Fabien Differential Revision: https://reviews.bitcoinabc.org/D10951

DrahtBot added the Utils/log/libs label Aug 25, 2020

practicalswift mentioned this pull request Aug 26, 2020

Spurious CI failure: feature_block.py (s390x) #19811

Closed

DrahtBot mentioned this pull request Aug 26, 2020

Relog configuration args on debug.log rotation #16673

Closed

promag reviewed Sep 1, 2020

View reviewed changes

theStack approved these changes Sep 15, 2020

View reviewed changes

DrahtBot mentioned this pull request Sep 22, 2020

log: Mitigate disk filling attacks by temporarily rate limiting LogPrintf(…) #19995

Closed

practicalswift force-pushed the logfunctionnames branch from 4be7635 to 791facc Compare September 29, 2020 17:58

theStack reviewed Oct 11, 2020

View reviewed changes

test/functional/test_framework/test_node.py Outdated Show resolved Hide resolved

practicalswift force-pushed the logfunctionnames branch 2 times, most recently from b9a2c64 to b0287dc Compare October 13, 2020 13:31

theStack approved these changes Oct 13, 2020

View reviewed changes

maflcko reviewed Dec 1, 2020

View reviewed changes

test/functional/test_framework/test_node.py Outdated Show resolved Hide resolved

practicalswift force-pushed the logfunctionnames branch 2 times, most recently from 49487d3 to 8cbeb9e Compare December 1, 2020 14:57

maflcko mentioned this pull request Dec 2, 2020

Disable fee estimation in blocksonly mode (by removing the fee estimates global) #18766

Merged

theStack approved these changes Dec 29, 2020

View reviewed changes

maflcko reviewed Jan 5, 2021

View reviewed changes

src/logging.h Outdated Show resolved Hide resolved

src/init.cpp Outdated Show resolved Hide resolved

maflcko mentioned this pull request Jan 13, 2021

Cleanup of -debug=net log messages #20724

Merged

practicalswift force-pushed the logfunctionnames branch from 8cbeb9e to 9f5fc7e Compare January 14, 2021 11:07

ajtowns reviewed Jan 15, 2021

View reviewed changes

src/init.cpp Outdated Show resolved Hide resolved

src/logging.cpp Outdated Show resolved Hide resolved

btcslade reviewed Jan 15, 2021

View reviewed changes

src/logging.cpp Outdated Show resolved Hide resolved

log: Prefix log messages with function name if -logsourcelocations is…

b4511e2

… set

practicalswift force-pushed the logfunctionnames branch from 09b9745 to b4511e2 Compare January 15, 2021 10:02

practicalswift changed the title ~~log: Prefix log messages with function name if -logfunctionnames is set~~ log: Prefix log messages with function name and source code location if -logsourcelocations is set Jan 15, 2021

DrahtBot mentioned this pull request Feb 8, 2021

Log: Add debug log category tag #21102

Closed

maflcko approved these changes Feb 18, 2021

View reviewed changes

maflcko mentioned this pull request Feb 18, 2021

Net processing: Only call PushAddress() from net_processing #21187

Merged

laanwj merged commit b805dbb into bitcoin:master Feb 18, 2021

practicalswift deleted the logfunctionnames branch April 10, 2021 19:45

bitcoin locked as resolved and limited conversation to collaborators Aug 16, 2022

log: Prefix log messages with function name and source code location if -logsourcelocations is set #19809

log: Prefix log messages with function name and source code location if -logsourcelocations is set #19809

Uh oh!

Conversation

practicalswift commented Aug 25, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Aug 26, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

theStack commented Aug 26, 2020

Uh oh!

laanwj commented Aug 27, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

promag left a comment

Choose a reason for hiding this comment

Uh oh!

jamesob commented Sep 1, 2020

Uh oh!

laanwj commented Sep 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

instagibbs commented Sep 3, 2020

Uh oh!

instagibbs commented Sep 3, 2020

Uh oh!

theStack left a comment

Choose a reason for hiding this comment

Uh oh!

sipa commented Sep 15, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

theStack commented Sep 15, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sipa commented Sep 16, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

practicalswift commented Sep 29, 2020

Uh oh!

Uh oh!

theStack left a comment

Choose a reason for hiding this comment

Uh oh!

practicalswift commented Dec 1, 2020

Uh oh!

Uh oh!

practicalswift commented Dec 1, 2020

Uh oh!

jonasschnelli commented Dec 1, 2020

Uh oh!

theStack left a comment

Choose a reason for hiding this comment

Uh oh!

jnewbery commented Dec 29, 2020

Uh oh!

maflcko left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

ajtowns commented Jan 14, 2021

Uh oh!

maflcko commented Jan 14, 2021

Uh oh!

practicalswift commented Jan 14, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ajtowns commented Jan 14, 2021

Uh oh!

maflcko commented Jan 14, 2021

Uh oh!

practicalswift commented Jan 14, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented Jan 14, 2021

Uh oh!

ajtowns left a comment

practicalswift commented Aug 25, 2020 •

edited

Loading

DrahtBot commented Aug 26, 2020 •

edited

Loading

laanwj commented Aug 27, 2020 •

edited

Loading

laanwj commented Sep 1, 2020 •

edited

Loading

sipa commented Sep 15, 2020 •

edited

Loading

theStack commented Sep 15, 2020 •

edited

Loading

sipa commented Sep 16, 2020 •

edited

Loading

practicalswift commented Jan 14, 2021 •

edited

Loading

practicalswift commented Jan 14, 2021 •

edited

Loading