Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Reorg causes orderly shutdown on btcd when addrindex=1 #340

Closed
aakselrod opened this issue Mar 4, 2015 · 5 comments
Closed

Reorg causes orderly shutdown on btcd when addrindex=1 #340

aakselrod opened this issue Mar 4, 2015 · 5 comments

Comments

@aakselrod
Copy link
Contributor

btcd seems to shut itself down during or shortly after a reorg when addrindex=1. It seems to corrupt the DB as simply restarting btcd just makes it shut itself right back down on the spot. Sample logs (from a btcd running on testnet3):

06:44:08 2015-03-04 [INF] CHAN: REORGANIZE: Block 000000000000056c231b5aa21a97b18279cb6f79788e3a143602ed5ef76497fe is causing a reorganize.
06:44:08 2015-03-04 [INF] CHAN: REORGANIZE: Chain forks at 00000000b5aa277d95d779ab467243e9e2ce60a939b3c36df8c5e6b53a49fb98
06:44:08 2015-03-04 [INF] CHAN: REORGANIZE: Old best chain head was 000000005d68052f51ea9f034ba60499d957c404e47e0c8d0662d596eac33d70
06:44:08 2015-03-04 [INF] CHAN: REORGANIZE: New best chain head is 000000000000056c231b5aa21a97b18279cb6f79788e3a143602ed5ef76497fe
06:44:28 2015-03-04 [INF] BMGR: Processed 2 blocks in the last 21.09s (15 transactions, height 325025, 2015-03-04 07:32:48 +0000 UTC)
06:44:28 2015-03-04 [INF] ADXR: Indexed addresses of 2 blocks in the last 21.09s (15 transactions, height 325025, 2015-03-04 07:32:48 +0000 UTC)
06:49:35 2015-03-04 [INF] BMGR: Processed 1 block in the last 5m6.27s (5 transactions, height 325026, 2015-03-04 07:32:48 +0000 UTC)
06:49:35 2015-03-04 [INF] ADXR: Indexed addresses of 1 block in the last 5m6.27s (5 transactions, height 325026, 2015-03-04 07:32:48 +0000 UTC)
06:50:18 2015-03-04 [INF] BMGR: Processed 1 block in the last 43.08s (1 transaction, height 325027, 2015-03-04 07:37:21 +0000 UTC)
06:50:18 2015-03-04 [INF] ADXR: Indexed addresses of 1 block in the last 43.08s (1 transaction, height 325027, 2015-03-04 07:37:21 +0000 UTC)
06:58:25 2015-03-04 [INF] BMGR: Processed 1 block in the last 8m7.23s (208 transactions, height 325028, 2015-03-04 07:42:40 +0000 UTC)
06:58:25 2015-03-04 [INF] ADXR: Indexed addresses of 1 block in the last 8m7.25s (208 transactions, height 325028, 2015-03-04 07:42:40 +0000 UTC)
07:03:35 2015-03-04 [INF] BMGR: Processed 1 block in the last 5m9.91s (94 transactions, height 325029, 2015-03-04 08:02:41 +0000 UTC)
07:03:35 2015-03-04 [ERR] ADXR: Couldn't get referenced txOut (303caba4550ae84ef9a8aa4e2bb872b390436d596779998a6f3bfe46cd104946:0): requested transaction does not exist
07:03:35 2015-03-04 [ERR] ADXR: Unable to index transactions of block requested transaction does not exist
07:03:35 2015-03-04 [WRN] SRVR: Server shutting down
07:03:35 2015-03-04 [WRN] RPCS: RPC server shutting down

and

