Reduce log noise #34729

ajtowns commented at 11:56 AM on March 4, 2026: contributor

This set of changes reduces some of the exaggerated logging that was introduced in #29236 when "error()" logging was upgraded from LogPrintf (aka LogInfo) to LogError. It also introduces LogWarnThenDebug() which duplicates the behaviour of #34549 which issues a warning the first time the log line is hit, but downgrades that to categorized debug messages afterwards. This function is used for failures that are likely caused by system configuration problems (so likely degrade the node's functionality and warrant admin attention) but are triggered by remote activity and thus could occur frequently.

DrahtBot commented at 11:56 AM on March 4, 2026: contributor

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

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/34729.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	sedited, ryanofsky
Concept ACK	l0rinc
Stale ACK	kevkevinpal

If your review is incorrectly listed, please copy-paste <code></code> into the comment that the bot should ignore.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#34778 (logging: rewrite macros to add ratelimit option, avoid unused strprintf, clarify confusing errors by ryanofsky)
#34520 (refactor: Add [[nodiscard]] to functions returning bool+mutable ref by maflcko)
#30343 (wallet, logging: Replace WalletLogPrintf() with LogInfo() by ryanofsky)
#30342 (kernel, logging: Pass Logger instances to kernel objects by ryanofsky)
#29256 (log, refactor: Allow log macros to accept context arguments by ryanofsky)

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.

ajtowns commented at 11:59 AM on March 4, 2026: contributor

See #30348 for further background; I think the changes here should be able to stand on their own merits. I haven't addressed cases where there's ambiguity between LogWarning and LogError here, but if there are other current cases where things are at Warning/Error and should be Info, or at Warning/Error/Info and should be Debug, happy to add them to this PR.

