Make logging for validation optional #6519

Merged
merged 6 commits into from Aug 11, 2015

Conversation

Projects
None yet
8 participants
@laanwj
Member

laanwj commented Aug 5, 2015

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.

@laanwj laanwj added the Validation label Aug 5, 2015

@sipa

This comment has been minimized.

Show comment
Hide comment
@sipa

sipa Aug 5, 2015

Member

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.

Member

sipa commented Aug 5, 2015

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

This comment has been minimized.

Show comment
Hide comment
@laanwj

laanwj Aug 5, 2015

Member

Yes let's do that...

Member

laanwj commented Aug 5, 2015

Yes let's do that...

Add debug message to CValidationState for optional extra information
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

This comment has been minimized.

Show comment
Hide comment
@laanwj

laanwj Aug 6, 2015

Member

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).

Member

laanwj commented Aug 6, 2015

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

View changes

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

This comment has been minimized.

@sipa

sipa Aug 6, 2015

Member

No closing bracket?

@sipa

sipa Aug 6, 2015

Member

No closing bracket?

This comment has been minimized.

@laanwj

laanwj Aug 6, 2015

Member

The bracket is not in the string.

@laanwj

laanwj Aug 6, 2015

Member

The bracket is not in the string.

This comment has been minimized.

@laanwj

laanwj Aug 6, 2015

Member

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

@laanwj

laanwj Aug 6, 2015

Member

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

@sipa

This comment has been minimized.

Show comment
Hide comment
@sipa

sipa Aug 6, 2015

Member

@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.

Member

sipa commented Aug 6, 2015

@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

This comment has been minimized.

Show comment
Hide comment
@laanwj

laanwj Aug 6, 2015

Member

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

Member

laanwj commented Aug 6, 2015

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

@sipa

This comment has been minimized.

Show comment
Hide comment
@sipa

sipa Aug 6, 2015

Member

Untested ACK (but see nit about closing bracket).

Member

sipa commented Aug 6, 2015

Untested ACK (but see nit about closing bracket).

@dexX7

This comment has been minimized.

Show comment
Hide comment
@dexX7

dexX7 Aug 7, 2015

Contributor

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!

Contributor

dexX7 commented Aug 7, 2015

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

View changes

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 has been minimized.

@morcos

morcos Aug 10, 2015

Member

This comment isn't accurate is it?

@morcos

morcos Aug 10, 2015

Member

This comment isn't accurate is it?

This comment has been minimized.

@laanwj

laanwj Aug 11, 2015

Member

Correct. This comment only holds for HIGHFEE.

@laanwj

laanwj Aug 11, 2015

Member

Correct. This comment only holds for HIGHFEE.

@morcos

This comment has been minimized.

Show comment
Hide comment
@morcos

morcos Aug 10, 2015

Member

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.

Member

morcos commented Aug 10, 2015

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

This comment has been minimized.

Show comment
Hide comment
@dcousens

dcousens Aug 11, 2015

Contributor

concept ACK

Contributor

dcousens commented Aug 11, 2015

concept ACK

@skarra

This comment has been minimized.

Show comment
Hide comment

skarra commented Aug 11, 2015

👍

laanwj added some commits Aug 6, 2015

Introduce REJECT_INTERNAL codes for local AcceptToMempool errors
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
It is necessary to be able to concisely log a validation state.
Convert CValidationState to a human-readable message for logging.
Remove most logging from transaction validation
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 information to errors in ConnectBlock, CheckBlock
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
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 laanwj merged commit 7f1f8f5 into bitcoin:master Aug 11, 2015

1 check was pending

continuous-integration/travis-ci/pr The Travis CI build is in progress
Details

laanwj added a commit that referenced this pull request Aug 11, 2015

Merge pull request #6519
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)
+ * for transactions, to signal internal conditions. They cannot and should not
+ * be sent over the P2P network.
+ */
+static const unsigned int REJECT_INTERNAL = 0x100;

This comment has been minimized.

@droark

droark Aug 12, 2015

Contributor

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

@droark

droark Aug 12, 2015

Contributor

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

@jtimon

This comment has been minimized.

Show comment
Hide comment
@jtimon

jtimon Sep 3, 2015

Member

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.

Member

jtimon commented Sep 3, 2015

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.

@jtimon

This comment has been minimized.

Show comment
Hide comment
@jtimon

jtimon Sep 3, 2015

WTF? why is this not in consensus/validation?
Since when are flags more readable by putting them in different places?

WTF? why is this not in consensus/validation?
Since when are flags more readable by putting them in different places?

luke-jr added a commit to luke-jr/bitcoin that referenced this pull request Nov 30, 2015

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

Github-Pull: #6519
Rebased-From: 9003c7c

luke-jr added a commit to luke-jr/bitcoin that referenced this pull request Dec 8, 2015

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

Github-Pull: #6519
Rebased-From: 9003c7c

laanwj added a commit to laanwj/bitcoin that referenced this pull request Feb 24, 2016

mempool: Reduce ERROR logging for mempool rejects
Continues "Make logging for validation optional" from #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 #5794.

Unfortunately a lot of new logging was introduced in #6871 (RBF) and
 #7287 (misc refactoring). This pull updates that new code.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment