search

decred / dcrwallet

A secure Decred wallet daemon written in Go (golang).
https://decred.org
ISC License
221 stars 156 forks source link

Two out of three wallets in a multi-wallet setup are stuck on an old block in testnet. #1486

Open David00 opened 5 years ago

David00 commented 5 years ago

I have a Ubuntu 18.04 server which has been running 3 testnet wallets for about 10 months now. They are all non-SPV. I believe the wallets were originally created in the 1.3 release some time ago and were previously upgraded to 1.4. The wallets have been off for a little while nearly 4 months and when I started them up today, only one of them would update to the latest block. The other two are stuck on block# 123119.

I built the master branch earlier today to verify the problem is still there. This is all on the same machine and the wallets are connecting to dcrd over localhost, each on their own port. I can see in both the wallet log and the dcrd log that dcrwallet successfully connects to dcrd.

As these are testnet wallets, I can provide the wallet files, configs, and credentials, if anyone wants to try and replicate.

I have tried running only one wallet at a time. I’ve tried running the wallets on the default dcrd testnet port (19109).

I can recreate the wallets from seed to verify whether or not the wallet file itself is the issue or if the issue lies instead with DCRD. However since I think it’s more likely to be a wallet issue, I wanted to open the issue here first.

jrick commented 5 years ago

Send the logs from the working wallet and at least one of the wallets that is not working.

David00 commented 5 years ago

Will do. What logging level do you need?

On Thu, Jun 13, 2019, 18:45 Josh Rickmar notifications@github.com wrote:

Send the logs from the working wallet and at least one of the wallets that is not working.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/decred/dcrwallet/issues/1486?email_source=notifications&email_token=AEJJ4EBBCEPABMU5C6GEZKLP2LZZ7A5CNFSM4HYB3HTKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODXVPJTY#issuecomment-501937359, or mute the thread https://github.com/notifications/unsubscribe-auth/AEJJ4ECY4Y7PAYOHKSY2HATP2LZZ7ANCNFSM4HYB3HTA .

jrick commented 5 years ago

info should be enough but debug won't hurt if you can collect new logs.

David00 commented 5 years ago

Ok. I will get some debug logs for ya. Probably not until later tonight or tomorrow afternoon.

On Thu, Jun 13, 2019, 19:01 Josh Rickmar notifications@github.com wrote:

info should be enough but debug won't hurt if you can collect new logs.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/decred/dcrwallet/issues/1486?email_source=notifications&email_token=AEJJ4EHMMFDGWEYNCYPSKKTP2L3ZNA5CNFSM4HYB3HTKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODXVP6TQ#issuecomment-501940046, or mute the thread https://github.com/notifications/unsubscribe-auth/AEJJ4EGTNBCPHFHILGPDRO3P2L3ZNANCNFSM4HYB3HTA .

David00 commented 5 years ago

Here are the debug logs. I first launched dcrd, then the working wallet#1, then the wallet#2 which is stuck. I have two other wallets on the same machine exhibiting the same behavior.

I've noticed that the stuck wallet (#2) never reports block updates either, which still leaves the possibility of an issue with dcrd.

dcrdlog.txt wallet#2 - not working.txt wallet#1 - working.txt

jrick commented 5 years ago

Block 0000000000063cd7d1be61c4cd8a16da79658f8c5b34fa1a6042f9573a6ee530 (from the non-working logs) doesn't exist in the testnet main chain (may have been reorged out).

There was a message after that new headers were fetched. If you restart that same wallet, does it log the same missing block or a different one?

David00 commented 5 years ago

I just restarted wallet #2 and it saying it's synced through the same block. Log below.

I also checked the old log file from wallet#2 to see exactly how long it was offline for between restarts, and I shut it down on Feb 24, 2019. (Today was the first start up since then).

david@dcrserver:~/decred/testnet-data$ echo "restarting wallet to check if block 6ee530 is registered"
restarting wallet to check if block 6ee530 is registered
david@dcrserver:~/decred/testnet-data$ .././dcrwallet-v1.5-dev -C /home/david/decred/testnet-data/spwallet2/dcrwallet.conf -d debug
2019-06-13 21:09:39.274 [INF] DCRW: Version 1.5.0-pre+dev (Go version go1.11 linux/amd64)
2019-06-13 21:09:40.257 [INF] WLLT: Opened wallet
2019-06-13 21:09:41.257 [INF] WLLT: The wallet has been unlocked without a time limit
2019-06-13 21:09:41.278 [INF] DCRW: gRPC server listening on 0.0.0.0:19121
2019-06-13 21:09:41.278 [INF] RPCS: Listening on 0.0.0.0:19120
2019-06-13 21:09:41.278 [INF] RPCS: Listening on [::]:19120
2019-06-13 21:09:41.278 [INF] DCRW: Attempting RPC client connection to localhost:19109
2019-06-13 21:09:41.279 [INF] DCRW: gRPC server listening on [::]:19121
2019-06-13 21:09:41.329 [INF] SYNC: Established connection to RPC server localhost:19109
2019-06-13 21:09:41.330 [INF] SYNC: Headers synced through block 0000000000063cd7d1be61c4cd8a16da79658f8c5b34fa1a6042f9573a6ee530 height 123119
2019-06-13 21:09:41.331 [INF] SYNC: Transactions synced through block 0000000000063cd7d1be61c4cd8a16da79658f8c5b34fa1a6042f9573a6ee530 height 123119
2019-06-13 21:09:41.831 [INF] SYNC: Fetched 1943 new header(s) ending at height 124855 from wss://localhost:19109/ws
2019-06-13 21:09:42.335 [INF] SYNC: Fetched 0 new header(s) ending at height 124855 from wss://localhost:19109/ws
2019-06-13 21:09:42.335 [INF] WLLT: Loading active addresses and unspent outputs...
2019-06-13 21:09:42.420 [INF] WLLT: Registered for transaction notifications for 1046 address(es) and 68 output(s)
2019-06-13 21:09:42.430 [WRN] SYNC: Could not publish one or more unmined transactions: wallet.PublishUnminedTransactions:: dcrd.jsonrpc.sendrawtransaction: -40: Rejected transaction f2fc7b290e3ad7f6ea420dc29f2d1bfa6fbe49568fe260587aa3c0871400ad34: transaction already exists
2019-06-13 21:09:42.431 [INF] SYNC: Blockchain sync completed, wallet ready for general usage.
jrick commented 5 years ago

