Page MenuHomePhabricator

[avalanche] Make block update logging more precise.
Needs RevisionPublic

Authored by tyler-smith on Apr 25 2022, 08:13.

Details

Reviewers
Fabien
deadalnix
Group Reviewers
Restricted Project
Summary

When logging a status change for blocks:

  1. Specify the change is for a block
  2. Specify invalidated/rejected/accepted/finalized
  3. Note when we are unparking
Test Plan
./test/functional/test_runner.py abc_p2p_avalanche_voting.py
./test/functional/test_runner.py abc_p2p_avalanche_proof_voting.py

Diff Detail

Event Timeline

@Fabien Let me know if there's something more you'd like to see regarding testing/test-plan for this change.

Fabien requested changes to this revision.Apr 25 2022, 14:29

About the test plan, since you are changing the logs, why not looking at the logs ? This can be done easily from the functional tests, which you should run BTW because they are the ones susceptible to wait for a log message.

src/net_processing.cpp
5219 ↗(On Diff #33293)

You can put the log into the lambda and remove some more duplicates

5233 ↗(On Diff #33293)

Same here, this can go into a lambda and remove some more duplicates

This revision now requires changes to proceed.Apr 25 2022, 14:29

Move logging into lambda, make unparkBlock lambda, and add to tests.

Failed tests logs:

====== Bitcoin ABC functional tests: abc_p2p_avalanche_voting.py --nolegacyavaproof ======

------- Stdout: -------
2022-04-27T11:01:21.285000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-without-wallet/test/tmp/test_runner_₿₵_  _20220427_105939/abc_p2p_avalanche_voting_56
2022-04-27T11:01:24.340000Z TestFramework (INFO): Poll for the chain tip...
2022-04-27T11:01:24.394000Z TestFramework (INFO): Poll for a selection of blocks...
2022-04-27T11:01:24.450000Z TestFramework (INFO): Poll for a selection of blocks, but some are now invalid...
2022-04-27T11:01:24.524000Z TestFramework (INFO): Poll for unknown blocks...
2022-04-27T11:01:24.578000Z TestFramework (INFO): Trigger polling from the node...
2022-04-27T11:01:26.622000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 136, in main
    self.run_test()
  File "/work/test/functional/abc_p2p_avalanche_voting.py", line 175, in run_test
    timeout=5)
  File "/usr/lib/python3.7/contextlib.py", line 119, in __exit__
    next(self.gen)
  File "/work/test/functional/test_framework/test_node.py", line 535, in assert_debug_log
    str(expected_msgs), print_log))
  File "/work/test/functional/test_framework/test_node.py", line 213, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['Avalanche accepted block']" does not partially match log:

 - 2022-04-27T11:01:24.624438Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5
 - 2022-04-27T11:01:24.634540Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=6
 - 2022-04-27T11:01:24.637244Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=1
 - 2022-04-27T11:01:24.644679Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=7
 - 2022-04-27T11:01:24.654841Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=8
 - 2022-04-27T11:01:24.661675Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=2
 - 2022-04-27T11:01:24.664954Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=3
 - 2022-04-27T11:01:24.665036Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=9
 - 2022-04-27T11:01:24.665078Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=4
 - 2022-04-27T11:01:24.666125Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=5
 - 2022-04-27T11:01:24.675154Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=10
 - 2022-04-27T11:01:24.685266Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=11
 - 2022-04-27T11:01:24.695413Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=12
 - 2022-04-27T11:01:24.705589Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=13
 - 2022-04-27T11:01:24.715753Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=14
 - 2022-04-27T11:01:24.725925Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=15
 - 2022-04-27T11:01:24.736092Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=16
 - 2022-04-27T11:01:24.746258Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=1
 - 2022-04-27T11:01:24.756423Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=2
 - 2022-04-27T11:01:24.766574Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=3
 - 2022-04-27T11:01:24.776710Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=4
 - 2022-04-27T11:01:24.786894Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5


2022-04-27T11:01:26.673000Z TestFramework (INFO): Stopping nodes
2022-04-27T11:01:26.875000Z TestFramework (WARNING): Not cleaning up dir /work/abc-ci-builds/build-without-wallet/test/tmp/test_runner_₿₵_  _20220427_105939/abc_p2p_avalanche_voting_56
2022-04-27T11:01:26.875000Z TestFramework (ERROR): Test failed. Test logging available at /work/abc-ci-builds/build-without-wallet/test/tmp/test_runner_₿₵_  _20220427_105939/abc_p2p_avalanche_voting_56/test_framework.log
2022-04-27T11:01:26.875000Z TestFramework (ERROR): 
2022-04-27T11:01:26.875000Z TestFramework (ERROR): Hint: Call /work/test/functional/combine_logs.py '/work/abc-ci-builds/build-without-wallet/test/tmp/test_runner_₿₵_  _20220427_105939/abc_p2p_avalanche_voting_56' to consolidate all logs
2022-04-27T11:01:26.875000Z TestFramework (ERROR): 
2022-04-27T11:01:26.875000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2022-04-27T11:01:26.875000Z TestFramework (ERROR): https://github.com/Bitcoin-ABC/bitcoin-abc/issues
2022-04-27T11:01:26.875000Z TestFramework (ERROR):