21:00:48 2015-03-04 [INF] CHAN: REORGANIZE: Block 0000000000000267f64950771bb419aaf66971d54684bb0424ce43f46c5e6517 is causing a reorganize.
21:00:48 2015-03-04 [INF] CHAN: REORGANIZE: Chain forks at 00000000f2582a33179947d80e3138543937501f10ba3daffef2f75898118265
21:00:48 2015-03-04 [INF] CHAN: REORGANIZE: Old best chain head was 0000000074eb8345e94ecf80097eda83e3dc91f0f1df4a311ca97637f149cddf
21:00:48 2015-03-04 [INF] CHAN: REORGANIZE: New best chain head is 0000000000000267f64950771bb419aaf66971d54684bb0424ce43f46c5e6517
21:00:48 2015-03-04 [INF] BMGR: Processed 1 block in the last 3m24.69s (25 transactions, height 325212, 2015-03-04 21:40:16 +0000 UTC)
21:00:48 2015-03-04 [INF] ADXR: Indexed addresses of 1 block in the last 3m24.69s (25 transactions, height 325212, 2015-03-04 21:40:16 +0000 UTC)
21:10:17 2015-03-04 [INF] BMGR: Processed 1 block in the last 9m29.43s (21 transactions, height 325213, 2015-03-04 21:42:57 +0000 UTC)
21:10:17 2015-03-04 [INF] ADXR: Indexed addresses of 1 block in the last 9m29.43s (21 transactions, height 325213, 2015-03-04 21:42:57 +0000 UTC)
21:16:49 2015-03-04 [INF] BMGR: Processed 2 blocks in the last 6m31.82s (62 transactions, height 325215, 2015-03-04 22:09:05 +0000 UTC)
21:16:49 2015-03-04 [WRN] BCDB: unable to decode tx block 325212 0000000000000267f64950771bb419aaf66971d54684bb0424ce43f46c5e6517 txoff 1895 txlen 191
21:16:49 2015-03-04 [ERR] ADXR: Unable to index transactions of block: transaction e1ee7585cd9a5b19cec0e72eaebc4353bba4cd82d97bbf3fa696c6578ecee8ac not found
21:16:49 2015-03-04 [WRN] SRVR: Server shutting down
21:16:49 2015-03-04 [WRN] RPCS: RPC server shutting down
21:16:49 2015-03-04 [INF] RPCS: RPC server shutdown complete
21:16:49 2015-03-04 [INF] ADXR: Address indexer shutting down
21:16:49 2015-03-04 [INF] BMGR: Block manager shutting down
21:16:49 2015-03-04 [INF] AMGR: Address manager shutting down
21:16:49 2015-03-04 [INF] SRVR: Server shutdown complete
21:16:49 2015-03-04 [INF] BTCD: Shutdown complete

Here's a log from a restart attempt:

22:33:00 2015-03-04 [INF] BTCD: Version 0.10.0-beta
22:33:00 2015-03-04 [INF] BTCD: Loading block database from '/home/ubuntu/.btcd/data/testnet/blocks_leveldb'
22:33:00 2015-03-04 [INF] BTCD: Block database loaded with block height 325215
22:33:00 2015-03-04 [INF] BMGR: Generating initial block node index. This may take a while...
22:33:01 2015-03-04 [INF] BMGR: Block index generation complete
22:33:01 2015-03-04 [INF] SRVR: Server listening on 0.0.0.0:18333
22:33:01 2015-03-04 [INF] SRVR: Server listening on [::]:18333
22:33:01 2015-03-04 [INF] RPCS: RPC server listening on 0.0.0.0:18334
22:33:01 2015-03-04 [INF] RPCS: RPC server listening on [::]:18334
22:33:01 2015-03-04 [INF] ADXR: Building up address index from height 325215 to 325215.
22:33:01 2015-03-04 [WRN] BCDB: unable to decode tx block 325212 > 0000000000000267f64950771bb419aaf66971d54684bb0424ce43f46c5e6517 txoff 1895 txlen 191
22:33:01 2015-03-04 [ERR] ADXR: Unable to index transactions of block: transaction e1ee7585cd9a5b19cec0e72eaebc4353bba4cd82d97bbf3fa696c6578ecee8ac not found
22:33:01 2015-03-04 [WRN] SRVR: Server shutting down
22:33:01 2015-03-04 [WRN] RPCS: RPC server shutting down
22:33:01 2015-03-04 [INF] RPCS: RPC server shutdown complete
22:33:01 2015-03-04 [INF] ADXR: Address indexer has caught up to best height, entering maintainence mode
22:33:01 2015-03-04 [INF] AMGR: Loaded 1801 addresses from file '/home/ubuntu/.btcd/data/testnet/peers.json'
22:33:01 2015-03-04 [INF] ADXR: Address indexer shutting down
22:33:01 2015-03-04 [INF] BMGR: Block manager shutting down
22:33:01 2015-03-04 [INF] AMGR: Address manager shutting down
22:33:01 2015-03-04 [INF] SRVR: Server shutdown complete
22:33:01 2015-03-04 [INF] BTCD: Shutdown complete
22:33:02 2015-03-04 [INF] DISC: 6 addresses found from DNS seed testnet-seed.bitcoin.petertodd.org
@davecgh davecgh changed the title Reorg crashes btcd when addrindex=1 Reorg causes orderly shutdown on btcd when addrindex=1 Mar 4, 2015
@Roasbeef
Copy link
Member

