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

practicalswift commented at 8:50 pm on August 25, 2020: contributor

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:

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

With -logthreadnames and -logfunctionnames:

0$ src/bitcoind -regtest -logthreadnames -logfunctionnames
12020-08-25T03:29:04Z [init] [ReportHardwareRand] Using RdRand as an additional entropy source
22020-08-25T03:29:04Z [init] [InitSignatureCache] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
32020-08-25T03:29:04Z [init] [InitScriptExecutionCache] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
42020-08-25T03:29:04Z [init] [LoadChainTip] Loaded best chain: hashBestChain=0fff88f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e22ff height=0 date=2011-02-02T23:16:42Z progress=1.000000
52020-08-25T03:29:04Z [init] [AppInitMain] block tree size = 1
62020-08-25T03:29:04Z [init] [AppInitMain] nBestHeight = 0
72020-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
82020-08-25T03:29:04Z [dnsseed] [ThreadDNSAddressSeed] 0 addresses found from DNS seeds

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

DrahtBot commented at 1:07 am on August 26, 2020: 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:

#21102 (Log: Add debug log category tag by wodry)
#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 commented at 3:53 am on August 26, 2020: member

Concept ACK (although I would suggest improving the PR description with s/mcedit/vim :stuck_out_tongue_winking_eye:) 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 commented at 9:03 am on August 27, 2020: member

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

promag commented at 0:23 am on September 1, 2020: member

Concept ACK.

Use in test framework?

jamesob commented at 1:16 am on September 1, 2020: member

Concept ACK, will review in the next few days

laanwj commented at 12:54 pm on September 1, 2020: member

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:

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

instagibbs commented at 7:08 pm on September 3, 2020: member

Ooh, concept ACK

instagibbs commented at 7:11 pm on September 3, 2020: member

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

theStack approved

theStack commented at 8:55 pm on September 15, 2020: member

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 commented at 9:34 pm on September 15, 2020: member

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 commented at 10:27 pm on September 15, 2020: member

@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 commented at 0:40 am on September 16, 2020: member

“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 force-pushed on Sep 29, 2020

practicalswift commented at 6:01 pm on September 29, 2020: contributor

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

in test/functional/test_framework/test_node.py:116 in 791facc677 outdated

112@@ -113,6 +113,8 @@ def __init__(self, i, datadir, *, chain, rpchost, timewait, timeout_factor, bitc
113 
114         if self.version_is_at_least(190000):
115             self.args.append("-logthreadnames")
116+        if self.version_is_at_least(200000):

theStack commented at 4:45 pm on October 11, 2020:

v0.20.0 is already released and obviously doesn’t include this new feature that is not even merged on master.

0        if self.version_is_at_least(209900):

practicalswift commented at 1:30 pm on October 13, 2020:

Oh, thanks! Fix pushed.

practicalswift force-pushed on Oct 13, 2020

theStack approved

theStack commented at 1:54 pm on October 13, 2020: member

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 commented at 12:53 pm on December 1, 2020: contributor

Anything left to do here? :)

in test/functional/test_framework/test_node.py:116 in b0287dc4fa outdated

112@@ -113,6 +113,8 @@ def __init__(self, i, datadir, *, chain, rpchost, timewait, timeout_factor, bitc
113 
114         if self.version_is_at_least(190000):
115             self.args.append("-logthreadnames")
116+        if self.version_is_at_least(209900):

MarcoFalke commented at 1:00 pm on December 1, 2020:

needs rebase

practicalswift commented at 1:32 pm on December 1, 2020:

Thanks! Rebased! :)

MarcoFalke commented at 1:37 pm on December 1, 2020:

I tried to say that this is a silent merge conflict. The version needs to be adjusted with the rebase as well

practicalswift force-pushed on Dec 1, 2020

practicalswift commented at 2:58 pm on December 1, 2020: contributor

Rebased and bumped version check :)

jonasschnelli commented at 7:18 pm on December 1, 2020: contributor

Concept ACK

theStack approved

theStack commented at 11:17 am on December 29, 2020: member

re-ACK 8cbeb9ec8650d6fe25afaae8b2a5f91aab00f2f7 🏞️

