Log RPC parameters (arguments) if -debug=rpcparams #16365

LarryRuane commented at 8:58 PM on July 9, 2019: contributor

When a developer is examining 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.

in src/rpc/server.cpp:374 in 7e412ceb67 outdated

 369 | +    // Log arguments unless sensitive.
 370 | +    static const std::set<std::string> blacklist = {
 371 | +        "encryptwallet",
 372 | +        "walletpassphrase",
 373 | +        "walletpassphrasechange",
 374 | +    };

maflcko commented at 9:03 PM on July 9, 2019:

Looks like this list is incomplete. Would be nice if it can be deduplicated with the existing QStringList historyFilter

fqlx commented at 12:02 AM on July 10, 2019:

This blacklist should be pulled out of a config rather than buried in the code.

LarryRuane commented at 5:52 PM on July 10, 2019:

What do you mean by "config"? Are you referring to ~/.bitcoin/bitcoin.conf?

maflcko commented at 6:03 PM on July 10, 2019:

I mean that it should go into a common module, probably ./src/util/ or similar.

DrahtBot commented at 10:34 PM on July 9, 2019: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#22736 (log, sync: change lock contention from preprocessor directive to log category by jonatack)
#20487 (Add syscall sandboxing using seccomp-bpf (Linux secure computing mode) by practicalswift)

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.

DrahtBot added the label Needs rebase on Jul 9, 2019

fanquake added the label RPC/REST/ZMQ on Jul 10, 2019

fanquake added the label Utils/log/libs on Jul 10, 2019

promag commented at 9:48 PM on July 10, 2019: member

How about private keys?

LarryRuane force-pushed on Jul 11, 2019

