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

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:

Specify the change is for a block
Specify invalidated/rejected/accepted/finalized
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

Repository

rABC Bitcoin ABC

Branch

TS_avalanche_logging

Lint

Lint Passed

Unit

No Test Coverage

Build Status

Buildable 18914
Build 37608: Build Diff	build-diff · build-without-wallet · build-debug · lint-circular-dependencies · build-clang-tidy · build-clang
Build 37607: arc lint + arc unit

Event Timeline

tyler-smith created this revision.Apr 25 2022, 08:13

Herald added a reviewer: Restricted Project. · View Herald TranscriptApr 25 2022, 08:13

tyler-smith requested review of this revision.Apr 25 2022, 08:13

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

Harbormaster completed remote builds in B18871: Diff 33293.Apr 25 2022, 08:31

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.

tyler-smith edited the test plan for this revision. (Show Details)Apr 27 2022, 10:52

Harbormaster completed remote builds in B18899: Diff 33330.Apr 27 2022, 11:02

Build Bitcoin ABC Diffs / Diff Testing (build-without-wallet) failed.

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

Build Bitcoin ABC Diffs / Diff Testing (build-debug) failed.

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

Build Bitcoin ABC Diffs / Diff Testing (build-diff) failed.

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

Tests are failing, back on your queue.

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

Remove incorrect, racy test assertion.

Harbormaster completed remote builds in B18914: Diff 33357.May 1 2022, 04:25

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.