The code not only modifies block dat files, but also leveldb files, which may be of smaller size. Such corruption may not force leveldb to abort, according to the intermittent test failures.
Fix the intermittent test failures by reverting https://github.com/bitcoin/bitcoin/commit/5ab6419f380cc0a8cde78b125f3eeee5fcba43ae .
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
For detailed information about the code coverage, see the test coverage report.
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | kevkevinpal, theStack, fjahr |
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
0@@ -1,11 +1,10 @@
1 #!/usr/bin/env python3
2-# Copyright (c) 2021-2022 The Bitcoin Core developers
3+# Copyright (c) 2021-present The Bitcoin Core developers
running this command
grep -nr --text "\-present" ./src
I only see these files using present
0./src/streams.cpp:1:// Copyright (c) 2009-present The Bitcoin Core developers
1./src/kernel/mempool_removal_reason.cpp:1:// Copyright (c) 2016-present The Bitcoin Core developers
2./src/kernel/mempool_removal_reason.h:1:// Copyright (c) 2016-present The Bitcoin Core developers
if this is something we’re going towards would we want to update the copy right of all files whenever there is a change to the file in any future PR’s?
The scripted-diff for all files should be easy to rebase, see the thread: #26817 (comment)
Let me know if I should drop it here and leave it for later. I don’t really mind either way, as I mostly care about not running into intermittent issues.
Can you link to the intermittent failures? Why not reduce the values instead?
You can simply run the test in a loop to see it fail. For example:
0./test/functional/feature_init.py --timeout-factor=.1 --randomseed=4861605774237699286
1
2...
3
4AssertionError: [node 0] bitcoind should have exited within 6s with expected error Error opening block database.
Why not reduce the values instead?
Yes, this patch is reducing the value.
Also, on a second thought, I don’t really understand the goal of the randomized byte corruptions. Are they supposed to increase the test coverage for different code paths? If yes, I think it makes sense to list those code paths. Otherwise, if only a single error-code-path is covered, I think a deterministic test is better.
I understand that the good first issue mentioned that advanced perturbations should be tested as well, but may require pulling in a leveldb parser. I don’t think it makes sense to pull in a leveldb parser for this, unless there is a good reason. (Recall that Bitcoin Core does not support running on hardware that corrupts the datadir). If there was a “honest” pertubation caused by a user setting or different leveldb version that causes issues, that’d be a different case, and it would be a good reason to check that specifically.
The same holds for mutating block files.
Other than that, I don’t think it makes sense to add a test for this. And in any case, adding a test for this, or modifying the existing test, should be a separate follow-up from fixing a bug by restoring the previous test.
Yes, this patch is reducing the value.
Maybe as a side-effect but it’s rolling back the randomization completely. What I mean is reducing the max value of seek, i.e. 15000 to something lower that is safe.
Maybe as a side-effect but it’s rolling back the randomization completely. What I mean is reducing the max value of
seek, i.e. 15000 to something lower that is safe.
Why? Did you see my previous comment?
Why? Did you see my previous comment?
It’s fine if you want to remove the randomization as well as you say in the other comment but that’s not what I meant when I said “Why not reduce the values instead?”. You replied to that “Yes, this patch is reducing the value.”. But that is not the only thing that it does and that’s why it’s not what I suggested. What I suggested is reducing the max value in seek.
./test/functional/feature_init.py –timeout-factor=.1 –randomseed=4861605774237699286
0$ ./test/functional/feature_init.py --timeout-factor=.1 --randomseed=4861605774237699286
12023-11-10T13:14:53.906000Z TestFramework (INFO): User supplied random seed 4861605774237699286
22023-11-10T13:14:53.907000Z TestFramework (INFO): PRNG seed is: 4861605774237699286
32023-11-10T13:14:53.907000Z TestFramework (INFO): Initializing test directory /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318
42023-11-10T13:14:54.678000Z TestFramework (INFO): Starting node and will exit after line b'Validating signatures for all blocks'
52023-11-10T13:14:54.848000Z TestFramework (INFO): Starting node and will exit after line b'scheduler thread start'
62023-11-10T13:14:54.971000Z TestFramework (INFO): Starting node and will exit after line b'Starting HTTP server'
72023-11-10T13:14:55.095000Z TestFramework (INFO): Starting node and will exit after line b'Loading P2P addresses'
82023-11-10T13:14:55.219000Z TestFramework (INFO): Starting node and will exit after line b'Loading banlist'
92023-11-10T13:14:55.342000Z TestFramework (INFO): Starting node and will exit after line b'Loading block index'
102023-11-10T13:14:55.483000Z TestFramework (INFO): Starting node and will exit after line b'Checking all blk files are present'
112023-11-10T13:14:55.678000Z TestFramework (INFO): Starting node and will exit after line b'Loaded best chain:'
122023-11-10T13:14:55.889000Z TestFramework (INFO): Starting node and will exit after line b'init message: Verifying blocks'
132023-11-10T13:14:56.121000Z TestFramework (INFO): Starting node and will exit after line b'init message: Starting network threads'
142023-11-10T13:14:56.508000Z TestFramework (INFO): Starting node and will exit after line b'net thread start'
152023-11-10T13:14:56.901000Z TestFramework (INFO): Starting node and will exit after line b'addcon thread start'
162023-11-10T13:14:57.299000Z TestFramework (INFO): Starting node and will exit after line b'initload thread start'
172023-11-10T13:14:57.720000Z TestFramework (INFO): Starting node and will exit after line b'txindex thread start'
182023-11-10T13:14:58.155000Z TestFramework (INFO): Starting node and will exit after line b'block filter index thread start'
192023-11-10T13:14:58.551000Z TestFramework (INFO): Starting node and will exit after line b'coinstatsindex thread start'
202023-11-10T13:14:58.953000Z TestFramework (INFO): Starting node and will exit after line b'msghand thread start'
212023-11-10T13:14:59.381000Z TestFramework (INFO): Starting node and will exit after line b'net thread start'
222023-11-10T13:14:59.815000Z TestFramework (INFO): Starting node and will exit after line b'addcon thread start'
232023-11-10T13:15:00.214000Z TestFramework (INFO): Starting node and will exit after line b'Verifying wallet'
242023-11-10T13:15:00.715000Z TestFramework (INFO): Test startup errors after removing certain essential files
252023-11-10T13:15:00.719000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/index/000048.ldb
262023-11-10T13:15:00.720000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/index/000054.ldb
272023-11-10T13:15:00.720000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/index/000051.ldb
282023-11-10T13:15:00.721000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/index/000046.ldb
292023-11-10T13:15:01.298000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/chainstate/000005.ldb
302023-11-10T13:15:01.305000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/chainstate/000090.ldb
312023-11-10T13:15:01.868000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/blk00000.dat
322023-11-10T13:15:02.440000Z TestFramework (INFO): Test startup errors after perturbing certain essential files
332023-11-10T13:15:02.473000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/index/000061.ldb
342023-11-10T13:15:02.473000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/index/000059.ldb
352023-11-10T13:15:02.473000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/index/000066.ldb
362023-11-10T13:15:02.673000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/chainstate/000005.ldb
372023-11-10T13:15:02.674000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/chainstate/000097.ldb
382023-11-10T13:15:02.674000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/chainstate/000092.ldb
392023-11-10T13:15:02.674000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/chainstate/000090.ldb
402023-11-10T13:15:02.935000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318/node0/regtest/blocks/blk00000.dat
412023-11-10T13:15:03.235000Z TestFramework (INFO): Stopping nodes
422023-11-10T13:15:03.236000Z TestFramework (INFO): Cleaning up /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_oiro5318 on exit
432023-11-10T13:15:03.236000Z TestFramework (INFO): Tests successful
Hm, this doesn’t fail for me on master.
Jup, that is what I mean when I say we don’t want to pull in a leveldb dependency into this test, unless there is a reason. leveldb has different code paths depending on the operating system. You are using macOS and I was using Linux. I presume you’ll be able to reproduce if you also use Linux. Alternatively, you can try to run the test in a loop on macOS, but I can’t do that, because I don’t have macOS.
If the test fails because the leveldb is smaller than the block files, I would propose keeping the randomization for the block files and adding a second deterministic test for leveldb?
Yes, I considered this and I think it could make sense. However, it may require reading the file size and using that as the maximum, or other changes. So for now, I made it trivial to review by just reverting, so that the CI and tests are no longer failing intermittently.
If the test fails because the leveldb is smaller than the block files, I would propose keeping the randomization for the block files and adding a second deterministic test for leveldb?
That was also my initial thought when reading this PR’s description. In contrast to the chainstate leveldb files, the block files are fully in our control and possible faulty behaviour caused by perturbation should (hopefully) be identical on all operating systems, as there is no external library involved.
I agree with @maflcko though that the highest priority now is to fix the CI, so reverting seems to be a reasonable first step. If someone is working on a follow-up introducing the random perturbation, feel free to ping me as reviewer.
ACK 44445ae8f1123c3affdcc0dbd7b3830eff5548ef
If someone is working on a follow-up introducing the random perturbation, feel free to ping me as reviewer.
Same here, happy to review
Jup, that is what I mean when I say we don’t want to pull in a leveldb dependency into this test, unless there is a reason. leveldb has different code paths depending on the operating system. You are using macOS and I was using Linux. I presume you’ll be able to reproduce if you also use Linux. Alternatively, you can try to run the test in a loop on macOS, but I can’t do that, because I don’t have macOS.
0root@vmd96750:~/bitcoin# ./test/functional/feature_init.py --timeout-factor=.1 --randomseed=4861605774237699286
12023-11-11T09:42:34.291000Z TestFramework (INFO): User supplied random seed 4861605774237699286
22023-11-11T09:42:34.291000Z TestFramework (INFO): PRNG seed is: 4861605774237699286
32023-11-11T09:42:34.296000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_20yqsr48
42023-11-11T09:42:36.852000Z TestFramework (INFO): Starting node and will exit after line b'Validating signatures for all blocks'
52023-11-11T09:42:37.111000Z TestFramework (INFO): Starting node and will exit after line b'scheduler thread start'
62023-11-11T09:42:37.264000Z TestFramework (INFO): Starting node and will exit after line b'Starting HTTP server'
72023-11-11T09:42:37.422000Z TestFramework (INFO): Starting node and will exit after line b'Loading P2P addresses'
82023-11-11T09:42:37.571000Z TestFramework (INFO): Starting node and will exit after line b'Loading banlist'
92023-11-11T09:42:37.722000Z TestFramework (INFO): Starting node and will exit after line b'Loading block index'
102023-11-11T09:42:37.875000Z TestFramework (INFO): Starting node and will exit after line b'Checking all blk files are present'
112023-11-11T09:42:38.041000Z TestFramework (INFO): Starting node and will exit after line b'Loaded best chain:'
122023-11-11T09:42:38.230000Z TestFramework (INFO): Starting node and will exit after line b'init message: Verifying blocks'
132023-11-11T09:42:38.417000Z TestFramework (INFO): Starting node and will exit after line b'init message: Starting network threads'
142023-11-11T09:42:38.747000Z TestFramework (INFO): Starting node and will exit after line b'net thread start'
152023-11-11T09:42:39.071000Z TestFramework (INFO): Starting node and will exit after line b'addcon thread start'
162023-11-11T09:42:39.365000Z TestFramework (INFO): Starting node and will exit after line b'initload thread start'
172023-11-11T09:42:39.620000Z TestFramework (INFO): Starting node and will exit after line b'txindex thread start'
182023-11-11T09:42:39.858000Z TestFramework (INFO): Starting node and will exit after line b'block filter index thread start'
192023-11-11T09:42:40.189000Z TestFramework (INFO): Starting node and will exit after line b'coinstatsindex thread start'
202023-11-11T09:42:40.494000Z TestFramework (INFO): Starting node and will exit after line b'msghand thread start'
212023-11-11T09:42:40.803000Z TestFramework (INFO): Starting node and will exit after line b'net thread start'
222023-11-11T09:42:41.104000Z TestFramework (INFO): Starting node and will exit after line b'addcon thread start'
232023-11-11T09:42:41.395000Z TestFramework (INFO): Starting node and will exit after line b'Verifying wallet'
242023-11-11T09:42:41.956000Z TestFramework (INFO): Test startup errors after removing certain essential files
252023-11-11T09:42:41.957000Z TestFramework (INFO): Deleting file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/index/000046.ldb
262023-11-11T09:42:41.957000Z TestFramework (INFO): Deleting file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/index/000054.ldb
272023-11-11T09:42:41.957000Z TestFramework (INFO): Deleting file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/index/000048.ldb
282023-11-11T09:42:41.957000Z TestFramework (INFO): Deleting file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/index/000051.ldb
292023-11-11T09:42:42.540000Z TestFramework (INFO): Deleting file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/chainstate/000090.ldb
302023-11-11T09:42:42.540000Z TestFramework (INFO): Deleting file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/chainstate/000005.ldb
312023-11-11T09:42:43.121000Z TestFramework (INFO): Deleting file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/blk00000.dat
322023-11-11T09:42:43.608000Z TestFramework (INFO): Test startup errors after perturbing certain essential files
332023-11-11T09:42:43.648000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/index/000061.ldb
342023-11-11T09:42:43.648000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/index/000066.ldb
352023-11-11T09:42:43.648000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/index/000059.ldb
362023-11-11T09:42:44.044000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/chainstate/000092.ldb
372023-11-11T09:42:44.046000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/chainstate/000090.ldb
382023-11-11T09:42:44.047000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/chainstate/000097.ldb
392023-11-11T09:42:44.047000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/chainstate/000005.ldb
402023-11-11T09:42:44.302000Z TestFramework (INFO): Perturbing file to ensure failure /tmp/bitcoin_func_test_20yqsr48/node0/regtest/blocks/blk00000.dat
412023-11-11T09:42:44.577000Z TestFramework (INFO): Stopping nodes
422023-11-11T09:42:44.577000Z TestFramework (INFO): Cleaning up /tmp/bitcoin_func_test_20yqsr48 on exit
432023-11-11T09:42:44.577000Z TestFramework (INFO): Tests successful
highest priority now is to fix the CI @theStack Can you link to a CI failure? Maybe I can reproduce it with that info.
Did you run the test in a loop on Linux?
So far two people reported local issues. There are also CI failures, for example https://cirrus-ci.com/task/5031659184062464?logs=ci#L4069
(This one also shows a memory leak due to the corruption, so that’d be another reason to not fiddle with levedb files, as it will cause an CI error, even if Bitcoin Core shut down with the correct error message)
So I was actually able to reproduce this by just hardcoding the max values of the random range:
0 tf.seek(15000)
1 tf.write(b'1' * 2000)
0$ ./test/functional/feature_init.py
12023-11-11T15:46:50.985000Z TestFramework (INFO): PRNG seed is: 7272134511591997577
22023-11-11T15:46:50.986000Z TestFramework (INFO): Initializing test directory /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm
32023-11-11T15:46:51.480000Z TestFramework (INFO): Starting node and will exit after line b'Validating signatures for all blocks'
42023-11-11T15:46:51.650000Z TestFramework (INFO): Starting node and will exit after line b'scheduler thread start'
52023-11-11T15:46:51.772000Z TestFramework (INFO): Starting node and will exit after line b'Starting HTTP server'
62023-11-11T15:46:51.896000Z TestFramework (INFO): Starting node and will exit after line b'Loading P2P addresses'
72023-11-11T15:46:52.019000Z TestFramework (INFO): Starting node and will exit after line b'Loading banlist'
82023-11-11T15:46:52.142000Z TestFramework (INFO): Starting node and will exit after line b'Loading block index'
92023-11-11T15:46:52.285000Z TestFramework (INFO): Starting node and will exit after line b'Checking all blk files are present'
102023-11-11T15:46:52.483000Z TestFramework (INFO): Starting node and will exit after line b'Loaded best chain:'
112023-11-11T15:46:52.694000Z TestFramework (INFO): Starting node and will exit after line b'init message: Verifying blocks'
122023-11-11T15:46:52.929000Z TestFramework (INFO): Starting node and will exit after line b'init message: Starting network threads'
132023-11-11T15:46:53.312000Z TestFramework (INFO): Starting node and will exit after line b'net thread start'
142023-11-11T15:46:53.709000Z TestFramework (INFO): Starting node and will exit after line b'addcon thread start'
152023-11-11T15:46:54.117000Z TestFramework (INFO): Starting node and will exit after line b'initload thread start'
162023-11-11T15:46:54.551000Z TestFramework (INFO): Starting node and will exit after line b'txindex thread start'
172023-11-11T15:46:54.983000Z TestFramework (INFO): Starting node and will exit after line b'block filter index thread start'
182023-11-11T15:46:55.385000Z TestFramework (INFO): Starting node and will exit after line b'coinstatsindex thread start'
192023-11-11T15:46:55.784000Z TestFramework (INFO): Starting node and will exit after line b'msghand thread start'
202023-11-11T15:46:56.215000Z TestFramework (INFO): Starting node and will exit after line b'net thread start'
212023-11-11T15:46:56.654000Z TestFramework (INFO): Starting node and will exit after line b'addcon thread start'
222023-11-11T15:46:57.052000Z TestFramework (INFO): Starting node and will exit after line b'Verifying wallet'
232023-11-11T15:46:57.555000Z TestFramework (INFO): Test startup errors after removing certain essential files
242023-11-11T15:46:57.557000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/index/000048.ldb
252023-11-11T15:46:57.557000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/index/000054.ldb
262023-11-11T15:46:57.558000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/index/000051.ldb
272023-11-11T15:46:57.559000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/index/000046.ldb
282023-11-11T15:46:58.132000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/chainstate/000005.ldb
292023-11-11T15:46:58.133000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/chainstate/000090.ldb
302023-11-11T15:46:58.704000Z TestFramework (INFO): Deleting file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/blk00000.dat
312023-11-11T15:46:59.279000Z TestFramework (INFO): Test startup errors after perturbing certain essential files
322023-11-11T15:46:59.303000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/index/000061.ldb
332023-11-11T15:46:59.303000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/index/000059.ldb
342023-11-11T15:46:59.303000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/blocks/index/000066.ldb
352023-11-11T15:46:59.506000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/chainstate/000005.ldb
362023-11-11T15:46:59.506000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/chainstate/000097.ldb
372023-11-11T15:46:59.507000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/chainstate/000092.ldb
382023-11-11T15:46:59.507000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/chainstate/000090.ldb
392023-11-11T15:47:59.510000Z TestFramework (ERROR): Assertion failed
40Traceback (most recent call last):
41 File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_node.py", line 605, in assert_start_raises_init_error
42 ret = self.process.wait(timeout=self.rpc_timeout)
43 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
44 File "/opt/homebrew/Cellar/python@3.11/3.11.5/Frameworks/Python.framework/Versions/3.11/lib/python3.11/subprocess.py", line 1264, in wait
45 return self._wait(timeout=timeout)
46 ^^^^^^^^^^^^^^^^^^^^^^^^^^^
47 File "/opt/homebrew/Cellar/python@3.11/3.11.5/Frameworks/Python.framework/Versions/3.11/lib/python3.11/subprocess.py", line 2038, in _wait
48 raise TimeoutExpired(self.args, timeout)
49subprocess.TimeoutExpired: Command '['/Users/FJ/projects/clones/bitcoin/src/bitcoind', '-datadir=/var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0', '-logtimemicros', '-debug', '-debugexclude=libevent', '-debugexclude=leveldb', '-debugexclude=rand', '-uacomment=testnode0', '-logthreadnames', '-logsourcelocations', '-loglevel=trace', '-txindex=1', '-blockfilterindex=1', '-coinstatsindex=1', '-checkblocks=200', '-checklevel=4']' timed out after 60 seconds
50
51During handling of the above exception, another exception occurred:
52
53Traceback (most recent call last):
54 File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_framework.py", line 132, in main
55 self.run_test()
56 File "/Users/FJ/projects/clones/bitcoin/./test/functional/feature_init.py", line 144, in run_test
57 start_expecting_error(err_fragment)
58 File "/Users/FJ/projects/clones/bitcoin/./test/functional/feature_init.py", line 51, in start_expecting_error
59 node.assert_start_raises_init_error(
60 File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_node.py", line 635, in assert_start_raises_init_error
61 self._raise_assertion_error(assert_msg)
62 File "/Users/FJ/projects/clones/bitcoin/test/functional/test_framework/test_node.py", line 176, in _raise_assertion_error
63 raise AssertionError(self._node_msg(msg))
64AssertionError: [node 0] bitcoind should have exited within 60s with expected error Error opening block database.
652023-11-11T15:47:59.581000Z TestFramework (INFO): Stopping nodes
662023-11-11T15:47:59.581000Z TestFramework (WARNING): Not cleaning up dir /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm
672023-11-11T15:47:59.582000Z TestFramework (ERROR): Test failed. Test logging available at /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/test_framework.log
682023-11-11T15:47:59.582000Z TestFramework (ERROR):
692023-11-11T15:47:59.583000Z TestFramework (ERROR): Hint: Call /Users/FJ/projects/clones/bitcoin/test/functional/combine_logs.py '/var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm' to consolidate all logs
702023-11-11T15:47:59.583000Z TestFramework (ERROR):
712023-11-11T15:47:59.583000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
722023-11-11T15:47:59.583000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
732023-11-11T15:47:59.583000Z TestFramework (ERROR):
I tried to look at the file sizes of the ldb files involved but the file where the test fails is deleted, not really sure why as of now
0$ la /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_6x2iwdcm/node0/regtest/chainstate/
1total 88
2drwx------ 8 FJ staff 256 Nov 11 16:46 ./
3drwx------ 16 FJ staff 512 Nov 11 16:46 ../
4-rw------- 1 FJ staff 17000 Nov 11 16:46 000005.ldb
5-rw------- 1 FJ staff 0 Nov 11 16:46 000105.log
6-rw------- 1 FJ staff 14919 Nov 11 16:46 000106.ldb
7-rw------- 1 FJ staff 16 Nov 11 16:46 CURRENT
8-rw------- 1 FJ staff 0 Nov 11 16:25 LOCK
9-rw------- 1 FJ staff 347 Nov 11 16:46 MANIFEST-000104
Instead I edited the log message to include a file size for the ldb files:
0 self.log.info(f"Perturbing file to ensure failure {target_file}, size: {os.path.getsize(target_file)}")
02023-11-11T15:56:25.464000Z TestFramework (INFO): Test startup errors after perturbing certain essential files
12023-11-11T15:56:25.506000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_i9rjmk54/node0/regtest/blocks/index/000061.ldb, size: 193
22023-11-11T15:56:25.506000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_i9rjmk54/node0/regtest/blocks/index/000059.ldb, size: 28142
32023-11-11T15:56:25.506000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_i9rjmk54/node0/regtest/blocks/index/000066.ldb, size: 193
42023-11-11T15:56:25.714000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_i9rjmk54/node0/regtest/chainstate/000005.ldb, size: 198
52023-11-11T15:56:25.714000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_i9rjmk54/node0/regtest/chainstate/000097.ldb, size: 451
62023-11-11T15:56:25.714000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_i9rjmk54/node0/regtest/chainstate/000092.ldb, size: 451
72023-11-11T15:56:25.714000Z TestFramework (INFO): Perturbing file to ensure failure /var/folders/9z/n7rz_6cj3bq__11k5kcrsvvm0000gn/T/bitcoin_func_test_i9rjmk54/node0/regtest/chainstate/000090.ldb, size: 14919
82023-11-11T15:57:25.719000Z TestFramework (ERROR): Assertion failed
So there are smaller ldb files that are perturbed first that don’t trigger the issue, it’s actually a bigger one where the failure happens.
I haven’t looked into this deeper yet but my best guess would be that ldb doesn’t care about this last, big file and doesn’t check it?
I haven’t looked into this deeper yet but my best guess would be that ldb doesn’t care about this last, big file and doesn’t check it?
No, that’s not it, otherwise the hardcoded test wouldn’t fail. If we don’t understand what leveldb is doing then I guess we should probably remove perturbing its files altogether.
If we don’t understand what leveldb is doing then I guess we should probably remove perturbing its files altogether.
sgtm, for a follow-up or alternative pull. The goal of this pull is not to change any test, but only to restore the previous code, which didn’t intermittently fail.