Each failure log is accessible here:
Bitcoin ABC functional tests: abc_p2p_avalanche_voting.py --nolegacyavaproof

Failed tests logs:

====== Bitcoin ABC functional tests: abc_p2p_avalanche_voting.py --nolegacyavaproof ======

------- Stdout: -------
2022-04-27T11:02:50.785000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_  _20220427_105843/abc_p2p_avalanche_voting_56
2022-04-27T11:02:54.540000Z TestFramework (INFO): Poll for the chain tip...
2022-04-27T11:02:54.593000Z TestFramework (INFO): Poll for a selection of blocks...
2022-04-27T11:02:54.651000Z TestFramework (INFO): Poll for a selection of blocks, but some are now invalid...
2022-04-27T11:02:54.776000Z TestFramework (INFO): Poll for unknown blocks...
2022-04-27T11:02:54.832000Z TestFramework (INFO): Trigger polling from the node...
2022-04-27T11:02:56.884000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 136, in main
    self.run_test()
  File "/work/test/functional/abc_p2p_avalanche_voting.py", line 175, in run_test
    timeout=5)
  File "/usr/lib/python3.7/contextlib.py", line 119, in __exit__
    next(self.gen)
  File "/work/test/functional/test_framework/test_node.py", line 535, in assert_debug_log
    str(expected_msgs), print_log))
  File "/work/test/functional/test_framework/test_node.py", line 213, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['Avalanche accepted block']" does not partially match log:

 - 2022-04-27T11:02:54.887723Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5
 - 2022-04-27T11:02:54.889623Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=1
 - 2022-04-27T11:02:54.898233Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=6
 - 2022-04-27T11:02:54.902815Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=2
 - 2022-04-27T11:02:54.905947Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=3
 - 2022-04-27T11:02:54.908749Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=7
 - 2022-04-27T11:02:54.919313Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=8
 - 2022-04-27T11:02:54.928691Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=4
 - 2022-04-27T11:02:54.929012Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=5
 - 2022-04-27T11:02:54.929301Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=6
 - 2022-04-27T11:02:54.929927Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=9
 - 2022-04-27T11:02:54.940525Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=10
 - 2022-04-27T11:02:54.951116Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=11
 - 2022-04-27T11:02:54.961678Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=12
 - 2022-04-27T11:02:54.972196Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=13
 - 2022-04-27T11:02:54.982708Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=14
 - 2022-04-27T11:02:54.993215Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=15
 - 2022-04-27T11:02:55.003729Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=16
 - 2022-04-27T11:02:55.014248Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=1
 - 2022-04-27T11:02:55.024792Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=2
 - 2022-04-27T11:02:55.035299Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=3
 - 2022-04-27T11:02:55.045788Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=4
 - 2022-04-27T11:02:55.056283Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5
 - 2022-04-27T11:02:55.066768Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=6
 - 2022-04-27T11:02:56.272334Z [../../src/wallet/bdb.cpp:664] [PeriodicFlush] Flushing wallet.dat
 - 2022-04-27T11:02:56.288064Z [../../src/wallet/bdb.cpp:673] [PeriodicFlush] Flushed wallet.dat 16ms


2022-04-27T11:02:56.935000Z TestFramework (INFO): Stopping nodes
2022-04-27T11:02:57.238000Z TestFramework (WARNING): Not cleaning up dir /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_  _20220427_105843/abc_p2p_avalanche_voting_56
2022-04-27T11:02:57.238000Z TestFramework (ERROR): Test failed. Test logging available at /work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_  _20220427_105843/abc_p2p_avalanche_voting_56/test_framework.log
2022-04-27T11:02:57.238000Z TestFramework (ERROR): 
2022-04-27T11:02:57.238000Z TestFramework (ERROR): Hint: Call /work/test/functional/combine_logs.py '/work/abc-ci-builds/build-debug/test/tmp/test_runner_₿₵_  _20220427_105843/abc_p2p_avalanche_voting_56' to consolidate all logs
2022-04-27T11:02:57.238000Z TestFramework (ERROR): 
2022-04-27T11:02:57.238000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2022-04-27T11:02:57.238000Z TestFramework (ERROR): https://github.com/Bitcoin-ABC/bitcoin-abc/issues
2022-04-27T11:02:57.238000Z TestFramework (ERROR):

