feature_asmap.py intermittent fail ( AssertionError: [node 0] Expected messages “[‘CheckAddrman: new 2, tried 2, total 4 started’, ‘CheckAddrman: completed’]” does not partially match log:) #29634

1. 
   maflcko commented at 2:03 pm on March 12, 2024: member

   https://cirrus-ci.com/task/5452911883321344?logs=ci#L4941

    0 test  2024-03-12T09:55:01.911000Z TestFramework (ERROR): Assertion failed 
    1                                   Traceback (most recent call last):
    2                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 131, in main
    3                                       self.run_test()
    4                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_asmap.py", line 132, in run_test
    5                                       self.test_asmap_interaction_with_addrman_containing_entries()
    6                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/feature_asmap.py", line 90, in test_asmap_interaction_with_addrman_containing_entries
    7                                       with self.node.assert_debug_log(
    8                                     File "/usr/lib/python3.10/contextlib.py", line 142, in __exit__
    9                                       next(self.gen)
   10                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 490, in assert_debug_log
   11                                       self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
   12                                     File "/ci_container_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_node.py", line 188, in _raise_assertion_error
   13                                       raise AssertionError(self._node_msg(msg))
   14                                   AssertionError: [node 0] Expected messages "['CheckAddrman: new 2, tried 2, total 4 started', 'CheckAddrman: completed']" does not partially match log:
   15                                    - 2024-03-12T09:53:41.898810Z [http] [httpserver.cpp:306] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:33584
   16                                    - 2024-03-12T09:53:41.898867Z [httpworker.2] [rpc/request.cpp:187] [parse] [rpc] ThreadRPCServer method=getnodeaddresses user=__cookie__
   17                                    - 2024-03-12T09:53:41.898904Z [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: new 3, tried 1, total 4 started
   18                                    - 2024-03-12T09:53:41.899039Z [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: completed (0.12ms)
   19                                    - 2024-03-12T09:53:41.899054Z [httpworker.2] [addrman.cpp:842] [GetAddr_] [addrman] GetAddr returned 1 random addresses
   20                                    - 2024-03-12T09:53:41.899065Z [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: new 3, tried 1, total 4 started
   21                                    - 2024-03-12T09:53:41.899182Z [httpworker.2] [logging/timer.h:58] [Log] [addrman] CheckAddrman: completed (0.11ms)
   22                                    - 2024-03-12T09:54:26.770784Z [scheduler] [net.cpp:2337] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers
   

2. maflcko added the label Tests on Mar 12, 2024
3. maflcko added the label CI failed on Mar 12, 2024
4. 
   brunoerg commented at 4:56 pm on March 12, 2024: contributor

   Perhaps related to #28998?
5. 
   mzumsande commented at 5:45 pm on March 12, 2024: contributor

   looks like 7b868e6b678502e86571976d696c0e3cb72c0884 from #29007 somehow didn’t work correctly (fyi @stratospher).

   [Edit]: I think it’s because the deterministic addrman wasn’t used the first time the node was started, see #29639 for a fix.

6. 
   fanquake commented at 5:02 pm on March 18, 2024: member

   https://cirrus-ci.com/task/5668620106203136?logs=ci#L8132
7. 
   mzumsande commented at 5:29 pm on March 18, 2024: contributor

   https://cirrus-ci.com/task/5668620106203136?logs=ci#L8132

   I’ve seen a couple other failed runs, I think the fix in #29639 is simple enough to be merged with 2 acks.

8. fanquake closed this on Mar 19, 2024

   ---

9. fanquake referenced this in commit 9f2609de09 on Mar 19, 2024

Contributors
maflcko brunoerg mzumsande fanquake

Labels
Tests CI failed