Make logging for validation optional #6519

laanwj · 2015-08-05T13:36:27Z

Avoid ERROR messages like ERROR: AcceptToMemoryPool : non-final. Logging of incoming transaction validation failures can be enabled optionally with-debug=mempoolrej.

Also introduces a consistent format for transaction validation failures that always includes the txid.

2015-08-05 13:25:26 txfail 4e5014c4084aab04aac280e4dc6e26ffbc76ea0feb817b98a1a67d8b18d4e80b: AcceptToMemoryPool: inputs already spent

I have opted for this approach instead of the one outlined in #5794 to remove all messages, because they provide extra troubleshooting information.

Fixes #5794.

sipa · 2015-08-05T13:52:00Z

Hmm, have you considered to not print the error immediately, but only report through ValidationState, and then have ProcessMessage choose (optionally) to report the error string it, if any?

That's also more compatible with future modularization of the consensus code, where you want to do the actual logging externally.

laanwj · 2015-08-05T14:59:07Z

Yes let's do that...

Add a field `strDebugMessage` which can be passed to DoS or Invalid, and queried using GetDebugMessage() to add extra troubleshooting information to the validation state.

laanwj · 2015-08-06T08:19:45Z

Done. CValidationState is augmented with optional debug information, which is logged upstream where possible.

This makes the change larger than originally intended, but the end result is better.
See commit messages/details for more information.

