Page MenuHomePhabricator

Log the reason for a block policy violation
ClosedPublic

Authored by sdulfari on Mar 27 2023, 19:21.

Details

Reviewers
PiRK
Fabien
Group Reviewers
Restricted Project
Commits
rABC3c6224afcb2c: Log the reason for a block policy violation
Summary

Introduce BlockPolicyValidationState so we can log reasons behind block policy
violations. This will also allow callers to make decisions based on the result
of the policy check rather than observing the resulting state (ie. block was
parked).

POLICY_VIOLATION is intentionally left vague. It is not clear in what other
ways policies might fail other than a simple rule violation but it is too early
to determine at this stage.

Test Plan
ninja check check-functional

Diff Detail

Repository
rABC Bitcoin ABC
Lint
Lint Not Applicable
Unit
Tests Not Applicable

Event Timeline

Failed tests logs:

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

------- Stdout: -------
2023-03-27T19:25:00.332000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-without-wallet/test/tmp/test_runner_₿₵_  _20230327_192303/abc_feature_minerfund_96
2023-03-27T19:25:00.646000Z TestFramework (INFO): Create some history
2023-03-27T19:25:04.741000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 137, in main
    self.run_test()
  File "/work/test/functional/abc_feature_minerfund.py", line 158, in run_test
    self.wait_until(lambda: parked_block(first_block_no_miner_fund))
  File "/usr/lib/python3.9/contextlib.py", line 124, in __exit__
    next(self.gen)
  File "/work/test/functional/test_framework/test_node.py", line 559, in assert_debug_log
    self._raise_assertion_error(
  File "/work/test/functional/test_framework/test_node.py", line 218, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['policy-bad-miner-fund']" does not partially match log:

 - 2023-03-27T19:25:02.731760Z (mocktime: 2036-07-18T13:30:00Z) [../../src/httpserver.cpp:249] [http_request_cb] Received a POST request for / from 127.0.0.1:58922
 - 2023-03-27T19:25:02.731816Z (mocktime: 2036-07-18T13:30:00Z) [../../src/rpc/request.cpp:182] [parse] ThreadRPCServer method=getchaintips user=__cookie__


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

Each failure log is accessible here:
Bitcoin ABC functional tests: abc_feature_minerfund.py

Failed tests logs:

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

------- Stdout: -------
2023-03-27T19:27:09.138000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20230327_192322/abc_feature_minerfund_96
2023-03-27T19:27:09.591000Z TestFramework (INFO): Create some history
2023-03-27T19:27:13.687000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 137, in main
    self.run_test()
  File "/work/test/functional/abc_feature_minerfund.py", line 158, in run_test
    self.wait_until(lambda: parked_block(first_block_no_miner_fund))
  File "/usr/lib/python3.9/contextlib.py", line 124, in __exit__
    next(self.gen)
  File "/work/test/functional/test_framework/test_node.py", line 559, in assert_debug_log
    self._raise_assertion_error(
  File "/work/test/functional/test_framework/test_node.py", line 218, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['policy-bad-miner-fund']" does not partially match log:

 - 2023-03-27T19:27:11.676547Z (mocktime: 2036-07-18T13:30:00Z) [../../src/httpserver.cpp:249] [http_request_cb] Received a POST request for / from 127.0.0.1:60862
 - 2023-03-27T19:27:11.676611Z (mocktime: 2036-07-18T13:30:00Z) [../../src/rpc/request.cpp:182] [parse] ThreadRPCServer method=getchaintips user=__cookie__


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

------- Stdout: -------
2023-03-27T19:31:35.771000Z TestFramework (INFO): Initializing test directory /work/abc-ci-builds/build-diff/test/tmp/test_runner_₿₵_  _20230327_192756/abc_feature_minerfund_96
2023-03-27T19:31:36.201000Z TestFramework (INFO): Create some history
2023-03-27T19:31:40.353000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/work/test/functional/test_framework/test_framework.py", line 137, in main
    self.run_test()
  File "/work/test/functional/abc_feature_minerfund.py", line 158, in run_test
    self.wait_until(lambda: parked_block(first_block_no_miner_fund))
  File "/usr/lib/python3.9/contextlib.py", line 124, in __exit__
    next(self.gen)
  File "/work/test/functional/test_framework/test_node.py", line 559, in assert_debug_log
    self._raise_assertion_error(
  File "/work/test/functional/test_framework/test_node.py", line 218, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Expected messages "['policy-bad-miner-fund']" does not partially match log:

 - 2023-03-27T19:31:38.342844Z (mocktime: 2036-07-18T13:30:00Z) [../../src/httpserver.cpp:249] [http_request_cb] Received a POST request for / from 127.0.0.1:37864
 - 2023-03-27T19:31:38.342905Z (mocktime: 2036-07-18T13:30:00Z) [../../src/rpc/request.cpp:182] [parse] ThreadRPCServer method=getchaintips user=__cookie__


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

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

Fix assert_debug_log related flakiness

This revision is now accepted and ready to land.Mar 28 2023, 09:27
Fabien requested changes to this revision.Mar 28 2023, 12:32
Fabien added a subscriber: Fabien.
Fabien added inline comments.
src/policy/block/minerfund.cpp
19 ↗(On Diff #38947)

You don't need the intermediate variable

24 ↗(On Diff #38947)

Add the block hash to the debug string

src/policy/block/parkingpolicy.h
8 ↗(On Diff #38947)

This kind of comment is never properly maintained, let's avoid it

src/test/policy_block_tests.cpp
78 ↗(On Diff #38947)

avoid the double negation:
BOOST_CHECK(state.IsValid());

87 ↗(On Diff #38947)

dito

src/validation.cpp
2730 ↗(On Diff #38947)

Does std::all stops on first false condition ?

2737 ↗(On Diff #38947)

You can avoid printing the hash if you previously added the hash to the validation state debug string

test/functional/abc_feature_minerfund.py
140 ↗(On Diff #38947)

Revert

154–158 ↗(On Diff #38947)
This revision now requires changes to proceed.Mar 28 2023, 12:32
  • Feedback
  • Replace std::all_of() with std::find_if_not() to make early bail a guarantee
  • Apply new lint
Fabien added inline comments.
src/test/policy_block_tests.cpp
51 ↗(On Diff #39128)

revert to size_t

This revision is now accepted and ready to land.Apr 3 2023, 07:45

Hello!
I installed Bitcoin ABC 0.29.2 to try to start solo mining. I use a 2678v3 processor, 32g of RAM, 1tb ssd. I ran it like this:

/bitcoind -zmqpubhashblock=tcp://127.0.0.1:28332 -rpcport=17024 -rpcuser=user -rpcpassword=mypass -datadir=/media/user/BitRez/xec/

After full synchronization, I created a wallet and received the address ecash:qr9euptgtjхххххххххххcv9mqgsjvsyz5.
After that, I saw the instructions on the official website e.cash/mining and following the link, I decided to install ecash-ckpool-solo. I cloned it into the directory where Bitcoin ABC 0.29.2 was located in a separate folder and compiled the code. after that I launched it with the command:

./ckpool -x

After that, I connected my miners according to the configuration file stratum+tcp://192.168.1.39:3333 and started mining. Decisions were sent and accepted successfully and there were no rejections. A day later I received a message:

[2024-04-28 08:37:23.194] Possible block solve diff 44603125984.910110 !
[2024-04-28 08:37:23.198] BLOCK ACCEPTED!
[2024-04-28 08:37:23.480] Solved and confirmed block 842275 by ecash:qr9euptgtjvn65e0cv7k5sl326vhvcv9mqgsjvsyz5
[2024-04-28 08:37:23.480] User ecash:qr9euptgtjvn65e0cv7k5sl326vhvcv9mqgsjvsyz5:{"hashrate1m": "607T", "hashrate5m": "627T", "hashrate1hr": "634T", "hashrate1d": "461T", "hashrate7d": "107T", "shares": 16518229736, "authorised": 1714161478}
[2024-04-28 08:37:23.480] Worker ecash:qr9euptgtjvn65e0cv7k5sl326vhvcv9mqgsjvsyz5:{"hashrate1m": "607T", "hashrate5m": "627T", "hashrate1hr": "634T", "hashrate1d": "461T", "hashrate7d": "107T"}

However, when I looked, I saw that the coins had not been credited. And the node has a message like this:

2024-04-28T04:37:23Z Park block because it violated a block policy: policy-bad-miner-fund, Block 000000000000000018a68f3d5878260fdc8d7d4408083a34ac72decd33e70179 violates miner fund policy
2024-04-28T04:37:23Z Considered switching to better tip 000000000000000018a68f3d5878260fdc8d7d4408083a34ac72decd33e70179 but that chain contains a parked block.
2024-04-28T04:37:23Z UpdateTip: new best=000000000000000018a68f3d5878260fdc8d7d4408083a34ac72decd33e70179 height=842275 version=0x2000c000 log2_work=88.512324 tx=298392063 date='2024-04-28T04:36:58Z' progress=1.000000 cache=0.3MiB(2324txo)
2024-04-28T04:37:23Z CreateNewBlock(): total size: 213 txs: 0 fees: 0 sigChecks 100
2024-04-28T04:37:26Z UpdateTip: new best=000000000000000018e621ee5d264052b6aa22239055b3f2e1b097f5ec59302d height=842274 version=0x2efb0000 log2_work=88.512324 tx=298392023 date='2024-04-28T04:10:47Z' progress=0.999983 cache=0.3MiB(2297txo)
2024-04-28T04:37:26Z Considered switching to better tip 000000000000000018a68f3d5878260fdc8d7d4408083a34ac72decd33e70179 but that chain contains a parked block.

I don't understand what is the reason and what violates the miners fund policy?