Stage 1 block verification failed ... Block(TemporarilyInvalid(OutOfBounds ...

[taoeffect]

I'm running:

• Which Parity version?: Parity/v1.8.11-stable-21522ff-20180227/x86_64-linux-gnu/rustc1.24.0
• Which operating system?: Linux
• How installed?: Official Docker build
• Are you fully synchronized?: yes
• Which network are you connected to?: ethereum
• Did you try to restart the node?: yes

Your issue description goes here below. Try to include actual vs. expected behavior and steps to reproduce the issue.

After updating my system and rebooting, parity is now returning strange errors (?) whose meaning and severity is indiscernible to me:

2018-03-16 01:45:19 UTC Stage 1 block verification failed for 8b9d…df96: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164734), found: 1521164736 }))
2018-03-16 01:45:19 UTC Stage 1 block verification failed for 8b9d…df96: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164734), found: 1521164736 }))
2018-03-16 01:45:20 UTC Stage 1 block verification failed for 8b9d…df96: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164735), found: 1521164736 }))
2018-03-16 01:45:21 UTC Imported #5262880 8b9d…df96 (43 txs, 2.23 Mgas, 121.91 ms, 6.18 KiB)
2018-03-16 01:45:22 UTC Imported #5262879 775c…4b98 (23 txs, 0.79 Mgas, 28.11 ms, 4.78 KiB)
2018-03-16 01:45:29 UTC Imported #5262881 bad1…3faa (63 txs, 7.99 Mgas, 251.72 ms, 12.34 KiB)
2018-03-16 01:45:44 UTC Imported #5262882 644a…1d25 (82 txs, 8.00 Mgas, 132.57 ms, 12.75 KiB)
2018-03-16 01:45:45 UTC   16/25 peers   5 MiB chain 71 MiB db 0 bytes queue 22 KiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-03-16 01:45:58 UTC Imported #5262883 f2e6…f3df (85 txs, 3.77 Mgas, 200.83 ms, 12.84 KiB)
2018-03-16 01:45:59 UTC Imported #5262882 b8d9…9197 (51 txs, 8.00 Mgas, 195.84 ms, 10.76 KiB)
2018-03-16 01:46:09 UTC Imported #5262884 8937…7000 (37 txs, 7.97 Mgas, 215.22 ms, 10.97 KiB)
2018-03-16 01:46:10 UTC Imported #5262884 5399…3cf3 (71 txs, 7.78 Mgas, 97.50 ms, 11.44 KiB)
2018-03-16 01:46:15 UTC Imported #5262885 94a7…ac6c (83 txs, 7.98 Mgas, 156.38 ms, 12.97 KiB)
2018-03-16 01:46:20 UTC   19/25 peers   5 MiB chain 71 MiB db 0 bytes queue 22 KiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-03-16 01:46:40 UTC Imported #5262886 b519…2217 (50 txs, 7.99 Mgas, 302.33 ms, 12.70 KiB)
2018-03-16 01:46:55 UTC   19/25 peers   5 MiB chain 71 MiB db 0 bytes queue 22 KiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-03-16 01:47:04 UTC Reorg to #5262887 6bdd…9b3d (b519…2217 #5262885 94a7…ac6c a3af…0f8c)
2018-03-16 01:47:04 UTC Imported #5262887 6bdd…9b3d (274 txs, 7.74 Mgas, 448.76 ms, 35.43 KiB) + another 1 block(s) containing 45 tx(s)
2018-03-16 01:47:27 UTC Imported #5262888 de64…5c25 (142 txs, 7.34 Mgas, 300.11 ms, 32.79 KiB)
2018-03-16 01:47:30 UTC   19/25 peers   6 MiB chain 71 MiB db 0 bytes queue 22 KiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-03-16 01:47:41 UTC Imported #5262889 e387…62f4 (144 txs, 7.99 Mgas, 240.18 ms, 25.17 KiB)
2018-03-16 01:47:51 UTC Imported #5262890 8a30…2f51 (63 txs, 1.54 Mgas, 116.14 ms, 7.37 KiB)
2018-03-16 01:47:57 UTC Imported #5262891 7651…35e6 (81 txs, 3.67 Mgas, 177.49 ms, 13.21 KiB)
2018-03-16 01:47:58 UTC Stage 1 block verification failed for af7e…2913: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164893), found: 1521164896 }))
2018-03-16 01:47:58 UTC Stage 1 block verification failed for af7e…2913: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164893), found: 1521164896 }))
2018-03-16 01:47:58 UTC Stage 1 block verification failed for af7e…2913: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164893), found: 1521164896 }))
2018-03-16 01:47:59 UTC Stage 1 block verification failed for af7e…2913: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164894), found: 1521164896 }))
2018-03-16 01:47:59 UTC Stage 1 block verification failed for af7e…2913: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164894), found: 1521164896 }))
2018-03-16 01:48:00 UTC Stage 1 block verification failed for af7e…2913: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521164895), found: 1521164896 }))
2018-03-16 01:48:01 UTC Imported #5262892 af7e…2913 (25 txs, 1.48 Mgas, 104.93 ms, 4.91 KiB)
2018-03-16 01:48:05 UTC   21/25 peers   5 MiB chain 71 MiB db 0 bytes queue 22 KiB sync  RPC:  0 conn,  0 req/s,   0 µs

So, I don't know what to do... It seems to still be importing new blocks. How bad is this? Do I need to start over? How? And what's going on?

[tomusdrw]

@taoeffect Could you please try to synchronize your local time?

[taoeffect]

