ci: failure in `rpc_scanblocks.py`

fanquake commented at 3:45 pm on April 8, 2024: member

https://github.com/bitcoin/bitcoin/actions/runs/8600455763/job/23565458580?pr=29707#step:7:3826:

0  node0 2024-04-08T13:15:12.710688Z [httpworker.3] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getindexinfo user=__cookie__ 
1 test  2024-04-08T13:15:12.711000Z TestFramework (ERROR): Assertion failed 
2                                   Traceback (most recent call last):
3                                     File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/test_framework/test_framework.py", line 132, in main
4                                       self.run_test()
5                                     File "/Users/runner/work/bitcoin/bitcoin/ci/scratch/build/bitcoin-x86_64-apple-darwin/test/functional/rpc_scanblocks.py", line 49, in run_test
6                                       assert blockhash in out['relevant_blocks']
7                                   AssertionError
8 node0 2024-04-08T13:15:12.711330Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:51647

fanquake added the label Tests on Apr 8, 2024

maflcko commented at 9:04 am on April 9, 2024: member

Is this a race where a validation event is lost?

0 node0 2024-04-08T13:15:11.629578Z [httpworker.0] [validationinterface.cpp:212] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=2194b76c425a2423728356cb8b9c82ad89068bcddfe8dc287c93732fb3354b59 block height=201 
1...
2 node0 2024-04-08T13:15:11.629801Z [scheduler] [validationinterface.cpp:212] [operator()] [validation] BlockConnected: block hash=2194b76c425a2423728356cb8b9c82ad89068bcddfe8dc287c93732fb3354b59 block height=201 
3...
4 node0 2024-04-08T13:15:11.639724Z [basic block filter index] [index/base.cpp:209] [Sync] basic block filter index is enabled at height 200 
5...
6 node0 2024-04-08T13:15:11.641186Z [basic block filter index] [util/thread.cpp:22] [TraceThread] basic block filter index thread exit 
7...
8 node0 2024-04-08T13:15:12.710688Z [httpworker.3] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getindexinfo user=__cookie__

Not sure if this is a bug in the index logic, or if the test needs to first wait for the sync.

Moving self.wait_until(lambda: all(i["synced"] for i in node.getindexinfo().values())) before the generate should hide this issue in the test.

cc @furszy

maflcko added the label UTXO Db and Indexes on Apr 9, 2024

maflcko added the label RPC/REST/ZMQ on Apr 9, 2024

furszy commented at 9:44 am on April 9, 2024: member

Quick check, the index seems to not have processed the block by the time scanblocks() (line 48) is called. The getindexinfo()['synced'] value is set to true after the index initial sync. It does not tell us anything about tip scanning. So, we can change line 46 check to verify the latest block height instead of the synced value. And that should fix the issue:

 0diff --git a/test/functional/rpc_scanblocks.py b/test/functional/rpc_scanblocks.py
 1--- a/test/functional/rpc_scanblocks.py	(revision 496f38dab4ba4506e4b628cb08ce4e582d638d07)
 2+++ b/test/functional/rpc_scanblocks.py	(date 1712655455099)
 3@@ -43,7 +43,7 @@
 4         # mine a block and assure that the mined blockhash is in the filterresult
 5         blockhash = self.generate(node, 1)[0]
 6         height = node.getblockheader(blockhash)['height']
 7-        self.wait_until(lambda: all(i["synced"] for i in node.getindexinfo().values()))
 8+        self.wait_until(lambda: all(i["best_block_height"] == height for i in node.getindexinfo().values()))
 9 
10         out = node.scanblocks("start", [f"addr({addr_1})"])
11         assert blockhash in out['relevant_blocks']

maflcko commented at 9:51 am on April 9, 2024: member

@furszy Are you sure? The event at block height = 201 does not exist anymore, so I don’t think it will be processed at all.

To summarize my excerpts from above:

Block 201 is mined, the event is put on the scheduler, and the event is consumed
The background index build is completing for height 200, and the index will start to listen to events?
The block 201 event is already consumed, so wont make it to the index
What would happen if a block 202 event was fired at some point?

Basically, my question is if this is a bug in the index code, or in the test code.

furszy commented at 10:20 am on April 9, 2024: member

