init: Stop indexes on shutdown after ChainStateFlushed callback. #17897

jimpo · 2020-01-08T20:12:39Z

Replaces #17852.

Currently, the latest index state may not be committed to disk on shutdown. The state is committed on ChainStateFlushed callbacks and the current init order unregisters the indexes as validation interfaces before the final ChainStateFlushed callback is called on them.

Issue identified by paulyc.

For review: an alternative or supplemental solution would be to call Commit at the end of BaseIndex::Stop. I don't see any harm in doing so and it makes the less prone to user error. However, the destructor would have to be modified to not call Stop because Commit calls a virtual method, so I figured it wasn't worth it. But I'm curious how others feel.

DrahtBot · 2020-01-08T23:22:35Z

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#14053 (Add address-based index (attempt 4?) by marcinja)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

promag

~~Code review ACK 4a6cb2f.~~

src/init.cpp

promag

This is actually bad. The moved code is after

    g_txindex.reset();
    DestroyAllBlockFilterIndexes();

which means the moved code does nothing now.

Currently, the latest index state may not be committed to disk on shutdown.

jimpo · 2020-01-10T00:52:19Z

Thanks @promag, fixed.

promag · 2020-01-10T10:51:52Z

Looks good now, this time I'll test.

promag

Is it me or the following

    if (g_txindex) {
        g_txindex->Interrupt();
    }
    ForEachBlockFilterIndex([](BlockFilterIndex& index) { index.Interrupt(); });

should be removed from Interrupt(NodeContext& node)?

jimpo · 2020-01-10T22:00:51Z

@promag I don't think so. Why?

promag · 2020-01-14T09:53:26Z

Actually I think it's fine, I was missing the !m_synced check.

I was seeing this order of events:

Interrupt() is called which asynchronously stops the loop in ThreadSync()
before UnregisterValidationInterface is called, validation notifications can be delivered, which can't be handled.

But now I see the m_synced flag to guard against this case.

Anyway, would be nice to include steps/changes to reproduce the original problem.

Code review ACK 9dd58ca, but failed to test because I can't reproduce the original problem.

paulyc · 2020-01-21T05:27:38Z

Actually I think it's fine, I was missing the !m_synced check.

I was seeing this order of events:

Interrupt() is called which asynchronously stops the loop in ThreadSync()

before UnregisterValidationInterface is called, validation notifications can be delivered, which can't be handled.

But now I see the m_synced flag to guard against this case.

Anyway, would be nice to include steps/changes to reproduce the original problem.

Code review ACK 9dd58ca, but failed to test because I can't reproduce the original problem.

So here is how I can currently reproduce it:

Create a new datadir, start syncing with txindex=1. Let it run a while until there are decent number of block files, say to block 190000. Kill it. So when you restart, you'd expect that the txindex would restart at the same point as the block indexer at 190000 since they were both at the same point before you killed the daemon, but instead, I see the txindex starting at 39339, even though the data is in the txindex leveldb, it still has to run through every block again until it catches up and sets a new checkpoint, which is what led me to believe it wasn't being closed correctly since that's when leveldb writes out the current metadata for the next load. Here's my logfile from doing that
bitcoind.txindex.redacted.log

promag · 2020-01-21T14:40:48Z

Thanks @paulyc, I have done that but didn't wait for that block count.

fjahr · 2020-01-22T00:09:37Z

tested ACK 9dd58ca

Tested as described by @paulyc. Also ran tests locally.

kallewoof · 2020-01-22T06:59:49Z

Tested ACK 9dd58ca

master branch showing txindex sync begins at block 0 upon restart