I just checked, and it already is synchronized, per output of date command. EDIT: also, the timestamps on the log are correct.

[Tbaut]

@taoeffect could you please run the beta docker parity/parity:beta, this error should be fixed in 1.9 according to #6704

Just for information about the time, you checked manually right ? we're talking about milliseconds difference eventually here. The easiest to verify is to visit https://time.is

[taoeffect]

I'll give it a try and report back, but just fyi, i think this is ridiculous. Surely you can figure out a way to make it less time dependent and robust, otherwise you're asking for network faults and flakiness.

See also Timestamps Unnecessary In Proof-of-Work?.

[tomusdrw]

@taoeffect The message is not critical, Parity will just ignore a block until it becomes valid according to the miner. If your time is in sync it's miner faults to produce "future block" and it may become and uncle instead. Miners are incentivised by difficulty algorithm to declare a fair timestamp from one side and by preference to include blocks that match current timestamp from the other.

[taoeffect]

I updated to v1.9.4-beta-6f21a32-20180228, and while the problem has lessened somewhat, I did just notice a single:

2018-03-18 23:42:34 UTC Stage 1 block verification failed for 33f6…6db5: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521416569), found: 1521416570 }))

So it's not completely gone, but definitely seems to be complaining less at least.

Also, strangely, when I checked the fullnode (before updating), it had stopped syncing completely, displaying a long series of this for several hours (up to the point that I checked):

2018-03-18 23:27:50 UTC    2/25 peers   6 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 23:28:25 UTC    2/25 peers   6 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 23:29:00 UTC    2/25 peers   6 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 23:29:35 UTC    2/25 peers   6 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 23:30:10 UTC    2/25 peers   6 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 23:30:45 UTC    2/25 peers   6 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 23:31:20 UTC    2/25 peers   6 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs

Starting at:

2018-03-18 19:00:05 UTC Imported #5278890 b8bb…6b7f (14 txs, 0.47 Mgas, 60.28 ms, 2.21 KiB)
2018-03-18 19:00:07 UTC Stage 1 block verification failed for 75ea…6cba: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521399622), found: 1521399623 }))
2018-03-18 19:00:09 UTC    2/25 peers   5 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 19:00:44 UTC    2/25 peers   5 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 19:01:19 UTC    2/25 peers   5 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 19:01:54 UTC    2/25 peers   5 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs
2018-03-18 19:02:29 UTC    2/25 peers   5 MiB chain 110 MiB db 0 bytes queue 51 KiB sync  RPC:  0 conn,  0 req/s, 51040 µs

After updating to the beta, it is now connecting to peers again, but I'm concerned about the sudden failure. This is something you may want to keep an eye on, as it might be another bug, or it might be an attack by ISPs now that net neutrality has been neutered.

[taoeffect]

Also, this just happened with the beta, don't know if it's worth opening another issue or not, so I'm posting it here (but let me know if you want me to put it in another issue):

2018-03-18 23:50:20 UTC Taking snapshot at #5280000
2018-03-18 23:50:20 UTC Periodic snapshot failed: block state pruned.Run with a longer `--pruning-history` or with `--no-periodic-snapshot`
2018-03-18 23:50:29 UTC   23/25 peers   6 MiB chain 87 MiB db 0 bytes queue 202 KiB sync  RPC:  0 conn,  0 req/s,   0 µs
2018-03-18 23:50:31 UTC Imported #5280101 7aaa…1c57 (260 txs, 7.86 Mgas, 218.66 ms, 31.36 KiB)
2018-03-18 23:50:33 UTC Stage 1 block verification failed for 551f…738a: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521417048), found: 1521417050 }))
2018-03-18 23:50:34 UTC Stage 1 block verification failed for 551f…738a: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521417049), found: 1521417050 }))
2018-03-18 23:50:34 UTC Stage 1 block verification failed for 551f…738a: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521417049), found: 1521417050 }))
2018-03-18 23:50:34 UTC Stage 1 block verification failed for 551f…738a: Block(TemporarilyInvalid(OutOfBounds { min: None, max: Some(1521417049), found: 1521417050 }))
2018-03-18 23:50:35 UTC Imported #5280102 551f…738a (68 txs, 8.00 Mgas, 127.17 ms, 12.38 KiB)

[rphmeier]

@taoeffect the periodic snapshot failing is expected behavior on a pruned node.

[AyushyaChitransh]

This issue is happening on my private network also. My parity version:

Parity//v1.10.0-unstable-fb4582a90-20180205/x86_64-linux-gnu/rustc1.23.0

I have synchronized my time using chrony, and I hope that my node does not go out of sync again. I am running chrony on centos using these commands:

sudo yum erase ntp* -y
sudo yum install chrony -y
sudo service chronyd start

[5chdn]

This is not a client issue, this could be also an Authority node with wrong time settings. This is rather a warning not an error.

[taoeffect]

This is not a client issue, this could be also an Authority node with wrong time settings.

Well, it wasn't an "Authority node" and the time settings were correct. However, I'll note that the issue does seem to have mostly gone away with the latest beta.

[5chdn]

What I meant is that the authority node authoring a block with a wrong timestamp sending it to your node with correct time settings. So not much you can do about it

[taoeffect]

What I meant is that the authority node authoring a block

"Authority node"? I thought those were only for Proof-of-Authority? This was happening on the main chain which doesn't have authorities AFAIK.

[tomusdrw]

@taoeffect on main chain it will be a miner producing blocks with timestamp set tiny bit in future. I will suppress this warning and make it a debug message instead, it's something that we were always doing anyway it just became a bit more visible now.