Roasbeef commented Mar 5, 2015

First, we're you running an outdated version of the addrindex from the branch it was developed in? I ask because the logging message "Couldn't get referenced txOut.." never appears in the current codebase.

Second, @aakselrod are you able to succesfully retireve either of these txids:

  • e1ee7585cd9a5b19cec0e72eaebc4353bba4cd82d97bbf3fa696c6578ecee8ac
  • 303caba4550ae84ef9a8aa4e2bb872b390436d596779998a6f3bfe46cd104946

with a call to getrawtransaction?

@aakselrod
Copy link
Contributor Author

@Roasbeef, I was running master from about 2-3 weeks ago. I haven't seen any issues since I pulled the most recent master yesterday, but I don't think we've seen any reorgs in the past day either. Even with the most up-to-date code, btcd would stop as soon as it started with the corrupted database, so I couldn't send a getrawtransaction to it when it was in this state. I did back up a broken DB from a few days ago so I can get that to you for analysis if you want.

@Roasbeef
Copy link
Member

A reorg on the testnet yesterday seems to have triggered this issue:

21:30:51 2015-03-22 [INF] BMGR: Processed 1 block in the last 20m0.89s (30 transactions, height 328645, 2015-03-22 23:30:50 -0400 EDT)
21:30:51 2015-03-22 [INF] ADXR: Indexed addresses of 1 block in the last 20m0.89s (30 transactions, height 328645, 2015-03-22 23:30:50 -0400 EDT)
21:50:52 2015-03-22 [INF] BMGR: Processed 1 block in the last 20m1.09s (42 transactions, height 328646, 2015-03-22 23:50:51 -0400 EDT)
21:50:52 2015-03-22 [INF] ADXR: Indexed addresses of 1 block in the last 20m1.1s (42 transactions, height 328646, 2015-03-22 23:50:51 -0400 EDT)
22:10:54 2015-03-22 [INF] BMGR: Processed 1 block in the last 20m2.05s (31 transactions, height 328647, 2015-03-23 00:10:52 -0400 EDT)
22:10:54 2015-03-22 [INF] ADXR: Indexed addresses of 1 block in the last 20m2.05s (31 transactions, height 328647, 2015-03-23 00:10:52 -0400 EDT)
22:18:42 2015-03-22 [INF] CHAN: REORGANIZE: Block 00000000000000c5f9d170299c11a31bf117c26a09848ce183c28818d36111e6 is causing a reorganize.
22:18:42 2015-03-22 [INF] CHAN: REORGANIZE: Chain forks at 00000000668e31f194e4b4fb23d39e583709666f50ffdb4d5309b0da4d35b28c
22:18:42 2015-03-22 [INF] CHAN: REORGANIZE: Old best chain head was 000000000f36d2503271eaf31e68022dcf5a0a0495790abaeaa2153420de9336
22:18:42 2015-03-22 [INF] CHAN: REORGANIZE: New best chain head is 00000000000000c5f9d170299c11a31bf117c26a09848ce183c28818d36111e6
22:18:42 2015-03-22 [INF] BMGR: Processed 1 block in the last 7m47.94s (11 transactions, height 328647, 2015-03-22 22:24:18 -0400 EDT)
22:18:42 2015-03-22 [INF] ADXR: Indexed addresses of 1 block in the last 7m47.94s (11 transactions, height 328647, 2015-03-22 22:24:18 -0400 EDT)
22:19:36 2015-03-22 [INF] BMGR: Processed 1 block in the last 53.68s (34 transactions, height 328648, 2015-03-22 22:44:19 -0400 EDT)
22:19:36 2015-03-22 [ERR] ADXR: Unable to index transactions of block: transaction fa6764111c4784d8ff56371f88046dbdca34be434d6e5136f759b15efbced153 not found
22:19:36 2015-03-22 [WRN] SRVR: Server shutting down
22:19:36 2015-03-22 [INF] ADXR: Address indexer shutting down
22:19:36 2015-03-22 [INF] BMGR: Block manager shutting down
22:19:36 2015-03-22 [INF] AMGR: Address manager shutting down
22:19:36 2015-03-22 [INF] SRVR: Server shutdown complete
22:19:36 2015-03-22 [INF] BTCD: Shutdown complete