@furszy Are you sure? The event at block height = 201 does not exist anymore, so I don’t think it will be processed at all.

Hmm ok, what I said could be another issue.. nvm. The index will probably stop syncing if this happens.. throwing a “WARNING: Block %s does not connect to an ancestor of..”. Will do some tests.

maflcko removed the label Tests on Apr 9, 2024

maflcko added the label CI failed on Apr 9, 2024

emc99 commented at 5:00 pm on April 11, 2024: none

Who performs ci?

furszy commented at 3:56 pm on April 12, 2024: member

Will do some tests.

Update: working on a fix. Will push it next week.

fanquake commented at 9:44 am on April 16, 2024: member

https://cirrus-ci.com/task/4562186641604608?logs=ci#L4268

maflcko commented at 9:04 am on April 23, 2024: member

https://cirrus-ci.com/task/4813688014635008?logs=ci#L3947

 0 node1 2024-04-22T20:51:07.549912Z [scheduler] [index/base.cpp:293] [BlockConnected] BlockConnected: WARNING: Block 20c19368f5c214888708d959d40752a61a0c5e2fb5b331876693773c113e5da1 does not connect to an ancestor of known best chain (tip=39455d83324a3dbbb15712ab63dd2f96b45a30f271617aa16c12483a561f721c); not updating index 
 1...
 2 node0 2024-04-22T20:51:08.867727Z [httpworker.2] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=gettxoutproof user=__cookie__ 
 3 node0 2024-04-22T20:51:08.868609Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:52468 
 4 node0 2024-04-22T20:51:08.868676Z [httpworker.1] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=verifytxoutproof user=__cookie__ 
 5 node0 2024-04-22T20:51:08.869152Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:52468 
 6 node0 2024-04-22T20:51:08.869212Z [httpworker.0] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=gettxoutproof user=__cookie__ 
 7 node0 2024-04-22T20:51:08.869690Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:52468 
 8 node0 2024-04-22T20:51:08.869754Z [httpworker.3] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=verifytxoutproof user=__cookie__ 
 9 node0 2024-04-22T20:51:08.870171Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:52468 
10 node0 2024-04-22T20:51:08.870255Z [httpworker.2] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=gettxoutproof user=__cookie__ 
11 node0 2024-04-22T20:51:08.870831Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:52468 
12 node0 2024-04-22T20:51:08.870901Z [httpworker.1] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=verifytxoutproof user=__cookie__ 
13 node1 2024-04-22T20:51:08.871443Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:40722 
14 node1 2024-04-22T20:51:08.871537Z [httpworker.2] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=gettxoutproof user=__cookie__ 
15 node1 2024-04-22T20:51:08.952814Z [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention m_nodes_mutex, net.cpp:1860 started 
16 node1 2024-04-22T20:51:08.960851Z [msghand] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:3159 started 
17 node1 2024-04-22T20:51:08.960874Z [net] [logging/timer.h:58] [Log] [lock] Enter: lock contention m_nodes_mutex, net.cpp:1860 completed (8027μs) 
18 node1 2024-04-22T20:51:10.290329Z [httpworker.2] [index/base.cpp:380] [BlockUntilSyncedToCurrentChain] BlockUntilSyncedToCurrentChain: txindex is catching up on block notifications 
19 node1 2024-04-22T20:51:10.290819Z [msghand] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:3159 completed (1329471μs) 
20 test  2024-04-22T20:51:10.302000Z TestFramework (ERROR): JSONRPC error 
21                                   Traceback (most recent call last):
22                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
23                                       self.run_test()
24                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/rpc_txoutproof.py", line 76, in run_test
25                                       assert_equal(self.nodes[0].verifytxoutproof(self.nodes[1].gettxoutproof([txid_spent])), [txid_spent])
26                                                                                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
27                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/coverage.py", line 50, in __call__
28                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
29                                                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
30                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 129, in __call__
31                                       raise JSONRPCException(response['error'], status)
32                                   test_framework.authproxy.JSONRPCException: Transaction not yet in block (-5)

achow101 closed this on Apr 25, 2024

ci: failure in rpc_scanblocks.py #29831

ci: failure in `rpc_scanblocks.py` #29831