jnewbery commented at 4:04 pm on December 29, 2020: member

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

in src/logging.h:189 in 8cbeb9ec86 outdated

186 // evaluating arguments when logging for the category is not enabled.
187 #define LogPrint(category, ...)              \
188     do {                                     \
189         if (LogAcceptCategory((category))) { \
190-            LogPrintf(__VA_ARGS__);          \
191+            LogPrintf_(__func__, __VA_ARGS__); \

MarcoFalke commented at 11:36 am on January 5, 2021:

Does this line need to be changed?

practicalswift commented at 11:07 am on January 14, 2021:

Good point. Fixed!

in src/init.cpp:882 in 8cbeb9ec86 outdated

878@@ -878,6 +879,7 @@ void InitLogging(const ArgsManager& args)
879 #ifdef HAVE_THREAD_LOCAL
880     LogInstance().m_log_threadnames = args.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
881 #endif
882+    LogInstance().m_log_functionnames = gArgs.GetBoolArg("-logfunctionnames", DEFAULT_LOGFUNCTIONNAMES);

MarcoFalke commented at 11:37 am on January 5, 2021:

0    LogInstance().m_log_functionnames = args.GetBoolArg("-logfunctionnames", DEFAULT_LOGFUNCTIONNAMES);

nit: Would be nice to not introduce more gArgs

practicalswift commented at 11:07 am on January 14, 2021:

Good point. Fixed!

MarcoFalke commented at 11:38 am on January 5, 2021: member

ACK 8cbeb9ec8650d6fe25afaae8b2a5f91aab00f2f7

ajtowns commented at 9:32 am on January 14, 2021: member

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?

MarcoFalke commented at 9:59 am on January 14, 2021: member

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

practicalswift force-pushed on Jan 14, 2021

practicalswift commented at 11:08 am on January 14, 2021: contributor

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 commented at 11:18 am on January 14, 2021: member

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.

MarcoFalke commented at 11:33 am on January 14, 2021: member

review ACK 9f5fc7eb55f8a19f6002f4cfe92e76c574ee8749

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

practicalswift commented at 12:04 pm on January 14, 2021: contributor

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

0$ src/bitcoind -regtest -logthreadnames -logfunctionnames
1…
22021-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! :)

MarcoFalke commented at 12:43 pm on January 14, 2021: member

review ACK 09b974587ff90834c3559c15b3ab7d9489c65d65

in src/init.cpp:535 in 09b974587f outdated

531@@ -532,6 +532,7 @@ void SetupServerArgs(NodeContext& node)
532 #else
533     hidden_args.emplace_back("-logthreadnames");
534 #endif
535+    argsman.AddArg("-logfunctionnames", strprintf("Prepend debug output with name of the originating function (default: %u)", DEFAULT_LOGFUNCTIONNAMES), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);

ajtowns commented at 6:46 am on January 15, 2021:

nit: I thought -logsourcelocation was a better name

practicalswift commented at 10:03 am on January 15, 2021:

Agreed! Now using -logsourcelocations. The plural suffix to be consistent with -logthreadnames.

in src/logging.cpp:247 in 09b974587f outdated

243     StdLockGuard scoped_lock(m_cs);
244     std::string str_prefixed = LogEscapeMessage(str);
245 
246+    if (m_log_functionnames && m_started_new_line) {
247+        str_prefixed.insert(0, "[" + source_file + ":" + ToString(source_line) + "] [" + logging_function + "] ");
248+    }

ajtowns commented at 6:47 am on January 15, 2021:

If I’d written it, I would have preferred [foo.cpp:123:Function()] vs [foo.cpp:123] [Function]

btcslade commented at 8:24 am on January 15, 2021:

Slight preference towards this style as well.

practicalswift commented at 10:06 am on January 15, 2021:

I tried with that, but I find the current version easier to parse.

As-is:

02021-01-15T10:00:03Z [init.cpp:1568] [AppInitMain] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
12021-01-15T10:00:03Z [noui.cpp:56] [noui_InitMessage] init message: Loading block index...                                                       
22021-01-15T10:00:03Z [validation.cpp:5171] [InitializeChainstate] Switching active chainstate to Chainstate [ibd] @ height -1 (null)
32021-01-15T10:00:03Z [dbwrapper.cpp:137] [CDBWrapper] Opening LevelDB in /root/.bitcoin/regtest/blocks/index
42021-01-15T10:00:03Z [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully

Alternative version suggested by @ajtowns:

02021-01-15T10:00:03Z [init.cpp:1568:AppInitMain] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
12021-01-15T10:00:03Z [noui.cpp:56:noui_InitMessage] init message: Loading block index...                                                       
22021-01-15T10:00:03Z [validation.cpp:5171:InitializeChainstate] Switching active chainstate to Chainstate [ibd] @ height -1 (null)
32021-01-15T10:00:03Z [dbwrapper.cpp:137:CDBWrapper] Opening LevelDB in /root/.bitcoin/regtest/blocks/index
42021-01-15T10:00:03Z [dbwrapper.cpp:141:CDBWrapper] Opened LevelDB successfully

I find the long […] blocks a bit heavy to parse TBH :)

Keeping as-is :)

