Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Windows Python: Intermittent issue in p2p_unrequested_blocks.py", line 98, in run_test test_node.send_and_ping(msg_block(blocks_h2[0])) assert self.is_connected AssertionError / AcceptBlock FAILED (time-too-old, block's timestamp is too early) #29897

Open
maflcko opened this issue Apr 16, 2024 · 2 comments
Open

Windows Python: Intermittent issue in p2p_unrequested_blocks.py", line 98, in run_test test_node.send_and_ping(msg_block(blocks_h2[0])) assert self.is_connected AssertionError / AcceptBlock FAILED (time-too-old, block's timestamp is too early) #29897

maflcko opened this issue Apr 16, 2024 · 2 comments
Labels
CI failed Upstream Windows

Comments

@maflcko
Copy link
Member

maflcko commented Apr 16, 2024

https://github.com/bitcoin/bitcoin/actions/runs/8689751788/job/23828088498?pr=29877#step:27:584

node0 2024-04-15T13:27:36.008782Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:4743] [ProcessMessage] [net] received block 20076ff9e9d9bace59d7621747b34dfb4af9b2f75ff499017397854f9fefb930 peer=0 
 node0 2024-04-15T13:27:36.008822Z [D:\a\bitcoin\bitcoin\src\validation.cpp:4145] [AcceptBlockHeader] [validation] AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 20076ff9e9d9bace59d7621747b34dfb4af9b2f75ff499017397854f9fefb930, time-too-old, block's timestamp is too early 
 node0 2024-04-15T13:27:36.008857Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:245] [BlockChecked] [validation] BlockChecked: block hash=20076ff9e9d9bace59d7621747b34dfb4af9b2f75ff499017397854f9fefb930 state=time-too-old, block's timestamp is too early 
 node0 2024-04-15T13:27:36.008883Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:1827] [Misbehaving] [net] Misbehaving: peer=0 (0 -> 100) DISCOURAGE THRESHOLD EXCEEDED 
Error: 2024-04-15T13:27:36.008905Z [D:\a\bitcoin\bitcoin\src\validation.cpp:4396] [ProcessNewBlock] [error] ProcessNewBlock: AcceptBlock FAILED (time-too-old, block's timestamp is too early) 
 node0 2024-04-15T13:27:36.008927Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:5067] [MaybeDiscourageAndDisconnect] [net] Warning: disconnecting but not discouraging local peer 0! 
 node0 2024-04-15T13:27:36.009001Z [D:\a\bitcoin\bitcoin\src\net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=0 
 node0 2024-04-15T13:27:36.009142Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=0 
 test  2024-04-15T13:27:36.058000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 132, in main
                                       self.run_test()
                                     File "D:\a\bitcoin\bitcoin/test/functional/p2p_unrequested_blocks.py", line 98, in run_test
                                       test_node.send_and_ping(msg_block(blocks_h2[0]))
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 686, in send_and_ping
                                       self.sync_with_ping(timeout=timeout)
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 699, in sync_with_ping
                                       self.wait_until(test_function, timeout=timeout)
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 586, in wait_until
                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor)
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\util.py", line 279, in wait_until_helper_internal
                                       if predicate():
                                          ^^^^^^^^^^^
                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 583, in test_function
                                       assert self.is_connected
                                   AssertionError
@maflcko
Copy link
Member Author

maflcko commented Apr 18, 2024

This is the known bug on Windows Python, where the time.time() returned is just wrong. See #25482 (comment)

@maflcko
Copy link
Member Author

maflcko commented Apr 18, 2024