$ ./bitcoind -txindex=1 -datadir=oij
[...]
2020-01-22T06:11:44Z Shutdown: In progress...
2020-01-22T06:11:44Z net thread exit
2020-01-22T06:11:44Z UpdateTip: new best=000000000000035010292db86f97a207d96a4106af108fcb016550dee0e4f96e height=168089 version=0x00000001 log2_work=67.727578 tx=2483951 date='2012-02-23T10:53:35Z' progress=0.004994 cache=202.5MiB(1524617txo)
[...]
2020-01-22T06:12:21Z Shutdown: done
$ ./bitcoind -txindex=1 -datadir=oij
[...]
2020-01-22T06:12:56Z Opening LevelDB in /Users/me/workspace/bitcoin/src/oij/indexes/txindex
2020-01-22T06:12:57Z Opened LevelDB successfully
2020-01-22T06:12:57Z Using obfuscation key for /Users/me/workspace/bitcoin/src/oij/indexes/txindex: 0000000000000000
2020-01-22T06:12:57Z txindex thread start
2020-01-22T06:12:57Z init message: Loading wallet...
2020-01-22T06:12:57Z Syncing txindex with block chain from height 0
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[...]

#17897 PR showing txindex sync prevails upon restart

$ ./bitcoind -txindex=1 -datadir=oij-jimpo
[...]
2020-01-22T06:17:35Z Opening LevelDB in /Users/me/workspace/bitcoin/src/oij-jimpo/indexes/txindex
2020-01-22T06:17:35Z Opened LevelDB successfully
2020-01-22T06:17:35Z Using obfuscation key for /Users/me/workspace/bitcoin/src/oij-jimpo/indexes/txindex: 0000000000000000
2020-01-22T06:17:35Z txindex thread start
2020-01-22T06:17:35Z txindex is enabled
2020-01-22T06:17:35Z init message: Loading wallet...
2020-01-22T06:17:35Z txindex thread exit
[...]
2020-01-22T06:39:03Z UpdateTip: new best=000000000000000a92ff09eb56af38ad02b64ee75d4b71274caa437efc1e8b6c height=172386 version=0x00000001 log2_work=67.87869 tx=2670294 date='2012-03-22T19:16:30Z' progress=0.005368 cache=213.9MiB(1617994txo)
[...]
2020-01-22T06:39:40Z Shutdown: done
$ ./bitcoind -txindex=1 -datadir=oij-jimpo
[...]
2020-01-22T06:46:12Z Loaded best chain: hashBestChain=000000000000000a92ff09eb56af38ad02b64ee75d4b71274caa437efc1e8b6c height=172386 date=2012-03-22T19:16:30Z progress=0.005368
[...]
2020-01-22T06:46:15Z Opening LevelDB in /Users/me/workspace/bitcoin/src/oij-jimpo/indexes/txindex
2020-01-22T06:46:16Z Opened LevelDB successfully
2020-01-22T06:46:16Z Using obfuscation key for /Users/me/workspace/bitcoin/src/oij-jimpo/indexes/txindex: 0000000000000000
2020-01-22T06:46:16Z txindex thread start
2020-01-22T06:46:16Z txindex is enabled at height 172386
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2020-01-22T06:46:16Z txindex thread exit
[...]

fanquake · 2020-01-22T09:29:38Z

Looks good. I've tested master (742f84d) vs this PR (9dd58ca) and am seeing the same fixed behaviour. Thanks @promag, @fjahr, @kallewoof and @paulyc for testing.

master

2020-01-22T08:56:22Z UpdateTip: new best=0000000000002d533ff0e59ee25496b4f403d8ce7b4b7fcd9181dadad8f625b3 height=118827 version=0x00000001 log2_work=61.774365 tx=416409 date='2011-04-17T13:39:54Z' progress=0.000837 cache=33.9MiB(212154txo)
^C2020-01-22T08:56:24Z tor: Thread interrupt
2020-01-22T08:56:24Z Shutdown: In progress...
<snip>
2020-01-22T08:56:25Z Shutdown: done
....
bitcoin $ ./src/bitcoind -txindex -datadir=/Users/michael/Desktop/master
2020-01-22T08:56:32Z Bitcoin Core version v0.19.99.0-742f84d0d (release build)
<snip>
2020-01-22T08:56:35Z Loaded best chain: hashBestChain=0000000000002d533ff0e59ee25496b4f403d8ce7b4b7fcd9181dadad8f625b3 height=118827 date=2011-04-17T13:39:54Z progress=0.000837
<snip>
2020-01-22T08:56:36Z Using obfuscation key for /Users/michael/Desktop/master/indexes/txindex: 0000000000000000
2020-01-22T08:56:36Z txindex thread start
2020-01-22T08:56:36Z Syncing txindex with block chain from height 65

