On bitcoind startup, write config args to debug.log (utils/log/libs)

https://github.com/bitcoin/bitcoin/pulls/16115

Host: jnewbery  -  PR author: LarryRuane

Notes

  • Configuration options can either be specified in a config file or passed as command-line arguments to the bitcoind or bitcoin-qt executable.
  • Config file and command line configuration interact in complex ways. See PR 15934 for a full treatment of how configuration options are merged and parsed.
  • The configuration options affect node behaviour at runtime in various ways.
  • When debugging or troubleshooting node issues, it’s very useful to know what configuration was applied to the node, but that information is not always available.
  • This PR prints the config file and command line configuration to the debug.log file on startup.
  • The PR was later updated to also reprint configuration options when the log file rotates.

Questions

  • In a review comment, Carl Dong suggests that it’d be “very useful to have the effective command line configuration at-a-glance”. How does this differ from what has been implemented in this PR? Why would it be difficult to implement?
  • Reviewers asked the PR author to add a blacklist of configuration that shouldn’t be logged. The author implemented that here. What are your thoughts about that implementation of a blacklist?
  • What is Bitcoin Core log shrinking? Where is it implemented?
  • What is log rotation? How can it be used for Bitcoin Core logs?
  • What is the purpose of the second commit in this PR (re-log configuration when debug.log is reopened)? What are your thoughts about that additional functionality?
  • What tests are included in this PR? Could any additional tests be added?

