Archive node often resync when restarting on docker

[yxliang01]

• Parity Ethereum version: 2.2.7-stable-b00a21f-20190115
• Operating system: Linux
• Installation: docker official image
• Fully synchronized: no
• Network: ethereum
• Restarted: yes

This happens on two separated nodes with the same setup. The nodes are archive node, tracing on, on HDD, fat-db one on one off. Currently one at around 5000000 block one at around 2700000.

actual behavior

After shutdown the node whether gracefully or not, starting the node will often start syncing from 0. However, since at times it can sync from the highest head, the db doesn't seem corrupted.

expected behavior

Every time, after a restart, the node should sync from the highest block it has synced so far.

Thanks

[grittibaenz]

I observe the same problem with the ETH Ropsten network. When updating from version 2.1.10 to version 2.2.7 it tries to resync the whole blockchain even though it was up-to-date:

root@host:~ # df -h
Filesystem               Size  Used Avail Use% Mounted on
/dev/sdb1                500G  303G  198G  61% /data

root@host:~ # docker container logs -f --tail 100 eth_parity_ropsten                                                                   Loading config file from /app/parity/conf/config.toml
2019-01-31 14:15:09 UTC Starting Parity-Ethereum/v2.2.7-stable-b00a21f-20190115/x86_64-linux-gnu/rustc1.31.1
2019-01-31 14:15:09 UTC Keys path /data/parity/base/keys/ropsten
2019-01-31 14:15:09 UTC DB path /data/parity/db/ropsten/db/ae90623718e47d66
2019-01-31 14:15:09 UTC State DB configuration: archive +Trace
2019-01-31 14:15:09 UTC Operating mode: active
2019-01-31 14:15:09 UTC Configured for Ropsten Testnet using Ethash engine
2019-01-31 14:15:14 UTC Public node URL: enode://f91eca5aae7f44e4254598ddea24acd5669a586490b8c60c4f4d482c4eea400692d252f2aae36b1194403ff7dba2ae446b047e1fab63f0a10b52fdcae5cc31b8@172.17.0.2:30303
2019-01-31 14:15:19 UTC Syncing     #366 0xbe94…3820    36.69 blk/s    2.2 tx/s    0.1 Mgas/s    743+ 1811 Qed     #2933    2/25 peers    153 KiB chain   14 KiB db    4 MiB queue  587 KiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-01-31 14:15:24 UTC Syncing    #3249 0xa575…7020   575.22 blk/s    0.4 tx/s    0.4 Mgas/s     91+ 3502 Qed     #6858    2/25 peers      1 MiB chain   16 KiB db    5 MiB queue  789 KiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-01-31 14:15:29 UTC Syncing    #5068 0x1b9a…58c9   362.57 blk/s    1.4 tx/s    0.3 Mgas/s   1332+ 7046 Qed    #13462    3/25 peers      2 MiB chain   20 KiB db   14 MiB queue    2 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-01-31 14:15:34 UTC Syncing    #5687 0x7bb4…5f1c   123.82 blk/s    0.4 tx/s    0.0 Mgas/s   2029+13111 Qed    #20835    4/25 peers      3 MiB chain   21 KiB db   29 MiB queue    6 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-01-31 14:15:39 UTC Syncing    #6317 0x32fc…3531   125.80 blk/s   24.4 tx/s    1.4 Mgas/s   1290+19176 Qed    #26797    4/25 peers      3 MiB chain   26 KiB db   43 MiB queue    5 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-01-31 14:15:44 UTC Syncing   #10962 0xbf7f…a03e   928.43 blk/s   28.8 tx/s   12.8 Mgas/s      0+17806 Qed    #28777    5/25 peers      7 MiB chain   58 KiB db   39 MiB queue   11 MiB sync  RPC:  0 conn,    0 req/s,   31 µs
2019-01-31 14:15:49 UTC Syncing   #14492 0xca72…2b92   706.20 blk/s  128.6 tx/s   33.8 Mgas/s      0+17840 Qed    #32339    5/25 peers      8 MiB chain  121 KiB db   41 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:15:54 UTC Syncing   #17323 0xccac…7786   566.20 blk/s  208.2 tx/s   48.7 Mgas/s      0+17340 Qed    #34671    5/25 peers      4 MiB chain  160 KiB db   40 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:15:59 UTC Syncing   #20181 0x56fb…39ab   571.40 blk/s  308.4 tx/s  133.4 Mgas/s      0+17056 Qed    #37243    6/25 peers      4 MiB chain  263 KiB db   38 MiB queue   11 MiB sync  RPC:  0 conn,    0 req/s,   24 µs
2019-01-31 14:16:04 UTC Syncing   #22445 0x1d47…ec67   453.00 blk/s  326.4 tx/s   62.4 Mgas/s      0+18059 Qed    #40514    6/25 peers      6 MiB chain  329 KiB db   40 MiB queue   12 MiB sync  RPC:  0 conn,    0 req/s,   24 µs
2019-01-31 14:16:09 UTC Syncing   #24763 0xff4f…f0b5   462.49 blk/s  328.0 tx/s  107.8 Mgas/s    679+18082 Qed    #43536    6/25 peers      6 MiB chain  430 KiB db   41 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   24 µs
2019-01-31 14:16:14 UTC Syncing   #27008 0xb722…c74c   446.94 blk/s  366.3 tx/s   82.8 Mgas/s   1733+17311 Qed    #47498    6/25 peers      6 MiB chain  531 KiB db   43 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   24 µs
2019-01-31 14:16:19 UTC Syncing   #28917 0x2427…2c7f   381.11 blk/s  209.0 tx/s   49.0 Mgas/s      0+18575 Qed    #47498    6/25 peers      6 MiB chain  610 KiB db   44 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   24 µs
2019-01-31 14:16:24 UTC Syncing   #32007 0x864a…fc01   616.03 blk/s  368.6 tx/s   67.5 Mgas/s   2825+16059 Qed    #50897    6/25 peers      6 MiB chain  702 KiB db   45 MiB queue   11 MiB sync  RPC:  0 conn,    1 req/s,   23 µs
2019-01-31 14:16:29 UTC Syncing   #34085 0x9d0b…5c3f   415.52 blk/s  204.0 tx/s   27.3 Mgas/s      0+16802 Qed    #50897    6/25 peers      6 MiB chain  728 KiB db   41 MiB queue   11 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:16:34 UTC Syncing   #36509 0x3ac0…372b   484.50 blk/s  263.9 tx/s   45.1 Mgas/s      0+16948 Qed    #53467    6/25 peers      6 MiB chain  789 KiB db   42 MiB queue   11 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:16:39 UTC Syncing   #39101 0x0aee…ae98   516.02 blk/s  379.7 tx/s   71.6 Mgas/s   1512+16057 Qed    #56687    6/25 peers      7 MiB chain  878 KiB db   43 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:16:44 UTC Syncing   #42319 0x2dd0…537d   643.53 blk/s  255.1 tx/s   39.5 Mgas/s      0+14360 Qed    #56687    6/25 peers      6 MiB chain  954 KiB db   37 MiB queue   13 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:16:49 UTC Syncing   #44438 0x7edd…0661   431.07 blk/s  456.3 tx/s   37.5 Mgas/s      5+14988 Qed    #59436    5/25 peers      7 MiB chain    1 MiB db   40 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:16:54 UTC Syncing   #47027 0x62c5…c9b0   517.60 blk/s 1005.0 tx/s  124.0 Mgas/s   1338+12968 Qed    #61341    6/25 peers      5 MiB chain    1 MiB db   35 MiB queue   11 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:16:59 UTC Syncing   #48667 0x6c66…77ce   328.20 blk/s  204.8 tx/s   42.1 Mgas/s      0+14954 Qed    #63629    6/25 peers      6 MiB chain    1 MiB db   37 MiB queue   12 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:04 UTC Syncing   #50364 0xb499…e0dc   339.33 blk/s  256.9 tx/s   31.3 Mgas/s    188+16243 Qed    #66802    5/25 peers      5 MiB chain    1 MiB db   41 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:09 UTC Syncing   #53074 0x2a2a…cf9c   542.00 blk/s  614.0 tx/s   57.4 Mgas/s      0+15236 Qed    #68315    5/25 peers      4 MiB chain    1 MiB db   40 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:14 UTC Syncing   #55510 0xcee8…0ae0   485.16 blk/s  598.7 tx/s   60.0 Mgas/s      1+14581 Qed    #70104    5/25 peers      7 MiB chain    1 MiB db   38 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:19 UTC Syncing   #57211 0x5845…e736   340.00 blk/s  297.8 tx/s   61.9 Mgas/s      0+15298 Qed    #72517    5/25 peers      7 MiB chain    1 MiB db   40 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:24 UTC Syncing   #59514 0xfc0e…1754   459.22 blk/s  480.8 tx/s   66.0 Mgas/s      0+15655 Qed    #75178    5/25 peers      7 MiB chain    2 MiB db   40 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:29 UTC Syncing   #62137 0xe7ca…844c   524.60 blk/s  355.0 tx/s  100.9 Mgas/s      0+14222 Qed    #76361    5/25 peers      5 MiB chain    2 MiB db   39 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:34 UTC Syncing   #64331 0x0969…8aad   437.81 blk/s  397.3 tx/s   95.5 Mgas/s      0+13587 Qed    #77927    5/25 peers      5 MiB chain    2 MiB db   39 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs
2019-01-31 14:17:39 UTC Syncing   #66374 0xbc65…149c   408.80 blk/s  302.0 tx/s  110.8 Mgas/s      0+12717 Qed    #79092    5/25 peers      5 MiB chain    2 MiB db   40 MiB queue   10 MiB sync  RPC:  0 conn,    0 req/s,   23 µs