This PR

2020-01-22T09:19:53Z Shutdown: In progress...
2020-01-22T09:19:53Z UpdateTip: new best=00000000000092c47111d9ca453b6df25b6e139faf438ab06070638417195fba height=116260 version=0x00000001 log2_work=61.415013 tx=385266 date='2011-04-02T06:16:42Z' progress=0.000774 cache=30.4MiB(196729txo)
<snip>
2020-01-22T09:20:10Z Shutdown: done
....
bitcoin $ ./src/bitcoind -txindex -datadir=/Users/michael/Desktop/17897
2020-01-22T09:20:54Z Bitcoin Core version v0.19.99.0-9dd58ca61 (release build)
<snip>
2020-01-22T09:21:02Z Loaded best chain: hashBestChain=00000000000092c47111d9ca453b6df25b6e139faf438ab06070638417195fba height=116260 date=2011-04-02T06:16:42Z progress=0.000774
<snip>
2020-01-22T09:21:07Z Using obfuscation key for /Users/michael/Desktop/17897/indexes/txindex: 0000000000000000
2020-01-22T09:21:07Z txindex thread start
2020-01-22T09:21:07Z init message: Loading wallet...
2020-01-22T09:21:07Z txindex is enabled at height 116260

…callback. 9dd58ca init: Stop indexes on shutdown after ChainStateFlushed callback. (Jim Posen) Pull request description: Replaces #17852. Currently, the latest index state may not be committed to disk on shutdown. The state is committed on `ChainStateFlushed` callbacks and the current init order unregisters the indexes as validation interfaces before the final `ChainStateFlushed` callback is called on them. Issue identified by paulyc. For review: an alternative or supplemental solution would be to call `Commit` at the end of `BaseIndex::Stop`. I don't see any harm in doing so and it makes the less prone to user error. However, the destructor would have to be modified to not call `Stop` because `Commit` calls a virtual method, so I figured it wasn't worth it. But I'm curious how others feel. ACKs for top commit: fjahr: tested ACK 9dd58ca paulyc: > Code review ACK [9dd58ca](9dd58ca), but failed to test because I can't reproduce the original problem. kallewoof: Tested ACK 9dd58ca promag: Code review ACK 9dd58ca, but failed to test because I can't reproduce the original problem. Tree-SHA512: 2918380b699833cb7eab07456d1667dbf8ebbe2d2b5988300a3cf5b6a6cfc818b6d9086e1936ffe7881f67e409306c4b91d61a08a169cfd0a301383479d4f3cb

Currently, the latest index state may not be committed to disk on shutdown. Github-Pull: #17897 Rebased-From: 9dd58ca

fanquake · 2020-01-22T10:27:55Z

This has been backported to the 0.19 branch in 9d980c1.

…lushed callback. 9dd58ca init: Stop indexes on shutdown after ChainStateFlushed callback. (Jim Posen) Pull request description: Replaces bitcoin#17852. Currently, the latest index state may not be committed to disk on shutdown. The state is committed on `ChainStateFlushed` callbacks and the current init order unregisters the indexes as validation interfaces before the final `ChainStateFlushed` callback is called on them. Issue identified by paulyc. For review: an alternative or supplemental solution would be to call `Commit` at the end of `BaseIndex::Stop`. I don't see any harm in doing so and it makes the less prone to user error. However, the destructor would have to be modified to not call `Stop` because `Commit` calls a virtual method, so I figured it wasn't worth it. But I'm curious how others feel. ACKs for top commit: fjahr: tested ACK 9dd58ca paulyc: > Code review ACK [9dd58ca](bitcoin@9dd58ca), but failed to test because I can't reproduce the original problem. kallewoof: Tested ACK 9dd58ca promag: Code review ACK 9dd58ca, but failed to test because I can't reproduce the original problem. Tree-SHA512: 2918380b699833cb7eab07456d1667dbf8ebbe2d2b5988300a3cf5b6a6cfc818b6d9086e1936ffe7881f67e409306c4b91d61a08a169cfd0a301383479d4f3cb

