ci: failure in p2p_addr_selfannouncement.py #34159

issue fanquake opened this issue on December 27, 2025
  1. fanquake commented at 3:55 PM on December 27, 2025: member

    https://github.com/bitcoin/bitcoin/actions/runs/20445863729/job/58749036885#step:9:3498:

     test  2025-12-22T23:47:48.293698Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12164: msg_pong(nonce=00000000) 
 test  2025-12-22T23:47:48.293794Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12164: msg_pong(nonce=00000006) 
 test  2025-12-22T23:47:48.344658Z TestFramework (ERROR): Unexpected exception 
                                   Traceback (most recent call last):
                                     File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/test_framework.py", line 142, in main
                                       self.run_test()
                                       ~~~~~~~~~~~~~^^
                                     File "/Users/runner/work/bitcoin/bitcoin/repo_archive/ci/scratch/build-aarch64-apple-darwin24.6.0/test/functional/p2p_addr_selfannouncement.py", line 67, in run_test
                                       self.self_announcement_test(outbound=False, addrv2=True)
                                       ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                     File "/Users/runner/work/bitcoin/bitcoin/repo_archive/ci/scratch/build-aarch64-apple-darwin24.6.0/test/functional/p2p_addr_selfannouncement.py", line 135, in self_announcement_test
                                       assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
                                       ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                     File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/util.py", line 80, in assert_equal
                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
                                   AssertionError: not(4 == 5)
 test  2025-12-22T23:47:48.347601Z TestFramework (DEBUG): Closing down network thread
  2. 0xB10C commented at 11:58 PM on December 27, 2025: contributor

    Will try to reproduce it. I suspect this is a addr message timestamp issue. Previously, I had something like this:

      # The tricky part of this test is the timestamp of the self-announcement.
  # The following helped me to debug timestamp mismatches, so I'm leaving it in for the next one.
  elif addr.ip == self.expected.ip and addr.port == self.expected.port and addr.nServices == self.expected.nServices:
      print(f"Self-announcement timestamp mismatch: got={addr.time} expected={self.expected.time}")

    to catch them, but dropped it in #34039 (review)

  3. 0xB10C referenced this in commit b3fef39e02 on Dec 28, 2025
  4. 0xB10C commented at 9:16 AM on December 28, 2025: contributor

    can reproduce with b3fef39: Self-announcement timestamp mismatch: got=2656803201 expected=2655075201

    2025-12-28T00:54:24.0578490Z 2025-12-28T00:53:21.268810Z TestFramework (INFO): Test that the node does an address self-announcement to inbound connections (addrv1)