Meeting Log

  113:00 <jnewbery> hi
  213:00 <nehan> hi
  313:00 <jkczyz> hi
  413:00 <lightlike> hello
  513:00 <ariard> hi
  613:00 <jnewbery> today's notes/questions are at: https://bitcoin-core-review-club.github.io/16115.html
  713:01 <jonatack> hi
  813:01 <jnewbery> jkczyz: I see you already left review comments. Great!
  913:01 <jnewbery> What were your overall thoughts on the PR?
 1013:02 <jnewbery> (open to anyone)
 1113:02 <digi_james> Hello
 1213:02 <jkczyz> Undecided if this is preferable to a command to print the args
 1313:03 <jnewbery> I think there's a PR that does that (RPC to print args) too
 1413:04 <jonatack> seems somewhat brittle, unfinished, and needs more test coverage
 1513:04 <jonatack> though good idea
 1613:04 <fjahr> Yeah, #15493 is the PR for print args
 1713:04 <jnewbery> jonatack: what part do you think is brittle
 1813:05 <jonatack> the blacklist part
 1913:05 <kanzure> hi
 2013:05 <jnewbery> fjahr: I don't think that's an RPC. That's a command line arg to pass to bitcoind
 2113:05 <michaelfolkson> I wasn't sure on the Concept ACK
 2213:05 <jnewbery> maybe 15493 was the one I was thinking of
 2313:06 <lightlike> certainly like the concept of writing the down this info. not sure if the second commit around rotating logs is needed (liked jkczyz comment about this).
 2413:06 <jnewbery> jkczyz: can you think of any advantage to logging to debug.log instead of an RPC?
 2513:06 <jonatack> jtczyz: yes, nice job on the review
 2613:07 <fjahr> jnewbery: that's the same number?
 2713:07 <jkczyz> jnewbery: Yeah, in cases where there is a crash under the given configuration
 2813:07 <jnewbery> fjahr: yes, I think I misremembered what that PR was doing
 2913:07 <fjahr> ah, got it
 3013:08 <jnewbery> jkczyz: right. Sometimes debug.log is all we've got. A user says "something strange happened" and we don't know what the config was
 3113:09 <michaelfolkson> But are we expecting them to give the whole debug.log from beginning to end? The config will be right at the start
 3213:09 <jnewbery> lighlike: yeah, I agree with your point about the second commit. It doesn't need to be bundled into the same PR
 3313:09 <michaelfolkson> Surely better to provide them separately
 3413:10 <jnewbery> michaelfolkson: (re: are we expecting them...) perhaps, but better to log somewhere than nowhere
 3513:10 <jnewbery> first question: in a review comment, Carl Dong suggests that it’d be “very useful to have the effective command line configuration at-a-glance”. How does this differ from what has been implemented in this PR? Why would it be difficult to implement?
 3613:11 <michaelfolkson> Provide two different logs? You only need the recent output to see what the problem was in the debug log
 3713:11 <nehan> i assumed he meant the values for all commandline arguments instead of just user-passed in ones
 3813:12 <jnewbery> nehan: that's part of it
 3913:12 <nehan> as promag points out that seems difficult because initialization happens all over the place
 4013:12 <jnewbery> all commandline args have default values. This PR doesn't print what those default values are if nothing is passed in explicitly
 4113:13 <jnewbery> there are also commandline args that interact with each other, so if one is set then it affects others
 4213:13 <jnewbery> eg https://github.com/bitcoin/bitcoin/blob/a7aa809027633556dd3280c6e29ca98eb3235a3d/src/init.cpp#L765
 4313:14 <jnewbery> nehan: yes, it's difficult because gArgs is accessed all over the code, and the actual values are only read/calculated where they're needed
 4413:14 <jnewbery> Next question: Reviewers asked the PR author to add a blacklist of configuration that shouldn’t be logged. The author implemented that here. What are your thoughts about that implementation of a blacklist?
 4513:15 <jnewbery> (here: https://github.com/bitcoin/bitcoin/pull/16115/files#diff-c9721a8bab21576f98fa79fda2715408R967)
 4613:15 <nehan> it would be easy for someone adding a sensitive argument to forget to update that blacklist
 4713:16 <jnewbery> nehan: I agree!
 4813:16 <nehan> i didn't look to see if there is a place in the code anyone adding an argument must update. if so, it would be good to add a comment there referencing the blacklist.
 4913:16 <jnewbery> any suggestions on a different implementation?
 5013:17 <jnewbery> nehan: good idea
 5113:17 <jonatack> a whitelist would be safer, though probably more involved
 5213:17 <jkczyz> Perhaps it could be built into the arg code. A bit saying if it should be blacklisted
 5313:17 <probably_dillon> a whitelist would suffer from the same "and what if someone forgets it?" problem
 5413:17 <fjahr> there should be a explicit declaration on each argument
 5513:17 <jnewbery> jonatack: yes. It suffers from the same problem (people forgetting to update it), but the impact is probably less bad
 5613:18 <jonatack> yes, not the same probable consequences
 5713:18 <fjahr> not when calling it, I mean as a type of something like taht in the code
 5813:18 <jnewbery> jkczyz,fjahr: yeah, perhaps a new 'sensitive data' flag could be added here: https://github.com/bitcoin/bitcoin/blob/a7aa809027633556dd3280c6e29ca98eb3235a3d/src/util/system.cpp#L542
 5913:19 <jnewbery> here's one existing flag: https://github.com/bitcoin/bitcoin/blob/a7aa809027633556dd3280c6e29ca98eb3235a3d/src/util/system.h#L138
 6013:20 <jnewbery> next question: What is Bitcoin Core log shrinking? Where is it implemented?
 6113:20 <nehan> ShrinkDebugFile() in logging.cpp
 6213:20 <jkczyz> Truncates start of log file if it grows too large (over 10MB * 110% = 11MB)
 6313:21 <michaelfolkson> Only on startup
 6413:21 <lightlike> called in init at startup (before logging anything else)
 6513:21 <jnewbery> nehan, jkczyz, michaelfolkson, lighlike: great answers :)
 6613:21 <jnewbery> any questions on what that's doing?
 6713:22 <michaelfolkson> What was the rationale for only shrinking on startup?
 6813:22 <jnewbery> If not, let's move on to the next question: What is log rotation? How can it be used for Bitcoin Core logs?
 6913:23 <michaelfolkson> Addresses problem of not shrinking the log after startup
 7013:23 <jkczyz> A tool for limiting the size of log files by breaking into multiple files
 7113:24 <jnewbery> fascinating. ShrinkDebugFile() was added by Satoshi: https://github.com/jnewbery/bitcoin/blob/0bbbee96b742e4ad0fd5e1d3c33e4bd2247e4445/util.cpp#L456
 7213:24 <jnewbery> jkczyz: right. Did you find where support for log rotation was added to bitcoin core?
 7313:25 <probably_dillon> is there something wrong with just relying a system's logrotate?
 7413:25 <jkczyz> jnewbery: I did not. Just assumed people used external tools for it
 7513:26 <jkczyz> jnewbery: I think I saw a PR where someone wanted to add it, though
 7613:26 <jnewbery> probably_dillon: that's exactly what happens. bitcoind does not rotate its own log files
 7713:26 <jnewbery> support for SIGHUP was added here: https://github.com/bitcoin/bitcoin/pull/917
 7813:26 <jnewbery> the PR author (LarryRuane) gives a good explanation of log rotation here: https://github.com/bitcoin/bitcoin/pull/16115#pullrequestreview-250179580
 7913:27 <jnewbery> External log rotation tools can be configured to prevent the log file from growing unbounded, see #917. Typically the way these tools work is, they first move (as in, the rename system call) debug.log to a different name....
 8013:27 <jnewbery> We've already addressed the next question, but any other thoughts about "What is the purpose of the second commit in this PR (re-log configuration when debug.log is reopened)? What are your thoughts about that additional functionality?"
 8113:28 <nehan> 1) 200 seems arbitrary 2) I think the logrotator should support saving the startup log instead of doing this
 8213:29 <jnewbery> nehan: I agree with both of those
 8313:29 <nehan> now someone has to think about whether or not to put information into this special re-log thing
 8413:30 <lightlike> I wonder if there are many users how use logrotate and delete the old logs immediately, so that writing the options down again is needed.
 8513:30 <probably_dillon> nehan: do you mean implementing this as a new "boot config log" log?
 8613:30 <jnewbery> I also didn't like the fact that the log timestamps are no longer monotonic after this PR
 8713:30 <jnewbery> That's probably going to confuse some log parsers
 8813:31 <nehan> probably_di: i don't think saving (or reprinting) initial log information should be handled in bitcoind
 8913:31 <jonatack> nehan: agreed. brittle.
 9013:32 <jkczyz> If args are logged at startup, it might be useful providing docs on how to configure the logrotate properly
 9113:33 <jnewbery> jkczyz: I agree that this is better addressed with documentation than adding complexity to the code. I don't know where exactly that documentation should live
 9213:34 <jnewbery> There is already precedence for including user tips in the /docs directory, eg: https://github.com/bitcoin/bitcoin/blob/master/doc/reduce-memory.md
 9313:34 <jnewbery> ok, final question: What tests are included in this PR? Could any additional tests be added?
 9413:35 <jonatack> The PR includes one functional test that launches a node, passing one blacklisted arg and one whitelisted arg, and verifies they are in the debug log with the blacklisted arg as ****.
 9513:35 <fjahr> a functional test that is called unit test in the commit message
 9613:35 <jkczyz> could include a test for blacklisted args with '-regtest.' or other such prefixes
 9713:35 <jonatack> For one, I'd like to see some edge cases tested as well.
 9813:36 <michaelfolkson> Such as?
 9913:36 <jonatack> such as jkczyz's suggestion