[0.19] Backports bitcoin#17858 Unbreak build with Boost 1.72.0 bitcoin#17654 cli: fix Fatal LevelDB error when specifying -blockfilterindex=basic twice bitcoin#17687 rpc: require second argument only for scantxoutset start action bitcoin#17728 wallet: Fix origfee return for bumpfee with feerate arg bitcoin#17643 test: fix "bitcoind already running" warnings on macOS bitcoin#17488 net: Log to net category for exceptions in ProcessMessages bitcoin#17762 Updates to appveyor config for VS2019 and Qt5.9.8 + msvc project fixes bitcoin#17364 Appveyor improvement - text file for vcpkg package list bitcoin#17416 Update msvc build for Visual Studio 2019 v16.4 bitcoin#17736 scripts: fix symbol-check & security-check argument passing bitcoin#17857 qt: Periodic translations update for 0.19 branch IsUsedDestination should count any known single-key address bitcoin#17621 init: Stop indexes on shutdown after ChainStateFlushed callback. bitcoin#17897 qt: Translations update pre-rc1 wallet: Reset reused transactions cache bitcoin#17843 Squashed 'src/univalue/' changes from 7890db9..98261b1 0.19: Update univalue subtree bitcoin#18100 qt: Pre-rc2 translations update

[0.19] Backports bitcoin#17858 Unbreak build with Boost 1.72.0 bitcoin#17654 cli: fix Fatal LevelDB error when specifying -blockfilterindex=basic twice bitcoin#17687 rpc: require second argument only for scantxoutset start action bitcoin#17728 wallet: Fix origfee return for bumpfee with feerate arg bitcoin#17643 test: fix "bitcoind already running" warnings on macOS bitcoin#17488 net: Log to net category for exceptions in ProcessMessages bitcoin#17762 Updates to appveyor config for VS2019 and Qt5.9.8 + msvc project fixes bitcoin#17364 Appveyor improvement - text file for vcpkg package list bitcoin#17416 Update msvc build for Visual Studio 2019 v16.4 bitcoin#17736 scripts: fix symbol-check & security-check argument passing bitcoin#17857 qt: Periodic translations update for 0.19 branch IsUsedDestination should count any known single-key address bitcoin#17621 init: Stop indexes on shutdown after ChainStateFlushed callback. bitcoin#17897 qt: Translations update pre-rc1 wallet: Reset reused transactions cache bitcoin#17843 Squashed 'src/univalue/' changes from 7890db9..98261b1 0.19: Update univalue subtree bitcoin#18100 qt: Pre-rc2 translations update [0.19] Further 0.19 backports bitcoin#18218 build: don't embed a build-id when building libdmg-hfsplus bitcoin#18004

…lushed callback. 9dd58ca init: Stop indexes on shutdown after ChainStateFlushed callback. (Jim Posen) Pull request description: Replaces bitcoin#17852. Currently, the latest index state may not be committed to disk on shutdown. The state is committed on `ChainStateFlushed` callbacks and the current init order unregisters the indexes as validation interfaces before the final `ChainStateFlushed` callback is called on them. Issue identified by paulyc. For review: an alternative or supplemental solution would be to call `Commit` at the end of `BaseIndex::Stop`. I don't see any harm in doing so and it makes the less prone to user error. However, the destructor would have to be modified to not call `Stop` because `Commit` calls a virtual method, so I figured it wasn't worth it. But I'm curious how others feel. ACKs for top commit: fjahr: tested ACK 9dd58ca paulyc: > Code review ACK [9dd58ca](bitcoin@9dd58ca), but failed to test because I can't reproduce the original problem. kallewoof: Tested ACK 9dd58ca promag: Code review ACK 9dd58ca, but failed to test because I can't reproduce the original problem. Tree-SHA512: 2918380b699833cb7eab07456d1667dbf8ebbe2d2b5988300a3cf5b6a6cfc818b6d9086e1936ffe7881f67e409306c4b91d61a08a169cfd0a301383479d4f3cb

