Remove extraneous ERROR messages where they give no extra information #4848

rebroad commented at 7:21 AM on September 5, 2014: contributor

This will help to reduce the debug.log output in some cases by two unnecessary additional lines.

(debug=mempool will need to be in bitcoin.conf to ensure the error is still captured in debug.log)

Remove extraneous ERROR messages where they give no additional information. dbc2fcbabe

Enable this debugging always now that the previous error messages are no longer logged. 3f6cba8825

rebroad force-pushed on Sep 5, 2014

BitcoinPullTester commented at 7:50 AM on September 5, 2014: none

Automatic sanity-testing: PASSED, see http://jenkins.bluematt.me/pull-tester/p4848_3f6cba882540c884a10d171b5f834026e4f4ef99/ for binaries and test log. This test script verifies pulls every time they are updated. It, however, dies sometimes and fails to test properly. If you are waiting on a test, please check timestamps to verify that the test.log is moving at http://jenkins.bluematt.me/pull-tester/current/ Contact BlueMatt on freenode if something looks broken.

jgarzik commented at 1:46 AM on September 15, 2014: contributor

ut ACK

However, I will note a minor concern (technical debt). Now that this message is enabled unconditionally, a non-debug configuration might spew more data to log than wanted during an attack.

This seems like the sort of thing I could see rate-limiting in the future.

rebroad commented at 2:13 PM on September 15, 2014: contributor

@jgarzik yes, an attack would still cause data spew, but with this patch it would be half as much as before the patch (with debug off. With debug on, it would be one third).

sipa commented at 1:14 AM on September 16, 2014: member

ut ACK

laanwj commented at 9:39 AM on September 16, 2014: member

I don't like creating any more technical debt. Can we avoid that?

rebroad commented at 3:01 PM on September 17, 2014: contributor

@laanwj where is the technical debt?

laanwj commented at 8:43 AM on September 18, 2014: member

@rebroad Technical debt is a term for "things that are postponed to be solved at some later date". Sometimes it is acceptable to increase technical debt, but only for important things that have to be fixed asap. Not for some silly logging change. I was referring to jgarzik's post above.

in src/main.cpp:None in 3f6cba8825

3819 | @@ -3820,9 +3820,8 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv,
3820 |          int nDoS = 0;
3821 |          if (state.IsInvalid(nDoS))
3822 |          {
3823 | -            LogPrint("mempool", "%s from peer=%d %s was not accepted into the memory pool: %s\n", tx.GetHash().ToString(),
3824 | -                pfrom->id, pfrom->cleanSubVer,
3825 | -                state.GetRejectReason());
3826 | +            LogPrintf("mempool: %s not accepted from peer=%d %s: %s\n", inv.ToString(),
3827 | +                pfrom->id, pfrom->cleanSubVer.substr(0,20), state.GetRejectReason());

laanwj commented at 8:32 AM on September 25, 2014:

Isn't the point of cleanSubVer already that it is cleaned for logging purposes? I don't see the point of doing another substr() here.

rebroad commented at 9:56 AM on September 26, 2014:

This string can be rather long sometimes. The full string is shown upon initial connection in the log. On Sep 25, 2014 4:32 PM, "Wladimir J. van der Laan" < notifications@github.com> wrote:

In src/main.cpp:
@@ -3820,9 +3820,8 @@ bool static ProcessMessage(CNode* pfrom, string strCommand, CDataStream& vRecv, int nDoS = 0; if (state.IsInvalid(nDoS)) {
       LogPrint("mempool", "%s from peer=%d %s was not accepted into the memory pool: %s\n", tx.GetHash().ToString(),
           pfrom->id, pfrom->cleanSubVer,
           state.GetRejectReason());
       LogPrintf("mempool: %s not accepted from peer=%d %s: %s\n", inv.ToString(),
           pfrom->id, pfrom->cleanSubVer.substr(0,20), state.GetRejectReason());
Isn't the point of cleanSubVer already that it is cleaned for logging purposes? I don't see the point of doing another substr() here.

— Reply to this email directly or view it on GitHub https://github.com/bitcoin/bitcoin/pull/4848/files#r18020393.

Diapolo commented at 4:24 PM on November 21, 2014: none

Is this still current? Needed at all now?

gmaxwell commented at 8:34 PM on November 21, 2014: contributor

I'm torn about this: I don't like giving peers DOS without any record as to why, and these log messages have been very helpful for debugging in the past (e.g. related to vin empty there was a bitcoin core wallet bug). OTOH, I don't think the word "Error" should ever show up in the log unless either the user's hardware is broken or there is a serious software/network issue that we'd like to hear about.

laanwj added the label Docs and Output on Dec 5, 2014

laanwj commented at 3:40 PM on January 7, 2015: member

We could just remove the word Error and log them as informational messages.

In any case, needs rebase.

laanwj commented at 1:37 PM on January 8, 2015: member

On second thought, I'm going to close this. I agree with @gmaxwell, but IMO that should be fixed for the entire code base at once, not incrementally. All uses of error will have to be considered to be changed to something else like info (or alternatively, to reduce diff size, do it analogous to arith_uint256 and change error to a function that just logs an informational message, and introduce a serious_error for ERROR:...).

laanwj closed this on Jan 8, 2015

sipa commented at 1:43 PM on January 8, 2015: member

I do think that many of these can actually just go away now, as the actual problem that occurred is propagated up using CValidationState, which can be reported at the top level.

MarcoFalke locked this on Sep 8, 2021