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.
This generalises the functionality introduced for PCP/NAT-PMP logging
in #34549.
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.
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | kevkevinpal, ryanofsky |
If your review is incorrectly listed, please copy-paste <!–meta-tag:bot-skip–> into the comment that the bot should ignore.
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.
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());
0 LogWarning(BCLog::VALIDATION, %s: Missing input %d in transaction \'%s\'", __func__, i, tx.GetHash().GetHex());
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());
0 LogWarning(BCLog::VALIDATION, "Block validation error: %s", state.ToString());
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
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);
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.
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);
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
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()));
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?
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)));
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
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);
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 then 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.
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.
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. ↩︎