Each failure log is accessible here:
Bitcoin ABC functional tests: abc_p2p_avalanche_voting.py --nolegacyavaproof

Failed tests logs:

====== Bitcoin ABC functional tests: abc_p2p_avalanche_voting.py ======

------- Stdout: -------
2022-04-27T11:06:30.183000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110346/abc_p2p_avalanche_voting_50
2022-04-27T11:06:33.446000Z TestFramework (INFO): Poll for the chain tip...
2022-04-27T11:06:33.500000Z TestFramework (INFO): Poll for a selection of blocks...
2022-04-27T11:06:33.556000Z TestFramework (INFO): Poll for a selection of blocks, but some are now invalid...
2022-04-27T11:06:33.629000Z TestFramework (INFO): Poll for unknown blocks...
2022-04-27T11:06:33.684000Z TestFramework (INFO): Trigger polling from the node...
2022-04-27T11:06:35.769000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 136, in main
    self.run_test()
  File "/work/test/functional/abc_p2p_avalanche_voting.py", line 175, in run_test
    timeout=5)
  File "/usr/lib/python3.7/contextlib.py", line 119, in __exit__
    next(self.gen)
  File "/work/test/functional/test_framework/test_node.py", line 535, in assert_debug_log
    str(expected_msgs), print_log))
  File "/work/test/functional/test_framework/test_node.py", line 213, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['Avalanche accepted block']" does not partially match log:

 - 2022-04-27T11:06:33.734547Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5
 - 2022-04-27T11:06:33.738016Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=1
 - 2022-04-27T11:06:33.740435Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=2
 - 2022-04-27T11:06:33.744692Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=6
 - 2022-04-27T11:06:33.754830Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=7
 - 2022-04-27T11:06:33.762891Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=3
 - 2022-04-27T11:06:33.762969Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=4
 - 2022-04-27T11:06:33.763033Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=5
 - 2022-04-27T11:06:33.764934Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=8
 - 2022-04-27T11:06:33.775036Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=9
 - 2022-04-27T11:06:33.785162Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=10
 - 2022-04-27T11:06:33.795289Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=11
 - 2022-04-27T11:06:33.805419Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=12
 - 2022-04-27T11:06:33.815559Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=13
 - 2022-04-27T11:06:33.825666Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=14
 - 2022-04-27T11:06:33.835800Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=15
 - 2022-04-27T11:06:33.845932Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=16
 - 2022-04-27T11:06:33.856035Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=1
 - 2022-04-27T11:06:33.866132Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=2
 - 2022-04-27T11:06:33.876295Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=3
 - 2022-04-27T11:06:33.886400Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=4
 - 2022-04-27T11:06:33.896531Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5
 - 2022-04-27T11:06:35.371230Z [../../src/wallet/bdb.cpp:664] [PeriodicFlush] Flushing wallet.dat
 - 2022-04-27T11:06:35.373929Z [../../src/wallet/bdb.cpp:673] [PeriodicFlush] Flushed wallet.dat 2ms


2022-04-27T11:06:35.820000Z TestFramework (INFO): Stopping nodes
2022-04-27T11:06:36.172000Z TestFramework (WARNING): Not cleaning up dir /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110346/abc_p2p_avalanche_voting_50
2022-04-27T11:06:36.172000Z TestFramework (ERROR): Test failed. Test logging available at /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110346/abc_p2p_avalanche_voting_50/test_framework.log
2022-04-27T11:06:36.172000Z TestFramework (ERROR): 
2022-04-27T11:06:36.172000Z TestFramework (ERROR): Hint: Call /work/test/functional/combine_logs.py '/work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110346/abc_p2p_avalanche_voting_50' to consolidate all logs
2022-04-27T11:06:36.172000Z TestFramework (ERROR): 
2022-04-27T11:06:36.172000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2022-04-27T11:06:36.172000Z TestFramework (ERROR): https://github.com/Bitcoin-ABC/bitcoin-abc/issues
2022-04-27T11:06:36.173000Z TestFramework (ERROR):
====== Bitcoin ABC functional tests with the next upgrade activated: abc_p2p_avalanche_voting.py ======

