On bitcoind startup, write config args to debug.log #16115
Conversation
|
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers. ConflictsReviewers, 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). |
src/util/system.cpp
Outdated
| @@ -964,6 +964,20 @@ std::string ArgsManager::GetChainName() const | |||
| return CBaseChainParams::MAIN; | |||
| } | |||
|
|
|||
| void ArgsManager::LogArgs() const | |||
| { | |||
| for (const auto arg: m_config_args) { | |||
There was a problem hiding this comment.
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.
src/util/system.cpp
Outdated
| LogPrintf("config-file arg: %s=%s\n", arg.first, value); | ||
| } | ||
| } | ||
| for (const auto arg: m_override_args) { |
There was a problem hiding this comment.
And accessing m_override_args requires holding cs_args :-)
8bf605f to
2cfbac2
Compare
|
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, and then I ran |
|
Related to #15493. |
src/util/system.cpp
Outdated
| @@ -964,6 +964,31 @@ std::string ArgsManager::GetChainName() const | |||
| return CBaseChainParams::MAIN; | |||
| } | |||
|
|
|||
| void ArgsManager::LogArgs() const | |||
There was a problem hiding this comment.
@ryanofsky You might have some thoughts on this?
There was a problem hiding this comment.
@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.
|
|
Not 100% sure if this is possible or in scope, but it'd be very useful to have the effective command line configuration at-a-glance, especially when trying to debug for others from looking at their logs. |
|
@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. |
2cfbac2 to
07e8c34
Compare
|
@kristapsk, I force-pushed a fix for both of your suggestions, thanks! I decided to leave the |
There was a problem hiding this comment.
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, df89103, 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):
2019-06-15T05:38:03Z Logging: start relogging initial messages
2019-06-15T05:37:09Z Bitcoin Core version v0.18.99.0-df891038c (release build)
2019-06-15T05:37:09Z Assuming ancestors of block 0000000000000037a8cd3e06cd5edbfe9dd1dbcc5dacab279376ef7cfc2b4c75 have valid signatures.
2019-06-15T05:37:09Z Setting nMinimumChainWork=00000000000000000000000000000000000000000000007dbe94253893cbd463
2019-06-15T05:37:09Z Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
2019-06-15T05:37:09Z Using RdSeed as additional entropy source
2019-06-15T05:37:09Z Using RdRand as an additional entropy source
2019-06-15T05:37:09Z Default data directory /home/larry/.bitcoin
2019-06-15T05:37:09Z Using data directory /home/larry/.bitcoin/testnet3
2019-06-15T05:37:09Z Config file: /home/larry/.bitcoin/bitcoin.conf
2019-06-15T05:37:09Z config-file arg: -testnet=1
2019-06-15T05:37:09Z command-line arg: -server=1
2019-06-15T05:37:09Z Using at most 125 automatic connections (1024 file descriptors available)
2019-06-15T05:37:09Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-06-15T05:37:10Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-06-15T05:37:10Z Using 4 threads for script verification
2019-06-15T05:37:10Z No wallet support compiled in!
2019-06-15T05:37:10Z scheduler thread start
2019-06-15T05:37:10Z HTTP: creating work queue of depth 16
2019-06-15T05:37:10Z No rpcpassword set - using random cookie authentication.
2019-06-15T05:37:10Z Generated RPC authentication cookie /home/larry/.bitcoin/testnet3/.cookie
2019-06-15T05:37:10Z HTTP: starting 4 worker threads
2019-06-15T05:37:10Z init message: Loading banlist...
2019-06-15T05:37:10Z Cache configuration:
2019-06-15T05:37:10Z * Using 2.0 MiB for block index database
2019-06-15T05:37:10Z * Using 8.0 MiB for chain state database
2019-06-15T05:37:10Z * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
2019-06-15T05:38:03Z Logging: end relogging initial messages
2019-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)
2019-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)
[.....]
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).
df89103 to
54c09ca
Compare
ce1ee92 to
371278f
Compare
There was a problem hiding this comment.
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?
src/util/system.cpp
Outdated
| } | ||
| std::string v = value; | ||
| for (const auto& b : blacklist) { | ||
| if (arg.first.find(b) != std::string::npos) { |
There was a problem hiding this comment.
This may inadvertently match an arg that contains a blacklisted arg name as a substring (but nonetheless should not be matched). Consider stripping any ignorable prefix from the arg and matching exactly instead. An added benefit is you can use a set for the blacklist as you had before.
src/util/system.h
Outdated
| @@ -297,6 +297,12 @@ class ArgsManager | |||
| * Return ArgsManager::NONE for unknown arg. | |||
| */ | |||
| unsigned int FlagsOfKnownArg(const std::string& key) const; | |||
|
|
|||
| /** | |||
| * During startup, LogPrintf() the config file options and | |||
There was a problem hiding this comment.
A couple nits:
- Drop "During startup" as this is referring to the call site.
- s/LogPrintf()/Log/ to avoid leaking implementation details in the documentation.
These will help keep the documentation in sync with the code as it changes.
There was a problem hiding this comment.
Good suggestion, implemented in latest commit, b6e55d5.
| def test_args_log(self): | ||
| with self.nodes[0].assert_debug_log(expected_msgs=[ | ||
| 'command-line arg: -addnode=some.node', | ||
| 'command-line arg: -torpassword=****', |
There was a problem hiding this comment.
Could you add any test cases for redacted args beginning with an ignorable prefix (e.g -regtest.)?
There was a problem hiding this comment.
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
|
The commit message for the test is incorrect: it is a functional test, not a unit test. |
src/util/system.cpp
Outdated
| } | ||
| std::string v = value; | ||
| for (const auto& b : blacklist) { | ||
| if (arg.first.find(b) != std::string::npos) { |
| def test_args_log(self): | ||
| with self.nodes[0].assert_debug_log(expected_msgs=[ | ||
| 'command-line arg: -addnode=some.node', | ||
| 'command-line arg: -torpassword=****', |
There was a problem hiding this comment.
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
src/logging.cpp
Outdated
| // While the system is initializing, save some reasonable number | ||
| // of (configuration-related) log messages for re-logging when | ||
| // the log file rotates (gets reopened). | ||
| 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. |
There was a problem hiding this comment.
I think it would be better for saving startup debug information to be handled outside of bitcoind. That way there's less confusion about what should/shouldn't get relogged, less code complexity, and users who save all their logs files will not be logging things redundantly.
Needless rebasing makes reviewing of consequent changes harder ;) Thank you. |
src/test/getarg_tests.cpp
Outdated
| gArgs.LogArgs(); | ||
|
|
||
| // Open and read debug.log. | ||
| FILE* file = fsbridge::fopen(LogInstance().m_file_path, "rb"); |
There was a problem hiding this comment.
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:
- Every `.cpp` and `.h` file should `#include` every header file it directly uses classes, functions or other
definitions from, even if those headers are already included indirectly through other headers.
- *Rationale*: Excluding headers because they are already indirectly included results in compilation
failures when those indirect dependencies change. Furthermore, it obscures what the real code
dependencies are.There was a problem hiding this comment.
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
There was a problem hiding this comment.
I think we could test this without reading an actual file by registering a log callback with PushBackCallback (and DeleteCallback afterwards).
There was a problem hiding this comment.
I think there is also an ASSERT_DEBUG_LOG which might come in handy
| self.start_node(0, extra_args=[ | ||
| '-addnode=some.node', | ||
| '-torpassword=mypass', | ||
| '-torpassword=torpassword', | ||
| ]) |
There was a problem hiding this comment.
Thanks @LarryRuane for taking the suggestion to cover all the 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.
| @@ -1218,6 +1218,7 @@ bool AppInitMain(NodeContext& node) | |||
| // Not categorizing as "Warning" because it's the default behavior | |||
| LogPrintf("Config file: %s (not found, skipping)\n", config_file_path.string()); | |||
| } | |||
| gArgs.LogArgs(); | |||
There was a problem hiding this comment.
nit: this is commented in the unit test but not here; perhaps add:
+
+ // Log the config arguments to debug.log
gArgs.LogArgs();There was a problem hiding this comment.
It seems this comment does not add any value here, no?
There was a problem hiding this comment.
I think it may gain time for occasional contributors/readers, and perhaps for those who haven't reviewed this PR, by confirming what the laconic gArgs.LogArgs(); is doing exactly (which args, logged where) without the need to git grep. At least, more help than harm.
8c09bf9 to
8317bb3
Compare
|
Thanks, I force-pushed the suggested changes. |
|
Tested ACK 8317bb3
diff --git a/src/init.cpp b/src/init.cpp
index 04305c9b23..6a91c8c1ce 100644
--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1218,6 +1218,8 @@ bool AppInitMain(NodeContext& node)
// Not categorizing as "Warning" because it's the default behavior
LogPrintf("Config file: %s (not found, skipping)\n", config_file_path.string());
}
+
+ // Log the config arguments to debug.log
gArgs.LogArgs();
LogPrintf("Using at most %i automatic connections (%i file descriptors available)\n", nMaxConnections, nFD);
diff --git a/src/test/getarg_tests.cpp b/src/test/getarg_tests.cpp
index 090c544be3..bebc56c57b 100644
--- a/src/test/getarg_tests.cpp
+++ b/src/test/getarg_tests.cpp
@@ -2,6 +2,7 @@
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
+#include <fs.h>
#include <util/strencodings.h>
#include <util/system.h>
#include <test/util/setup_common.h>
diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py
index de8461ea5a..ec6268f5fb 100755
--- a/test/functional/feature_config_args.py
+++ b/test/functional/feature_config_args.py
@@ -99,16 +99,16 @@ class ConfArgsTest(BitcoinTestFramework):
unexpected_msgs=[
'alice:f7efda5c189b999524f151318c0c86$d5b51b3beffbc0',
'127.1.1.1',
- 'satoshi',
- 'tpass',
+ 'secret-rpcuser',
+ 'secret-torpassword',
]):
self.start_node(0, extra_args=[
'-addnode=some.node',
'-rpcauth=alice:f7efda5c189b999524f151318c0c86$d5b51b3beffbc0',
'-rpcbind=127.1.1.1',
'-rpcpassword=',
- '-rpcuser=satoshi',
- '-torpassword=tpass',
+ '-rpcuser=secret-rpcuser',
+ '-torpassword=secret-torpassword',
])
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 |
|
ACK 8317bb3 |
src/util/system.h
Outdated
| @@ -145,6 +145,8 @@ class ArgsManager | |||
| * between mainnet and regtest/testnet won't cause problems due to these | |||
| * parameters by accident. */ | |||
| NETWORK_ONLY = 0x200, | |||
| // This argument's value is sensitive (such as a password). | |||
| DONT_LOG = 0x400, | |||
There was a problem hiding this comment.
I'd prefer to call this 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.
f107077 to
ad2f146
Compare
|
Implemented review suggestions:
Here 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 |
ad2f146 to
03fdf86
Compare
|
ACK 03fdf86 |
03fdf86 to
b951b09
Compare
There was a problem hiding this comment.
ACK b951b09 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.
$ src/test/test_bitcoin -t getarg_tests/logargs -l test_suite
.../...
2020-01-30T20:48:38Z Command-line arg: dontlog=****
2020-01-30T20:48:38Z Command-line arg: okaylog="public"
2020-01-30T20:48:38Z Command-line arg: okaylog-bool=""
2020-01-30T20:48:38Z Command-line arg: okaylog-negbool=false
$ bitcoind -dbcache=512 -logips=0 -walletbroadcast=0
2020-01-30T19:01:24Z Bitcoin Core version v0.19.99.0-b951b0973c (debug build)
2020-01-30T19:01:24Z Assuming ancestors of block 00000000000000000005f8920febd3925f8272a6a71237563d78c2edfdd09ddf have valid signatures.
2020-01-30T19:01:24Z Setting nMinimumChainWork=000000000000000000000000000000000000000008ea3cf107ae0dec57f03fe8
2020-01-30T19:01:24Z Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation
2020-01-30T19:01:24Z Using RdSeed as additional entropy source
2020-01-30T19:01:24Z Using RdRand as an additional entropy source
2020-01-30T19:01:24Z Default data directory /home/jon/.bitcoin
2020-01-30T19:01:24Z Using data directory /home/jon/.bitcoin
2020-01-30T19:01:24Z Config file: /home/jon/.bitcoin/bitcoin.conf
2020-01-30T19:01:24Z Config file arg: addresstype="bech32"
2020-01-30T19:01:24Z Config file arg: blocksonly="0"
2020-01-30T19:01:24Z Config file arg: dbcache="10240"
2020-01-30T19:01:24Z Config file arg: logips="1"
2020-01-30T19:01:24Z Config file arg: maxconnections="512"
2020-01-30T19:01:24Z Config file arg: maxuploadtarget="0"
2020-01-30T19:01:24Z Config file arg: par="0"
2020-01-30T19:01:24Z Config file arg: rpcpassword=****
2020-01-30T19:01:24Z Config file arg: rpcuser=****
2020-01-30T19:01:24Z Config file arg: server="1"
2020-01-30T19:01:24Z Config file arg: txindex="1"
2020-01-30T19:01:24Z Config file arg: walletbroadcast="1"
2020-01-30T19:01:24Z Command-line arg: dbcache="512"
2020-01-30T19:01:24Z Command-line arg: logips="0"
2020-01-30T19:01:24Z Command-line arg: walletbroadcast="0"
2020-01-30T19:01:24Z Using at most 512 automatic connections (1024 file descriptors available)
|
ACK b951b09 🐪 Show signature and timestampSignature: Timestamp of file with hash |
b951b09 on startup, write config options to debug.log (Larry Ruane) Pull request description: When a developer is examining `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. ACKs for top commit: MarcoFalke: ACK b951b09 🐪 jonatack: ACK b951b09 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. Tree-SHA512: bbca4fb3d49f99261758302bde0b8b67300ccc72e7380b01f1f66a146ae8a008a045df0ca5ca9664caff034d0ee38ea7ef38a50f38374525608c07ba52790358
Cherry-picked from upstream Bitcoin Core PR bitcoin/bitcoin#16115 but the implementation is very different.
Summary: This is a backport of Core [[bitcoin/bitcoin#16115 | PR16115]] Test Plan: ninja all check-all Reviewers: #bitcoin_abc, Fabien Reviewed By: #bitcoin_abc, Fabien Differential Revision: https://reviews.bitcoinabc.org/D5937
When a developer is examining
debug.logafter something goes wrong, it's often useful to know the exact options the failing instance ofbitcoindwas started with. Sometimes thedebug.logfile is all that's available for the analysis. This PR logs thebitcoin.confentries and command-line arguments todebug.logon startup.