10013:37 <probably_dillon> testing the whole blacklist seems prudent.
10113:37 <jonatack> probably
10213:37 <jonatack> probably_dillon: yes
10313:38 <lightlike> the commit message is wrong ("unit test"), should be functional
10413:39 <jnewbery> this also seems like a good candidate for unit tests, since the new functionality is in a single class (ArgsManager)
10513:39 <jnewbery> There are already units tests for ArgsManager, eg https://github.com/bitcoin/bitcoin/blob/master/src/test/getarg_tests.cpp
10613:39 <jonatack> Unit tests for the code changes would be nice, too, esp the blacklist
10713:39 <jnewbery> ok, that's all I had. Did anyone else have any remaining questions/comments they wanted to bring up?
10813:40 <lightlike> (sorry, missed comment by fjahr)
10913:40 <michaelfolkson> If you were to use a sensitive flag you could run a test to ensure the flag catches all entries
11013:40 <michaelfolkson> What are your thoughts on how this PR should progress @jnewbery? Suggest the flag on the PR?
11113:41 <jkczyz> michaelfolkson: Was goind to say the same :)
11213:41 <michaelfolkson> Or keep it in documentation?
11313:41 <jnewbery> michaelfolkson: My main piece of feedback is: split the PR in two. No need to bundle two changes in the same PR
11413:41 <michaelfolkson> Or continue improving the PR as designed?
11513:41 <jnewbery> I'm a concept ACK on the first commit, but a weak concept NACK on the second
11613:42 <nehan> when i ran this, my debug.log had the following: 2019-08-14T15:56:58Z Warning: Unsupported logging category -debug=cmdline1.
11713:42 <nehan> i couldn't track down why that was happening. do you know?
11813:43 <jnewbery> the `-debug` argument takes one or more logging categories. cmdline1 is not a valid logging category
11913:43 <nehan> ok, thanks. it wasn't in the log mentioned in https://github.com/bitcoin/bitcoin/pull/16115#issue-283090468
12013:43 <jnewbery> the log came from here: https://github.com/bitcoin/bitcoin/blob/a7aa809027633556dd3280c6e29ca98eb3235a3d/src/init.cpp#L1005
12113:43 <jnewbery> I suspect you'd see the same thing on master
12213:44 <jnewbery> any other questions?
12313:45 <michaelfolkson> I have a question on the config. As a first time user I agonized over what in the config file I could change later and what I needed to get right before installing. Should this be made clearer?
12413:45 <jnewbery> what do you mean 'before installing'?
12513:45 <michaelfolkson> Some choices can't be reversed eg testnet choice, once pruned can't unprune
12613:46 <michaelfolkson> Other choices can be changed later eg which nodes you connect to
12713:46 <michaelfolkson> I don't know how many fit in that first category, probably not many
12813:46 <jonatack> michaelfolkson: before IBD?
12913:46 <michaelfolkson> Sorry yes
13013:46 <jonatack> that seems like a great question
13113:47 <jnewbery> Yeah, I'm not sure. I think `bitcoind --help` should probably give you the information you need. If you think the help text is lacking, then you should open a PR to improve it.
13213:47 <fjahr> you could do both on the same machine using the same bitcoind, with a different datadir
13313:47 <jnewbery> There's also this, that might help you: https://jlopp.github.io/bitcoin-core-config-generator/
13413:47 <jnewbery> (repo here: https://github.com/jlopp/bitcoin-core-config-generator)
13513:48 <michaelfolkson> Yeah that is helpful. Doesn't address this currently
13613:48 <michaelfolkson> That's good suggestion <fjahr>
13713:48 <jonatack> maybe an initial node setup doc in the /doc dir
13813:48 <wumpus> -prune and -txindex are probably the only options that you want to be sure to get right before ibd because they take quite some time to switch around
13913:49 <jnewbery> wumpus: I think -txindex is much better now that it happens in a background thread (it can be switched on and off)
14013:49 <wumpus> prune because it throws away blocks, txindex because it's a huge amont of work to build the index
14113:49 <michaelfolkson> Cool, thanks. I remember it really slowed me down because I didn't want to make wrong choices that weren't easily reversible
14213:50 <jnewbery> I think prune is the important one
14313:50 <wumpus> jnewbery: it's definitely become better
14413:50 <jnewbery> any final questions, or are people happy to wrap it up there?
14513:50 <wumpus> still txindex can take quite a long time too. that it happens in the background doesn't make it faster :)
14613:50 <jonatack> michaelfolkson: this state of mind can be precious for adding docs
14713:51 <jonatack> initial perspective
14813:51 <jnewbery> wumpus: yeah, it's still slow, but at least you don't have to reindex to add it, which I think was the case before
14913:51 <michaelfolkson> Yeah should take advantage of it whilst I still have it ;)
15013:52 <jnewbery> lots of great questions this week. Thanks everyone (and thanks wumpus for stopping by!)
15113:52 <jnewbery> Here's your homework for next week:
15213:52 <michaelfolkson> Yeah, was great. Thanks everyone
15313:53 <jnewbery> - review https://bitcoin-core-review-club.github.io/15931.html. I'll try to get notes and questions up in the next couple of days
15413:53 <jnewbery> - leave comments on this week's PR (https://github.com/bitcoin/bitcoin/pull/16115)
15513:53 <jnewbery> - take a look through the open PRs (either https://github.com/bitcoin/bitcoin/pulls or https://bitcoinacks.com/), and see if there are any you think would be interesting for us to discuss
15613:54 <jnewbery> I'm still waiting for my first comment in here: https://github.com/bitcoin-core-review-club/bitcoin-core-review-club.github.io/issues/14 :)
15713:54 <jnewbery> that's it. Thanks everyone!
15813:54 <fjahr> thanks jnewbery
15913:54 <wumpus> jnewbery: true, it used to be that even removing the index took a full reindex, at least removing it should be fast now !
16013:54 <wumpus> yes thanks everyone
16113:55 <lightlike> thanks!
16213:55 <michaelfolkson> Ah it is an issue <jnewbery>. I was looking for that a couple of weeks ago haha
16313:55 <jkczyz> yeah, good session!
16413:55 <jonatack> jnewbery, wumpus: thanks! ... thanks, everyone!
16513:55 <fanquake> That PSBT shuffle inputs PR will be a good one.
16613:55 <nehan> thanks!