Edit:
Fully synchronized: yes
Network: ethereum-ropsten
Restarted: yes

Configuration:

...
chain = "ropsten"
warp = false
apis = ["web3", "eth", "net", "rpc", "traces"]
tracing = "on"
pruning = "archive"
...

[yxliang01]

@grittibaenz Do you mean that your problem happens only when you try to upgrade the Parity version?

[grittibaenz]

@yxliang01: That is indeed a good question. I am currently resyncing the blockchain and will do a snapshot once done. After that I will do some further testing and report back. It might take another 1-2 days.

[yxliang01]

@grittibaenz Hmm Okay :)

[nostdm]

I have the same problem with the latest 2.2.8 version:

I had deployed and fully synced a Parity Ropsten node version 2.1.10 with the --pruning=archive option.

It finished syncing a few days ago and is currently at the latest Ropsten block - the same block that ropsten.etherscan.io shows (currently 4936368).

When I upgrade the node to version 2.2.8, it starts syncing from the genesis block instead of reusing the existing state.

In the past when I upgraded the Parity version it would reuse the old state and keep syncing - in the worst case it would re-org the bad blocks, but with the latest version it seems to create a new state trie and starts syncing from the beginning.

[yxliang01]

@nostdm @joshua-mir Actually no, this is not a duplicate of #10275 I think. The problem that I had is on a node that was synced from the very beginning using 2.2.7, no upgrading was performed. While #10275 is trying to describe a similar outcome but then it happened right after upgrading from older version. The main difference is that for my case, the originally synced head come back after some number of restarts, and reset to genesis again after some number of restarts.