2025-12-28T00:54:24.0682490Z 2025-12-28T00:53:21.269773Z TestFramework (INFO): Check that we get an initial self-announcement when connecting to a node and sending a GETADDR (inbound, addrv1)
2025-12-28T00:54:24.0783520Z 2025-12-28T00:53:21.733615Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
2025-12-28T00:54:24.0884810Z Self-announcement timestamp mismatch: got=2656803201 expected=2655075201
2025-12-28T00:54:24.0985270Z 2025-12-28T00:54:23.651301Z TestFramework (ERROR): Unexpected exception
2025-12-28T00:54:24.1004690Z Traceback (most recent call last):
2025-12-28T00:54:24.1005350Z   File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/test_framework.py", line 142, in main
2025-12-28T00:54:24.1006280Z     self.run_test()
2025-12-28T00:54:24.1006580Z     ~~~~~~~~~~~~~^^
2025-12-28T00:54:24.1008060Z   File "/Users/runner/work/bitcoin/bitcoin/repo_archive/ci/scratch/build-aarch64-apple-darwin24.6.0/test/functional/p2p_addr_selfannouncement.py", line 70, in run_test
2025-12-28T00:54:24.1008940Z     self.self_announcement_test(outbound=False, addrv2=False)
2025-12-28T00:54:24.1010810Z     ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-12-28T00:54:24.1011690Z   File "/Users/runner/work/bitcoin/bitcoin/repo_archive/ci/scratch/build-aarch64-apple-darwin24.6.0/test/functional/p2p_addr_selfannouncement.py", line 139, in self_announcement_test
2025-12-28T00:54:24.1012630Z     assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
2025-12-28T00:54:24.1013240Z     ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-12-28T00:54:24.1014500Z   File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/util.py", line 80, in assert_equal
2025-12-28T00:54:24.1015240Z     raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
2025-12-28T00:54:24.1017350Z AssertionError: not(515 == 516)
2025-12-28T00:54:24.1019860Z 2025-12-28T00:54:23.840132Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
2025-12-28T00:54:24.1021170Z 2025-12-28T00:54:23.840292Z TestFramework (WARNING): Not cleaning up dir /Users/runner/work/bitcoin/bitcoin/repo_archive/ci/scratch/test_runner/test_runner_₿_🏃_20251228_003917/p2p_addr_selfannouncement_97
2025-12-28T00:54:24.1025000Z 2025-12-28T00:54:23.840351Z TestFramework (ERROR): Test failed. Test logging available at /Users/runner/work/bitcoin/bitcoin/repo_archive/ci/scratch/test_runner/test_runner_₿_🏃_20251228_003917/p2p_addr_selfannouncement_97/test_framework.log
2025-12-28T00:54:24.1026100Z 2025-12-28T00:54:23.841833Z TestFramework (ERROR): 
2025-12-28T00:54:24.1027130Z 2025-12-28T00:54:23.842117Z TestFramework (ERROR): Hint: Call /Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/combine_logs.py '/Users/runner/work/bitcoin/bitcoin/repo_archive/ci/scratch/test_runner/test_runner_₿_🏃_20251228_003917/p2p_addr_selfannouncement_97' to consolidate all logs
2025-12-28T00:54:24.1028120Z 2025-12-28T00:54:23.842206Z TestFramework (ERROR): 
2025-12-28T00:54:24.1028740Z 2025-12-28T00:54:23.842385Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-12-28T00:54:24.1029540Z 2025-12-28T00:54:23.843333Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2025-12-28T00:54:24.1030030Z 2025-12-28T00:54:23.844562Z TestFramework (ERROR):
  5. naiyoma commented at 2:51 PM on December 30, 2025: contributor

    can reproduce with b3fef39: Self-announcement timestamp mismatch: got=2656803201 expected=2655075201

    I haven’t been able to reproduce this, Is the time difference btwn got and expected, consistently 20 day ?

  6. 0xB10C commented at 4:20 PM on December 30, 2025: contributor

    can reproduce with b3fef39: Self-announcement timestamp mismatch: got=2656803201 expected=2655075201

    I haven’t been able to reproduce this, Is the time difference btwn got and expected, consistently 20 day ?

    Sorry, I didn't link to https://github.com/0xB10C/bitcoin/actions/runs/20546158233 - I'm not seeing the failure locally, just in CI.

    I was playing around with it in https://github.com/0xB10C/bitcoin/pull/15, and I think one options is to be less strict about the timestamp similar to:

            self.addr_messages_received += 1
        for addr in message.addrs:
            self.addresses_received += 1
-           if addr == self.expected:
+           if addr.time >= self.expected.time and addr.ip == self.expected.ip and addr.port == self.expected.port and addr.nServices == self.expected.nServices:
                self.self_announcements_received += 1
  7. hebasto commented at 11:09 AM on December 31, 2025: member

    On OmniOS, https://github.com/hebasto/bitcoin-core-nightly/actions/runs/20611492118/job/59196832666:

    181/282 - p2p_addr_selfannouncement.py failed, Duration: 1 s

stdout:
2025-12-31T04:29:42.401827Z TestFramework (INFO): PRNG seed is: 12631707991788085
2025-12-31T04:29:42.403417Z TestFramework (INFO): Initializing test directory /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_042118/p2p_addr_selfannouncement_96
2025-12-31T04:29:43.082640Z TestFramework (INFO): Test that the node does an address self-announcement to inbound connections (addrv1)
2025-12-31T04:29:43.087917Z TestFramework (INFO): Check that we get an initial self-announcement when connecting to a node and sending a GETADDR (inbound, addrv1)
2025-12-31T04:29:43.285933Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
2025-12-31T04:29:43.380398Z TestFramework (ERROR): Unexpected exception
Traceback (most recent call last):
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_framework.py", line 142, in main
    self.run_test()
    ~~~~~~~~~~~~~^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 66, in run_test
    self.self_announcement_test(outbound=False, addrv2=False)
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 135, in self_announcement_test
    assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
    ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/util.py", line 80, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(1 == 2)
