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

issue maflcko openend this issue on April 16, 2024
  1. maflcko commented at 5:44 pm on April 16, 2024: member

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

     0node0 2024-04-15T13:27:36.008782Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:4743] [ProcessMessage] [net] received block 20076ff9e9d9bace59d7621747b34dfb4af9b2f75ff499017397854f9fefb930 peer=0 
 1 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 
 2 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 
 3 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 
 4Error: 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) 
 5 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! 
 6 node0 2024-04-15T13:27:36.009001Z [D:\a\bitcoin\bitcoin\src\net.cpp:541] [CloseSocketDisconnect] [net] disconnecting peer=0 
 7 node0 2024-04-15T13:27:36.009142Z [D:\a\bitcoin\bitcoin\src\net_processing.cpp:1708] [FinalizeNode] [net] Cleared nodestate for peer=0 
 8 test  2024-04-15T13:27:36.058000Z TestFramework (ERROR): Assertion failed 
 9                                   Traceback (most recent call last):
10                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 132, in main
11                                       self.run_test()
12                                     File "D:\a\bitcoin\bitcoin/test/functional/p2p_unrequested_blocks.py", line 98, in run_test
13                                       test_node.send_and_ping(msg_block(blocks_h2[0]))
14                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 686, in send_and_ping
15                                       self.sync_with_ping(timeout=timeout)
16                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 699, in sync_with_ping
17                                       self.wait_until(test_function, timeout=timeout)
18                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 586, in wait_until
19                                       wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor)
20                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\util.py", line 279, in wait_until_helper_internal
21                                       if predicate():
22                                          ^^^^^^^^^^^
23                                     File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 583, in test_function
24                                       assert self.is_connected
25                                   AssertionError
  2. maflcko added the label Tests on Apr 16, 2024
  3. maflcko added the label CI failed on Apr 16, 2024
  4. maflcko removed the label Tests on Apr 18, 2024
  5. maflcko added the label Windows on Apr 18, 2024
  6. maflcko added the label Upstream on Apr 18, 2024
  7. maflcko commented at 6:09 am on April 18, 2024: member
    This is the known bug on Windows Python, where the time.time() returned is just wrong. See #25482 (comment)
  8. maflcko commented at 6:13 am on April 18, 2024: member 
      02024-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) 
  12024-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) 
  22024-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) 
  32024-04-15T13:27:36.5173897Z  test  2024-04-15T13:27:35.999000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:11540 
  42024-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 
  52024-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__ 
  62024-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 
  72024-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__ 
  82024-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 
  92024-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)] 
 102024-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)] 
 112024-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)] 
 122024-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)] 
 132024-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) 
 142024-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 
 152024-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 
 162024-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 
 172024-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)] 
 182024-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)] 
 192024-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)] 
 202024-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)] 
 212024-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 
 222024-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)] 
 232024-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)] 
 242024-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 
 252024-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)] 
 262024-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)] 
 272024-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)] 
 282024-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 
 292024-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) 
 302024-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 
 312024-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) 
 322024-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)] 
 332024-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)] 
 342024-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 
 352024-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 
 362024-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) 
 372024-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 
 382024-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 
 392024-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) 
 402024-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 
 412024-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 
 422024-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 
 432024-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 
 442024-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__ 
 452024-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 
 462024-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)] 
 472024-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)] 
 482024-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)] 
 492024-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)] 
 502024-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) 
 512024-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 
 522024-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 
 532024-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 
 542024-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 
 552024-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 
 562024-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 
 572024-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)] 
 582024-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)] 
 592024-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)] 
 602024-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)] 
 612024-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 
 622024-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 
 632024-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)] 
 642024-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)] 
 652024-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 
 662024-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)] 
 672024-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)] 
 682024-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)] 
 692024-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 
 702024-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) 
 712024-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)] 
 722024-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)] 
 732024-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 
 742024-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 
 752024-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 
 762024-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) 
 772024-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 
 782024-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 
 792024-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) 
 802024-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 
 812024-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__ 
 822024-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 
 832024-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__ 
 842024-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 
 852024-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 
 862024-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 
 872024-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 
 882024-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 
 892024-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) 
 902024-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! 
 912024-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 
 922024-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 
 932024-04-15T13:27:36.5477076Z  test  2024-04-15T13:27:36.058000Z TestFramework (ERROR): Assertion failed 
 942024-04-15T13:27:36.5477994Z                                    Traceback (most recent call last):
 952024-04-15T13:27:36.5479135Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\test_framework.py", line 132, in main
 962024-04-15T13:27:36.5480198Z                                        self.run_test()
 972024-04-15T13:27:36.5481267Z                                      File "D:\a\bitcoin\bitcoin/test/functional/p2p_unrequested_blocks.py", line 98, in run_test
 982024-04-15T13:27:36.5482409Z                                        test_node.send_and_ping(msg_block(blocks_h2[0]))
 992024-04-15T13:27:36.5483587Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 686, in send_and_ping
1002024-04-15T13:27:36.5484691Z                                        self.sync_with_ping(timeout=timeout)
1012024-04-15T13:27:36.5485820Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 699, in sync_with_ping
1022024-04-15T13:27:36.5486976Z                                        self.wait_until(test_function, timeout=timeout)
1032024-04-15T13:27:36.5488111Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 586, in wait_until
1042024-04-15T13:27:36.5489656Z                                        wait_until_helper_internal(test_function, timeout=timeout, lock=p2p_lock, timeout_factor=self.timeout_factor)
1052024-04-15T13:27:36.5491322Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\util.py", line 279, in wait_until_helper_internal
1062024-04-15T13:27:36.5492484Z                                        if predicate():
1072024-04-15T13:27:36.5493107Z                                           ^^^^^^^^^^^
1082024-04-15T13:27:36.5494155Z                                      File "D:\a\bitcoin\bitcoin\test\functional\test_framework\p2p.py", line 583, in test_function
1092024-04-15T13:27:36.5495272Z                                        assert self.is_connected
1102024-04-15T13:27:36.5495931Z                                    AssertionError
  9. maflcko renamed this:
    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)
    on Apr 18, 2024
  10. maflcko commented at 3:08 pm on July 31, 2024: member
    Still an issue as of #29897#ref-pullrequest-2326471203
  11. hodlinator commented at 10:05 pm on October 22, 2024: contributor

    Encountered here: https://github.com/hodlinator/bitcoin/actions/runs/11460619753/job/31887736863#step:12:590

    (Still running on a base of 84cd6478c422bc296589ab031f5c76e7bab2704d from 16 September though).


maflcko hodlinator

Labels
Windows Upstream CI failed

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-12-21 15:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me