Background verifier sometimes goes back

[phahulin]

I'm running:

• Which Parity version?: 1.11.8
• Which operating system?: Linux
• How installed?: via binaries
• Are you fully synchronized?: no
• Which network are you connected to?: core, sokol
• Did you try to restart the node?: yes

We run a POA-based networks (sokol and core). After upgrade to 1.11.8 I'm getting hard time syncing with the network using warp-sync.
After all snapshots were downloaded, a verifier in the background starts processing blocks (if I understand correctly), here's a piece of log:

2018-08-07 20:21:42    #1320360   15/25 peers   7 MiB chain 87 MiB db 0 bytes queue 5 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-07 20:21:45  Imported #4050210 0x6620…f959 (2 txs, 0.25 Mgas, 16 ms, 0.85 KiB)
2018-08-07 20:21:51  Imported #4050211 0x7253…604b (1 txs, 0.02 Mgas, 0 ms, 0.67 KiB)
2018-08-07 20:21:55  Imported #4050212 0x3af3…1b8a (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB)
2018-08-07 20:22:01  Imported #4050213 0xc563…69f7 (1 txs, 0.23 Mgas, 3 ms, 0.75 KiB)
2018-08-07 20:22:05  Imported #4050214 0x3187…d824 (0 txs, 0.00 Mgas, 0 ms, 0.57 KiB)
2018-08-07 20:22:10  Imported #4050215 0x688d…38f4 (1 txs, 0.23 Mgas, 4 ms, 0.75 KiB)
2018-08-07 20:22:12    #1345587   15/25 peers   6 MiB chain 87 MiB db 0 bytes queue 5 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-07 20:22:15  Imported #4050216 0xef42…9d84 (0 txs, 0.00 Mgas, 0 ms, 0.57 KiB)
2018-08-07 20:22:20  Imported #4050217 0x9754…49d1 (2 txs, 0.40 Mgas, 4 ms, 0.99 KiB)
2018-08-07 20:22:25  Imported #4050218 0x5528…1323 (0 txs, 0.00 Mgas, 1 ms, 0.57 KiB)
2018-08-07 20:22:30  Imported #4050219 0x30e4…589e (1 txs, 0.23 Mgas, 2 ms, 0.75 KiB)
2018-08-07 20:22:41  Imported #4050221 0x3dbc…4ce5 (1 txs, 0.08 Mgas, 1 ms, 0.80 KiB) + another 1 block(s) containing 1 tx(s)
2018-08-07 20:22:46  Imported #4050222 0x28b2…f2fa (1 txs, 0.07 Mgas, 5 ms, 0.80 KiB)
2018-08-07 20:22:50    #1375534   15/25 peers   7 MiB chain 87 MiB db 0 bytes queue 85 KiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-07 20:22:51  Imported #4050223 0x57a7…9be5 (0 txs, 0.00 Mgas, 4 ms, 0.57 KiB)
2018-08-07 20:22:55  Imported #4050224 0x6b50…3828 (0 txs, 0.00 Mgas, 8 ms, 0.57 KiB)
2018-08-07 20:23:00  Imported #4050225 0x8898…a33b (1 txs, 0.18 Mgas, 8 ms, 0.71 KiB)
2018-08-07 20:23:05  Imported #4050226 0xca15…f9eb (0 txs, 0.00 Mgas, 10 ms, 0.57 KiB)
2018-08-07 20:23:10  Imported #4050227 0x1b17…91f5 (2 txs, 0.40 Mgas, 9 ms, 0.99 KiB)
2018-08-07 20:23:15  Imported #4050228 0x6726…0861 (2 txs, 0.24 Mgas, 4 ms, 1.04 KiB)
2018-08-07 20:23:20  Imported #4050229 0x466d…f469 (3 txs, 0.69 Mgas, 14 ms, 1.10 KiB)
2018-08-07 20:23:22       #8636   15/25 peers   6 MiB chain 87 MiB db 0 bytes queue 1 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-07 20:23:26  Imported #4050230 0x4092…dace (4 txs, 0.79 Mgas, 10 ms, 1.41 KiB)
2018-08-07 20:23:32  Imported #4050231 0xd356…9b8f (1 txs, 0.18 Mgas, 6 ms, 0.71 KiB)
2018-08-07 20:23:35  Imported #4050232 0xbd55…a91e (0 txs, 0.00 Mgas, 0 ms, 0.57 KiB)
2018-08-07 20:23:41  Imported #4050233 0xd0de…d6d8 (6 txs, 0.84 Mgas, 4 ms, 1.62 KiB)
2018-08-07 20:23:46  Imported #4050234 0x6b69…b6c5 (1 txs, 0.07 Mgas, 3 ms, 0.80 KiB)
2018-08-07 20:23:51  Imported #4050235 0x51e7…665f (0 txs, 0.00 Mgas, 7 ms, 0.57 KiB)
2018-08-07 20:23:56  Imported #4050236 0x20c4…db14 (2 txs, 0.46 Mgas, 22 ms, 0.93 KiB)
2018-08-07 20:23:57      #13716   15/25 peers   6 MiB chain 87 MiB db 0 bytes queue 1 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-07 20:24:00  Imported #4050237 0x4672…a188 (0 txs, 0.00 Mgas, 8 ms, 0.57 KiB)
2018-08-07 20:24:06  Imported #4050238 0x9e69…9455 (3 txs, 0.22 Mgas, 12 ms, 0.93 KiB)
2018-08-07 20:24:10  Imported #4050239 0x884a…2481 (2 txs, 0.04 Mgas, 2 ms, 0.78 KiB)
2018-08-07 20:24:15  Imported #4050240 0x63cc…ab77 (5 txs, 0.51 Mgas, 24 ms, 1.43 KiB)
2018-08-07 20:24:20  Imported #4050241 0x86a3…d6ba (3 txs, 0.21 Mgas, 4 ms, 1.02 KiB)
2018-08-07 20:24:25  Imported #4050242 0xa90c…aa55 (3 txs, 0.27 Mgas, 3 ms, 0.96 KiB)
2018-08-07 20:24:31  Imported #4050243 0x51ee…3def (2 txs, 0.04 Mgas, 3 ms, 0.78 KiB)