CI log excerpt 
2024-04-15T13:27:36.5164046Z  test  2024-04-15T13:27:35.999000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11540: msg_block(block=CBlock(nVersion=4 hashPrevBlock=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe hashMerkleRoot=894d347901f746841d50a120c07cf7ae0dc1d8afed389e63ad1032d8d4dfbcf1 nTime=Mon Apr 15 13:27:36 2024 nBits=207fffff nNonce=00000000 vtx=[CTransaction(nVersion=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=5251 nSequence=4294967295)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=51)] wit=CTxWitness(... (msg truncated) 
2024-04-15T13:27:36.5169619Z  test  2024-04-15T13:27:35.999000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11540: msg_ping(nonce=00000000) 
2024-04-15T13:27:36.5171638Z  test  2024-04-15T13:27:35.999000Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:11540: msg_ping(nonce=00000002) 
2024-04-15T13:27:36.5173897Z  test  2024-04-15T13:27:35.999000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:11540 
2024-04-15T13:27:36.5176109Z  node1 2024-04-15T13:27:36.000002Z [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:62213 
2024-04-15T13:27:36.5178719Z  node1 2024-04-15T13:27:36.000098Z [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:187] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__ 
2024-04-15T13:27:36.5181342Z  node0 2024-04-15T13:27:36.001243Z [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:62212 
2024-04-15T13:27:36.5183988Z  node0 2024-04-15T13:27:36.001349Z [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:187] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__ 
2024-04-15T13:27:36.5186739Z  node0 2024-04-15T13:27:36.001459Z [D:\a\bitcoin\bitcoin\src\node\miner.cpp:163] [CreateNewBlock] CreateNewBlock(): block weight: 896 txs: 0 fees: 0 sigops 400 
2024-04-15T13:27:36.5189379Z  node0 2024-04-15T13:27:36.001518Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2337] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
2024-04-15T13:27:36.5191915Z  node0 2024-04-15T13:27:36.001555Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2439] [ConnectBlock] [bench]     - Fork checks: 0.04ms [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5194962Z  node0 2024-04-15T13:27:36.001585Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2531] [ConnectBlock] [bench]       - Connect 1 transactions: 0.03ms (0.026ms/tx, 0.000ms/txin) [0.00s (0.01ms/blk)] 
2024-04-15T13:27:36.5198997Z  node0 2024-04-15T13:27:36.001614Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2549] [ConnectBlock] [bench]     - Verify 0 txins: 0.06ms (0.000ms/txin) [0.00s (0.03ms/blk)] 
2024-04-15T13:27:36.5202246Z  node0 2024-04-15T13:27:36.001642Z [D:\a\bitcoin\bitcoin\src\node\miner.cpp:182] [CreateNewBlock] [bench] CreateNewBlock() packages: 0.01ms (0 packages, 0 updated descendants), validity: 0.20ms (total 0.21ms) 
2024-04-15T13:27:36.5205650Z  node0 2024-04-15T13:27:36.001681Z [D:\a\bitcoin\bitcoin\src\validation.cpp:4209] [AcceptBlockHeader] [validation] Saw new header hash=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe height=1 
2024-04-15T13:27:36.5208302Z  node0 2024-04-15T13:27:36.002059Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3007] [ConnectTip] [bench]   - Using cached block 
2024-04-15T13:27:36.5210424Z  node0 2024-04-15T13:27:36.002085Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3017] [ConnectTip] [bench]   - Load block from disk: 0.02ms 
2024-04-15T13:27:36.5212760Z  node0 2024-04-15T13:27:36.002114Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2337] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
2024-04-15T13:27:36.5215173Z  node0 2024-04-15T13:27:36.002140Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2439] [ConnectBlock] [bench]     - Fork checks: 0.03ms [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5217906Z  node0 2024-04-15T13:27:36.002175Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2531] [ConnectBlock] [bench]       - Connect 1 transactions: 0.03ms (0.031ms/tx, 0.000ms/txin) [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5220782Z  node0 2024-04-15T13:27:36.002201Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2549] [ConnectBlock] [bench]     - Verify 0 txins: 0.06ms (0.000ms/txin) [0.00s (0.04ms/blk)] 
2024-04-15T13:27:36.5223646Z  node0 2024-04-15T13:27:36.002630Z [D:\a\bitcoin\bitcoin\src\flatfile.cpp:69] [Allocate] [validation] Pre-allocating up to position 0x100000 in rev00000.dat 
2024-04-15T13:27:36.5226339Z  node0 2024-04-15T13:27:36.003087Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2563] [ConnectBlock] [bench]     - Write undo data: 0.88ms [0.00s (0.29ms/blk)] 
2024-04-15T13:27:36.5228941Z  node0 2024-04-15T13:27:36.003114Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2578] [ConnectBlock] [bench]     - Index writing: 0.04ms [0.00s (0.01ms/blk)] 
2024-04-15T13:27:36.5232195Z  node0 2024-04-15T13:27:36.003137Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:245] [BlockChecked] [validation] BlockChecked: block hash=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe state=Valid 
2024-04-15T13:27:36.5235317Z  node0 2024-04-15T13:27:36.003165Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3036] [ConnectTip] [bench]   - Connect total: 1.08ms [0.00s (0.39ms/blk)] 
2024-04-15T13:27:36.5237787Z  node0 2024-04-15T13:27:36.003193Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3045] [ConnectTip] [bench]   - Flush: 0.03ms [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5240185Z  node0 2024-04-15T13:27:36.003215Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3055] [ConnectTip] [bench]   - Writing chainstate: 0.02ms [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5243321Z  node0 2024-04-15T13:27:36.003235Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:222] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=1 txs removed=0 
2024-04-15T13:27:36.5246495Z  node0 2024-04-15T13:27:36.003274Z [D:\a\bitcoin\bitcoin\src\validation.cpp:1848] [IsInitialBlockDownload] Leaving InitialBlockDownload (latching to false) 
2024-04-15T13:27:36.5265068Z  node0 2024-04-15T13:27:36.003315Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:222] [operator ()] [validation] MempoolTransactionsRemovedForBlock: block height=1 txs removed=0 
2024-04-15T13:27:36.5269308Z  node0 2024-04-15T13:27:36.003371Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2814] [UpdateTipLog] UpdateTip: new best=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe height=1 version=0x20000000 log2_work=2.000000 tx=2 date='2024-04-15T13:27:36Z' progress=1.000000 cache=0.3MiB(1txo) 
2024-04-15T13:27:36.5272872Z  node0 2024-04-15T13:27:36.003394Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3071] [ConnectTip] [bench]   - Connect postprocess: 0.18ms [0.00s (0.10ms/blk)] 
2024-04-15T13:27:36.5275319Z  node0 2024-04-15T13:27:36.003416Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3075] [ConnectTip] [bench] - Connect block: 1.33ms [0.00s (0.65ms/blk)] 
2024-04-15T13:27:36.5277892Z  node0 2024-04-15T13:27:36.003437Z [D:\a\bitcoin\bitcoin\src\txmempool.cpp:663] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
2024-04-15T13:27:36.5281124Z  node0 2024-04-15T13:27:36.003467Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:212] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe block height=1 
2024-04-15T13:27:36.5285825Z  node0 2024-04-15T13:27:36.003486Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:183] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe fork block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (in IBD=false) 
2024-04-15T13:27:36.5290353Z  node0 2024-04-15T13:27:36.003555Z [D:\a\bitcoin\bitcoin\src\policy\fees.cpp:708] [processBlock] [estimatefee] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
2024-04-15T13:27:36.5294146Z  node0 2024-04-15T13:27:36.003588Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:212] [operator ()] [validation] BlockConnected: block hash=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe block height=1 
2024-04-15T13:27:36.5298558Z  node0 2024-04-15T13:27:36.003680Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:183] [operator ()] [validation] UpdatedBlockTip: new block hash=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe fork block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (in IBD=false) 
2024-04-15T13:27:36.5302779Z  node0 2024-04-15T13:27:36.003750Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:5781] [SendMessages] [net] SendMessages: sending inv peer=0 hash=4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe 
2024-04-15T13:27:36.5305508Z  node0 2024-04-15T13:27:36.003776Z [D:\a\bitcoin\bitcoin\src\net.cpp:3738] [PushMessage] [net] sending inv (37 bytes) peer=0 
2024-04-15T13:27:36.5307633Z  node0 2024-04-15T13:27:36.003862Z [D:\a\bitcoin\bitcoin\src\net.cpp:3738] [PushMessage] [net] sending feefilter (8 bytes) peer=0 
2024-04-15T13:27:36.5310103Z  node1 2024-04-15T13:27:36.004562Z [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:62213 
2024-04-15T13:27:36.5312690Z  node1 2024-04-15T13:27:36.004621Z [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:187] [parse] [rpc] ThreadRPCServer method=generatetoaddress user=__cookie__ 
2024-04-15T13:27:36.5315307Z  node1 2024-04-15T13:27:36.004717Z [D:\a\bitcoin\bitcoin\src\node\miner.cpp:163] [CreateNewBlock] CreateNewBlock(): block weight: 896 txs: 0 fees: 0 sigops 400 
2024-04-15T13:27:36.5317865Z  node1 2024-04-15T13:27:36.004782Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2337] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
2024-04-15T13:27:36.5320353Z  node1 2024-04-15T13:27:36.004818Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2439] [ConnectBlock] [bench]     - Fork checks: 0.04ms [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5323095Z  node1 2024-04-15T13:27:36.004846Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2531] [ConnectBlock] [bench]       - Connect 1 transactions: 0.02ms (0.025ms/tx, 0.000ms/txin) [0.00s (0.01ms/blk)] 
2024-04-15T13:27:36.5326568Z  node1 2024-04-15T13:27:36.004873Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2549] [ConnectBlock] [bench]     - Verify 0 txins: 0.05ms (0.000ms/txin) [0.00s (0.03ms/blk)] 
2024-04-15T13:27:36.5329617Z  node1 2024-04-15T13:27:36.004899Z [D:\a\bitcoin\bitcoin\src\node\miner.cpp:182] [CreateNewBlock] [bench] CreateNewBlock() packages: 0.00ms (0 packages, 0 updated descendants), validity: 0.20ms (total 0.20ms) 
2024-04-15T13:27:36.5332978Z  node1 2024-04-15T13:27:36.004933Z [D:\a\bitcoin\bitcoin\src\validation.cpp:4209] [AcceptBlockHeader] [validation] Saw new header hash=54271631f3855807857233b5bad9426412e0c36048efc247375ee75bac099869 height=1 
2024-04-15T13:27:36.5361811Z  node0 2024-04-15T13:27:36.005013Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:3466] [ProcessMessage] [net] received: getdata (37 bytes) peer=0 
2024-04-15T13:27:36.5364132Z  node0 2024-04-15T13:27:36.005043Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:4068] [ProcessMessage] [net] received getdata (1 invsz) peer=0 
2024-04-15T13:27:36.5366951Z  node0 2024-04-15T13:27:36.005067Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:4071] [ProcessMessage] [net] received getdata for: block 4ea0ebae5e05d36fd76d9e8b74df5858d92619c07e759207b4599172704a26fe peer=0 
2024-04-15T13:27:36.5369531Z  node1 2024-04-15T13:27:36.005308Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3007] [ConnectTip] [bench]   - Using cached block 
2024-04-15T13:27:36.5371576Z  node1 2024-04-15T13:27:36.005335Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3017] [ConnectTip] [bench]   - Load block from disk: 0.03ms 
2024-04-15T13:27:36.5373824Z  node1 2024-04-15T13:27:36.005364Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2337] [ConnectBlock] [bench]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
2024-04-15T13:27:36.5376114Z  node1 2024-04-15T13:27:36.005395Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2439] [ConnectBlock] [bench]     - Fork checks: 0.03ms [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5378678Z  node1 2024-04-15T13:27:36.005423Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2531] [ConnectBlock] [bench]       - Connect 1 transactions: 0.02ms (0.024ms/tx, 0.000ms/txin) [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5381337Z  node1 2024-04-15T13:27:36.005449Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2549] [ConnectBlock] [bench]     - Verify 0 txins: 0.05ms (0.000ms/txin) [0.00s (0.03ms/blk)] 
2024-04-15T13:27:36.5383577Z  node0 2024-04-15T13:27:36.005457Z [D:\a\bitcoin\bitcoin\src\net.cpp:3738] [PushMessage] [net] sending block (215 bytes) peer=0 
2024-04-15T13:27:36.5385801Z  node1 2024-04-15T13:27:36.005844Z [D:\a\bitcoin\bitcoin\src\flatfile.cpp:69] [Allocate] [validation] Pre-allocating up to position 0x100000 in rev00000.dat 
2024-04-15T13:27:36.5388175Z  node1 2024-04-15T13:27:36.006249Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2563] [ConnectBlock] [bench]     - Write undo data: 0.79ms [0.00s (0.26ms/blk)] 
2024-04-15T13:27:36.5390504Z  node1 2024-04-15T13:27:36.006276Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2578] [ConnectBlock] [bench]     - Index writing: 0.04ms [0.00s (0.01ms/blk)] 
2024-04-15T13:27:36.5393397Z  node1 2024-04-15T13:27:36.006299Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:245] [BlockChecked] [validation] BlockChecked: block hash=54271631f3855807857233b5bad9426412e0c36048efc247375ee75bac099869 state=Valid 
2024-04-15T13:27:36.5396259Z  node1 2024-04-15T13:27:36.006325Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3036] [ConnectTip] [bench]   - Connect total: 0.99ms [0.00s (0.36ms/blk)] 
2024-04-15T13:27:36.5398466Z  node1 2024-04-15T13:27:36.006354Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3045] [ConnectTip] [bench]   - Flush: 0.03ms [0.00s (0.02ms/blk)] 
2024-04-15T13:27:36.5400709Z  node1 2024-04-15T13:27:36.006375Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3055] [ConnectTip] [bench]   - Writing chainstate: 0.02ms [0.00s (0.01ms/blk)] 
2024-04-15T13:27:36.5403644Z  node1 2024-04-15T13:27:36.006393Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:222] [MempoolTransactionsRemovedForBlock] [validation] Enqueuing MempoolTransactionsRemovedForBlock: block height=1 txs removed=0 
2024-04-15T13:27:36.5407804Z  node1 2024-04-15T13:27:36.006448Z [D:\a\bitcoin\bitcoin\src\validation.cpp:2814] [UpdateTipLog] UpdateTip: new best=54271631f3855807857233b5bad9426412e0c36048efc247375ee75bac099869 height=1 version=0x20000000 log2_work=2.000000 tx=2 date='2024-04-15T13:27:36Z' progress=1.000000 cache=0.3MiB(1txo) 
2024-04-15T13:27:36.5411152Z  node1 2024-04-15T13:27:36.006480Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3071] [ConnectTip] [bench]   - Connect postprocess: 0.10ms [0.00s (0.08ms/blk)] 
2024-04-15T13:27:36.5413544Z  node1 2024-04-15T13:27:36.006510Z [D:\a\bitcoin\bitcoin\src\validation.cpp:3075] [ConnectTip] [bench] - Connect block: 1.17ms [0.00s (0.59ms/blk)] 
2024-04-15T13:27:36.5415809Z  node1 2024-04-15T13:27:36.006538Z [D:\a\bitcoin\bitcoin\src\txmempool.cpp:663] [check] [mempool] Checking mempool with 0 transactions and 0 inputs 
2024-04-15T13:27:36.5418419Z  node1 2024-04-15T13:27:36.006574Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:222] [operator ()] [validation] MempoolTransactionsRemovedForBlock: block height=1 txs removed=0 
2024-04-15T13:27:36.5421716Z  node1 2024-04-15T13:27:36.006630Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:212] [BlockConnected] [validation] Enqueuing BlockConnected: block hash=54271631f3855807857233b5bad9426412e0c36048efc247375ee75bac099869 block height=1 
2024-04-15T13:27:36.5426115Z  node1 2024-04-15T13:27:36.006651Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:183] [UpdatedBlockTip] [validation] Enqueuing UpdatedBlockTip: new block hash=54271631f3855807857233b5bad9426412e0c36048efc247375ee75bac099869 fork block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (in IBD=true) 
2024-04-15T13:27:36.5430407Z  node1 2024-04-15T13:27:36.006789Z [D:\a\bitcoin\bitcoin\src\policy\fees.cpp:708] [processBlock] [estimatefee] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
2024-04-15T13:27:36.5433973Z  node1 2024-04-15T13:27:36.006819Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:212] [operator ()] [validation] BlockConnected: block hash=54271631f3855807857233b5bad9426412e0c36048efc247375ee75bac099869 block height=1 
2024-04-15T13:27:36.5438131Z  node1 2024-04-15T13:27:36.006859Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:183] [operator ()] [validation] UpdatedBlockTip: new block hash=54271631f3855807857233b5bad9426412e0c36048efc247375ee75bac099869 fork block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (in IBD=true) 
2024-04-15T13:27:36.5441600Z  node0 2024-04-15T13:27:36.007167Z [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:62212 
2024-04-15T13:27:36.5443987Z  node0 2024-04-15T13:27:36.007253Z [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:187] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
2024-04-15T13:27:36.5446369Z  node1 2024-04-15T13:27:36.007709Z [D:\a\bitcoin\bitcoin\src\httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:62213 
2024-04-15T13:27:36.5448723Z  node1 2024-04-15T13:27:36.007795Z [D:\a\bitcoin\bitcoin\src\rpc\request.cpp:187] [parse] [rpc] ThreadRPCServer method=getbestblockhash user=__cookie__ 
2024-04-15T13:27:36.5451008Z  node0 2024-04-15T13:27:36.008740Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:3466] [ProcessMessage] [net] received: block (144 bytes) peer=0 
2024-04-15T13:27:36.5453673Z  node0 2024-04-15T13:27:36.008782Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:4743] [ProcessMessage] [net] received block 20076ff9e9d9bace59d7621747b34dfb4af9b2f75ff499017397854f9fefb930 peer=0 
2024-04-15T13:27:36.5457601Z  node0 2024-04-15T13:27:36.008822Z [D:\a\bitcoin\bitcoin\src\validation.cpp:4145] [AcceptBlockHeader] [validation] AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 20076ff9e9d9bace59d7621747b34dfb4af9b2f75ff499017397854f9fefb930, time-too-old, block's timestamp is too early 
2024-04-15T13:27:36.5461964Z  node0 2024-04-15T13:27:36.008857Z [D:\a\bitcoin\bitcoin\src\validationinterface.cpp:245] [BlockChecked] [validation] BlockChecked: block hash=20076ff9e9d9bace59d7621747b34dfb4af9b2f75ff499017397854f9fefb930 state=time-too-old, block's timestamp is too early 
2024-04-15T13:27:36.5465216Z  node0 2024-04-15T13:27:36.008883Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:1827] [Misbehaving] [net] Misbehaving: peer=0 (0 -> 100) DISCOURAGE THRESHOLD EXCEEDED 
2024-04-15T13:27:36.5467987Z  node0 2024-04-15T13:27:36.008905Z [D:\a\bitcoin\bitcoin\src\validation.cpp:4396] [ProcessNewBlock] [error] ProcessNewBlock: AcceptBlock FAILED (time-too-old, block's timestamp is too early) 
2024-04-15T13:27:36.5470987Z  node0 2024-04-15T13:27:36.008927Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:5067] [MaybeDiscourageAndDisconnect] [net] Warning: disconnecting but not discouraging local peer 0! 
2024-04-15T13:27:36.5473396Z  node0 2024-04-15T13:27:36.009001Z [D:\a\bitcoin\bitcoin\src\net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=0 
2024-04-15T13:27:36.5475463Z  node0 2024-04-15T13:27:36.009142Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=0 
2024-04-15T13:27:36.5477076Z  test  2024-04-15T13:27:36.058000Z TestFramework (ERROR): Assertion failed 
2024-04-15T13:27:36.5477994Z                                    Traceback (most recent call last):
2024-04-15T13:27:36.5479135Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 132, in main
2024-04-15T13:27:36.5480198Z                                        self.run_test()
2024-04-15T13:27:36.5481267Z                                      File "D:\a\bitcoin\bitcoin/test/functional/p2p_unrequested_blocks.py", line 98, in run_test
2024-04-15T13:27:36.5482409Z                                        test_node.send_and_ping(msg_block(blocks_h2[0]))
2024-04-15T13:27:36.5483587Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 686, in send_and_ping
2024-04-15T13:27:36.5484691Z                                        self.sync_with_ping(timeout=timeout)
2024-04-15T13:27:36.5485820Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 699, in sync_with_ping
2024-04-15T13:27:36.5486976Z                                        self.wait_until(test_function, timeout=timeout)
2024-04-15T13:27:36.5488111Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 586, in wait_until
2024-04-15T13:27:36.5489656Z                                        wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor)
2024-04-15T13:27:36.5491322Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\util.py", line 279, in wait_until_helper_internal
2024-04-15T13:27:36.5492484Z                                        if predicate():
2024-04-15T13:27:36.5493107Z                                           ^^^^^^^^^^^
2024-04-15T13:27:36.5494155Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 583, in test_function
2024-04-15T13:27:36.5495272Z                                        assert self.is_connected
2024-04-15T13:27:36.5495931Z                                    AssertionError

@maflcko maflcko changed the title Intermittent issue in p2p_unrequested_blocks.py", line 98, in run_test test_node.send_and_ping(msg_block(blocks_h2[0])) assert self.is_connected AssertionError / AcceptBlock FAILED (time-too-old, block's timestamp is too early) Windows Python: Intermittent issue in p2p_unrequested_blocks.py", line 98, in run_test test_node.send_and_ping(msg_block(blocks_h2[0])) assert self.is_connected AssertionError / AcceptBlock FAILED (time-too-old, block's timestamp is too early) Apr 18, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
CI failed Upstream Windows
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@maflcko