ci: failure in p2p_addr_selfannouncement.py

fanquake commented at 3:55 pm on December 27, 2025: member

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

 0 test  2025-12-22T23:47:48.293698Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12164: msg_pong(nonce=00000000) 
 1 test  2025-12-22T23:47:48.293794Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:12164: msg_pong(nonce=00000006) 
 2 test  2025-12-22T23:47:48.344658Z TestFramework (ERROR): Unexpected exception 
 3                                   Traceback (most recent call last):
 4                                     File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/test_framework.py", line 142, in main
 5                                       self.run_test()
 6                                       ~~~~~~~~~~~~~^^
 7                                     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
 8                                       self.self_announcement_test(outbound=False, addrv2=True)
 9                                       ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
10                                     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
11                                       assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
12                                       ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
13                                     File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/util.py", line 80, in assert_equal
14                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
15                                   AssertionError: not(4 == 5)
16 test  2025-12-22T23:47:48.347601Z TestFramework (DEBUG): Closing down network thread

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:

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

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

0xB10C referenced this in commit b3fef39e02 on Dec 28, 2025

0xB10C commented at 9:16 am on December 28, 2025: contributor

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

 02025-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)
 12025-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)
 22025-12-28T00:54:24.0783520Z 2025-12-28T00:53:21.733615Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
 32025-12-28T00:54:24.0884810Z Self-announcement timestamp mismatch: got=2656803201 expected=2655075201
 42025-12-28T00:54:24.0985270Z 2025-12-28T00:54:23.651301Z TestFramework (ERROR): Unexpected exception
 52025-12-28T00:54:24.1004690Z Traceback (most recent call last):
 62025-12-28T00:54:24.1005350Z   File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/test_framework.py", line 142, in main
 72025-12-28T00:54:24.1006280Z     self.run_test()
 82025-12-28T00:54:24.1006580Z     ~~~~~~~~~~~~~^^
 92025-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
102025-12-28T00:54:24.1008940Z     self.self_announcement_test(outbound=False, addrv2=False)
112025-12-28T00:54:24.1010810Z     ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
122025-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
132025-12-28T00:54:24.1012630Z     assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
142025-12-28T00:54:24.1013240Z     ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
152025-12-28T00:54:24.1014500Z   File "/Users/runner/work/bitcoin/bitcoin/repo_archive/test/functional/test_framework/util.py", line 80, in assert_equal
162025-12-28T00:54:24.1015240Z     raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
172025-12-28T00:54:24.1017350Z AssertionError: not(515 == 516)
182025-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.
192025-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
202025-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
212025-12-28T00:54:24.1026100Z 2025-12-28T00:54:23.841833Z TestFramework (ERROR): 
222025-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
232025-12-28T00:54:24.1028120Z 2025-12-28T00:54:23.842206Z TestFramework (ERROR): 
242025-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.
252025-12-28T00:54:24.1029540Z 2025-12-28T00:54:23.843333Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
262025-12-28T00:54:24.1030030Z 2025-12-28T00:54:23.844562Z TestFramework (ERROR):

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 ?

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:

0        self.addr_messages_received += 1
1        for addr in message.addrs:
2            self.addresses_received += 1
3-           if addr == self.expected:
4+           if addr.time >= self.expected.time and addr.ip == self.expected.ip and addr.port == self.expected.port and addr.nServices == self.expected.nServices:
5                self.self_announcements_received += 1

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:

 0181/282 - p2p_addr_selfannouncement.py failed, Duration: 1 s
 1
 2stdout:
 32025-12-31T04:29:42.401827Z TestFramework (INFO): PRNG seed is: 12631707991788085
 42025-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
 52025-12-31T04:29:43.082640Z TestFramework (INFO): Test that the node does an address self-announcement to inbound connections (addrv1)
 62025-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)
 72025-12-31T04:29:43.285933Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
 82025-12-31T04:29:43.380398Z TestFramework (ERROR): Unexpected exception
 9Traceback (most recent call last):
10  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_framework.py", line 142, in main
11    self.run_test()
12    ~~~~~~~~~~~~~^^
13  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 66, in run_test
14    self.self_announcement_test(outbound=False, addrv2=False)
15    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
16  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 135, in self_announcement_test
17    assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
18    ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
19  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/util.py", line 80, in assert_equal
20    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
21AssertionError: not(1 == 2)
222025-12-31T04:29:43.445243Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
232025-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
242025-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
252025-12-31T04:29:43.446523Z TestFramework (ERROR): 
262025-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
272025-12-31T04:29:43.446907Z TestFramework (ERROR): 
282025-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.
292025-12-31T04:29:43.447489Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
302025-12-31T04:29:43.447623Z TestFramework (ERROR): 
31
32
33stderr:
34[node 0] Cleaning up leftover process