ajtowns commented at 6:52 am on January 15, 2021: member

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?

btcslade commented at 8:26 am on January 15, 2021: none

ACK 09b974587ff90834c3559c15b3ab7d9489c65d65

log: Prefix log messages with function name if -logsourcelocations is set b4511e2e2e

practicalswift force-pushed on Jan 15, 2021

practicalswift commented at 10:29 am on January 15, 2021: contributor

@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 :)

practicalswift renamed this:
~~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
on Jan 15, 2021

MarcoFalke approved

MarcoFalke commented at 8:43 am on February 18, 2021: member

review ACK b4511e2e2ed1a6077ae6826a9ee6b7a311293d08 🌃

Signature:

 0-----BEGIN PGP SIGNED MESSAGE-----
 1Hash: SHA512
 2
 3review ACK b4511e2e2ed1a6077ae6826a9ee6b7a311293d08 🌃
 4-----BEGIN PGP SIGNATURE-----
 5
 6iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
 7pUgUpQv+KjsWdQmlTRct27nvZGqCCHtsB6PCiZiAO9uywglBEBu6cTsDnGsVnH3h
 8EyJYPc2a19PaY8MH8uocTrR7owPl7TgqaufvhFPWd63pkg6WLk3W9R+eot//mOFV
 9za90hjk8oexnnPxaREWqXLJh7qQxNwYhGirpOdQ+gId35a5y/qYPumaPN97oZTQg
107xU85Ik2V+kAdD7y/6qUfB82ZRlwjfirSl9MdctznaXsaQLuQoGbkSdoliZNdl8e
11D6xCplsSq7Sxy8cLnzpKHeX/7ouZTv/yeeLRD874kJX/CLzij2x5Pg7Hs2dnCT9f
12zoq8Nu1BR9O2hoRf7rKbJva4tZBOHUKdmDOeUX8ozkwmcA8U2YMBr0Y6QvZZJX8H
13QvDpkV513nUAj2BjjLxQOAkJAwi+hCcQu8LWJVN+BMD6iTZ6IJ0zJws8bdXCq4Fk
14ernWM0gjqDfpaDy4O3Ita+MQsKS9ylM5ojjMKBKG+XJdZiC8vqjbDq4cXPtJ9E1x
15HLVdMr8S
16=ezwm
17-----END PGP SIGNATURE-----

Timestamp of file with hash 1aea386739b0674d3af7837475dd6afb7545a269fc384634b14a41a5d3a0d80d -

laanwj commented at 1:25 pm on February 18, 2021: member

Code review ACK b4511e2e2ed1a6077ae6826a9ee6b7a311293d08

laanwj merged this on Feb 18, 2021

laanwj closed this on Feb 18, 2021

sidhujag referenced this in commit 8c5039108f on Feb 18, 2021

practicalswift deleted the branch on Apr 10, 2021

Fabcien referenced this in commit adaff8063b on Feb 2, 2022

DrahtBot locked this on Aug 16, 2022

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

Conflicts