------- Stdout: -------
2022-04-27T11:11:06.745000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110810/abc_p2p_avalanche_voting_50
2022-04-27T11:11:10.017000Z TestFramework (INFO): Poll for the chain tip...
2022-04-27T11:11:10.071000Z TestFramework (INFO): Poll for a selection of blocks...
2022-04-27T11:11:10.127000Z TestFramework (INFO): Poll for a selection of blocks, but some are now invalid...
2022-04-27T11:11:10.200000Z TestFramework (INFO): Poll for unknown blocks...
2022-04-27T11:11:10.255000Z TestFramework (INFO): Trigger polling from the node...
2022-04-27T11:11:12.299000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 136, in main
    self.run_test()
  File "/work/test/functional/abc_p2p_avalanche_voting.py", line 175, in run_test
    timeout=5)
  File "/usr/lib/python3.7/contextlib.py", line 119, in __exit__
    next(self.gen)
  File "/work/test/functional/test_framework/test_node.py", line 535, in assert_debug_log
    str(expected_msgs), print_log))
  File "/work/test/functional/test_framework/test_node.py", line 213, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['Avalanche accepted block']" does not partially match log:

 - 2022-04-27T11:11:10.301619Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5
 - 2022-04-27T11:11:10.304467Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=1
 - 2022-04-27T11:11:10.311735Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=6
 - 2022-04-27T11:11:10.317082Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=2
 - 2022-04-27T11:11:10.321852Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=7
 - 2022-04-27T11:11:10.331965Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=8
 - 2022-04-27T11:11:10.339171Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=3
 - 2022-04-27T11:11:10.341252Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=4
 - 2022-04-27T11:11:10.341359Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=5
 - 2022-04-27T11:11:10.342039Z [../../src/net_processing.cpp:3501] [ProcessMessage] received: avaresponse (653 bytes) peer=6
 - 2022-04-27T11:11:10.342082Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=9
 - 2022-04-27T11:11:10.352201Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=10
 - 2022-04-27T11:11:10.362317Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=11
 - 2022-04-27T11:11:10.372432Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=12
 - 2022-04-27T11:11:10.382571Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=13
 - 2022-04-27T11:11:10.392692Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=14
 - 2022-04-27T11:11:10.402810Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=15
 - 2022-04-27T11:11:10.412925Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=16
 - 2022-04-27T11:11:10.423040Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=1
 - 2022-04-27T11:11:10.433159Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=2
 - 2022-04-27T11:11:10.443276Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=3
 - 2022-04-27T11:11:10.453393Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=4
 - 2022-04-27T11:11:10.463509Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=5
 - 2022-04-27T11:11:10.473626Z [../../src/net.cpp:3655] [PushMessage] sending avapoll (585 bytes) peer=6


2022-04-27T11:11:12.349000Z TestFramework (INFO): Stopping nodes
2022-04-27T11:11:12.501000Z TestFramework (WARNING): Not cleaning up dir /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110810/abc_p2p_avalanche_voting_50
2022-04-27T11:11:12.501000Z TestFramework (ERROR): Test failed. Test logging available at /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110810/abc_p2p_avalanche_voting_50/test_framework.log
2022-04-27T11:11:12.501000Z TestFramework (ERROR): 
2022-04-27T11:11:12.501000Z TestFramework (ERROR): Hint: Call /work/test/functional/combine_logs.py '/work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20220427_110810/abc_p2p_avalanche_voting_50' to consolidate all logs
2022-04-27T11:11:12.501000Z TestFramework (ERROR): 
2022-04-27T11:11:12.502000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2022-04-27T11:11:12.502000Z TestFramework (ERROR): https://github.com/Bitcoin-ABC/bitcoin-abc/issues
2022-04-27T11:11:12.502000Z TestFramework (ERROR):

Each failure log is accessible here:
Bitcoin ABC functional tests: abc_p2p_avalanche_voting.py
Bitcoin ABC functional tests with the next upgrade activated: abc_p2p_avalanche_voting.py

deadalnix requested changes to this revision.Apr 28 2022, 14:37
deadalnix added a subscriber: deadalnix.

Tests are failing, back on your queue.

This revision now requires changes to proceed.Apr 28 2022, 14:37

Remove incorrect, racy test assertion.

deadalnix requested changes to this revision.May 1 2022, 20:47
deadalnix added inline comments.
src/net_processing.cpp
5209

You'd be better off using logging the right thing is each case and then goto to a common sink rather than the spaghetti on the right.

5241

If you do not declare variable or take a lock (which declares a variable inside its macro), you don't need to introduce a scope.

test/functional/abc_p2p_avalanche_voting.py
202

Why did this become racy? The code already uses wait_until so there are no reason for this to be racey, unless something was broken at some point.

This revision now requires changes to proceed.May 1 2022, 20:47