fanquake commented at 12:37 pm on December 31, 2025: member

https://github.com/bitcoin/bitcoin/actions/runs/20546486544/job/59017686783?pr=34156#step:11:3758

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:

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

naiyoma commented at 12:47 pm on December 31, 2025: contributor

got this with the diff above

 02025-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)
 1>>> HANDLE_ADDR_MESSAGE called, expected.time=1767184790
 22025-12-31T12:39:50.304489Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
 3BEFORE bumpmocktime()
 4>>> HANDLE_ADDR_MESSAGE called, expected.time=1767184790
 5Self-announcement timestamp mismatch: got=1768912790 expected=1767184790
 6AFTER bumpmocktime(), before setting expected.time
 72025-12-31T12:39:50.459889Z TestFramework (ERROR): Unexpected exception
 8Traceback (most recent call last):
 9  File "/home/ubuntu/Projects/bitcoin/test/functional/test_framework/test_framework.py", line 142, in main
10    self.run_test()
11  File "/home/ubuntu/Projects/bitcoin/./build/test/functional/p2p_addr_selfannouncement.py", line 69, in run_test
12    self.self_announcement_test(outbound=False, addrv2=False)
13  File "/home/ubuntu/Projects/bitcoin/./build/test/functional/p2p_addr_selfannouncement.py", line 141, in self_announcement_test
14    assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
15  File "/home/ubuntu/Projects/bitcoin/test/functional/test_framework/util.py", line 80, in assert_equal
16    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
17AssertionError: not(1 == 2)

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.

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:

 0182/282 - p2p_addr_selfannouncement.py failed, Duration: 6 s
 1
 2stdout:
 32025-12-31T14:10:01.054524Z TestFramework (INFO): PRNG seed is: 279208991052383101
 42025-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
 52025-12-31T14:10:03.459488Z TestFramework (INFO): Test that the node does an address self-announcement to inbound connections (addrv1)
 62025-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)
 72025-12-31T14:10:04.247264Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv1)
 82025-12-31T14:10:04.961413Z TestFramework (INFO): Test that the node does an address self-announcement to inbound connections (addrv2)
 92025-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)
102025-12-31T14:10:05.115558Z TestFramework (INFO): Check that we get more self-announcements sometime later (inbound, addrv2)
112025-12-31T14:10:05.739087Z TestFramework (ERROR): Unexpected exception
12Traceback (most recent call last):
13  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/test_framework.py", line 142, in main
14    self.run_test()
15    ~~~~~~~~~~~~~^^
16  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 67, in run_test
17    self.self_announcement_test(outbound=False, addrv2=True)
18    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
19  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/build/test/functional/p2p_addr_selfannouncement.py", line 135, in self_announcement_test
20    assert_equal(addr_receiver.self_announcements_received, last_self_announcements_received + 1)
21    ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
22  File "/home/runner/work/bitcoin-core-nightly/bitcoin-core-nightly/test/functional/test_framework/util.py", line 80, in assert_equal
23    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
24AssertionError: not(5 == 6)
252025-12-31T14:10:05.745570Z TestFramework (INFO): Not stopping nodes as test failed. The dangling processes will be cleaned up later.
262025-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
272025-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
282025-12-31T14:10:05.746147Z TestFramework (ERROR): 
292025-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
302025-12-31T14:10:05.746466Z TestFramework (ERROR): 
312025-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.
322025-12-31T14:10:05.746787Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
332025-12-31T14:10:05.746885Z TestFramework (ERROR): 
34
35
36stderr:
37[node 0] Cleaning up leftover process

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:

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

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

fanquake commented at 12:36 pm on January 2, 2026: member

https://github.com/bitcoin/bitcoin/actions/runs/20656499701/job/59310311647#step:9:3863

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

0xB10C referenced this in commit 31852057ea on Jan 5, 2026

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

fanquake closed this on Jan 6, 2026

fanquake referenced this in commit d7cbdfa090 on Jan 6, 2026

ci: failure in p2p_addr_selfannouncement.py #34159