Adding more info to this: I checked back on some chat logs starting around Jan 30 2019 and it was at this time that the testnet3 network was asic bombed and we had to perform a very large reorg to drop the difficulty back to levels that could be mined with the C0 GPU miner. You are likely stuck on that chain and there is either a bug with dcrd's getheaders JSON-RPC method not finding the correct fork point, or wallet isn't handling the response correctly.

I'll make a wallet patch tomorrow to add some extra RPCs to query the chain state of the wallet that will help debug this.

jrick commented 5 years ago

Oh and before i hit the bed, can you ask you to backup that problematic database (so we can test fixes later) and then try to sync it with --spv --spvconnect=localhost:19108?

David00 commented 5 years ago

Sure thing. I created a tarball of the entire testnet3 DCRD folder and I backed up the wallet.db file just in case too. I've restarted wallet#2 and I'm letting it process all the filters. I probably should have turned off debug logging for that part, but oh well :)

David00 commented 5 years ago

So wallet#2 - the one that I launched with SPV mode enabled - is showing the following for all the blocks it's getting:

2019-06-14 12:24:50.525 [INF] SYNC: Received sidechain or orphan block 00000000067a77da2f7280d4845c0f3abf46d7d40df3f3aa3a980a6ba086f3a2, height 212787
2019-06-14 12:24:52.667 [INF] SYNC: Received sidechain or orphan block 0000000000c50422bc7f8229a88d1384eee6937122695e528bb349382bd17e9a, height 212787
2019-06-14 12:27:11.257 [INF] SYNC: Received sidechain or orphan block 00000000062c85a39d084ba008c5d31300a22c46c7a5b3e9f8d0cd53b90fd9f4, height 212788
2019-06-14 12:27:34.271 [INF] SYNC: Received sidechain or orphan block 00000000015115a8c09c10db0058bf1a25bb42406c54aea7aaa006a3b6ac68f0, height 212789

Also, running getbestblock with wallet#2 shows the following:

{
  "hash": "0000000000063cd7d1be61c4cd8a16da79658f8c5b34fa1a6042f9573a6ee530",
  "height": 123119
}

The getbestblock command with wallet #1 is correct:

{
  "hash": "0000000001be5a7ce8ab2b23d6439374bb8046c64961d7b07fefcec8d262d421",
  "height": 212790
}
jrick commented 5 years ago

I'm beginning to think that the issue isn't so much that the chain can't be attached all the way back to the genesis block, but rather that the abandoned chain has more total work than the currently-mined chain, making it "better", and the wallet is refusing to reorg to a "worse" chain. I'll try to get you a patch to verify this...

David00 commented 5 years ago

Hey jrick, will the patch be a new branch off master, or a commit on the master branch? I’m asking because I don’t yet know how to pull a specific commit and build from it. (Also asking to remind you) :)

jrick commented 5 years ago

It will be off master, since you may also need to use one of the new JSON-RPC methods that was just added (getblockhash).

David00 commented 5 years ago

Ok, thanks. Am I waiting for you to push a patch to dcrwallet?

David00 commented 5 years ago

FYI, this appears to have happened to a user from a ticket splitting group I was helping on mainnet also. They couldn't sync past block 342913, and the tail of their dcrd log was showing the following lines:

2019-06-21 09:39:07.888 [INF] CHAN: Adding orphan block 00000000000000000b4b91f8311ee991f62fbf2ff01f4ab65a60031878aab151 with parent 00000000000000000fb19b1be0afd6f6542eb8e460011d0ffc061169741b3c0b 2019-06-21 09:39:08.031 [INF] CHAN: Adding orphan block 00000000000000001d1d3f30622126c031261dfccc3fbcbd5cb62310f50ff8b6 with parent 00000000000000000b4b91f8311ee991f62fbf2ff01f4ab65a60031878aab151 2019-06-21 09:39:08.032 [INF] CHAN: Adding orphan block 0000000000000000147f61b3147e029669b63ecabfa6223798b49d58265ed8a7 with parent 00000000000000001d1d3f30622126c031261dfccc3fbcbd5cb62310f50ff8b6 2019-06-21 09:39:08.404 [INF] BMGR: Rejected block 0000000000000000187d00f495bc73394a70aad2c8761c6d2ccc584b90cbc967 from 139.99.106.160:9108 (outbound): previous block 00000000000000000a2d564bbe2ecf3fb982d19bb528db0302d903293b99ed33 is known to be invalid 2019-06-21 09:39:08.404 [INF] CHAN: Adding orphan block 0000000000000000008832b98af8a6fd0ccebbafbd331294affafcf6cd571dac with parent 0000000000000000147f61b3147e029669b63ecabfa6223798b49d58265ed8a7

I helped them delete their blockchain data and start new since they encountered this on mainnet and needed to regain access to their funds.