N.B.: I've also removed the logging in CScriptCheck::operator()(). This is consistent but I'm uncertain about this, because this means that the script error is no longer logged in case of verification through CCheckQueue (so in the case of blocks). However it is logged when called directly from CheckInputs (https://github.com/bitcoin/bitcoin/blob/master/src/main.cpp#L1394).

sipa · 2015-08-06T09:32:19Z

src/main.cpp

+{
+    return strprintf("%s%s (code %i)",
+        state.GetRejectReason(),
+        state.GetDebugMessage().empty() ? "" : (", "+state.GetDebugMessage()),


No closing bracket?

The bracket is not in the string.

Removed the parenthesis around ", "+... - they made the code harder to read instead of easier.

sipa · 2015-08-06T09:46:06Z

@laanwj That's not very consistent, as I think that means it will be printed with -par=1 and not with other values. I don't know of a better solution, though.

laanwj · 2015-08-06T09:49:11Z

@sipa So we just call par=1 mode 'safe mode with debugging'. Voila.

sipa · 2015-08-06T10:01:08Z

Untested ACK (but see nit about closing bracket).

dexX7 · 2015-08-07T20:50:38Z

Also introduces a consistent format for transaction validation failures that always includes the txid.

Great PR, I'm running it for some hours, and this is really useful!

morcos · 2015-08-10T18:34:52Z

src/main.h

+ * for transactions, to signal internal conditions. They cannot and should not
+ * be sent over the P2P network.
+ */
+static const unsigned int REJECT_INTERNAL = 0x100;
 /** local "reject" message codes for RPC which can not be triggered by p2p trasactions */


This comment isn't accurate is it?

Correct. This comment only holds for HIGHFEE.

morcos · 2015-08-10T18:37:21Z

I really like this idea, there are going to be a whole slew of new possible reject reasons with 6470 and with limited mempool chains. It will be nice to be able to output them in debugging situations.

dcousens · 2015-08-11T04:21:19Z

concept ACK

skarra · 2015-08-11T10:46:48Z

👍

Add status codes specific to AcceptToMempool procession of transactions. These can never happen due to block validation, and must never be sent over the P2P network. Add assertions where appropriate.

It is necessary to be able to concisely log a validation state. Convert CValidationState to a human-readable message for logging.

Remove unnecessary direct logging in CheckTransaction, AcceptToMemoryPool, CheckTxInputs, CScriptCheck::operator() All status information should be returned in the CValidationState. Relevant debug information is also added to the CValidationState using the recently introduced debug message. Do keep the "BUG! PLEASE REPORT THIS! ConnectInputs failed against MANDATORY but not STANDARD flags" error as it is meant to appear as bug in the log.

Add detailed state information to the errors, as it is no longer being logged downstream. Also add the state information to mempool rejection debug message in ProcessMessages.

Move mempool rejections to debug category `mempoolrej`, to make it possible to show them without enabling the entire category `mempool` which is high volume.

7f1f8f5 Move mempool rejections to new debug category (Wladimir J. van der Laan) 66daed5 Add information to errors in ConnectBlock, CheckBlock (Wladimir J. van der Laan) 6cab808 Remove most logging from transaction validation (Wladimir J. van der Laan) 9003c7c Add function to convert CValidationState to a human-readable message (Wladimir J. van der Laan) dc58258 Introduce REJECT_INTERNAL codes for local AcceptToMempool errors (Wladimir J. van der Laan) fbf44e6 Add debug message to CValidationState for optional extra information (Wladimir J. van der Laan)

droark · 2015-08-12T04:23:45Z

src/main.h

+ * for transactions, to signal internal conditions. They cannot and should not
+ * be sent over the P2P network.
+ */
+static const unsigned int REJECT_INTERNAL = 0x100;


Just curious, was the duplication of the REJECT_HIGHFEE value intentional?

jtimon · 2015-09-03T20:27:57Z

I've been trying to "move error messages up" for consensus and policy functions in different ways and with multiple attempts since at least January 15th 2015 (the first version of #5669 which also moved CheckTransaction to consensus/consensus did that).
I would have appreciated to be asked for review on this one. Now it's too late to complain about its flaws but I still will do it.

It is necessary to be able to concisely log a validation state. Convert CValidationState to a human-readable message for logging. Github-Pull: bitcoin#6519 Rebased-From: 9003c7c

Continues "Make logging for validation optional" from bitcoin#6519. The idea there was to remove all ERROR logging of rejected transaction, and move it to one message in the class 'mempoolrej' which logs the state message (and debug info). The superfluous ERRORs in the log "terrify" users, see for example issue bitcoin#5794. Unfortunately a lot of new logging was introduced in bitcoin#6871 (RBF) and bitcoin#7287 (misc refactoring). This pull updates that new code.

ca489c9 [Tests] Fix expected error messages (random-zebra) 9f84c52 Consensus: Remove calls to error() and FormatStateMessage() (random-zebra) 0e4d964 Move mempool rejections to new debug category (random-zebra) e0db16d Add information to errors in ConnectBlock, CheckBlock (random-zebra) d4ed81c Remove most logging from transaction validation (random-zebra) 94b2577 Add function to convert CValidationState to a human-readable message (random-zebra) 1ddc88f Introduce REJECT_INTERNAL codes for local AcceptToMempool errors (random-zebra) 55e00a2 Add debug message to CValidationState for optional extra information (random-zebra) 05cf74b Add absurdly high fee message to validation state (for RPC propagation) (random-zebra) Pull request description: - change `CValidationState::chRejectCode` to int - add `CValidationState::strDebugMessage` for optional information - add `FormatStateMessage` function to convert CValidationState to a human-readable message - introduce REJECT_INTERNAL rejection codes for ATMP and make their logging optional - remove unnecessary direct logging in `CheckTransaction`, `AcceptToMemoryPool`, `CheckTxInputs`, `CScriptCheck::operator()` - add detailed state information to the errors in `CheckBlock` and `ConnectBlock` Backported from: - bitcoin#5913 - bitcoin#6519 - bitcoin#7287 ACKs for top commit: Fuzzbawls: ACK ca489c9 furszy: re ACK ca489c9 and merging Tree-SHA512: ab972801fa45c2f84abf84790b0f0f22dc5668e170f51785f3cfbf806bda7988f55bbd43c24ae591ffe3bd62190f6cd99a3b640373c431ab92c0ddcabea1c999

ZIP 239 preparations 4 Cherry-picked from the following upstream PRs: - bitcoin/bitcoin#5913 - Replaces #3111. - Includes an extra commit included by upstream in the merge outside the PR. - bitcoin/bitcoin#6519 - bitcoin/bitcoin#7179 - bitcoin/bitcoin#7853 - bitcoin/bitcoin#7960

laanwj added the Validation label Aug 5, 2015

laanwj mentioned this pull request Aug 5, 2015

Add absurdly high fee message to validation state #5913

Merged

Add debug message to CValidationState for optional extra information

fbf44e6

Add a field `strDebugMessage` which can be passed to DoS or Invalid, and queried using GetDebugMessage() to add extra troubleshooting information to the validation state.

laanwj force-pushed the 2015_08_validation_error_spam branch from 72a3bb7 to 0cbeb26 Compare August 6, 2015 08:07

sipa reviewed Aug 6, 2015
View reviewed changes

laanwj force-pushed the 2015_08_validation_error_spam branch from 0cbeb26 to 72f7864 Compare August 6, 2015 10:12

morcos reviewed Aug 10, 2015
View reviewed changes

dcousens mentioned this pull request Aug 11, 2015

Downgrade ERROR to something less less terrifying? #5794

Closed

laanwj added 5 commits August 11, 2015 17:29

Introduce REJECT_INTERNAL codes for local AcceptToMempool errors

dc58258

Add status codes specific to AcceptToMempool procession of transactions. These can never happen due to block validation, and must never be sent over the P2P network. Add assertions where appropriate.

Add function to convert CValidationState to a human-readable message

9003c7c

It is necessary to be able to concisely log a validation state. Convert CValidationState to a human-readable message for logging.

Add information to errors in ConnectBlock, CheckBlock

66daed5

Add detailed state information to the errors, as it is no longer being logged downstream. Also add the state information to mempool rejection debug message in ProcessMessages.

Move mempool rejections to new debug category

7f1f8f5

Move mempool rejections to debug category `mempoolrej`, to make it possible to show them without enabling the entire category `mempool` which is high volume.

laanwj force-pushed the 2015_08_validation_error_spam branch from 72f7864 to 7f1f8f5 Compare August 11, 2015 15:30

laanwj merged commit 7f1f8f5 into bitcoin:master Aug 11, 2015

droark reviewed Aug 12, 2015
View reviewed changes

jtimon mentioned this pull request Aug 20, 2015

Optimizations: Consensus: In AcceptToMemoryPool, ConnectBlock, and CreateNewBlock #6445

Closed

laanwj mentioned this pull request Nov 6, 2015

ERROR: AcceptToMemoryPool: non-final #6518

Closed

laanwj mentioned this pull request Dec 14, 2015

Separate RPC events from catch-all debug.log #7199

Closed

laanwj mentioned this pull request Feb 9, 2016

Double spends do not create a reject message #4057

Closed

laanwj mentioned this pull request Feb 24, 2016

mempool: Re-remove ERROR logging for mempool rejects #7592

Merged

str4d mentioned this pull request Feb 15, 2018

Ensure AcceptToMemoryPool is only called when chainActive is accurate zcash/zcash#2951

Open

random-zebra mentioned this pull request Jun 9, 2020

[Refactoring] CValidationState logging PIVX-Project/PIVX#1670

Merged

str4d mentioned this pull request Aug 13, 2021

ZIP 239 preparations 4 zcash/zcash#5275

Merged

bitcoin locked as resolved and limited conversation to collaborators Sep 8, 2021

Make logging for validation optional #6519

Make logging for validation optional #6519

Uh oh!

Conversation

laanwj commented Aug 5, 2015

Uh oh!

sipa commented Aug 5, 2015

Uh oh!

laanwj commented Aug 5, 2015

Uh oh!

laanwj commented Aug 6, 2015

Uh oh!

sipa Aug 6, 2015

Choose a reason for hiding this comment

Uh oh!

laanwj Aug 6, 2015

Choose a reason for hiding this comment

Uh oh!

laanwj Aug 6, 2015

Choose a reason for hiding this comment

Uh oh!

sipa commented Aug 6, 2015

Uh oh!

laanwj commented Aug 6, 2015

Uh oh!

sipa commented Aug 6, 2015

Uh oh!

dexX7 commented Aug 7, 2015

Uh oh!

morcos Aug 10, 2015

Choose a reason for hiding this comment

Uh oh!

laanwj Aug 11, 2015

Choose a reason for hiding this comment

Uh oh!

morcos commented Aug 10, 2015

Uh oh!

dcousens commented Aug 11, 2015

Uh oh!

skarra commented Aug 11, 2015

Uh oh!

droark Aug 12, 2015

Choose a reason for hiding this comment

Uh oh!

jtimon commented Sep 3, 2015

Uh oh!

Uh oh!