As you can see it goes 1345587 -> 1375534 and then drops to 8636. This can happen multiple times, so it's hard to get the verification process to complete. It happens on different block numbers

To test it yourself, please use our spec.json and list of reserved peers

$ parity --chain spec.json --reserved-peers bootnodes.txt

[Tbaut]

Thanks for the report, I've seen this happening on mainnet also (cf this comment)

[phahulin]

I'm actually seeing this trying to sync archive + trace node from ethereum mainnet.
Initially it goes well, but if you restart parity, the old block processing goes into this loop

2018-08-14 09:24:54  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #56174    7/25 peers     37 KiB chain  0 bytes db  0 bytes queue    3 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:25:04  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #79415    9/25 peers     37 KiB chain  0 bytes db  0 bytes queue    9 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:25:14  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #79415    9/25 peers     37 KiB chain  0 bytes db  0 bytes queue   13 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:25:24  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed       #57    6/25 peers     37 KiB chain  0 bytes db    2 KiB queue    8 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:25:34  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed       #54    7/25 peers     53 KiB chain  0 bytes db  0 bytes queue    6 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:25:44  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed       #57    6/25 peers     53 KiB chain  0 bytes db  0 bytes queue    7 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:25:59  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed       #47    4/25 peers    107 KiB chain  0 bytes db  0 bytes queue    6 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:26:29     6/25 peers    107 KiB chain  0 bytes db  0 bytes queue    6 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:26:59     6/25 peers    107 KiB chain  0 bytes db  0 bytes queue    6 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:27:29     6/25 peers    107 KiB chain  0 bytes db  0 bytes queue    6 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:27:34  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed        #0    7/25 peers    107 KiB chain  0 bytes db  0 bytes queue    6 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:27:39  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #13462    6/25 peers    107 KiB chain  0 bytes db  0 bytes queue    8 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:27:49  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #48766    5/25 peers    107 KiB chain  0 bytes db  0 bytes queue    9 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:27:59  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #52190    7/25 peers    107 KiB chain  0 bytes db  0 bytes queue    9 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:28:09  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #74256    8/25 peers    107 KiB chain  0 bytes db  0 bytes queue    8 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:28:19  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #65397    8/25 peers    107 KiB chain  0 bytes db  0 bytes queue    9 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:28:29  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #41117    7/25 peers    107 KiB chain  0 bytes db  0 bytes queue   10 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:28:39  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #57373   11/25 peers    107 KiB chain  0 bytes db  0 bytes queue   15 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:28:49  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #57373   12/25 peers    107 KiB chain  0 bytes db  0 bytes queue   17 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:28:59  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #57373   13/25 peers    107 KiB chain  0 bytes db  0 bytes queue   19 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:29:09  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #70571   13/25 peers    107 KiB chain  0 bytes db  0 bytes queue   10 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:29:19  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #52007   11/25 peers    107 KiB chain  0 bytes db  0 bytes queue   12 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:29:29  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #52007   12/25 peers    107 KiB chain  0 bytes db  0 bytes queue   19 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:29:39  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #42799   12/25 peers    107 KiB chain  0 bytes db  0 bytes queue   24 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:29:49  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #50164   11/25 peers    107 KiB chain  0 bytes db  0 bytes queue   11 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:29:59  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #67071   11/25 peers    107 KiB chain  0 bytes db  0 bytes queue    9 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:30:09  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #62101   12/25 peers    107 KiB chain  0 bytes db  0 bytes queue   11 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:30:19  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #44173   14/25 peers    107 KiB chain  0 bytes db  0 bytes queue    9 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:30:29  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #15749   15/25 peers    107 KiB chain  0 bytes db  0 bytes queue   10 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:30:39  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #32765   15/25 peers    107 KiB chain  0 bytes db  0 bytes queue   12 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:30:49  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed     #4699   14/25 peers    107 KiB chain  0 bytes db  0 bytes queue   10 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:30:59  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed     #4699   15/25 peers    107 KiB chain  0 bytes db  0 bytes queue   33 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:31:09  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed     #4701   16/25 peers    107 KiB chain  0 bytes db  0 bytes queue   36 MiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-08-14 09:31:19  Syncing #4241078 0x7a7d…3489     0 blk/s    0 tx/s   0 Mgas/s      0+    0 Qed    #64011   14/25 peers    107 KiB chain  0 bytes db  0 bytes queue   18 MiB sync  RPC:  0 conn,  0 req/s,   0 µs