in src/validation.cpp:193 in c665935d02 outdated

 189 | @@ -190,7 +190,7 @@ std::optional<std::vector<int>> CalculatePrevHeights(
 190 |                                ? tip.nHeight + 1 // Assume all mempool transaction confirm in the next block.
 191 |                                : coin->nHeight;
 192 |          } else {
 193 | -            LogInfo("ERROR: %s: Missing input %d in transaction \'%s\'\n", __func__, i, tx.GetHash().GetHex());
 194 | +            LogWarning("%s: Missing input %d in transaction \'%s\'", __func__, i, tx.GetHash().GetHex());

kevkevinpal commented at 2:48 PM on March 4, 2026:

            LogWarning(BCLog::VALIDATION, %s: Missing input %d in transaction \'%s\'", __func__, i, tx.GetHash().GetHex());

ajtowns commented at 3:12 AM on March 5, 2026:

LogWarning doesn't accept a filter category because it isn't filterable.

in src/validation.cpp:2619 in c665935d02 outdated

2615 | @@ -2616,7 +2616,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
2616 |          }
2617 |      }
2618 |      if (!state.IsValid()) {
2619 | -        LogInfo("Block validation error: %s", state.ToString());
2620 | +        LogWarning("Block validation error: %s", state.ToString());

kevkevinpal commented at 2:48 PM on March 4, 2026:

        LogWarning(BCLog::VALIDATION, "Block validation error: %s", state.ToString());

ajtowns commented at 3:12 AM on March 5, 2026:

LogWarning doesn't accept a filter category because it isn't filterable.

kevkevinpal commented at 2:41 AM on March 6, 2026:

Ahh ya my bad. Also, it makes sense to have only debug logs to be filterable since warnings and errors should always be seen.

kevkevinpal commented at 3:00 PM on March 4, 2026: contributor

ACK c665935d02b633032147e58436e3a1c6511d64f3

This is a good improvement on the amount of functional code dedicated to logging. Also, the LogWarnThenDebug log will be useful in future cases to help avoid log noise

Added two comments about potentially adding BCLog::VALIDATION to the two validation logs touched

in src/netbase.cpp:398 in 75674718fd outdated

 394 | @@ -395,7 +395,7 @@ bool Socks5(const std::string& strDest, uint16_t port, const ProxyCredentials* a
 395 |          IntrRecvError recvr;
 396 |          LogDebug(BCLog::NET, "SOCKS5 connecting %s\n", strDest);
 397 |          if (strDest.size() > 255) {
 398 | -            LogError("Hostname too long\n");
 399 | +            LogDebug(BCLog::PROXY, "Hostname too long for SOCKS5 proxying: %s", strDest);

ryanofsky commented at 5:17 PM on March 6, 2026:

In commit "netbase: Tidy up logging levels" (436bc942d362aefbf7315c73f74d032dcb75f435)

Maybe prefix this with Error: to indicate a problem has occurred and distinguish this from informational debug messages

Would suggest the same for other some messages below that aren't clearly labeled as error or failures.

l0rinc commented at 11:14 AM on May 12, 2026:

Not sure about this. Wouldn't that just blur the line between what's an error, what's a warning, and what's info and debug? Wouldn't LogWarnThenDebug suffice for that case?

ryanofsky commented at 5:21 PM on May 18, 2026:

re: #34729 (review)

Not sure about this. Wouldn't that just blur the line between what's an error, what's a warning, and what's info and debug? Wouldn't LogWarnThenDebug suffice for that case?

I just think we should make it easy to distinguish failure messages from status messages. So I'd agree LogWarnThenDebug would be an improvement because it would provide a clearer indication that something is wrong.

But I think you should be allowed to use the word "Error" even if you are not literally calling the LogError macro. I've said elsewhere the LogError macro is poorly named for what it's it's currently intended to be used for (severe errors causing the node to not function), and think a name like LogCritical would be better.

in src/netbase.cpp:415 in 75674718fd outdated

 411 | @@ -412,40 +412,40 @@ bool Socks5(const std::string& strDest, uint16_t port, const ProxyCredentials* a
 412 |          sock.SendComplete(vSocks5Init, g_socks5_recv_timeout, g_socks5_interrupt);
 413 |          uint8_t pchRet1[2];
 414 |          if (InterruptibleRecv(pchRet1, 2, g_socks5_recv_timeout, sock) != IntrRecvError::OK) {
 415 | -            LogInfo("Socks5() connect to %s:%d failed: InterruptibleRecv() timeout or other failure\n", strDest, port);
 416 | +            LogDebug(BCLog::PROXY, "Socks5() connect to %s:%d failed: InterruptibleRecv() timeout or other failure", strDest, port);

ryanofsky commented at 5:30 PM on March 6, 2026:

In commit "netbase: Reduce levels of socks5 error logging" (75674718fd35102be0db288802c7dc3af57ca986)

If this is an error communicating with the proxy server (as opposed to an error with the proxy server making a remote connection), it would seem potentially important for the user to know about so they can fix the problem with the server. Hiding this could make problems harder to diagnose, and it might be better to keep the previous level

in src/netbase.cpp:558 in 436bc942d3 outdated

 555 |  #endif
 556 |  
 557 |      // Set the non-blocking option on the socket.
 558 |      if (!sock->SetNonBlocking()) {
 559 | -        LogInfo("Error setting socket to non-blocking: %s\n", NetworkErrorString(WSAGetLastError()));
 560 | +        LogWarnThenDebug(BCLog::NET, "Error setting socket to non-blocking: %s", NetworkErrorString(WSAGetLastError()));

ryanofsky commented at 5:38 PM on March 6, 2026:

In commit "netbase: Tidy up logging levels" (436bc942d362aefbf7315c73f74d032dcb75f435)

This change seems ok, but if the goal in the commit message is to use higher levels for errors "that may be due to system misconfiguration" I don't know why this socket error would be more likely to be the result of misconfiguration than SO_NOSIGPIPE above, or if something else account for the difference like this error being considered more severe?

ajtowns commented at 1:27 PM on March 9, 2026:

The SO_NOSIGPIPE error is marked as "continuing anyway", rather than immediately failing the connection, which seems fairly straightforwardly less severe.

in src/bitcoin-tx.cpp:663 in c02d589667 outdated

 658 | @@ -659,7 +659,9 @@ static void MutateTxSign(CMutableTransaction& tx, const std::string& flagStr)
 659 |                  UniValue v = prevOut["redeemScript"];
 660 |                  std::vector<unsigned char> rsData(ParseHexUV(v, "redeemScript"));
 661 |                  CScript redeemScript(rsData.begin(), rsData.end());
 662 | -                tempKeystore.AddCScript(redeemScript);
 663 | +                if (!tempKeystore.AddCScript(redeemScript)) {
 664 | +                    throw std::runtime_error(strprintf("Error adding redeemscript=%s", HexStr(redeemScript)));

ryanofsky commented at 5:48 PM on March 6, 2026:

In commit "script: Lower level of oversized redeemScript log, push errors to callers" (c02d58966796c80a37d745957e37d5134d0c093d)

It seems good to throw an error here though text of this message doesn't seem ideal. Redeemscript blob is potentially large and earler logged message seems more helpful (though I'm not sure if logs are shown in bitcoin-tx so it might also be useless). Might want to add another TODO comment here to improve

l0rinc commented at 12:23 PM on May 12, 2026:

yeah, maybe something like:

                    throw std::runtime_error(strprintf("invalid redeemScript: exceeds maximum size of %d bytes", MAX_SCRIPT_ELEMENT_SIZE));

in src/netbase.cpp:677 in 75674718fd outdated

 673 | @@ -674,7 +674,7 @@ std::unique_ptr<Sock> Proxy::Connect() const
 674 |  #ifdef HAVE_SOCKADDR_UN
 675 |      auto sock = CreateSock(AF_UNIX, SOCK_STREAM, 0);
 676 |      if (!sock) {
 677 | -        LogError("Cannot create a socket for connecting to %s\n", m_unix_socket_path);
 678 | +        LogWarnThenDebug(BCLog::PROXY, "Cannot create a socket for connecting to %s", m_unix_socket_path);

ryanofsky commented at 7:07 PM on March 6, 2026:

In commit "netbase: Reduce levels of socks5 error logging" (75674718fd35102be0db288802c7dc3af57ca986)

I’m not sure LogWarnThenDebug() is the best fit here. Compared to the earlier uses in this commit and the previous one, this seems less like a persistent configuration problem and more like something that could be intermittent, e.g. due to hitting resource limits.

In that case, warning exactly once and never again may hide recurring failures. It would seem better to have a rate limit and show the error once per hour or once per day while it is still occurring, not to just show it once and never again for the lifetime of the process. Absent that, keeping this at info/warning/error level might be safer.

ryanofsky approved

ryanofsky commented at 8:28 PM on March 6, 2026: contributor

Code review ACK c665935d02b633032147e58436e3a1c6511d64f3, Concept -0. Changes here seem logical overall, and I left comments the few places where I had concerns. The LogWarnThenDebug macro also seems cool and potentially useful more places.

The thing I don’t like about this change is that it makes it harder to see if messages are errors or warnings or normal notifications. Being able to see [error] and [warning] tags is a nice feature that is unfortunate to lose. [^1]

In an ideal world I would use LogWarning and LogError macros more places rather than fewer. I would also make LogWarning and LogError messages configurable and not always shown, and add a LogCritical level for truly critical messages that should always be shown even when debug logging is off.

That said, this PR seems fine overall: some positives, some negatives, and the code changes look ok.

[^1]: Note that a message’s error/warning/info status is orthogonal to its priority. A message could describe a normal condition (info), an unexpected condition (warning), or a failure condition (error), and any of these messages could have high or low priority depending how important the information is, whether the condition is temporary or permanent, what side effects it could lead to, and whether it might require manual intervention.

in src/netbase.cpp:649 in 436bc942d3 outdated

 645 | @@ -646,15 +646,15 @@ std::unique_ptr<Sock> ConnectDirectly(const CService& dest, bool manual_connecti
 646 |  {
 647 |      auto sock = CreateSock(dest.GetSAFamily(), SOCK_STREAM, IPPROTO_TCP);
 648 |      if (!sock) {
 649 | -        LogError("Cannot create a socket for connecting to %s\n", dest.ToStringAddrPort());
 650 | +        LogDebug(BCLog::NET, "Cannot create a socket for connecting to %s", dest.ToStringAddrPort());

sedited commented at 1:21 PM on March 11, 2026:

In commit 436bc942d362aefbf7315c73f74d032dcb75f435

I'm a bit confused when you are choosing Debug and when WarnThenDebug in this commit. What is the difference between these cases?

ajtowns commented at 9:21 PM on March 11, 2026:

Proxy::Connect failing means you can't connect to the proxy you've configured, which seems likely to be a fairly serious problem for your node, and that error is likely the thing you need to see; ConnectDirectly failing might also be a severe problem, but it might also just be that you're trying to connect over ipv6 because your node says "why not?" but your OS says "no way", which is not really problematic at all. Note that CreateSock is CreateSockOS which mostly has LogWarnThenDebug before it returns nullptr as well.

Not particularly wedded to any particular choices here, these were just my best guesses.

sedited commented at 10:13 AM on March 13, 2026:

Thanks for elaborating. Makes sense to me.

DrahtBot added the label Needs rebase on Apr 20, 2026

ajtowns force-pushed on Apr 22, 2026

DrahtBot added the label CI failed on Apr 22, 2026

DrahtBot removed the label Needs rebase on Apr 23, 2026

DrahtBot removed the label CI failed on Apr 23, 2026

DrahtBot added the label Needs rebase on Apr 23, 2026

util/log: Add LogWarnThenDebug() helper

This generalises the functionality introduced for PCP/NAT-PMP logging
in #34549.

e054403acc

netbase: Reduce levels of socks5 error logging ec2a8c7215

netbase: Tidy up logging levels

This mostly reduces log noise by using BCLog::NET debug logging where
possible (with `LogWarnThenDebug()` used to ensure the first log message
still appears for things that may be due to system misconfiguration).
Also drops some unnecessary trailing newlines.

05911121b7

script: Lower level of oversized redeemScript log, push errors to callers 5266bb723c

kernel/coinstats: Downgrade ComputeUTXOStates log level 9bc68e5662

txindex: Downgrade log messages and include index name 4410a0e8aa

validation: Upgrade log levels for possible block corruption warnings 5359a99eb9

ajtowns force-pushed on Apr 23, 2026

DrahtBot added the label CI failed on Apr 23, 2026

DrahtBot removed the label Needs rebase on Apr 23, 2026

DrahtBot removed the label CI failed on Apr 23, 2026

sedited approved

sedited commented at 11:26 AM on May 10, 2026: contributor

ACK 5359a99eb9b5bd442daee6c35d133ee5ea9f6583

DrahtBot requested review from ryanofsky on May 10, 2026

DrahtBot requested review from kevkevinpal on May 10, 2026

in src/netbase.cpp:1 in ec2a8c7215

l0rinc commented at 11:12 AM on May 12, 2026:

ec2a8c7 netbase: Reduce levels of socks5 error logging:

Given that the original authors thought these should be errors, we could add short commit message explanations to clarify why these (expected?) conditions are no longer treated as serious errors. Obviously, no need to overdo it, but maybe add a short summary of your GitHub comments about the categories and constraints you've considered.

l0rinc commented at 12:01 PM on May 12, 2026:

9bc68e5 kernel/coinstats: Downgrade ComputeUTXOStates log level:

Commit message nit: ComputeUTXOStates -> ComputeUTXOStats

ajtowns commented at 1:38 PM on May 12, 2026:

The original authors tagged them with "ERROR:" via the error() helper, which was accurate -- they're not things that are expected to happen in normal usage, and error() just added some log text and an early exit. That was changed to invoke LogError in #29236 which was not correct per the definition of that function in the docs, and this PR just corrects that.

in doc/developer-notes.md:756 in e054403acc

 752 | @@ -753,6 +753,11 @@ logging messages. They should be used as follows:
 753 |    severe enough to warrant shutting down the node (e.g., system time
 754 |    appears to be wrong, unknown soft fork appears to have activated).
 755 |  
 756 | +- `LogWarnThenDebug(BCLog::CATEGORY, fmt, params...)` should be used

l0rinc commented at 11:22 AM on May 12, 2026:

e054403 util/log: Add LogWarnThenDebug() helper:

Nit: the Log prefix is kinda redundant, but it is consistent with the existing functions, so in this PR it makes sense to keep it (maybe in a follow-up we could remove it).

in src/netbase.cpp:967 in 05911121b7

 960 | @@ -961,7 +961,7 @@ CService GetBindAddress(const Sock& sock)
 961 |      if (sock.GetSockName(sa, &len) == 0) {
 962 |          addr_bind.SetSockAddr(sa, len);
 963 |      } else {
 964 | -        LogWarning("getsockname failed\n");
 965 | +        LogWarning("getsockname failed");
 966 |      }
 967 |      return addr_bind;
 968 |  }

l0rinc commented at 11:46 AM on May 12, 2026:

0591112 netbase: Tidy up logging levels:

Since we're already modifying it, maybe we could make it consistent with other similar calls and log the error:

    if (sock.GetSockName(sa, &len) != 0) {
        LogWarning("GetSockName failed: %s", NetworkErrorString(WSAGetLastError()));
    } else {
        addr_bind.SetSockAddr(sa, len);
    }

in src/kernel/coinstats.cpp:139 in 9bc68e5662

 135 | @@ -136,7 +136,7 @@ static std::optional<CCoinsStats> ComputeUTXOStats(T hash_obj, CCoinsView* view,
 136 |              outputs[key.n] = std::move(coin);
 137 |              stats.coins_count++;
 138 |          } else {
 139 | -            LogError("%s: unable to read value\n", __func__);
 140 | +            LogDebug(BCLog::COINDB, "%s: unable to read value", __func__);

l0rinc commented at 11:54 AM on May 12, 2026:

9bc68e5 kernel/coinstats: Downgrade ComputeUTXOStates log level:

It seems to me that every single caller checks the result, usually returning an Error or throwing, so demoting this makes sense. Maybe we could extend the commit message with this info.

For consistency with other similar "unable to read" messages, and to continue our __func__ removals, maybe we could adjust this to something like:

            LogDebug(BCLog::COINDB, "ComputeUTXOStats: unable to read value for key %s", key.ToString());

in src/util/log.h:127 in e054403acc

 122 | @@ -123,4 +123,15 @@ inline void LogPrintFormatInternal(SourceLocation&& source_loc, BCLog::LogFlags
 123 |  #define LogDebug(category, ...) detail_LogIfCategoryAndLevelEnabled(category, BCLog::Level::Debug, __VA_ARGS__)
 124 |  #define LogTrace(category, ...) detail_LogIfCategoryAndLevelEnabled(category, BCLog::Level::Trace, __VA_ARGS__)
 125 |  
 126 | +// Log unconditionally the first time this statement is hit, then conditionally afterwards
 127 | +#define LogWarnThenDebug(category, ...) \

l0rinc commented at 12:08 PM on May 12, 2026:

e054403 util/log: Add LogWarnThenDebug() helper:

Could we test the behavior of this newly added logger with a simple unit test, something like:

namespace {
void LogWarnThenDebugFromSameLocation(std::string_view message)
{
    LogWarnThenDebug(BCLog::NET, "warn_then_debug: %s", message);
}
} // namespace
BOOST_FIXTURE_TEST_CASE(logging_LogWarnThenDebug, LogSetup)
{
    LogWarnThenDebugFromSameLocation("first");
    LogWarnThenDebugFromSameLocation("suppressed");

    LogInstance().EnableCategory(BCLog::NET);
    LogWarnThenDebugFromSameLocation("debug");

    std::vector log_lines{ReadDebugLogLines()};
    std::vector<std::string> expected = {
        "[warning] warn_then_debug: first",
        "[net] warn_then_debug: debug",
    };
    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
}

in src/util/log.h:135 in e054403acc

 130 | +      if (!_warned.exchange(true)) { \
 131 | +          LogWarning(__VA_ARGS__); \
 132 | +      } else { \
 133 | +          LogDebug(category, __VA_ARGS__); \
 134 | +      } \
 135 | +   } while(0)

l0rinc commented at 12:19 PM on May 12, 2026:

e054403 util/log: Add LogWarnThenDebug() helper:

nit: The current _warned flag names the second state, so the first branch has to be expressed as a negation. Could this instead track whether the call site should still warn? That keeps the first-warning branch first and makes the condition read directly:

    do { \
        static std::atomic_bool _should_warn{true}; \
        if (_should_warn.exchange(false)) { \
            LogWarning(__VA_ARGS__); \
        } else { \
            LogDebug(category, __VA_ARGS__); \
        } \
    } while (0)

nit1: The formatting seems a bit off compared to detail_LogIfCategoryAndLevelEnabled, by one space per indentation level. nit2: We could use static std::atomic_bool _warned{false} here instead and add #include <atomic>. nit3: while is not a function, so I added a space after it.

in src/index/txindex.cpp:102 in 4410a0e8aa

  98 | @@ -99,7 +99,7 @@ bool TxIndex::FindTx(const Txid& tx_hash, uint256& block_hash, CTransactionRef&
  99 |  
 100 |      AutoFile file{m_chainstate->m_blockman.OpenBlockFile(postx, true)};
 101 |      if (file.IsNull()) {
 102 | -        LogError("OpenBlockFile failed");
 103 | +        LogWarning("%s: OpenBlockFile failed", GetName());

l0rinc commented at 12:27 PM on May 12, 2026:

4410a0e txindex: Downgrade log messages and include index name:

We've added the index names, maybe we could add a bit more info:

        LogWarning("%s: failed to open block file for tx %s at %s",
                   GetName(), tx_hash.ToString(), postx.ToString());

and the later ones:

        LogWarning("%s: failed to read tx %s at %s offset %s: %s",
                   GetName(), tx_hash.ToString(), postx.ToString(), postx.nTxOffset, e.what());

and

        LogWarning("%s: txid mismatch for tx %s at %s offset %s (read %s)",
                   GetName(), tx_hash.ToString(), postx.ToString(), postx.nTxOffset, tx->GetHash().ToString());

in src/netbase.cpp:514 in ec2a8c7215

 513 |          if (InterruptibleRecv(pchRet3, 2, g_socks5_recv_timeout, sock) != IntrRecvError::OK) {
 514 | -            LogError("Error reading from proxy\n");
 515 | +            LogDebug(BCLog::PROXY, "Error reading from SOCKS5 proxy");
 516 |              return false;
 517 |          }
 518 |          LogDebug(BCLog::NET, "SOCKS5 connected %s\n", strDest);

l0rinc commented at 12:32 PM on May 12, 2026:

ec2a8c7 netbase: Reduce levels of socks5 error logging:

Slightly unrelated, but some connection-management diagnostics outside netbase may still be repeated in logs for ordinary retries, e.g. https://github.com/bitcoin/bitcoin/blob/10ca73c02cbff59f2134c0c7da3b8d0a7e727475/src/net.cpp#L394 Maybe we could also change this one to something like:

LogDebug(BCLog::NET, "Failed to open new connection to %s, already connected", addrConnect.ToStringAddrPort());

l0rinc approved

l0rinc commented at 12:40 PM on May 12, 2026: contributor

The changes make sense to me, Concept ACK. I would also be fine merging as-is, but please consider the few remaining comments.

ryanofsky commented at 5:30 PM on May 18, 2026: contributor

Code review ACK 5359a99eb9b5bd442daee6c35d133ee5ea9f6583. Concept -0 as explained in previous review (because this makes it harder to tell when errors are happening). No changes since previous review other than rebase.

DrahtBot requested review from l0rinc on May 18, 2026