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.

Reviews

See the guideline for information on the review process.

Type	Reviewers
Stale ACK	kevkevinpal, ryanofsky

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:

#34520 (refactor: Add [[nodiscard]] to functions returning bool+mutable ref by maflcko)

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.

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

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