For some reason, in this case it only happens when you restart a node that has synced a lot of blocks already.
I left this node running for a couple of nights and it never moved anymore.
Makes it impossible to actually complete the syncing process.

[andresilva]

@phahulin Could you build and test this PR #9407? In my tests it fixed the ancient block sync on POA chain.

[phahulin]

Will do, thanks

[phahulin]

Hi @andresilva
I can't reproduce this issue myself on a "ordinary" node with this PR, but it still reproduces on validator's node (the one I mentioned in #9323)

2018-08-26 01:22:41 UTC IO Worker #0 INFO import     #513896   23/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s, 147849 µs
2018-08-26 01:23:16 UTC IO Worker #2 INFO import     #483322   23/25 peers      6 MiB chain   66 MiB db  0 bytes queue   20 MiB sync  RPC:  0 conn,    3 req/s, 41005 µs
2018-08-26 01:23:52 UTC IO Worker #1 INFO import     #500329   23/25 peers      6 MiB chain   66 MiB db  0 bytes queue   20 MiB sync  RPC:  0 conn,    2 req/s,  302 µs
2018-08-26 01:24:26 UTC IO Worker #1 INFO import     #521396   23/25 peers      6 MiB chain   66 MiB db  0 bytes queue   21 MiB sync  RPC:  0 conn,    1 req/s, 186321 µs
2018-08-26 01:25:01 UTC IO Worker #0 INFO import     #530596   23/25 peers      5 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  237 µs
2018-08-26 01:27:22 UTC IO Worker #2 INFO import     #100232   23/25 peers      6 MiB chain   66 MiB db  0 bytes queue   22 MiB sync  RPC:  0 conn,    3 req/s, 106787 µs
2018-08-26 01:28:32 UTC IO Worker #3 INFO import     #106323    5/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  204 µs
2018-08-26 01:29:07 UTC IO Worker #1 INFO import     #107978   14/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    1 req/s,  200 µs
2018-08-26 01:29:37 UTC IO Worker #2 INFO import     #108406   10/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  120 µs
2018-08-26 01:30:12 UTC IO Worker #0 INFO import     #123461   24/25 peers      6 MiB chain   66 MiB db  0 bytes queue   20 MiB sync  RPC:  0 conn,    3 req/s,  291 µs
2018-08-26 01:30:48 UTC IO Worker #2 INFO import     #161545   24/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    2 req/s,  194 µs
2018-08-26 01:31:52 UTC IO Worker #3 INFO import     #177370   23/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    6 req/s,  105 µs
2018-08-26 01:32:28 UTC IO Worker #0 INFO import     #178478   16/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  228 µs
2018-08-26 01:33:02 UTC IO Worker #2 INFO import     #175124   24/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  125 µs
2018-08-26 01:33:37 UTC IO Worker #3 INFO import     #179712   22/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  104 µs
2018-08-26 01:34:08 UTC IO Worker #2 INFO import     #163948   24/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  130 µs
2018-08-26 01:34:43 UTC IO Worker #1 INFO import     #180813   18/25 peers      6 MiB chain   66 MiB db  0 bytes queue   19 MiB sync  RPC:  0 conn,    3 req/s,  149 µs

and again a lot of messages with queue_ancient_block.