debug.log after something goes wrong, it’s often useful to know the exact options the failing instance of bitcoind was started with. Sometimes the debug.log file is all that’s available for the analysis. This PR logs the bitcoin.conf entries and command-line arguments to debug.log on startup.
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
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.
Knowing the startup parameters for debug purposes is certainly helpful. Unsure about logging rpcpassword (maybe add a blacklist?).
Yepp. Agree this is very useful for troubleshooting, but be careful with logging sensitive information (people do post these things to the internet sometimes).
963@@ -964,6 +964,20 @@ std::string ArgsManager::GetChainName() const
964 return CBaseChainParams::MAIN;
965 }
966
967+void ArgsManager::LogArgs() const
968+{
969+ for (const auto arg: m_config_args) {
Accessing m_config_args requires holding cs_args.
Also: use const reference to avoid copying. The const reference comment applies also for the for loops below.
969+ for (const auto arg: m_config_args) {
970+ for (const auto value: arg.second) {
971+ LogPrintf("config-file arg: %s=%s\n", arg.first, value);
972+ }
973+ }
974+ for (const auto arg: m_override_args) {
m_override_args requires holding cs_args :-)
Thank all of you for the good comments! Force-pushed (since this PR is so small) to address all review comments. I added a blacklist, but please verify that it contains the correct items. I tested this manually, bitcoin.conf contains:
0debug=1
1debug=xxx
2torpassword=hellotor
and then I ran bitcoind --debug=cmdline111 --rpcuser=hellouser and the following appeared in debug.log:
02019-05-30T15:31:29Z config-file arg: -debug=1
12019-05-30T15:31:29Z config-file arg: -debug=xxx
22019-05-30T15:31:29Z config-file arg: -torpassword=****
32019-05-30T15:31:29Z command-line arg: -debug=cmdline111
42019-05-30T15:31:29Z command-line arg: -rpcuser=****
52019-05-30T15:31:29Z command-line arg: -server=1
963@@ -964,6 +964,31 @@ std::string ArgsManager::GetChainName() const
964 return CBaseChainParams::MAIN;
965 }
966
967+void ArgsManager::LogArgs() const
@ryanofsky You might have some thoughts on this?
I don’t object to this change, but it does seems a little unusual to write the config file to the debug log. Especially when you have to mask passwords and such.
For debugging purposes, my preferred alternative would be to have a -printconfig flag (similar to existing -help or -version flags) that would print the current settings in ini format. This could be more convenient for debugging because you’d be able to parse the config and get instant feedback without having to bring the daemon up and down. I was also thinking about this as a way of implementing A.J’s suggestion from #15935 (comment) to help debug dynamic settings (“viewing/exporting the current dynamic settings […], so you can paste them into your bitcoin.conf”)
Concept ACK, but found two issues.
02019-06-11T22:57:43Z config-file arg: -regtest.rpcpassword=123456abcdef
12019-06-11T22:57:43Z config-file arg: -regtest.rpcuser=bitcoinrpc
22019-06-11T22:57:43Z config-file arg: -rpcpassword=****
32019-06-11T22:57:43Z config-file arg: -rpcuser=****
42019-06-11T22:57:43Z config-file arg: -server=1
52019-06-11T22:57:43Z config-file arg: -test.bind=127.0.0.1
62019-06-11T22:57:43Z config-file arg: -test.prune=1000
72019-06-11T22:57:43Z command-line arg: -testnet=
@dongcarl that’s a bigger change. Basically all default values are defined when the arg is used, so what you want would require to duplicate all of that or move the defaults to one place elsewhere. I don’t think debug log should have all args but maybe we could add an option to control that.
In #15493 I propose to add a RPC to also see effective arg values.
= off if there are no value arguments, because I didn’t want to assume that having no values would always be the same as =1.
I just noticed this PR is incomplete. To provide a little background for those not very familiar with the logging code: The client shrinks debug.log upon startup if it’s larger than a moderate size (11 MB), preserving the most recent 10 MB. This happens only at startup, so if bitcoind runs for a long time, and happens to do a lot of logging, the log file can become enormous.
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. Because the client has an open file handle to this file, it continues to log to it even though it’s been moved. Then the log rotation tool sends the client a SIGHUP signal to cause it to close its file descriptor and reopen debug.log. Now it’s actually creating a new debug.log file, and future logging goes there. No data are lost during this switch. The log rotation tool can now do whatever it wants with the renamed (old) log file. It may compress it, offload it, or, either immediately or after some time, delete it.
If it deletes it, the configuration information that this PR causes to be logged during startup no longer exists anywhere.
The latest commit, https://github.com/bitcoin/bitcoin/pull/16115/commits/df891038ccce1ea15d2cabcd6717acf60ca9e9ee, re-logs the configuration information whendebug.log is reopened. This guarantees that debug.log always contains the configuration messages. My first idea was to re-log only the configuration file and command line arguments (that are being written by the first part of this PR). But there’s a lot of other useful stuff that gets logged at just after startup. Here’s what appears in debug.log during my testing, after it’s reopened (this does not appear on the console):
02019-06-15T05:38:03Z Logging: start relogging initial messages
12019-06-15T05:37:09Z Bitcoin Core version v0.18.99.0-df891038c (release build)
22019-06-15T05:37:09Z Assuming ancestors of block 0000000000000037a8cd3e06cd5edbfe9dd1dbcc5dacab279376ef7cfc2b4c75 have valid signatures.
32019-06-15T05:37:09Z Setting nMinimumChainWork=00000000000000000000000000000000000000000000007dbe94253893cbd463
42019-06-15T05:37:09Z Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
52019-06-15T05:37:09Z Using RdSeed as additional entropy source
62019-06-15T05:37:09Z Using RdRand as an additional entropy source
72019-06-15T05:37:09Z Default data directory /home/larry/.bitcoin
82019-06-15T05:37:09Z Using data directory /home/larry/.bitcoin/testnet3
92019-06-15T05:37:09Z Config file: /home/larry/.bitcoin/bitcoin.conf
102019-06-15T05:37:09Z config-file arg: -testnet=1
112019-06-15T05:37:09Z command-line arg: -server=1
122019-06-15T05:37:09Z Using at most 125 automatic connections (1024 file descriptors available)
132019-06-15T05:37:09Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
142019-06-15T05:37:10Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
152019-06-15T05:37:10Z Using 4 threads for script verification
162019-06-15T05:37:10Z No wallet support compiled in!
172019-06-15T05:37:10Z scheduler thread start
182019-06-15T05:37:10Z HTTP: creating work queue of depth 16
192019-06-15T05:37:10Z No rpcpassword set - using random cookie authentication.
202019-06-15T05:37:10Z Generated RPC authentication cookie /home/larry/.bitcoin/testnet3/.cookie
212019-06-15T05:37:10Z HTTP: starting 4 worker threads
222019-06-15T05:37:10Z init message: Loading banlist...
232019-06-15T05:37:10Z Cache configuration:
242019-06-15T05:37:10Z * Using 2.0 MiB for block index database
252019-06-15T05:37:10Z * Using 8.0 MiB for chain state database
262019-06-15T05:37:10Z * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
272019-06-15T05:38:03Z Logging: end relogging initial messages
282019-06-15T05:38:03Z UpdateTip: new best=0000000000000046799df07296169b65f1a203c13b22ffe6df812454ca1e6e45 height=1382445 version=0x20000000 log2_work=71.151478 tx=27610552 date='2018-08-09T15:30:58Z' progress=0.622489 cache=1.6MiB(12574txo)
292019-06-15T05:38:03Z UpdateTip: new best=000000000000007cdf5e7a5a62f116cad1bb1ba492df4c8aef6b2f9a56075d9f height=1382446 version=0x20000000 log2_work=71.151519 tx=27611112 date='2018-08-09T15:31:47Z' progress=0.622494 cache=1.6MiB(12585txo)
30[.....]
It’s great to know the exact version number, that this client doesn’t include a wallet, and other configuration things. Note the two “extra” lines that begin with Logging: to show the start and end of this re-logging. The timestamps of the re-logged messages are the original timestamps from when the client actually started (in this case only about a minute earlier); out-of-order timestamps are a little odd, but on the other hand it’s nice to know when the client actually started. After the Logging: end relogging initial messages line, the logging continues where it left off before the file reopen (I was doing reindex at the time).
977+ LogPrintf("%s %s\n", prefix, arg.first);
978+ continue;
979+ }
980+ std::string v = value;
981+ for (const auto& b : blacklist) {
982+ if (arg.first.find(b) != std::string::npos) {
During the PR review club session, it came up that a flag could be added for sensitive args.
https://github.com/bitcoin/bitcoin/blob/a7aa809027633556dd3280c6e29ca98eb3235a3d/src/util/system.h#L138 https://github.com/bitcoin/bitcoin/blob/a7aa809027633556dd3280c6e29ca98eb3235a3d/src/util/system.cpp#L542
Then rather than maintaining a blacklist, the flag could be checked before logging.
296@@ -297,6 +297,12 @@ class ArgsManager
297 * Return ArgsManager::NONE for unknown arg.
298 */
299 unsigned int FlagsOfKnownArg(const std::string& key) const;
300+
301+ /**
302+ * During startup, LogPrintf() the config file options and
A couple nits:
These will help keep the documentation in sync with the code as it changes.
81@@ -82,10 +82,23 @@ def test_log_buffer(self):
82 self.start_node(0, extra_args=['-noconnect=0'])
83 self.stop_node(0)
84
85+ def test_args_log(self):
86+ with self.nodes[0].assert_debug_log(expected_msgs=[
87+ 'command-line arg: -addnode=some.node',
88+ 'command-line arg: -torpassword=****',
-regtest.)?
Also during the PR review club, it was suggested to update ArgsManager’s unit tests rather than using a functional test.
https://github.com/bitcoin/bitcoin/blob/master/src/test/getarg_tests.cpp
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
renamesystem call)debug.logto a different name. Because the client has an open file handle to this file, it continues to log to it even though it’s been moved. Then the log rotation tool sends the client aSIGHUPsignal to cause it to close its file descriptor and reopendebug.log. Now it’s actually creating a newdebug.logfile, and future logging goes there. No data are lost during this switch. The log rotation tool can now do whatever it wants with the renamed (old) log file. It may compress it, offload it, or, after some time, delete it.If it deletes it, the configuration information that this PR causes to be logged during startup no longer exists anywhere.
The latest commit, df89103, re-logs the configuration information when
debug.logis reopened. This guarantees thatdebug.logalways contains the configuration messages. My first idea was to re-log only the configuration file and command line arguments (that are being written by the first part of this PR). But there’s a lot of other useful stuff that gets logged at just after startup. Here’s what appears indebug.logduring my testing, after it’s reopened (this does not appear on the console):
There’s quite a bit of complexity added to the code to handle this case (e.g. the additional logic in BCLog::Logger::LogPrintStr and the fact m_relog_save is modified across different functions).
In practice, how often does this situation arise and where the missing information would have been helpful? Would it be reasonable for users to configure their log rotation tools to preserve the first log file instead?
245 m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
246
247+ // While the system is initializing, save some reasonable number
248+ // of (configuration-related) log messages for re-logging when
249+ // the log file rotates (gets reopened).
250+ if (m_relog_save && m_msgs_relog.size() < 200) {
I think this PR should be split in two. The two commits on startup, write config options to debug.log and re-log configuration when debug.log is reopened both address logging, but are essentially independent.
I’m a concept ACK for the first commit (on startup, write config options to debug.log) and would like to see it merged, but a weak concept NACK on the second (re-log configuration when debug.log is reopened) since I think it adds unnecessary complexity to the bitcoind code for something that should really be handled externally.
958@@ -959,6 +959,43 @@ std::string ArgsManager::GetChainName() const
959 return CBaseChainParams::MAIN;
960 }
961
962+static void logArgs(
963+ const std::string& prefix,
964+ const std::map<std::string, std::vector<std::string>>& args)
965+{
966+ // don't log passwords and other sensitive values
967+ static const std::string blacklist[] = {
Short of refactoring this PR to use a flag as suggested elsewhere and during the PR Review Club (log here);
97+ ]):
98 self.start_node(0, extra_args=[
99 '-addnode=some.node',
100- '-torpassword=mypass',
101+ '-torpassword=torpassword',
102 ])
debug.log are indeed not logged. I wanted to add test the full list of what should not be logged (torpassword, rpcauth, rpcbind, rpcpassword, rpcuser), but specifying any of those except torpassword on the command line causes the test framework to fail ("Error: no RPC connection), so I couldn’t think of a way to test that the logging of those is suppressed. I think this test is still useful, however, because it’s pretty easy to see in init.cpp that torpassword is treated the same as the others (namely, that they all include ArgsManager::DONT_LOG).
DONT_LOG cases and your change to pass only the values to unexpected_messages makes it even better. The only thing I regret is having suggested “satoshi” as the rpcuser because it pollutes git grepping; a name that isn’t already used by the codebase like “charlie” or “abc123”, etc., would have been better.
Thanks for all the review feedback! The most recent force-push removes the second part of this PR (the extra logging that happens when the log rotates). I agree with @narula’s and others’ opinions that this can be handled outside of bitcoind. I will probably submit a separate PR for relogging the config information on log rotation.
A good way for the log rotation tools to work is to either save all the log files (which may not be practical), or, when rotating the log file, check to see if the file being rotated out includes the start of the currently-running bitcoind instance (it could search for the string Bitcoin Core version). If found, keep the file, or at least that section of the file. Then remember to send that part to a developer or support person requesting debug.log. (It’s that “remember” part that makes me wonder if relogging on log rotation might still be a good idea.)
An additional thought related to this part of my most recent comment:
Then remember to send that part to a developer or support person requesting
debug.log
Here’s a better procedure that the log rotation tool can follow: After moving debug.log to a new name, it can create a new debug.log file and write the initial (configuration-related) messages to it. Then send the SIGHUP signal. The next log message will be appended to debug.log – after the initial messages. (I verified this behavior.)
974+ if (FlagsOfKnownArg(arg.first) & DONT_LOG)
975+ continue;
976+ for (auto& value : arg.second) {
977+ if (value.empty()) {
978+ LogPrintf("%s %s\n", prefix, arg.first);
979+ continue;
continue, it would be more natural to use an else clause.
970+ const std::string& prefix,
971+ const std::map<std::string, std::vector<std::string>>& args) const
972+{
973+ for (const auto& arg : args) {
974+ if (FlagsOfKnownArg(arg.first) & DONT_LOG)
975+ continue;
@jkczyz, thanks, adding a flag is an excellent idea, implemented in b6e55d5. Does that also address your concern about matching a substring? It seems to me it does, since we’re not doing any string or pattern matching at all.
Yeah, looks like FlagsOfKnownArg handles this for you.
306@@ -307,7 +307,9 @@ def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT):
307 wait_until(self.is_node_stopped, timeout=timeout)
308
309 @contextlib.contextmanager
310- def assert_debug_log(self, expected_msgs, unexpected_msgs=[], timeout=2):
311+ def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
312+ if unexpected_msgs is None:
313+ unexpected_msgs = []
972+{
973+ for (const auto& arg : args) {
974+ for (auto& value : arg.second) {
975+ if (value.empty()) {
976+ LogPrintf("%s %s\n", prefix, arg.first);
977+ } else {
To give you a little better understanding of what this PR does, here’s part of the debug.log file after running one of the functional (python) tests with the -nocleanup option. After the most recent rebase, the config file section string gets printed out (within square brackets):
02019-11-18T22:47:48.371866Z [init] Default data directory /home/larry/.bitcoin
12019-11-18T22:47:48.371882Z [init] Using data directory /tmp/bitcoin_func_test_z99aclji/node0/regtest
22019-11-18T22:47:48.371901Z [init] Config file: /tmp/bitcoin_func_test_z99aclji/node0/bitcoin.conf
32019-11-18T22:47:48.371922Z [init] config-file arg: regtest=1
42019-11-18T22:47:48.371937Z [init] config-file arg: [regtest] bind=127.0.0.1
52019-11-18T22:47:48.371950Z [init] config-file arg: [regtest] discover=0
62019-11-18T22:47:48.371963Z [init] config-file arg: [regtest] dnsseed=0
72019-11-18T22:47:48.371976Z [init] config-file arg: [regtest] fallbackfee=0.0002
82019-11-18T22:47:48.371990Z [init] config-file arg: [regtest] keypool=1
92019-11-18T22:47:48.372002Z [init] config-file arg: [regtest] listenonion=0
102019-11-18T22:47:48.372015Z [init] config-file arg: [regtest] port=14243
112019-11-18T22:47:48.372031Z [init] config-file arg: [regtest] printtoconsole=0
122019-11-18T22:47:48.372049Z [init] config-file arg: [regtest] rpcport=19243
132019-11-18T22:47:48.372072Z [init] config-file arg: [regtest] server=1
142019-11-18T22:47:48.372088Z [init] config-file arg: [regtest] shrinkdebugfile=0
152019-11-18T22:47:48.372106Z [init] config-file arg: [regtest] upnp=0
162019-11-18T22:47:48.372119Z [init] command-line arg: datadir=/tmp/bitcoin_func_test_z99aclji/node0
172019-11-18T22:47:48.372135Z [init] command-line arg: debug
182019-11-18T22:47:48.372150Z [init] command-line arg: debugexclude=libevent
192019-11-18T22:47:48.372165Z [init] command-line arg: debugexclude=leveldb
202019-11-18T22:47:48.372179Z [init] command-line arg: logthreadnames
212019-11-18T22:47:48.372194Z [init] command-line arg: logtimemicros
222019-11-18T22:47:48.372209Z [init] command-line arg: uacomment=testnode0
232019-11-18T22:47:48.372223Z [init] command-line arg: wallet=0
242019-11-18T22:47:48.372236Z [init] Using at most 125 automatic connections (1024 file descriptors available)
It actually could be useful to have this information available when trying to debug or analyze a functional test or the code being tested (although you can figure it out if you study the code enough), because some of these values differ across the tests.
891+ if (valueStr.size()) {
892+ LogPrintf("%s %s%s=%s\n", prefix, sectionStr, arg.first, valueStr);
893+ } else {
894+ LogPrintf("%s %s%s\n", prefix, sectionStr, arg.first);
895+ }
896+ }
In commit “merge with ‘Deduplicate settings’ commit” (d95fdc78c965708866156898588221a8d983396f)
Would suggest:
0if (FlagsOfKnownArg(arg.first) & DONT_LOG) {
1 LogPrintf("%s %s%s=****\n", prefix, sectionStr, arg.first);
2} else {
3 LogPrintf("%s %s%s=%s\n", prefix, sectionStr, arg.first, value.write());
4}
This is simpler than formatting code in the PR, more future proof, and also less ambiguous about negated options.
Would also suggest squashing commits.
@ryanofsky, thanks, I like that much better. I implemented your suggestion (with a small difference, only a single call to LogPrintf()), rebased, squashed, force-pushed (eb973ff916f88ed36b59ae6466ec16dd30811215). The formatting is slightly different now, but I like that the code is much simpler and the output is more consistent (this is from one of the functional tests):
02019-11-26T16:09:54.048744Z [init] config-file arg: regtest="1"
12019-11-26T16:09:54.048755Z [init] config-file arg: [regtest] bind="127.0.0.1"
22019-11-26T16:09:54.048765Z [init] config-file arg: [regtest] discover="0"
32019-11-26T16:09:54.048774Z [init] config-file arg: [regtest] dnsseed="0"
42019-11-26T16:09:54.048784Z [init] config-file arg: [regtest] fallbackfee="0.0002"
52019-11-26T16:09:54.048793Z [init] config-file arg: [regtest] keypool="1"
62019-11-26T16:09:54.048802Z [init] config-file arg: [regtest] listenonion="0"
72019-11-26T16:09:54.048812Z [init] config-file arg: [regtest] port="11068"
82019-11-26T16:09:54.048822Z [init] config-file arg: [regtest] printtoconsole="0"
92019-11-26T16:09:54.048833Z [init] config-file arg: [regtest] rpcport="16068"
102019-11-26T16:09:54.048843Z [init] config-file arg: [regtest] server="1"
112019-11-26T16:09:54.048854Z [init] config-file arg: [regtest] shrinkdebugfile="0"
122019-11-26T16:09:54.048865Z [init] config-file arg: [regtest] upnp="0"
132019-11-26T16:09:54.048874Z [init] command-line arg: datadir="/tmp/bitcoin_func_test_wmar_kd1/node0"
142019-11-26T16:09:54.048884Z [init] command-line arg: debug=""
152019-11-26T16:09:54.048895Z [init] command-line arg: debugexclude="libevent"
162019-11-26T16:09:54.048904Z [init] command-line arg: debugexclude="leveldb"
172019-11-26T16:09:54.048914Z [init] command-line arg: logthreadnames=""
182019-11-26T16:09:54.048924Z [init] command-line arg: logtimemicros=""
192019-11-26T16:09:54.048934Z [init] command-line arg: uacomment="testnode0"
I like the way negative arguments are displayed; as you say, they are less ambiguous. There are no examples of such from above, but I ran src/bitcoind -noreindex and the following appears in debug.log:
02019-11-26T17:00:24Z command-line arg: reindex=false
I added a unit test for this too. Thank you for taking the time to review!
873@@ -874,6 +874,29 @@ std::string ArgsManager::GetChainName() const
874 return GetArg("-chain", CBaseChainParams::MAIN);
875 }
876
877+void ArgsManager::logArgsPrefix(
878+ const std::string& prefix,
879+ const std::string& section,
880+ const std::map<std::string, std::vector<util::SettingsValue>>& args) const
881+{
882+ std::string sectionStr = section.empty() ? "" : "[" + section + "] ";
In commit “on startup, write config options to debug.log” (eb973ff916f88ed36b59ae6466ec16dd30811215)
sectionStr is an older convention for variable names. Newer code is using section_str https://github.com/bitcoin/bitcoin/blob/master/doc/developer-notes.md#coding-style-c
Code review ACK eb973ff916f88ed36b59ae6466ec16dd30811215. Looks good!
I don’t know how to write an automated test for these changes, suggestions are welcome.
Could remove this line from the PR description since there are tests now.
882+
883+void ArgsManager::LogArgs() const
884+{
885+ LOCK(cs_args);
886+ for (const auto& section : m_settings.ro_config) {
887+ logArgsPrefix("config-file arg:", section.first, section.second);
884+{
885+ LOCK(cs_args);
886+ for (const auto& section : m_settings.ro_config) {
887+ logArgsPrefix("config-file arg:", section.first, section.second);
888+ }
889+ logArgsPrefix("command-line arg:", "", m_settings.command_line_options);
I’ll squash after review (or, at least before merge)
It is better to squash before review as a merge commit should contain ACKs with the latest commit hash.
Tested ACK 3028a27c5fde8e341cccb743b31a02c1bd7d934d
I’ve left a couple of small style nit. Feel free to ignore.
Code review ACK 4a88ddac84235398a0ea8c041baee7192a6b4d09
Rebased onto master …
I don’t think this needed rebasing on master. It’s better not to rebase on master unless necessary, since it generates additional work for reviewers
I don’t think this needed rebasing on master. It’s better not to rebase on master unless necessary, since it generates additional work for reviewers
Absolutely right, sorry about that; I actually thought of that just after I did that. I’ll avoid unnecessary rebases from now on. Thanks for the new ACK.
ACK 4a88ddac84235398a0ea8c041baee7192a6b4d09, I have tested the code on Linux Mint 19.3, including:
bitcoin.confbitcoin.conf and in the command lineEvery time it works as expected.
@ryanofsky : current branch is 4a88dda
Thanks fixed comment. That was the hash I meant
297@@ -298,7 +298,9 @@ def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT):
298 wait_until(self.is_node_stopped, timeout=timeout)
299
300 @contextlib.contextmanager
301- def assert_debug_log(self, expected_msgs, timeout=2):
302+ def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
303+ if unexpected_msgs is None:
304+ unexpected_msgs = []
Can simplify?
0- def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
1- if unexpected_msgs is None:
2- unexpected_msgs = []
3+ def assert_debug_log(self, expected_msgs, unexpected_msgs=[], timeout=2):
None as the default argument instead of a mutable default arg: https://docs.python-guide.org/writing/gotchas/#what-you-should-do-instead
82@@ -83,10 +83,28 @@ def test_log_buffer(self):
83 self.start_node(0, extra_args=['-noconnect=0'])
84 self.stop_node(0)
85
86+ def test_args_log(self):
Could use a docstring or logging here, e.g.
0+ self.log.info('Test config args logging')
That said, the whole file is lacking logging, not just this test, so feel free to ignore.
94+ unexpected_msgs=[
95+ 'torpassword=torpassword',
96+ ]):
97+ self.start_node(0, extra_args=[
98+ '-addnode=some.node',
99+ '-torpassword=torpassword',
This test can be improved with (tested change):
0 expected_msgs=[
1 'Command-line arg: addnode="some.node"',
2+ 'Command-line arg: rpcauth=****',
3+ 'Command-line arg: rpcbind=****',
4+ 'Command-line arg: rpcpassword=****',
5+ 'Command-line arg: rpcuser=****',
6 'Command-line arg: torpassword=****',
7 'Config file arg: regtest="1"',
8 'Config file arg: [regtest] server="1"',
9 ],
10 unexpected_msgs=[
11+ 'rpcauth=alice:f7efda5c189b999524f151318c0c86$d5b51b3beffbc0',
12+ 'rpcbind=127.1.1.1',
13+ 'rpcuser=satoshi',
14 'torpassword=torpassword',
15 ]):
16 self.start_node(0, extra_args=[
17 '-addnode=some.node',
18+ '-rpcauth=alice:f7efda5c189b999524f151318c0c86$d5b51b3beffbc0',
19+ '-rpcbind=127.1.1.1',
20+ '-rpcpassword=',
21+ '-rpcuser=satoshi',
22 '-torpassword=torpassword',
rpcuser=satoshi to just satoshi. The reason is, if there was a weird bug by which the log contained (let’s say) ruser=satoshi or rpcuser = satoshi (note the spaces around =) or many other variants, this test would still pass. What we really care about is not leaking the values of these settings (the string satoshi) to the log file, so those values are what we should make sure aren’t present in the log file.
… force-pushed (without rebasing onto master)…
Needless rebasing makes reviewing of consequent changes harder ;) Thank you.
feature_config_args.py test, tested locally on Linux Mint 19.3.
194+
195+ // Log the arguments to debug.log
196+ gArgs.LogArgs();
197+
198+ // Open and read debug.log.
199+ FILE* file = fsbridge::fopen(LogInstance().m_file_path, "rb");
Should #include <fs.h> be explicitly added to this file? Other code and unit tests using fsbridge seem to include it, and according to developer-notes.md:
0- Every `.cpp` and `.h` file should `#include` every header file it directly uses classes, functions or other
1 definitions from, even if those headers are already included indirectly through other headers.
2
3 - *Rationale*: Excluding headers because they are already indirectly included results in compilation
4 failures when those indirect dependencies change. Furthermore, it obscures what the real code
5 dependencies are.
Other than that, the new unit tests look good and provide helpful feedback when run with
src/test/test_bitcoin -t getarg_tests/logargs -l all
PushBackCallback (and DeleteCallback afterwards).
ASSERT_DEBUG_LOG which might come in handy
1217@@ -1218,6 +1218,7 @@ bool AppInitMain(NodeContext& node)
1218 // Not categorizing as "Warning" because it's the default behavior
1219 LogPrintf("Config file: %s (not found, skipping)\n", config_file_path.string());
1220 }
1221+ gArgs.LogArgs();
nit: this is commented in the unit test but not here; perhaps add:
0+
1+ // Log the config arguments to debug.log
2 gArgs.LogArgs();
gArgs.LogArgs(); is doing exactly (which args, logged where) without the need to git grep. At least, more help than harm.
Tested ACK 8317bb35b63062e0d54de3af19d923456e1cb467
git diff 8c09bf9..8317bb3 since last push:
0diff --git a/src/init.cpp b/src/init.cpp
1index 04305c9b23..6a91c8c1ce 100644
2--- a/src/init.cpp
3+++ b/src/init.cpp
4@@ -1218,6 +1218,8 @@ bool AppInitMain(NodeContext& node)
5 // Not categorizing as "Warning" because it's the default behavior
6 LogPrintf("Config file: %s (not found, skipping)\n", config_file_path.string());
7 }
8+
9+ // Log the config arguments to debug.log
10 gArgs.LogArgs();
11
12 LogPrintf("Using at most %i automatic connections (%i file descriptors available)\n", nMaxConnections, nFD);
13diff --git a/src/test/getarg_tests.cpp b/src/test/getarg_tests.cpp
14index 090c544be3..bebc56c57b 100644
15--- a/src/test/getarg_tests.cpp
16+++ b/src/test/getarg_tests.cpp
17@@ -2,6 +2,7 @@
18 // Distributed under the MIT software license, see the accompanying
19 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
20
21+#include <fs.h>
22 #include <util/strencodings.h>
23 #include <util/system.h>
24 #include <test/util/setup_common.h>
25diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py
26index de8461ea5a..ec6268f5fb 100755
27--- a/test/functional/feature_config_args.py
28+++ b/test/functional/feature_config_args.py
29@@ -99,16 +99,16 @@ class ConfArgsTest(BitcoinTestFramework):
30 unexpected_msgs=[
31 'alice:f7efda5c189b999524f151318c0c86$d5b51b3beffbc0',
32 '127.1.1.1',
33- 'satoshi',
34- 'tpass',
35+ 'secret-rpcuser',
36+ 'secret-torpassword',
37 ]):
38 self.start_node(0, extra_args=[
39 '-addnode=some.node',
40 '-rpcauth=alice:f7efda5c189b999524f151318c0c86$d5b51b3beffbc0',
41 '-rpcbind=127.1.1.1',
42 '-rpcpassword=',
43- '-rpcuser=satoshi',
44- '-torpassword=tpass',
45+ '-rpcuser=secret-rpcuser',
46+ '-torpassword=secret-torpassword',
47 ])
48 self.stop_node(0)
Launching bitcoind with this PR adds the following lines to the debug log that correctly list all of the custom settings, re-sorted in alphabetical order (first the config file settings, followed by the command line args) between Config file: and Using at most 512 automatic connections:
02020-01-13T19:14:02Z Config file arg: addresstype="bech32"
12020-01-13T19:14:02Z Config file arg: blocksonly="0"
22020-01-13T19:14:02Z Config file arg: dbcache="8192"
32020-01-13T19:14:02Z Config file arg: logips="1"
42020-01-13T19:14:02Z Config file arg: maxconnections="512"
52020-01-13T19:14:02Z Config file arg: maxuploadtarget="0"
62020-01-13T19:14:02Z Config file arg: par="0"
72020-01-13T19:14:02Z Config file arg: rpcpassword=****
82020-01-13T19:14:02Z Config file arg: rpcuser=****
92020-01-13T19:14:02Z Config file arg: server="1"
102020-01-13T19:14:02Z Config file arg: txindex="1"
112020-01-13T19:14:02Z Config file arg: walletbroadcast="1"
122020-01-13T19:14:02Z Command-line arg: dbcache="256"
132020-01-13T19:14:02Z Command-line arg: logips="0"
142020-01-13T19:14:02Z Command-line arg: walletbroadcast="0"
144@@ -145,6 +145,8 @@ class ArgsManager
145 * between mainnet and regtest/testnet won't cause problems due to these
146 * parameters by accident. */
147 NETWORK_ONLY = 0x200,
148+ // This argument's value is sensitive (such as a password).
149+ DONT_LOG = 0x400,
SENSITIVE or PRIVATE or similar to avoid a negated option (which might lead to double negations), but more importantly make it agnostic of how the values are reported. If in the future someone adds a getconfigargs RPC, the internal wording “log” seems a bit off.
Implemented review suggestions:
DONT_LOG to SENSITIVEdebug.logHere are the changes in the last force-push (I think this PR should remain a single commit), in case that’s helpful to reviewers: https://github.com/LarryRuane/bitcoin/compare/8317bb35b63062e0d54de3af19d923456e1cb467..03fdf86b6d4bc036c707a0b0d84995f438283b11
ACK b951b0973c reviewed diff, re-code review, built, ran tests, launched bitcoind and reviewed debug log output, verified value of str debug log in the added unit test.
0$ src/test/test_bitcoin -t getarg_tests/logargs -l test_suite
1.../...
2
32020-01-30T20:48:38Z Command-line arg: dontlog=****
42020-01-30T20:48:38Z Command-line arg: okaylog="public"
52020-01-30T20:48:38Z Command-line arg: okaylog-bool=""
62020-01-30T20:48:38Z Command-line arg: okaylog-negbool=false
0$ bitcoind -dbcache=512 -logips=0 -walletbroadcast=0
12020-01-30T19:01:24Z Bitcoin Core version v0.19.99.0-b951b0973c (debug build)
22020-01-30T19:01:24Z Assuming ancestors of block 00000000000000000005f8920febd3925f8272a6a71237563d78c2edfdd09ddf have valid signatures.
32020-01-30T19:01:24Z Setting nMinimumChainWork=000000000000000000000000000000000000000008ea3cf107ae0dec57f03fe8
42020-01-30T19:01:24Z Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
52020-01-30T19:01:24Z Using RdSeed as additional entropy source
62020-01-30T19:01:24Z Using RdRand as an additional entropy source
72020-01-30T19:01:24Z Default data directory /home/jon/.bitcoin
82020-01-30T19:01:24Z Using data directory /home/jon/.bitcoin
92020-01-30T19:01:24Z Config file: /home/jon/.bitcoin/bitcoin.conf
102020-01-30T19:01:24Z Config file arg: addresstype="bech32"
112020-01-30T19:01:24Z Config file arg: blocksonly="0"
122020-01-30T19:01:24Z Config file arg: dbcache="10240"
132020-01-30T19:01:24Z Config file arg: logips="1"
142020-01-30T19:01:24Z Config file arg: maxconnections="512"
152020-01-30T19:01:24Z Config file arg: maxuploadtarget="0"
162020-01-30T19:01:24Z Config file arg: par="0"
172020-01-30T19:01:24Z Config file arg: rpcpassword=****
182020-01-30T19:01:24Z Config file arg: rpcuser=****
192020-01-30T19:01:24Z Config file arg: server="1"
202020-01-30T19:01:24Z Config file arg: txindex="1"
212020-01-30T19:01:24Z Config file arg: walletbroadcast="1"
222020-01-30T19:01:24Z Command-line arg: dbcache="512"
232020-01-30T19:01:24Z Command-line arg: logips="0"
242020-01-30T19:01:24Z Command-line arg: walletbroadcast="0"
252020-01-30T19:01:24Z Using at most 512 automatic connections (1024 file descriptors available)
ACK b951b0973cfd4e0db4607a00d434a04afb0d6199 🐪
Signature:
0-----BEGIN PGP SIGNED MESSAGE-----
1Hash: SHA512
2
3ACK b951b0973cfd4e0db4607a00d434a04afb0d6199 🐪
4-----BEGIN PGP SIGNATURE-----
5
6iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
7pUgHewwAixdou/20sx/EQar5cdubgAQpvKEAXE9fZwjP6zu0ZBrabem2sc8gsVkD
8bvQPvnTscdaIvHkOzkZ860STB+nr77x483AKc+Dl4G4Z4LecMv8iXSQmoVOwlxl2
9rsdUVFQnLAUB9phu9RccJwXUyEsoaGAy/sUcoaHwv3nuApqgNZZptjmCUO3lK5sw
10vQ/XT30gVZ6xSlfP21ZQaMaqps4MHOB9Z1X5hjnxm49/XMg+4Et3TJKbGyTNwcm6
11Ue/raLdaPtq6htfkhMIro9cc95Bfy1Nr9X4fGpte7IAu4waT5bJQVF2EeoQPyh0d
12LEOHe5cQPRsUOd5RvzYmCFqGsM5qRZw9BrQ6yUG13c7tYOi4xc7tdCabE8BUgFuR
13NqAw90SZMFl8wdDsQHub0H0V5EDxo92YzukM1J+h40OgG3ozZc3dS7SbPhqNpnoN
14uul5igOr4HICcNDPDHufDW4WAzvh8PpUlqCQnzF/BKnbYQjGZvhtB7asR4v0lH3w
15LtVy1Blz
16=hrjv
17-----END PGP SIGNATURE-----
Timestamp of file with hash 7113306c6076473032eb8637f29927398a935b895b4ee90467fca953dfb9ba72 -