@nostdm @grittibaenz Would you like to try restarting your node multiple times to see whether the synced head can come back? If yes, then it's a duplicate. If not, it's not a duplicate.

[jam10o-new]

Thanks for figuring this out, we can definitely reopen #10275 if it's as you are describing. However I do suspect this is a problem with sync logic in general with 2.2.7 (freshly updated or not) so it might be valuable for @nostdm to try your workaround as well.

[nostdm]

Someone on Gitter suggested to rename the keys and chains directories from chains/test to chains/ropsten and keys/test to keys/ropsten.
I can confirm it solved the issue for me.

[yxliang01]

@nostdm solved the issue as in, after renaming, you can continue syncing where you were at?

[jam10o-new]

(issue #10160 for reference, it might be what @grittibaenz is experiencing, but not what you are @yxliang01)

[yxliang01]

@joshua-mir I think you wrongly mentioned @grittibaenz (should be @nostdm I guess)

[jam10o-new]

Both actually.

[yxliang01]

@joshua-mir Hmm just wondering, is this issue being investigated? Or, is this backlogged?

[jam10o-new]

I don't believe there is anyone actively working on this issue at the moment, I haven't been able to reproduce this locally, are you still seeing this often?

[yxliang01]

@joshua-mir Yes. This is still reproducible. Are you using Parity in docker container? I believe this is a bug because this happens on two different and independent nodes with the same version.

[jam10o-new]

Whoops. Haven't tried in docker yet actually, let me try that now 🙏 are you mounting any volumes?

[yxliang01]

I am mounting the /home/parity/.local/share/io.parity.ethereum read-write. I terminate Parity via Ctrl+C. Parity received SIGINT and saying "finishing work". File permissions look fine.

[grittibaenz]

Sorry for never getting back to you. I had busy week(s) and reporting + testing issues with almost every Geth, Parity and IOTA IRI release is tedious.

As I didn't update our ETH Ropsten nodes because of this bug, we obviously ran into the wrong direction of the fork. This means I am currently again resyncing the full Ropsten blockchain with one node. The second node has now a garbage-chain, but I can do some testing with it:

2534877 <-2.2.9 (full node - resyncing)
4978107 <-2.2.9 (light node - up-to-date)
4975236 <-2.1.10 (full node - garbage-chain)

When updating from 2.1.10 to version 2.2.9 (after the fork, sadly), it again starts resyncing the full blockchain (as it did with 2.2.7:

Loading config file from /app/parity/conf/config.toml

2019-02-07 16:34:59 UTC Starting Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1

2019-02-07 16:34:59 UTC Keys path /data/parity/base/keys/ropsten

2019-02-07 16:34:59 UTC DB path /data/parity/db/ropsten/db/ae90623718e47d66

2019-02-07 16:34:59 UTC State DB configuration: archive +Trace

2019-02-07 16:34:59 UTC Operating mode: active

2019-02-07 16:34:59 UTC Configured for Ropsten Testnet using Ethash engine

2019-02-07 16:35:04 UTC Syncing       #0 0x4194…4a2d     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed        #0    2/25 peers      8 KiB chain  0 bytes db  0 bytes queue   38 KiB sync  RPC:  0 conn,    0 req/s,    0 µs

2019-02-07 16:35:04 UTC Public node URL: enode://9c9574b070696ef6ce546c9826830703cfaecdac2645317bf5fbfcc1a486db40db37571bf3e54e423239d79b0bae0f494cb73942480598b009f62fa3a6b27c88@172.17.0.2:30303

2019-02-07 16:35:09 UTC Syncing       #0 0x4194…4a2d     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed        #0    2/25 peers      8 KiB chain  0 bytes db  0 bytes queue   39 KiB sync  RPC:  0 conn,    0 req/s,    0 µs

2019-02-07 16:35:14 UTC Syncing       #0 0x4194…4a2d     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed        #0    2/25 peers      8 KiB chain  0 bytes db  0 bytes queue   39 KiB sync  RPC:  0 conn,    0 req/s,    0 µs

2019-02-07 16:35:19 UTC Syncing       #0 0x4194…4a2d     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed        #0    2/25 peers      8 KiB chain  0 bytes db  0 bytes queue   39 KiB sync  RPC:  0 conn,    0 req/s,    0 µs

2019-02-07 16:35:24 UTC Syncing       #0 0x4194…4a2d     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed        #0    2/25 peers      8 KiB chain  0 bytes db  0 bytes queue   39 KiB sync  RPC:  0 conn,    0 req/s,    0 µs

2019-02-07 16:35:29 UTC Syncing       #0 0x4194…4a2d     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed        #0    3/25 peers      8 KiB chain  0 bytes db  0 bytes queue   39 KiB sync  RPC:  0 conn,    0 req/s,    0 µs

2019-02-07 16:35:34 UTC Syncing    #1808 0xb8c3…d98b   361.60 blk/s    4.4 tx/s    0.3 Mgas/s     76+   10 Qed     #1905    2/25 peers    642 KiB chain   14 KiB db  128 KiB queue  683 KiB sync  RPC:  0 conn,    0 req/s,    0 µs

Please let me know what I can test for you. This problem is(!) reproducible.

[yxliang01]

@grittibaenz Thanks for your update. However, from what you said, looks like this problem occurs right after an upgrade. Would you like to try restarting the upgraded node to see whether a resync is performed? Since my problem occurs every time I restart it without any upgrading.

[brandoncurtis]

I just upgraded Parity from v2.3.0 to v2.3.2.

Upon restart, it began resyncing the Ropsten chain from genesis.

I took a look, and this is occurring because Parity changed the Ropsten directory name:

• old ~/.local/share/io.parity.ethereum/chains/test
• new: ~/.local/share/io.parity.ethereum/chains/ropsten

By renaming test to ropsten, it will continue syncing from where it left off before the upgrade.

[yxliang01]

@brandoncurtis The change of directory name, is it happening upon exiting Parity or upon starting Parity? Also, if you restarting for multiple times, does it recover automatically?

[brandoncurtis]

Upon restarting parity, it creates the new directory chains/ropsten and begins syncing from genesis there.

To fix the problem, I deleted this new directory and renamed the existing chains/test, which contains my fully-synced Ropsten node. Upon restarting Parity, it continues to sync from where I left off before the upgrade.

[jam10o-new]

We're getting alot of reports that should be in #10160 on this issue, sorry @yxliang01

[yxliang01]

@joshua-mir Yeah. Confirm that there is no chains/ropsten and chains/test for my case (I know they shouldn't exist in my case anyways). By the way, are you now able to reproduce in docker environment?

[jam10o-new]

Haven't been able to. I suspect it's something to do with the blocks nearer to the chain head, so I'll try again with a node I'll keep running for longer.

[yxliang01]

@joshua-mir hmm as stated in the first thread, it happened ever since at 2700000. So, maybe you want to try to reach that height.

[sammisetty]

Is there any latest update on above?

We had a fully synced archive node(mainnet) on 2.0.7. We upgraded it to 2.2.7 and had the same issue of node syncing from genesis block after upgrade instead of catching up from latest block, we left the node for two weeks and the sync was observed to be very slow about 40000 blocks per day. We again updated the node from 2.2.7 to 2.2.11 and the sync started from genesis block, the sync was fast till 2.6 Million blocks and after that it became very slow, about 11000 blocks per day. Any help is much appreciated, it's been three to four weeks with no solution!

[yxliang01]

@sammisetty I think slow down after 2.6 million blocks is related to the DOS on Ethereum (FYI, https://www.reddit.com/r/ethereum/comments/5es5g4/a_state_clearing_faq/ ). (well, my node is also syncing very slowly both around 2.6 million blocks and 4 million blocks and now stuck.) As far as I know, there's no progress on this issue since they can't reproduce. As this is not major to me at this moment, I am working on something having higher priority now and try not to shut it down... If you have time, maybe you can start your node with -l trace then post your log here?

[sammisetty]

@yxliang01 I will start the node with -l trace and post the log soon.

I also have another question, db/chains/ethereum/db/uniqueId/snapshot folder has two sub-folders

1. Current with size 8GB and
2. In_Progress with size 1.4 GB

Is there any reason that you know for two folders?

[yxliang01]

Hmm I no longer encounter this problem recently and this issue is stale (no other new people reported encountering same issue recently). I suggest closing this issue. If anyone or me counter this again, we can reopen or create a new issue :) . @joshua-mir Sounds good?