2025-12-31T04:29:43.445243Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
2025-12-31T04:29:43.445591Z TestFramework (WARNING): Not cleaning up dir /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_042118/p2p_addr_selfannouncement_96
2025-12-31T04:29:43.445763Z TestFramework (ERROR): Test failed. Test logging available at /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_042118/p2p_addr_selfannouncement_96/test_framework.log
2025-12-31T04:29:43.446523Z TestFramework (ERROR): 
2025-12-31T04:29:43.446782Z TestFramework (ERROR): Hint: Call /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/combine_logs.py '/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_042118/p2p_addr_selfannouncement_96' to consolidate all logs
2025-12-31T04:29:43.446907Z TestFramework (ERROR): 
2025-12-31T04:29:43.447013Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-12-31T04:29:43.447489Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2025-12-31T04:29:43.447623Z TestFramework (ERROR): 


stderr:
[node 0] Cleaning up leftover process
  9. naiyoma commented at 12:39 PM on December 31, 2025: contributor

    Sorry, I didn't link to https://github.com/0xB10C/bitcoin/actions/runs/20546158233 - I'm not seeing the failure locally, just I

    I think this happens when there's a delay between calling bumpmocktime() and updating expected.time.

    tried this locally:

    +++ b/test/functional/p2p_addr_selfannouncement.py
@@ -37,11 +37,14 @@ class SelfAnnouncementReceiver(P2PInterface):
         self.addrv2_test = addrv2
 
     def handle_addr_message(self, message):
+        print(f">>> HANDLE_ADDR_MESSAGE called, expected.time={self.expected.time}")
         self.addr_messages_received += 1
         for addr in message.addrs:
             self.addresses_received += 1
             if addr == self.expected:
                 self.self_announcements_received += 1
+            elif addr.ip == self.expected.ip and addr.port == self.expected.port and addr.nServices == self.expected.nServices:
+                print(f"Self-announcement timestamp mismatch: got={addr.time} expected={self.expected.time}")
 
     def on_addrv2(self, message):
         assert (self.addrv2_test)
@@ -119,7 +122,7 @@ class AddrSelfAnnouncementTest(BitcoinTestFramework):
             addr_receiver.send_and_ping(msg_headers([tip_header]))
 
         self.log.info(f"Check that we get more self-announcements sometime later ({connection_type}, {addr_version})")
-        for _ in range(5):
+        for _ in range(500):
             last_self_announcements_received = addr_receiver.self_announcements_received
             last_addr_messages_received = addr_receiver.addr_messages_received
             last_addresses_received = addr_receiver.addresses_received
@@ -128,7 +131,10 @@ class AddrSelfAnnouncementTest(BitcoinTestFramework):
                 # self-announcements are sent on an exponential distribution with mean interval of 24h.
                 # Setting the mocktime 20d forward gives a probability of (1 - e^-(480/24)) that
                 # the event will occur (i.e. this fails once in ~500 million repeats).
+                print(f"BEFORE bumpmocktime()")
                 self.nodes[0].bumpmocktime(20 * ONE_DAY)
+                time.sleep(0.1)
+                print(f"AFTER bumpmocktime(), before setting expected.time")
                 addr_receiver.expected.time = self.nodes[0].mocktime
  10. naiyoma commented at 12:47 PM on December 31, 2025: contributor

    got this with the diff above

    2025-12-31T12:39:50.147708Z TestFramework (INFO): Check that we get an initial self-announcement when connecting to a node and sending a GETADDR (inbound, addrv1)
>>> HANDLE_ADDR_MESSAGE called, expected.time=1767184790
2025-12-31T12:39:50.304489Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
BEFORE bumpmocktime()
>>> HANDLE_ADDR_MESSAGE called, expected.time=1767184790
Self-announcement timestamp mismatch: got=1768912790 expected=1767184790
AFTER bumpmocktime(), before setting expected.time
2025-12-31T12:39:50.459889Z TestFramework (ERROR): Unexpected exception
Traceback (most recent call last):
  File "/home/ubuntu/Projects/bitcoin/test/functional/test_framework/test_framework.py", line 142, in main
    self.run_test()
  File "/home/ubuntu/Projects/bitcoin/./build/test/functional/p2p_addr_selfannouncement.py", line 69, in run_test
    self.self_announcement_test(outbound=False, addrv2=False)
  File "/home/ubuntu/Projects/bitcoin/./build/test/functional/p2p_addr_selfannouncement.py", line 141, in self_announcement_test
    assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
  File "/home/ubuntu/Projects/bitcoin/test/functional/test_framework/util.py", line 80, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(1 == 2)
  11. naiyoma commented at 1:27 PM on December 31, 2025: contributor

    I was playing around with it in 0xB10C#15, and I think one options is to be less strict about the timestamp similar to:

          if addr.time >= self.expected.time and addr.ip == self.expected.ip and addr.port == self.expected.port and addr.nServices == self.expected.nServices:

    I'm not sure this is always the case. Is it possible that addr.time <= self.expected.time could occur ? i think checking ip,port,service is sufficient.

  12. hebasto commented at 2:46 PM on December 31, 2025: member

    On NetBSD 9.4, https://github.com/hebasto/bitcoin-core-nightly/actions/runs/20619499569/job/59218560248:

    182/282 - p2p_addr_selfannouncement.py failed, Duration: 6 s