in src/logging.h:57 in 91ee96bd93 outdated

  53 | @@ -54,6 +54,7 @@ namespace BCLog {
  54 |          COINDB      = (1 << 18),
  55 |          QT          = (1 << 19),
  56 |          LEVELDB     = (1 << 20),
  57 | +        RPCPARAMS   = (1 << 21),

LarryRuane commented at 5:04 AM on July 11, 2019:

I'm undecided if a new category is needed, or just enable this additional logging with rpc. We don't have many of the 32 category bits remaining (although we could easily change to use a uint64_t).

in src/rpc/request.cpp:193 in 91ee96bd93 outdated

 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");

LarryRuane commented at 5:05 AM on July 11, 2019:

Could print each param on a separate line.

LarryRuane commented at 5:12 AM on July 11, 2019: contributor

Rebased, addressed review comments, force-pushed.

DrahtBot removed the label Needs rebase on Jul 11, 2019

promag commented at 12:56 AM on July 12, 2019: member

IMO the blacklist doesn't look a great option.

How about disallow -debug=rpcparams in mainnet and drop the blacklist?

instagibbs commented at 6:16 PM on July 12, 2019: member

concept NACK, someone is going to forget when adding a new RPC and start logging secrets in production.

I think @promag suggestion is better.

LarryRuane force-pushed on Jul 13, 2019

DrahtBot added the label Needs rebase on Aug 5, 2019

promag commented at 2:04 PM on August 5, 2019: member

Another approach is to add a sensitive options/flag (false by default) to ~~RPCHelpMan~~ RPCArg.

LarryRuane force-pushed on Aug 6, 2019

LarryRuane commented at 6:19 AM on August 6, 2019: contributor

@promag, interesting idea, I like that it would allow specific arguments to be designated as sensitive, rather than the entire method. Also, it would be nice not to have to touch so many lines of code (as my latest commit does). But @instagibbs's concern, #16365 (comment), which I was attempted to overcome with my latest commit, becomes live again.

DrahtBot removed the label Needs rebase on Aug 6, 2019

DrahtBot added the label Needs rebase on Aug 21, 2019

LarryRuane force-pushed on Aug 22, 2019

LarryRuane commented at 6:28 PM on August 22, 2019: contributor

Rebased, replaced functional (python) test with a proper unit test.

DrahtBot removed the label Needs rebase on Aug 22, 2019

DrahtBot added the label Needs rebase on Sep 2, 2019

LarryRuane force-pushed on Sep 2, 2019

DrahtBot removed the label Needs rebase on Sep 2, 2019

LarryRuane force-pushed on Sep 2, 2019

LarryRuane commented at 8:35 PM on September 2, 2019: contributor

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.

DrahtBot added the label Needs rebase on Sep 5, 2019

LarryRuane force-pushed on Sep 5, 2019

DrahtBot removed the label Needs rebase on Sep 5, 2019

DrahtBot added the label Needs rebase on Sep 14, 2019

LarryRuane force-pushed on Sep 15, 2019

DrahtBot removed the label Needs rebase on Sep 15, 2019

laanwj added the label Feature on Sep 30, 2019

DrahtBot added the label Needs rebase on Oct 30, 2019

LarryRuane force-pushed on Nov 1, 2019

DrahtBot removed the label Needs rebase on Nov 1, 2019

DrahtBot added the label Needs rebase on Nov 5, 2019

LarryRuane force-pushed on Nov 7, 2019

LarryRuane commented at 9:08 PM on November 7, 2019: contributor

Rebased to resolve conflicts.

DrahtBot removed the label Needs rebase on Nov 7, 2019

LarryRuane force-pushed on Nov 21, 2019

LarryRuane commented at 4:46 PM on November 22, 2019: contributor

I don't know the cause of the Travis CI failure; 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?

LarryRuane force-pushed on Dec 14, 2019

DrahtBot added the label Needs rebase on Jan 9, 2020

LarryRuane force-pushed on Jan 9, 2020

DrahtBot removed the label Needs rebase on Jan 10, 2020

LarryRuane closed this on Jan 10, 2020

LarryRuane commented at 3:33 PM on January 10, 2020: contributor

Sorry, I accidentally closed this PR, reopening now...

LarryRuane reopened this on Jan 10, 2020

LarryRuane force-pushed on Jan 11, 2020

DrahtBot added the label Needs rebase on Feb 18, 2020

promag commented at 11:24 PM on March 15, 2020: member

Still not buying the approach.

How about disallow -debug=rpcparams in mainnet and drop the blacklist?

Couldn't we use this approach for now?

LarryRuane commented at 4:58 AM on March 16, 2020: contributor

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.

sipa commented at 5:46 PM on March 17, 2020: member

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:

Make it possible to have an optional argument to the CRPCCommand constructors, which defaults to DONT_LOG, and not explicitly change it initially for any commands.
Then incrementally introduce DO_LOG flags, which can be done separately without needing to keep the whole PR up to date here.

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(); }

LarryRuane force-pushed on Mar 18, 2020

in src/rpc/server.cpp:242 in 0f92dff5f0 outdated

 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,  },

LarryRuane commented at 1:56 AM on March 18, 2020:

This is to show how to enable logging, an example.

in src/rpc/server.cpp:454 in 0f92dff5f0 outdated

 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));

LarryRuane commented at 1:56 AM on March 18, 2020:

This has changed to also print the method string.

in src/zmq/zmqrpc.cpp:57 in 0f92dff5f0 outdated

  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,           {} },

LarryRuane commented at 1:58 AM on March 18, 2020:

I could remove this, but this change allows test/lint/check-rpc-mappings.py to check this file also (was missing).

in test/lint/check-rpc-mappings.py:23 in 0f92dff5f0 outdated

  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",

LarryRuane commented at 1:58 AM on March 18, 2020:

Added two missing files (besides my test).

in src/rpc/server.cpp:445 in 0f92dff5f0 outdated

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

LarryRuane commented at 1:59 AM on March 18, 2020:

If testnet, always show the arguments.

LarryRuane commented at 2:02 AM on March 18, 2020: contributor

Thanks, @sipa and @promag, I took both of your advice. The default now is to not log arguments on mainnet, and always log arguments on testnet. This change is now much less invasive.

DrahtBot removed the label Needs rebase on Mar 18, 2020

LarryRuane force-pushed on Jul 13, 2020

DrahtBot added the label Needs rebase on Aug 12, 2020

LarryRuane force-pushed on Aug 12, 2020

DrahtBot removed the label Needs rebase on Aug 12, 2020

DrahtBot added the label Needs rebase on Aug 13, 2020

LarryRuane force-pushed on Sep 4, 2020

DrahtBot removed the label Needs rebase on Sep 4, 2020

DrahtBot added the label Needs rebase on Sep 15, 2020

LarryRuane force-pushed on Sep 28, 2020

DrahtBot removed the label Needs rebase on Sep 28, 2020

LarryRuane renamed this:
~~Log RPC parameters (arguments) if -debug=rpcparams~~
[WIP] Log RPC parameters (arguments) if -debug=rpcparams
on Sep 29, 2020

LarryRuane force-pushed on Sep 29, 2020

LarryRuane commented at 6:05 AM on September 29, 2020: contributor

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

$ bitcoin-cli getnetworkinfo
$ bitcoin-cli getblockhash 0
$ bitcoin-cli logging '["rpcparams"]' '["rpc","mempool"]'
$ bitcoin-cli encryptwallet WALLET-PASSWORD-SECRET

Here's what appears in debug.log:

2020-09-29T05:58:50Z rpc=getnetworkinfo()
2020-09-29T05:59:00Z rpc=getblockhash(0)
2020-09-29T06:02:51Z rpc=logging([rpcparams],[rpc,mempool])
2020-09-29T06:02:55Z rpc=encryptwallet(****)

LarryRuane renamed this:
~~[WIP] Log RPC parameters (arguments) if -debug=rpcparams~~
Log RPC parameters (arguments) if -debug=rpcparams
on Sep 29, 2020

in src/rpc/server.cpp:616 in 45fb5d040e outdated

 597 | +            "waitforblockheight",
 598 | +            "waitfornewblock",
 599 | +            "walletcreatefundedpsbt",
 600 | +            "walletlock",
 601 | +            "walletprocesspsbt",
 602 | +        };

LarryRuane commented at 2:58 PM on September 29, 2020:

This allow list came from listing all the RPCs and then removing the following:

signmessagewithprivkey
signrawtransactionwithkey
signrawtransactionwithwallet
signmessage
createwallet
encryptwallet
importmulti
importprivkey
sethdseed
walletpassphrase
walletpassphrasechange

As far as I can tell, these are the RPCs whose arguments shouldn't be logged.

jonatack commented at 11:10 AM on August 19, 2021:

Maintainence of this list seems like a drawback. It would be nice if a test fails somewhere when an RPC is added or removed without the allow list being updated, e.g. with a list of structs of all the RPCs with an associated safe/unsafe bool value, or something like CRPCConvertParam. Feel to ignore if unrealistic.

DrahtBot added the label Needs rebase on Mar 2, 2021

LarryRuane force-pushed on Mar 3, 2021

DrahtBot removed the label Needs rebase on Mar 3, 2021

DrahtBot added the label Needs rebase on Apr 5, 2021

LarryRuane force-pushed on Apr 12, 2021

DrahtBot removed the label Needs rebase on Apr 12, 2021

DrahtBot added the label Needs rebase on Apr 27, 2021

Log RPC parameters if -debug=rpcparams 7d22a6fad9

LarryRuane force-pushed on Apr 29, 2021

DrahtBot removed the label Needs rebase on Apr 29, 2021