Re-count of the order of events that triggered the shutdown above:

Restart attempt with addrindex activated:

01:16:24 2015-03-23 [INF] BTCD: Version 0.10.0-beta
01:16:24 2015-03-23 [INF] BTCD: Loading block database from '/root/.btcd/data/testnet/blocks_leveldb'
01:16:24 2015-03-23 [INF] BTCD: Profile server listening on :6061
01:16:24 2015-03-23 [INF] BTCD: Block database loaded with block height 328670
01:16:24 2015-03-23 [INF] BMGR: Generating initial block node index.  This may take a while...
01:16:24 2015-03-23 [INF] BMGR: Block index generation complete
01:16:24 2015-03-23 [INF] SRVR: Server listening on 0.0.0.0:18333
01:16:24 2015-03-23 [INF] SRVR: Server listening on [::]:18333
01:16:24 2015-03-23 [INF] RPCS: RPC server listening on 127.0.0.1:18334
01:16:24 2015-03-23 [INF] ADXR: Building up address index from height 328648 to 328670.
01:16:24 2015-03-23 [ERR] ADXR: Unable to index transactions of block: transaction fa6764111c4784d8ff56371f88046dbdca34be434d6e5136f759b15efbced153 not found
01:16:24 2015-03-23 [WRN] SRVR: Server shutting down
01:16:24 2015-03-23 [WRN] RPCS: RPC server shutting down
01:16:24 2015-03-23 [INF] RPCS: RPC server shutdown complete
01:16:24 2015-03-23 [INF] AMGR: Loaded 2292 addresses from file '/root/.btcd/data/testnet/peers.json'
01:16:24 2015-03-23 [INF] ADXR: Address indexer shutting down
01:16:24 2015-03-23 [INF] BMGR: Block manager shutting down
01:16:25 2015-03-23 [INF] AMGR: Address manager shutting down
01:16:25 2015-03-23 [INF] DISC: 1 addresses found from DNS seed testnet-seed.bluematt.me
01:16:25 2015-03-23 [INF] DISC: 6 addresses found from DNS seed testnet-seed.bitcoin.petertodd.org
01:16:25 2015-03-23 [INF] SRVR: Server shutdown complete
01:16:25 2015-03-23 [INF] BTCD: Shutdown complete

Result of trying to lookup the missing tx:

➜  testnet btcctl getrawtransaction fa6764111c4784d8ff56371f88046dbdca34be434d6e5136f759b15efbced153
-5: No information available about transaction

Interestingly, a reorg on the 20th was handled without fail:

04:57:03 2015-03-20 [INF] ADXR: Indexed addresses of 1 block in the last 10m43.09s (20 transactions, 
05:10:49 2015-03-20 [INF] BMGR: Processed 1 block in the last 13m47.3s (15 transactions, height 328220, 2015-03-20 07:10:48 -0400 EDT)
05:10:49 2015-03-20 [INF] ADXR: Indexed addresses of 1 block in the last 13m46.72s (15 transactions, height 328220, 2015-03-20 07:10:48 -0400 EDT)
05:10:56 2015-03-20 [INF] CHAN: REORGANIZE: Block 0000000000000223db3b97a87b6fdd41f33000b4f8c2df6ae206ecc86c9d716a is causing a reorganize.
05:10:56 2015-03-20 [INF] CHAN: REORGANIZE: Chain forks at 00000000ab6b90a8323420d32fb65f6e089685a4f3112326b7d84341f212501b
05:10:56 2015-03-20 [INF] CHAN: REORGANIZE: Old best chain head was 0000000041aa4af6b79310d43cd4cc38bad9c6508973cc3d5988bfaf2e545dd7
05:10:56 2015-03-20 [INF] CHAN: REORGANIZE: New best chain head is 0000000000000223db3b97a87b6fdd41f33000b4f8c2df6ae206ecc86c9d716a
05:17:34 2015-03-20 [INF] BMGR: Processed 2 blocks in the last 6m44.72s (33 transactions, height 328221, 2015-03-20 06:20:19 -0400 EDT)
05:17:34 2015-03-20 [INF] ADXR: Indexed addresses of 2 blocks in the last 6m44.72s (33 transactions, 
05:21:06 2015-03-20 [INF] BMGR: Processed 1 block in the last 3m31.51s (14 transactions, height 328222, 2015-03-20 06:40:20 -0400 EDT)
05:21:06 2015-03-20 [INF] ADXR: Indexed addresses of 1 block in the last 3m31.51s (14 transactions, height 328222, 2015-03-20 06:40:20 -0400 EDT)

@davecgh
Copy link
Member

davecgh commented Mar 23, 2015

I believe this has been resolved with #354. @aakselrod is doing some testing to ensure that is the case.

@aakselrod
Copy link
Contributor Author

This has definitely not been resolved with #354 but I'll be working on fixing it as soon as I update #354 to the point where it's ready to merge.

aakselrod added a commit to aakselrod/btcd that referenced this issue Mar 27, 2015
@aakselrod
Fix btcsuite#340 and DropAfterBlockBySha/NewestSha bug.
b445b56 
- Delete spent TX in setclearSpentData when unspent by block
  disconnect on reorg.

- Test spent TX deletion when reorg causes block disconnect.

- Test for correct NewestSha results after DropAfterBlockBySha.

- Fix DropAfterBlockBySha to update info for NewestSha.
aakselrod added a commit to aakselrod/btcd that referenced this issue Mar 27, 2015
@aakselrod
Fix btcsuite#340 and DropAfterBlockBySha/NewestSha bug.
ccb7d4c 
- Delete spent TX in setclearSpentData when unspent by block
  disconnect on reorg.

- Test spent TX deletion when reorg causes block disconnect.

- Test for correct NewestSha results after DropAfterBlockBySha.

- Fix DropAfterBlockBySha to update info for NewestSha.
aakselrod added a commit to aakselrod/btcd that referenced this issue Mar 27, 2015
@aakselrod
Fix btcsuite#340 and DropAfterBlockBySha/NewestSha bug.
d6e5d56 
- Delete spent TX in setclearSpentData when unspent by block
  disconnect on reorg; return an error when there's more than
  one record to delete in the spent TX as that should never
  happen.

- Test spent TX deletion when reorg causes block disconnect.

- Test for correct NewestSha results after DropAfterBlockBySha.

- Fix DropAfterBlockBySha to update info for NewestSha.
aakselrod added a commit to aakselrod/btcd that referenced this issue Mar 27, 2015
@aakselrod
Fix btcsuite#340 and DropAfterBlockBySha/NewestSha bug.
055bfc2 
- Delete spent TX in setclearSpentData when unspent by block
  disconnect on reorg; return an error when there's more than
  one record to delete in the spent TX as that should never
  happen.

- Test spent TX deletion when reorg causes block disconnect.

- Test for correct NewestSha results after DropAfterBlockBySha.

- Fix DropAfterBlockBySha to update info for NewestSha.

- Updated copyright statements in modified files
aakselrod added a commit to aakselrod/btcd that referenced this issue Mar 30, 2015
@aakselrod
Fix btcsuite#340 and DropAfterBlockBySha/NewestSha bug.
24b2e33 
- Delete spent TX in setclearSpentData when unspent by block
  disconnect on reorg; return an error when there's more than
  one record to delete in the spent TX as that should never
  happen.

- Test spent TX deletion when reorg causes block disconnect.

- Test for correct NewestSha results after DropAfterBlockBySha.

- Fix DropAfterBlockBySha to update info for NewestSha.

- Updated copyright statements in modified files
davecgh pushed a commit that referenced this issue Mar 30, 2015
@aakselrod @davecgh
Fix #340 and DropAfterBlockBySha/NewestSha bug.
7c46f21 
- Delete spent TX in setclearSpentData when unspent by block
  disconnect on reorg; return an error when there's more than
  one record to delete in the spent TX as that should never
  happen.

- Test spent TX deletion when reorg causes block disconnect.

- Test for correct NewestSha results after DropAfterBlockBySha.

- Fix DropAfterBlockBySha to update info for NewestSha.

- Updated copyright statements in modified files
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Roasbeef @aakselrod @davecgh