stdout:
2025-12-31T14:10:01.054524Z TestFramework (INFO): PRNG seed is: 279208991052383101
2025-12-31T14:10:01.060063Z TestFramework (INFO): Initializing test directory /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_135038/p2p_addr_selfannouncement_96
2025-12-31T14:10:03.459488Z TestFramework (INFO): Test that the node does an address self-announcement to inbound connections (addrv1)
2025-12-31T14:10:03.472186Z TestFramework (INFO): Check that we get an initial self-announcement when connecting to a node and sending a GETADDR (inbound, addrv1)
2025-12-31T14:10:04.247264Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
2025-12-31T14:10:04.961413Z TestFramework (INFO): Test that the node does an address self-announcement to inbound connections (addrv2)
2025-12-31T14:10:04.963778Z TestFramework (INFO): Check that we get an initial self-announcement when connecting to a node and sending a GETADDR (inbound, addrv2)
2025-12-31T14:10:05.115558Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv2)
2025-12-31T14:10:05.739087Z TestFramework (ERROR): Unexpected exception
Traceback (most recent call last):
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_framework.py", line 142, in main
    self.run_test()
    ~~~~~~~~~~~~~^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 67, in run_test
    self.self_announcement_test(outbound=False, addrv2=True)
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 135, in self_announcement_test
    assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
    ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/util.py", line 80, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(5 == 6)
2025-12-31T14:10:05.745570Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
2025-12-31T14:10:05.745741Z TestFramework (WARNING): Not cleaning up dir /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_135038/p2p_addr_selfannouncement_96
2025-12-31T14:10:05.745854Z TestFramework (ERROR): Test failed. Test logging available at /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_135038/p2p_addr_selfannouncement_96/test_framework.log
2025-12-31T14:10:05.746147Z TestFramework (ERROR): 
2025-12-31T14:10:05.746352Z TestFramework (ERROR): Hint: Call /home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/combine_logs.py '/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test_runner_₿_🏃_20251231_135038/p2p_addr_selfannouncement_96' to consolidate all logs
2025-12-31T14:10:05.746466Z TestFramework (ERROR): 
2025-12-31T14:10:05.746574Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-12-31T14:10:05.746787Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
2025-12-31T14:10:05.746885Z TestFramework (ERROR): 


stderr:
[node 0] Cleaning up leftover process
  13. 0xB10C commented at 3:26 PM on December 31, 2025: contributor

    I'm not sure this is always the case. Is it possible that addr.time <= self.expected.time could occur ? i think checking ip,port,service is sufficient.

    that would work around the issue, but I think we should have coverage for the self-announcement timestamp being correct(ish).

    I think this happens when there's a delay between calling bumpmocktime() and updating expected.time.

    An earlier version of #34039 didn't use bumpmocktime(). We could revert to doing:

    self.mocktime += 20 * ONE_DAY
addr_receiver.expected.time = self.mocktime
self.nodes[0].setmocktime(self.mocktime)
addr_receiver.sync_with_ping()

    to make sure the expected timestamp is set before bumping the mocktime.

  15. naiyoma commented at 3:43 PM on January 2, 2026: contributor

    An earlier version of #34039 didn't use bumpmocktime(). We could revert to doing:

    Yeah, this is certainly a better option

  16. 0xB10C referenced this in commit 31852057ea on Jan 5, 2026
  17. 0xB10C commented at 3:57 PM on January 5, 2026: contributor

    An earlier version of #34039 didn't use bumpmocktime(). We could revert to doing:

    Yeah, this is certainly a better option

    doing this in https://github.com/bitcoin/bitcoin/pull/34204

  18. fanquake closed this on Jan 6, 2026
  19. fanquake referenced this in commit d7cbdfa090 on Jan 6, 2026
Contributors
fanquake0xB10Cnaiyomahebasto
Linked (view graph)
#34204 test: fix intermittent failure in p2p_addr_selfannouncement
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: 2026-04-26 06:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me