If we're unable to disconnect a block during normal operation, then that is a failure of our local system (such as disk failure) or the chain that we are on (eg CVE-2018-17144), but cannot be due to failure of the (more work) chain that we're trying to validate.
We should abort rather than stay on a less work chain.
Fixes #14341.
2552 | @@ -2551,6 +2553,9 @@ bool CChainState::ActivateBestChainStep(CValidationState& state, const CChainPar 2553 | // This is likely a fatal error, but keep the mempool consistent, 2554 | // just in case. Only remove from the mempool in this case. 2555 | UpdateMempoolForReorg(disconnectpool, false); 2556 | + if (!g_abort_node) {
Wouldn't it make more sense to move this check into AbortNode otherwise it seems that this is a flag to indicate the node should be aborted as opposed to a flag that indicates the nodes has been aborted via AbortNode.
So I was thinking that I didn't want to add a place to the code where we might call into AbortNode twice, but since I haven't analyzed exactly what happens in that case I wasn't sure I wanted to change any existing behavior if we're doing that somewhere already.
If everyone is comfortable with globally ensuring that AbortNode() enforces the 1 abort call limit, then I can move this in there, or otherwise perhaps I could just rename this variable to be a bit clearer?
I don't think it is worth the burden of having this undocumented global in the source code to ease today's review of the diff at the cost of all future review of the overall code.
I'd prefer to be consistent by allowing AbortNode to be called multiple times and then either overwriting the warning string or keeping the previous one, but special casing the reorg warning to not overwrite any previous warnings seems arbitrary.
Perhaps I should get rid of the call to AbortNode in DisconnectTip, and then do away with this new global and unconditionally call AbortNode in ABCStep? That would result in a behavior change for invalidateblock and certain failures in RewindBlockIndex, but that might actually be desirable anyway.
37 | + # attempt 38 | + self.nodes[1].generate(4) 39 | + connect_nodes(self.nodes[0], 1) 40 | + 41 | + # Check that node0 aborted 42 | + self.nodes[0].assert_debug_log("Failed to disconnect block")
Would be nice to limit the scope of this context to the minimum required (right after the wait_until). (Compare other uses of with node.assert_debug_log(expected_msgs=reason):)
Not sure I understand exactly how this is supposed to be used, but can you take a look at the fixup I just pushed and let me know if this is what you have in mind?
It is like a context manager that checks what lines get appended to the debug log during its use. And the shortest use seems to me
with self.nodes[0].assert_debug_log("Failed to disconnect block"):
connect_nodes(self.nodes[0], 1)
# Check that node0 aborted
self.log.info("Waiting for crash")
wait_until(lambda: self.nodes[0].is_node_stopped(), timeout=60)
#Exits here and checks debug log for error string
34 | + os.unlink(undo_file) 35 | + 36 | + # Connecting to a node with a more work chain will trigger a reorg 37 | + # attempt 38 | + self.nodes[1].generate(4) 39 | + with self.nodes[0].assert_debug_log("Failed to disconnect block"):
This fails for me with:
AssertionError: [node 0] Expected message "F" does not partially match log:
- 2019-02-01T18:00:39.595725Z Received a POST request for / from 127.0.0.1:41758
- 2019-02-01T18:00:39.595784Z ThreadRPCServer method=addnode user=__cookie__
- 2019-02-01T18:00:39.595808Z trying connection 127.0.0.1:11153 lastseen=0.0hrs
- 2019-02-01T18:00:39.596518Z Added connection peer=0
- 2019-02-01T18:00:39.596544Z sending version (114 bytes) peer=0
- 2019-02-01T18:00:39.596611Z send version message: version 70015, blocks=3, us=[::]:0, peer=0
- 2019-02-01T18:00:39.598387Z Received a POST request for / from 127.0.0.1:41758
- 2019-02-01T18:00:39.598441Z ThreadRPCServer method=getpeerinfo user=__cookie__
- 2019-02-01T18:00:39.645960Z received: version (114 bytes) peer=0
- 2019-02-01T18:00:39.646044Z sending verack (0 bytes) peer=0
- 2019-02-01T18:00:39.646189Z sending getaddr (0 bytes) peer=0
- 2019-02-01T18:00:39.646257Z receive version message: /Satoshi:0.17.99(testnode1)/: version 70015, blocks=4, us=[::]:0, peer=0
- 2019-02-01T18:00:39.646287Z added time data, samples 2, offset +0 (+0 minutes)
- 2019-02-01T18:00:39.646307Z received: verack (0 bytes) peer=0
- 2019-02-01T18:00:39.646319Z New outbound peer connected: version: 70015, blocks=4, peer=0
- 2019-02-01T18:00:39.646326Z sending sendheaders (0 bytes) peer=0
- 2019-02-01T18:00:39.646355Z sending sendcmpct (9 bytes) peer=0
- 2019-02-01T18:00:39.646390Z sending sendcmpct (9 bytes) peer=0
- 2019-02-01T18:00:39.646439Z sending ping (8 bytes) peer=0
- 2019-02-01T18:00:39.646505Z initial getheaders (2) to peer=0 (startheight:4)
- 2019-02-01T18:00:39.646522Z sending getheaders (133 bytes) peer=0
- 2019-02-01T18:00:39.646634Z sending feefilter (8 bytes) peer=0
- 2019-02-01T18:00:39.650027Z Received a POST request for / from 127.0.0.1:41758
- 2019-02-01T18:00:39.650092Z ThreadRPCServer method=getpeerinfo user=__cookie__
- 2019-02-01T18:00:39.650672Z received: sendheaders (0 bytes) peer=0
- 2019-02-01T18:00:39.650721Z received: sendcmpct (9 bytes) peer=0
- 2019-02-01T18:00:39.650737Z received: sendcmpct (9 bytes) peer=0
- 2019-02-01T18:00:39.650751Z received: ping (8 bytes) peer=0
- 2019-02-01T18:00:39.650763Z sending pong (8 bytes) peer=0
- 2019-02-01T18:00:39.650825Z received: getheaders (165 bytes) peer=0
- 2019-02-01T18:00:39.650841Z getheaders 1 to end from peer=0
- 2019-02-01T18:00:39.650854Z sending headers (244 bytes) peer=0
- 2019-02-01T18:00:39.650895Z received: feefilter (8 bytes) peer=0
- 2019-02-01T18:00:39.650907Z received: feefilter of 0.00001000 BTC/kB from peer=0
- 2019-02-01T18:00:39.650934Z received: pong (8 bytes) peer=0
- 2019-02-01T18:00:39.650950Z received: headers (325 bytes) peer=0
- 2019-02-01T18:00:39.651028Z Requesting block 031ddb2a71a0787d38ffcf11ac71c785003a4a4d05a79b6edac7f2e7c86728a6 from peer=0
- 2019-02-01T18:00:39.651035Z Requesting block 24466befe557061e633ff435931ce3d802ce50fbe93199b55a9b3d689e12b346 from peer=0
- 2019-02-01T18:00:39.651042Z Requesting block 72dc4f648af86c3051f264f161d5ca18283adbe9b2b16eed8763ed4594173a73 from peer=0
- 2019-02-01T18:00:39.651048Z Requesting block 22046fc9668cae25c57f70a4b02f8599320a259f63564de4d7cf15648cdd9910 from peer=0
- 2019-02-01T18:00:39.651054Z Downloading blocks toward 22046fc9668cae25c57f70a4b02f8599320a259f63564de4d7cf15648cdd9910 (4) via headers direct fetch
Could be fixed with
diff --git a/test/functional/feature_abortnode.py b/test/functional/feature_abortnode.py
index ad1b0cd8ca..9b5b3a67d1 100755
--- a/test/functional/feature_abortnode.py
+++ b/test/functional/feature_abortnode.py
@@ -36,12 +36,11 @@ class AbortNodeTest(BitcoinTestFramework):
# Connecting to a node with a more work chain will trigger a reorg
# attempt
self.nodes[1].generate(4)
- with self.nodes[0].assert_debug_log("Failed to disconnect block"):
+ with self.nodes[0].assert_debug_log(["Failed to disconnect block"]):
connect_nodes(self.nodes[0], 1)
-
- # Check that node0 aborted
- self.log.info("Waiting for crash")
- wait_until(lambda: self.nodes[0].is_node_stopped(), timeout=60)
+ # Check that node0 aborted
+ self.log.info("Waiting for crash")
+ wait_until(lambda: self.nodes[0].is_node_stopped(), timeout=60)
self.log.info("Node crashed - now verifying restart fails")
self.nodes[0].assert_start_raises_init_error()
Concept ACK.
Concept ACK. The test seems a little fragile (an unrelated change to rename undo files or merge them into block files would break it), but I don't see a better way to do it.
21 | + self.num_nodes = 2 22 | + 23 | + def setup_network(self): 24 | + self.setup_nodes() 25 | + # We'll connect the nodes later 26 | + pass
pass redundant?
Removed in latest commit.
Thanks @MarcoFalke I took your change to the test, hopefully it passes travis now. If it's too flaky though I'll just drop it from this PR.
Updated this PR to get rid of the g_abort_node global, and instead change DisconnectTip to no longer call AbortNode itself, and instead leave it to the caller to decide how to handle failures.
This slightly changes the behavior of invalidateblock and RewindBlockIndex -- I believe it's an improvement but reviewers should take note.
32 | + # Deleting the undo file will result in reorg failure 33 | + os.unlink(undo_file) 34 | + 35 | + # Connecting to a node with a more work chain will trigger a reorg 36 | + # attempt 37 | + self.nodes[1].generate(3)
Any reason to not generate 4 here instead?
Yes-- if you generate 4 here, then the call to connect_nodes() afterward can trigger a crash on node0 before the function returns, which causes problems for the test.
25 | + # We'll connect the nodes later 26 | + 27 | + def run_test(self): 28 | + self.nodes[0].generate(3) 29 | + datadir = get_datadir_path(self.options.tmpdir, 0) 30 | + undo_file = datadir + "/regtest/blocks/rev00000.dat"
Should use os.path.join.
nit, could inline this below
os.unlink(os.path.join(datadir, 'regtest', 'blocks', 'rev00000.dat'))
Done in latest commit.
11 | +""" 12 | + 13 | +from test_framework.test_framework import BitcoinTestFramework 14 | +from test_framework.util import wait_until, get_datadir_path, connect_nodes 15 | +import os 16 | +
nit, double new line.
I'm not seeing the extra new-line in our style guide, nor does it seem to be failing our style linter? Leaving as-is.
@sdaftuar in test/functional/README.md you see
- Where possible, try to adhere to PEP-8 guidelines
Then in https://www.python.org/dev/peps/pep-0008/#blank-lines you can see guide.
No this should not be changed. Unlike other rules in pep8, some of which prevent nasty bugs in python, having two or one new line is completely equivalent.
42 | + # Check that node0 aborted 43 | + self.log.info("Waiting for crash") 44 | + wait_until(lambda: self.nodes[0].is_node_stopped(), timeout=60) 45 | + self.log.info("Node crashed - now verifying restart fails") 46 | + self.nodes[0].assert_start_raises_init_error() 47 | +
nit, double new line.
<!--e57a25ab6845829454e8d69fc972939a-->
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
<!--174a7506f384e20aa4161008e828411d-->
No conflicts as of last run.
38 | + connect_nodes(self.nodes[0], 1) 39 | + self.nodes[1].generate(1) 40 | + 41 | + # Check that node0 aborted 42 | + self.log.info("Waiting for crash") 43 | + wait_until(lambda: self.nodes[0].is_node_stopped(), timeout=60)
Nit: Is the lambda needed here?
Concept ACK
2294 | @@ -2295,7 +2295,7 @@ bool CChainState::DisconnectTip(CValidationState& state, const CChainParams& cha 2295 | std::shared_ptr<CBlock> pblock = std::make_shared<CBlock>(); 2296 | CBlock& block = *pblock; 2297 | if (!ReadBlockFromDisk(block, pindexDelete, chainparams.GetConsensus())) 2298 | - return AbortNode(state, "Failed to read block");
In commit "[validation] Crash if disconnecting a block fails" (dafa0b7e1615a4e0985ece5d5f044f14753edcf6)
Note: I was initially confused by the change to this line which removes an existing abort call. But this is just cleanup. Aborting here would be redundant with the new abort call below, which is broader and covers more failure cases.
utACK daf67ad1d3cd6de67776fa26d49e6b1ba66aae7d. Or slightly tested. Confirmed that when the fix is reverted, wait_until in the test times out.
2550 | @@ -2551,6 +2551,7 @@ bool CChainState::ActivateBestChainStep(CValidationState& state, const CChainPar 2551 | // This is likely a fatal error, but keep the mempool consistent, 2552 | // just in case. Only remove from the mempool in this case. 2553 | UpdateMempoolForReorg(disconnectpool, false); 2554 | + AbortNode(state, "Failed to disconnect block; see debug.log for details");
In commit "[validation] Crash if disconnecting a block fails" (dafa0b7e1615a4e0985ece5d5f044f14753edcf6)
Probably would be good to have a comment saying that it's better to abort than stay active using a chain that doesn't have the most work (so it's clear that handling the error this way is really intentional and this isn't just fragile code).
Done.
If we're unable to disconnect a block during normal operation, then that is a
failure of our local system (such as disk failure) or the chain that we are on
(eg CVE-2018-17144), but cannot be due to failure of the (more work) chain that
we're trying to validate.
We should abort rather than stay on a less work chain.
Added a comment as @ryanofsky requested.
utACK a47df13471e3168e2e02023fb20cdf2414141b36. Only change since last review is new comment.
utACK a47df13471e3168e2e02023fb20cdf2414141b36
32 | + os.unlink(os.path.join(datadir, 'regtest', 'blocks', 'rev00000.dat')) 33 | + 34 | + # Connecting to a node with a more work chain will trigger a reorg 35 | + # attempt. 36 | + self.nodes[1].generate(3) 37 | + with self.nodes[0].assert_debug_log(["Failed to disconnect block"]):
nit, use ' throughout.
ACK a47df1347, it takes awhile to quit (RPC connection timeouts) but that's unrelated - hope to fix that soon.
Left 2 nits and a suggestion to improve the test Here's
@@ -11,6 +11,7 @@
"""
from test_framework.test_framework import BitcoinTestFramework
+from test_framework.test_node import ErrorMatch
from test_framework.util import wait_until, get_datadir_path, connect_nodes
import os
@@ -42,7 +43,9 @@ class AbortNodeTest(BitcoinTestFramework):
self.log.info("Waiting for crash")
wait_until(lambda: self.nodes[0].is_node_stopped(), timeout=60)
self.log.info("Node crashed - now verifying restart fails")
- self.nodes[0].assert_start_raises_init_error()
+ self.nodes[0].assert_start_raises_init_error(expected_msg='Corrupted block database detected', match=ErrorMatch.PARTIAL_REGEX)
+
+ self.start_node(0, ['-reindex'])
if __name__ == '__main__':
AbortNodeTest().main()
utACK a47df13471e3168e2e02023fb20cdf2414141b36. Didn't bother to review the test in detail, it looked fine. Debated whether invalidateblock should ever crash the node, but not crashing in the case of hitting a pruned block (which is the only change here) is clearly better, even if there are other cases I'd argue we should crash in.
Anything else needed here?
ACK a47df13471e3168e2e02023fb20cdf2414141b36
I'll leave the test nits alone for now, someone can pick up in a future PR if there's interest.
Agree
even if there are other cases I'd argue we should crash in. @TheBlueMatt Did you want to open an issue listing these cases, or just dump out your thoughts?