Make non-critical unconditional logging conditional to reduce risk of disk fill attacks and to improve user experience #20174

As MarcoFalke noted in #19995 ("Mitigate disk filling attacks by temporarily rate limiting LogPrintf(…)"):

I'd prefer if unconditional logs were only used for the init/shutdown sequence and local system errors, such as data corruption. Anything else the average user probably doesn't care about, and if they did, they could enable the corresponding debug category and provide enough disk space for the debug log file.

And in #19832 (comment):

Generally, it should be possible to run Bitcoin Core with well-defined resource usage in an unsupervised setting. Ideally, the resource usage depends on command line settings and user behaviour, not on remote peer (mis)behaviour. And with "unsupervised" I mean that the users doesn't check the debug log unless there is a local software malfunction or other issue that needs manual debugging.

I agree that we use too much unconditional logging.

It is bad for two reasons:

• From a security perspective unnecessary unconditional logging risks open up for disk fill attacks.
• From a usability perspective unnecessary unconditional logging risks burying important log messages (anomalies) in logs about mundane expected stuff (non-anomalies).

I suggest gradually making non-critical unconditional logging conditional (opt-in via -debug) to reduce risk of disk fill attacks and to improve user experience.

More concretely that would mean changing from LogPrintf("…\n"); to LogPrint(DEBUG_CATEGORY, "…\n");.

Some candidates for changing from unconditional to conditional debug logging:

src/flatfile.cpp:   LogPrintf("Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);
src/net.cpp:        LogPrintf("socket send error %s\n", NetworkErrorString(nErr));
src/net.cpp:        LogPrintf("socket sending timeout: %is\n", nTime - pnode->nLastSend);
src/net.cpp:        LogPrintf("socket receive timeout: %is\n", nTime - pnode->nLastRecv);
src/net.cpp:        LogPrintf("ping timeout: %fs\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - pnode->m_ping_start.load()));
src/validation.cpp: LogPrintf("Leaving block file %i: %s\n", nLastBlockFile, vinfoBlockFile[nLastBlockFile].ToString());

These are (AFAICT) either a.) peer triggerable (edit: in low volume at least) or b.) uninteresting from a user perspective :)

Getting rid of the cases above as a start would significantly reduce the amount of log spam when in steady state (non-IBD).

These are (AFAICT) either a.) peer triggerable or b.) uninteresting from a user perspective :)

Which are (a)? Most seem (b) to me, and I'm not even sure they're that "uninteresting" (although the content could be improved to be user-friendly).

Because I don't see how they are (a), I'm not sure there is any security gain.

@naumenkogs

Oh, to be clear: I meant "peer triggerable" as the union of a.) "peer triggerable in low volume" (spammy but generally not a problem from a security perspective), b.) "peer triggerable in high volume" (may be used for disk fill attacks).

Note that the first case "peer triggerable in low volume" includes logging of events that is the result of "remote peer (mis)behaviour".

Generally I subscribe to this logging philosophy described by MarcoFalke in #19995: "I'd prefer if unconditional logs were only used for the init/shutdown sequence and local system errors, such as data corruption. Anything else the average user probably doesn't care about, and if they did, they could enable the corresponding debug category and provide enough disk space for the debug log file.", and ideally in combination with some kind of general mitigation like the one I suggested in #19995 ("Mitigate disk filling attacks by temporarily rate limiting LogPrintf(…)").

Which are (a)? Most seem (b) to me, and I'm not even sure they're that "uninteresting" (although the content could be improved to be user-friendly).

I think these are spammy/uninteresting:

src/flatfile.cpp:   LogPrintf("Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);
src/validation.cpp: LogPrintf("Leaving block file %i: %s\n", nLastBlockFile, vinfoBlockFile[nLastBlockFile].ToString());

I think these are peer triggerable in the sense that they are the result of "remote peer (mis)behaviour" (and hopefully only in low volume):

src/net.cpp:        LogPrintf("socket send error %s\n", NetworkErrorString(nErr));
src/net.cpp:        LogPrintf("socket sending timeout: %is\n", nTime - pnode->nLastSend);
src/net.cpp:        LogPrintf("socket receive timeout: %is\n", nTime - pnode->nLastRecv);
src/net.cpp:        LogPrintf("ping timeout: %fs\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - pnode->m_ping_start.load()));

If someone comes up with a way in which these could be made peer triggerable in high volume then that should be discussed with security@ of course :)

(And if we had a mitigation in place we wouldn't have to worry much about disk fill attacks at all :))

Not sure if others agree, but I'd be interested in a category for higher-level, less frequent p2p logging--e.g. peer misbehavior, eviction, timeout, connection/disconnection, some of which is unconditionally logged--that is separate from the lower-level, high-frequency net message logging (inv, getdata, etc.)

@jonatack Seems off-topic to this discussion, but I agree that splitting off tx-relay into a NET_TX_RELAY (sub) category could make sense.

@naumenkogs

These are (AFAICT) either a.) peer triggerable or b.) uninteresting from a user perspective :)

Which are (a)? Most seem (b) to me, and I'm not even sure they're that "uninteresting" (although the content could be improved to be user-friendly).

The problem with say the "ping timeout" unconditional log message is that it can be trivially remotely triggered by anyone:

$ src/bitcoind -regtest &
…
2020-11-01T04:00:00Z init message: Done loading
…
# Trigger unconditional log message "ping timeout: 1200s"
$ xxd -p -r <<< "fabfb5da76657273696f6e000000000056000000b268b319801101000100000000000000d1f99e5f00000000010000000000000000000000000000000000ffff000000000000010000000000000000000000000000000000ffff0000000000004804b6a278c1a74e00ffffffff01fabfb5da76657261636b000000000000000000005df6e0e2" | \
    nc 127.0.0.1 18444 > /dev/null &
# Wait...
…
2020-11-01T04:20:00Z ping timeout: 1200.020729s

The above can be parallelized by an attacker to give the target a slow but steady stream of "ping timeout" messages to confuse the target operator. (To be clear: I don't think the "ping timeout" case can be used for any disk fill attack thanks to the 1200 s delay, but peer triggerable log spamming is annoying even if our disks are not filled.)

I think cheaply peer triggerable log messages that are printed also for incoming connections should either be moved to a separate log category (say BCLog::NET), or at least only be printed for outgoing connections only to make it harder for an attacker to use them for nefarious purposes.

Would you object to that? If so, what would the main objection be? :)