Summary: > Currently, the latest index state may not be committed to disk on shutdown. > The state is committed on ChainStateFlushed callbacks and the current init order unregisters the indexes as validation interfaces before the final ChainStateFlushed callback is called on them. > This was causing the txindexing progress to have fallen behind to its last random checkpoint the next time bitcoind was started. This is a backport of Core [[bitcoin/bitcoin#17897 | PR17897]] Test Plan: `ninja all check-all` Reviewers: #bitcoin_abc, deadalnix Reviewed By: #bitcoin_abc, deadalnix Differential Revision: https://reviews.bitcoinabc.org/D8663

fanquake added the UTXO Db and Indexes label Jan 8, 2020

promag reviewed Jan 9, 2020

View reviewed changes

src/init.cpp Outdated Show resolved Hide resolved

promag reviewed Jan 9, 2020

View reviewed changes

init: Stop indexes on shutdown after ChainStateFlushed callback.

9dd58ca

Currently, the latest index state may not be committed to disk on shutdown.

jimpo force-pushed the index-commit branch from 4a6cb2f to 29a31d6 Compare January 10, 2020 00:51

fanquake added the Needs backport (0.19) label Jan 10, 2020

jimpo force-pushed the index-commit branch from 29a31d6 to 9dd58ca Compare January 10, 2020 03:10

promag reviewed Jan 10, 2020

View reviewed changes

fanquake merged commit 9dd58ca into bitcoin:master Jan 22, 2020

fanquake pushed a commit that referenced this pull request Jan 22, 2020

init: Stop indexes on shutdown after ChainStateFlushed callback.

9d980c1

Currently, the latest index state may not be committed to disk on shutdown. Github-Pull: #17897 Rebased-From: 9dd58ca

fanquake removed the Needs backport (0.19) label Jan 22, 2020

MarkLTZ mentioned this pull request Apr 4, 2020

Bitcoin PR tracking litecoinz-core/litecoinz#14

Closed

bitcoin locked as resolved and limited conversation to collaborators Feb 15, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

init: Stop indexes on shutdown after ChainStateFlushed callback. #17897

init: Stop indexes on shutdown after ChainStateFlushed callback. #17897

Uh oh!

jimpo commented Jan 8, 2020 •

edited by fanquake

Loading

Uh oh!

DrahtBot commented Jan 8, 2020

Uh oh!

promag left a comment •

edited

Loading

Uh oh!

Uh oh!

promag left a comment •

edited

Loading

Uh oh!

jimpo commented Jan 10, 2020

Uh oh!

promag commented Jan 10, 2020

Uh oh!

promag left a comment

Uh oh!

jimpo commented Jan 10, 2020

Uh oh!

promag commented Jan 14, 2020 •

edited

Loading

Uh oh!

paulyc commented Jan 21, 2020

Uh oh!

promag commented Jan 21, 2020

Uh oh!

fjahr commented Jan 22, 2020

Uh oh!

kallewoof commented Jan 22, 2020

Uh oh!

fanquake commented Jan 22, 2020

Uh oh!

fanquake commented Jan 22, 2020

Uh oh!

Uh oh!

init: Stop indexes on shutdown after ChainStateFlushed callback. #17897

init: Stop indexes on shutdown after ChainStateFlushed callback. #17897

Uh oh!

Conversation

jimpo commented Jan 8, 2020 • edited by fanquake Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Jan 8, 2020

Conflicts

Uh oh!

promag left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

promag left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jimpo commented Jan 10, 2020

Uh oh!

promag commented Jan 10, 2020

Uh oh!

promag left a comment

Choose a reason for hiding this comment

Uh oh!

jimpo commented Jan 10, 2020

Uh oh!

promag commented Jan 14, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

paulyc commented Jan 21, 2020

Uh oh!

promag commented Jan 21, 2020

Uh oh!

fjahr commented Jan 22, 2020

Uh oh!

kallewoof commented Jan 22, 2020

Uh oh!

fanquake commented Jan 22, 2020

master

This PR

Uh oh!

fanquake commented Jan 22, 2020

Uh oh!

Uh oh!

jimpo commented Jan 8, 2020 •

edited by fanquake

Loading

promag left a comment •

edited

Loading

promag left a comment •

edited

Loading

promag commented Jan 14, 2020 •

edited

Loading