in src/logging.h:62 in 7d22a6fad9

  58 | @@ -59,6 +59,7 @@ namespace BCLog {
  59 |          VALIDATION  = (1 << 21),
  60 |          I2P         = (1 << 22),
  61 |          IPC         = (1 << 23),
  62 | +        RPCPARAMS   = (1 << 24),

jonatack commented at 11:02 AM on August 19, 2021:

test/functional/rpc_misc.py::L60 needs to be updated: AssertionError: not(25 == 24)

in src/rpc/server.cpp:586 in 7d22a6fad9

 581 | +            "prioritisetransaction",
 582 | +            "pruneblockchain",
 583 | +            "psbtbumpfee",
 584 | +            "reconsiderblock",
 585 | +            "removeprunedfunds",
 586 | +            "rescanblockchain",

jonatack commented at 11:04 AM on August 19, 2021:

This list seems to need an update for new RPCS (restorewallet comes to mind, not sure if there are others)

in src/rpc/server.cpp:626 in 7d22a6fad9

 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 | +            }

jonatack commented at 11:11 AM on August 19, 2021:

Maybe replace this loop with a call to util/string.h::Join()

in src/test/rpc_tests.cpp:513 in 7d22a6fad9

 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);

jonatack commented at 11:37 AM on August 19, 2021:

Some (tested) ideas, feel free to pick/choose/ignore

-    FILE* file = fsbridge::fopen(LogInstance().m_file_path, "rb");
+    FILE* file{fsbridge::fopen(LogInstance().m_file_path, "rb")};
     fseek(file, 0, SEEK_END);
     std::vector<char> vch(ftell(file), 0);
     fseek(file, 0, SEEK_SET);
-    size_t nbytes = fread(vch.data(), 1, vch.size(), file);
+    const size_t nbytes{fread(vch.data(), 1, vch.size(), file)};
     fclose(file);
 
     // This checks the test (not the code being tested).
     BOOST_CHECK_EQUAL(nbytes, vch.size());
 
     // Check that what should appear does, and what shouldn't doesn't.
-    std::string str(vch.begin(), vch.end());
+    const std::string str{vch.begin(), vch.end()};
@@ -512,8 +512,8 @@ BOOST_AUTO_TEST_CASE(rpc_logparams)
-    BOOST_CHECK(str.find("some-key") == std::string::npos);
-    BOOST_CHECK(str.find("some-message") == std::string::npos);
+    BOOST_CHECK_EQUAL(str.find("some-key"), std::string::npos);
+    BOOST_CHECK_EQUAL(str.find("some-message"), std::string::npos);

in src/rpc/server.cpp:623 in 7d22a6fad9

 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 += ",";

jonatack commented at 11:49 AM on August 19, 2021:

Not sure here, perhaps separate the params with ", " (comma + space)

now

2021-08-19T11:45:46Z rpc=getmempoolancestors(b6a5ed05bc71c8ccc5316,true)

comma+space

2021-08-19T11:45:46Z rpc=getmempoolancestors(b6a5ed05bc71c8ccc5316, true)

jonatack commented at 11:55 AM on August 19, 2021: contributor

Tested almost-ACK 7d22a6fad9d855e9dbb0bca70857c9aadc55f188 rebased to current master, modulo the comments below

LarryRuane commented at 3:37 PM on August 20, 2021: contributor

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!

LarryRuane marked this as a draft on Aug 20, 2021

DrahtBot commented at 11:19 PM on December 13, 2021: contributor

🐙 This pull request conflicts with the target branch and needs rebase.

<sub>Want to unsubscribe from rebase notifications on this pull request? Just convert this pull request to a "draft".</sub>

DrahtBot added the label Needs rebase on Dec 13, 2021

DrahtBot commented at 1:07 PM on March 21, 2022: contributor

There hasn't been much activity lately and the patch still needs rebase. What is the status here?

Is it still relevant? ➡️ Please solve the conflicts to make it ready for review and to ensure the CI passes.
Is it no longer relevant? ➡️ Please close.
Did the author lose interest or time to work on this? ➡️ Please close it and mark it 'Up for grabs' with the label, so that it can be picked up in the future.

fanquake commented at 10:45 AM on December 6, 2022: member

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.

fanquake closed this on Dec 6, 2022

bitcoin locked this on Dec 6, 2023