debug.log (or client terminal output), it’s often useful to know which RPCs have been submitted to the client; this can be enabled with the -debug=rpc configuration option. But this prints only the method name. This PR adds -debug=rpcparams to enable the logging of each RPC’s parameters (arguments). The parameters of certain RPCs are keys or passwords; these should not be logged.
369+ // Log arguments unless sensitive.
370+ static const std::set<std::string> blacklist = {
371+ "encryptwallet",
372+ "walletpassphrase",
373+ "walletpassphrasechange",
374+ };
QStringList historyFilter
~/.bitcoin/bitcoin.conf?
./src/util/ or similar.
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.
53@@ -54,6 +54,7 @@ namespace BCLog {
54 COINDB = (1 << 18),
55 QT = (1 << 19),
56 LEVELDB = (1 << 20),
57+ RPCPARAMS = (1 << 21),
rpc. We don’t have many of the 32 category bits remaining (although we could easily change to use a uint64_t).
188+ for (size_t i = 0; i < params.size(); ++i) {
189+ if (i > 0)
190+ LogPrint(BCLog::RPCPARAMS, ",");
191+ LogPrint(BCLog::RPCPARAMS, "%s", SanitizeString(params[i].getValStr()));
192+ }
193+ LogPrint(BCLog::RPCPARAMS, "]\n");
IMO the blacklist doesn’t look a great option.
How about disallow -debug=rpcparams in mainnet and drop the blacklist?
concept NACK, someone is going to forget when adding a new RPC and start logging secrets in production.
I think @promag suggestion is better.
RPCHelpManRPCArg.
I had an idea for what may be an improvement. It’s in a separate commit, “replace sensitive bool with more general flags”. Please let me know what you think; this commit is optional.
Modifying all of the lines of the static const CRPCCommand commands[] tables is disruptive, and all that’s being done is to add a boolean value (to indicate whether to log the RPC’s params or not). As long as we’re touching all these lines anyway, why not implement a more general flags bitfield, of which DONTLOG is just the first bit. There may be other future attributes that would be useful to add to RPC methods. With this commit, adding them would touch only the lines corresponding to the affected RPCs, rather than all of them.
feature_pruning.py succeeds on my machine. I would not think this PR has any particular connection to that test. Maybe it’s a transient failure?
Still not buying the approach.
How about disallow
-debug=rpcparamsin mainnet and drop the blacklist?
Couldn’t we use this approach for now?
Couldn’t we use this approach for now?
Just so I’m sure I understand, you’re suggesting not adding the flags member to CRPCCommand (here, which causes many lines to be touched, and that’s clearly undesirable), and instead just don’t censor anything (no black or white list), but restrict this to testnet only?
I like that idea, would make this PR much simpler. If it proves useful on testnet, then we can try to find an acceptable way to bring it to mainnet – maybe there’s a less intrusive way that’s still very safe. I always appreciate your comments.
So it seems everything depends on whether this is considered useful for mainnet. I can imagine that for production logging it is. If not, @promag’s approach is fine. If it is, the safest approach seems something like the current approach.
There is perhaps a less disruptive approach:
One unrelated nit: I think it would be a bit cleaner to log the RPC command and arguments in the same log line (the logic would be something like if (debug_rpcparams && command.do_log) { log_rpc_with_params(); } else if (debug_rpc || debug_rpcparams) { log_rpc_without_params(); }
238@@ -238,7 +239,7 @@ static const CRPCCommand vRPCCommands[] =
239 // --------------------- ------------------------ ----------------------- ----------
240 /* Overall control/query calls */
241 { "control", "getrpcinfo", &getrpcinfo, {} },
242- { "control", "help", &help, {"command"} },
243+ { "control", "help", &help, {"command"}, CRPCCommand::LOG_OK, },
449+ if (i > 0) {
450+ param += ",";
451+ }
452+ param += request.params[i].getValStr();
453+ }
454+ LogPrintf("RPC method=%s params=[%s]\n", SanitizeString(request.strMethod), SanitizeString(param));
47@@ -48,7 +48,7 @@ UniValue getzmqnotifications(const JSONRPCRequest& request)
48 return result;
49 }
50
51-const CRPCCommand commands[] =
52+static const CRPCCommand commands[] =
53 { // category name actor (function) argNames
54 // ----------------- ------------------------ ----------------------- ----------
55 { "zmq", "getzmqnotifications", &getzmqnotifications, {} },
test/lint/check-rpc-mappings.py to check this file also (was missing).
17@@ -18,6 +18,9 @@
18 "src/rpc/net.cpp",
19 "src/rpc/rawtransaction.cpp",
20 "src/wallet/rpcwallet.cpp",
21+ "src/qt/test/rpcnestedtests.cpp",
22+ "src/zmq/zmqrpc.cpp",
23+ "src/test/rpc_tests.cpp",
439@@ -439,6 +440,19 @@ UniValue CRPCTable::execute(const JSONRPCRequest &request) const
440
441 static bool ExecuteCommand(const CRPCCommand& command, const JSONRPCRequest& request, UniValue& result, bool last_handler)
442 {
443+ // Log arguments if requested, unless sensitive.
444+ if (LogAcceptCategory(BCLog::RPCPARAMS) && request.params.size() > 0 &&
445+ (Params().IsTestChain() || (command.flags & CRPCCommand::LOG_OK)))
Force-pushed (diff) a different approach that does not require changing each of the 149 per-rpc CRPCCommand initializers. This new way is much less invasive and more manageable. I finally decided it’s best to go with an “allow” list (hard to beat simplicity). If someone adds a new RPC later without being aware of this form of logging, its arguments will not be logged. That makes this approach very safe against accidentally leaking secret information to the log file. I incorporated some of the review comments as well.
Here are some examples (without showing the RPC output):
0$ bitcoin-cli getnetworkinfo
1$ bitcoin-cli getblockhash 0
2$ bitcoin-cli logging '["rpcparams"]' '["rpc","mempool"]'
3$ bitcoin-cli encryptwallet WALLET-PASSWORD-SECRET
Here’s what appears in debug.log:
02020-09-29T05:58:50Z rpc=getnetworkinfo()
12020-09-29T05:59:00Z rpc=getblockhash(0)
22020-09-29T06:02:51Z rpc=logging([rpcparams],[rpc,mempool])
32020-09-29T06:02:55Z rpc=encryptwallet(****)
597+ "waitforblockheight",
598+ "waitfornewblock",
599+ "walletcreatefundedpsbt",
600+ "walletlock",
601+ "walletprocesspsbt",
602+ };
This allow list came from listing all the RPCs and then removing the following:
0signmessagewithprivkey
1signrawtransactionwithkey
2signrawtransactionwithwallet
3signmessage
4createwallet
5encryptwallet
6importmulti
7importprivkey
8sethdseed
9walletpassphrase
10walletpassphrasechange
As far as I can tell, these are the RPCs whose arguments shouldn’t be logged.
CRPCConvertParam. Feel to ignore if unrealistic.
58@@ -59,6 +59,7 @@ namespace BCLog {
59 VALIDATION = (1 << 21),
60 I2P = (1 << 22),
61 IPC = (1 << 23),
62+ RPCPARAMS = (1 << 24),
test/functional/rpc_misc.py::L60 needs to be updated: AssertionError: not(25 == 24)
581+ "prioritisetransaction",
582+ "pruneblockchain",
583+ "psbtbumpfee",
584+ "reconsiderblock",
585+ "removeprunedfunds",
586+ "rescanblockchain",
restorewallet comes to mind, not sure if there are others)
621+ for (size_t i = 0; i < request.params.size(); ++i) {
622+ if (i > 0) {
623+ params += ",";
624+ }
625+ params += request.params[i].write();
626+ }
util/string.h::Join()
508+
509+ // All arguments replaced by **** (secret information)
510+ BOOST_CHECK(str.find("rpc=signmessagewithprivkey(****)") != std::string::npos);
511+ // Make sure these don't somehow appear
512+ BOOST_CHECK(str.find("some-key") == std::string::npos);
513+ BOOST_CHECK(str.find("some-message") == std::string::npos);
Some (tested) ideas, feel free to pick/choose/ignore
0- FILE* file = fsbridge::fopen(LogInstance().m_file_path, "rb");
1+ FILE* file{fsbridge::fopen(LogInstance().m_file_path, "rb")};
2 fseek(file, 0, SEEK_END);
3 std::vector<char> vch(ftell(file), 0);
4 fseek(file, 0, SEEK_SET);
5- size_t nbytes = fread(vch.data(), 1, vch.size(), file);
6+ const size_t nbytes{fread(vch.data(), 1, vch.size(), file)};
7 fclose(file);
8
9 // This checks the test (not the code being tested).
10 BOOST_CHECK_EQUAL(nbytes, vch.size());
11
12 // Check that what should appear does, and what shouldn't doesn't.
13- std::string str(vch.begin(), vch.end());
14+ const std::string str{vch.begin(), vch.end()};
15@@ -512,8 +512,8 @@ BOOST_AUTO_TEST_CASE(rpc_logparams)
16- BOOST_CHECK(str.find("some-key") == std::string::npos);
17- BOOST_CHECK(str.find("some-message") == std::string::npos);
18+ BOOST_CHECK_EQUAL(str.find("some-key"), std::string::npos);
19+ BOOST_CHECK_EQUAL(str.find("some-message"), std::string::npos);
618+ if (logging_allow_list.find(request.strMethod) == logging_allow_list.end()) {
619+ params = "****";
620+ } else {
621+ for (size_t i = 0; i < request.params.size(); ++i) {
622+ if (i > 0) {
623+ params += ",";
Not sure here, perhaps separate the params with ", " (comma + space)
now
02021-08-19T11:45:46Z rpc=getmempoolancestors(b6a5ed05bc71c8ccc5316,true)
comma+space
02021-08-19T11:45:46Z rpc=getmempoolancestors(b6a5ed05bc71c8ccc5316, true)
Maintenance of this list seems like a drawback
I agree, I’m going to convert this PR to draft because I think there’s a better way to do this that doesn’t require a separate list. I’ll also pick up your other suggestions. Thanks for taking the time to look it over!
🐙 This pull request conflicts with the target branch and needs rebase.
Want to unsubscribe from rebase notifications on this pull request? Just convert this pull request to a “draft”.
I’m going to convert this PR to draft because I think there’s a better way to do this that doesn’t require a separate list. I’ll also pick up your other suggestions.
Given it’s been 16 months this statement, I’m going to close this for now. Feel free to comment / ping if you’re going to work on this again and need the PR reopened.