Skip to content
This repository has been archived by the owner on Nov 6, 2020. It is now read-only.

Bad block detected: TimestampOverflow #10688

Closed
stabastian opened this issue May 22, 2019 · 19 comments · Fixed by #10720
Closed

Bad block detected: TimestampOverflow #10688

stabastian opened this issue May 22, 2019 · 19 comments · Fixed by #10720
Labels
F2-bug 🐞 The client fails to follow expected behavior. M4-core ⛓ Core client code / Rust. P5-sometimesoon 🌲 Issue is worth doing soon.
Milestone

Comments

@stabastian
Copy link

  • Parity Ethereum version: 2.4.6-stable
  • Operating system: Linux Ubuntu 16.04.6
  • Installation: Docker image
  • Fully synchronized: yes
  • Network: Custom private network
  • Restarted: no

I have configured a private network with PoA Aura and the follow chain spec:

{
  "name": "Chain Name",
  "engine": {
    "authorityRound": {
      "params": {
        "blockReward": 0,
        "stepDuration": 5,
        "maximumEmptySteps": 24,
        "emptyStepsTransition": 0,
        "maximumUncleCountTransition": 0,
        "maximumUncleCount": 0,
        "validators": {
          "multi": {
            "0": {
              "list": [
                "0x..."
              ]
            },
            "5": {
              "safeContract": "0x0000000000000000000000000000000000000005"
            }
          }
        }
      }
    }
  },
  "params": {
    "gasLimitBoundDivisor": "0x400",
    "maximumExtraDataSize": "0x20",
    "minGasLimit": "0x1388",
    "networkID": "0x1E61",
    "eip140Transition": 0,
    "eip211Transition": 0,
    "eip214Transition": 0,
    "eip658Transition": 0,
    "eip145Transition": 0,
    "eip1014Transition": 0,
    "eip1052Transition": 0
  },
...

From block 6 onwards I have added 2 more validators and after a good working time for some reason 2 of those 3 validators started to show a warning message:

5/22/2019 8:51:38 AM2019-05-22 11:51:38 UTC IO Worker #0 WARN client  Stage 1 block verification failed for 0x0eec…b457: Error(Block(TimestampOverflow), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
5/22/2019 8:51:38 AM   0:     0x56176aa8b19d - <no info>
5/22/2019 8:51:38 AM   1:     0x56176aa8a562 - <no info>
5/22/2019 8:51:38 AM   2:     0x56176a7e3ec8 - <no info>
5/22/2019 8:51:38 AM   3:     0x56176a7e41f5 - <no info>
5/22/2019 8:51:38 AM   4:     0x56176a2b3f9e - <no info>
5/22/2019 8:51:38 AM   5:     0x56176a228376 - <no info>
5/22/2019 8:51:38 AM   6:     0x56176a14b5d5 - <no info>
5/22/2019 8:51:38 AM   7:     0x56176a113be5 - <no info>
5/22/2019 8:51:38 AM   8:     0x56176a29724e - <no info>
5/22/2019 8:51:38 AM   9:     0x561769d58009 - <no info>
5/22/2019 8:51:38 AM  10:     0x561769d4c2ab - <no info>
5/22/2019 8:51:38 AM  11:     0x561769d4688e - <no info>
5/22/2019 8:51:38 AM  12:     0x561769e46bdf - <no info>
5/22/2019 8:51:38 AM  13:     0x561769e319b2 - <no info>
5/22/2019 8:51:38 AM  14:     0x561769e5ec31 - <no info>
5/22/2019 8:51:38 AM  15:     0x561769e67bfc - <no info>
5/22/2019 8:51:38 AM  16:     0x561769e2ab6c - <no info>
5/22/2019 8:51:38 AM  17:     0x561769e26712 - <no info>
5/22/2019 8:51:38 AM  18:     0x561769e796b6 - <no info>
5/22/2019 8:51:38 AM  19:     0x561769e2618a - <no info>
5/22/2019 8:51:38 AM  20:     0x561769e26dd3 - <no info>
5/22/2019 8:51:38 AM  21:     0x561769e26aaa - <no info>
5/22/2019 8:51:38 AM  22:     0x561769e264c6 - <no info>
5/22/2019 8:51:38 AM  23:     0x561769e5f6d3 - <no info>
5/22/2019 8:51:38 AM  24:     0x561769e32b26 - <no info>
5/22/2019 8:51:38 AM  25:     0x56176ab03ed9 - <no info>
5/22/2019 8:51:38 AM  26:     0x561769e65a27 - <no info>
5/22/2019 8:51:38 AM  27:     0x56176ab0321d - <no info>
5/22/2019 8:51:38 AM  28:     0x7fdfe8d256b9 - <no info>
5/22/2019 8:51:38 AM  29:     0x7fdfe884541c - <no info>
5/22/2019 8:51:38 AM  30:                0x0 - <no info>) } })
5/22/2019 8:51:38 AM2019-05-22 11:51:38 UTC IO Worker #0 ERROR client
5/22/2019 8:51:38 AMBad block detected: TimestampOverflow
5/22/2019 8:51:38 AMRLP: f902a6f9023da0dd92a234003d080ffa3797248fed73c12b32d348a1ca06befb65d6bb8391323ca01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794e132c75a856370c4cf9ea732e77a634ba75566ada0fa19792eaf5dfde912f80f3f0e9280518cd52e366e74af4f150e22c4c9fded0da0bbca51265e7d4059de3f0011f95cadf54e1085005e194bfcc9080b0168a17763a0056b23fbba480696b65fe5a59b8f2148a1299103c4f57df839233af2cf4ca2d2b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffd820447836acfc0825208845ce537cc96d583010b0b8650617269747986312e32382e30826c698412943e5cb8413c4e71b358308c419d24973ee80dc26724da7a7bd1e30fe311208b3feda90f9d1386c2c9d53714f0630300440ac2d3070b497de88fa10d98829df4df0483282f01c0f863f8611c808252089461c6d9385a6e380d38f8c07d8578c88e80b0de428080823ce5a0662464db5481328ad4e694c30eb4b3936e6f08de182847e320709434a8198598a0200fd2deac543f854d24bccc4ead009f800b38ca1d3aa750dab60858e706dffdc0
5/22/2019 8:51:38 AMHeader: Header { parent_hash: 0xdd92a234003d080ffa3797248fed73c12b32d348a1ca06befb65d6bb8391323c, timestamp: 1558525900, number: 1095, author: 0xe132c75a856370c4cf9ea732e77a634ba75566ad, transactions_root: 0xbbca51265e7d4059de3f0011f95cadf54e1085005e194bfcc9080b0168a17763, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [213, 131, 1, 11, 11, 134, 80, 97, 114, 105, 116, 121, 134, 49, 46, 50, 56, 46, 48, 130, 108, 105], state_root: 0xfa19792eaf5dfde912f80f3f0e9280518cd52e366e74af4f150e22c4c9fded0d, receipts_root: 0x056b23fbba480696b65fe5a59b8f2148a1299103c4f57df839233af2cf4ca2d2, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 21000, gas_limit: 7000000, difficulty: 340282366920938463463374607431768211453, seal: [[132, 18, 148, 62, 92], [184, 65, 60, 78, 113, 179, 88, 48, 140, 65, 157, 36, 151, 62, 232, 13, 194, 103, 36, 218, 122, 123, 209, 227, 15, 227, 17, 32, 139, 63, 237, 169, 15, 157, 19, 134, 194, 201, 213, 55, 20, 240, 99, 3, 0, 68, 10, 194, 211, 7, 11, 73, 125, 232, 143, 161, 13, 152, 130, 157, 244, 223, 4, 131, 40, 47, 1], [192]], hash: Some(0x0eec15560b9fd0023898eb55cc3f07f8e340e724e58f764afd33f62d9b5fb457) }
5/22/2019 8:51:38 AMUncles:
5/22/2019 8:51:38 AMTransactions:[Tx 0] UnverifiedTransaction { unsigned: Transaction { nonce: 28, gas_price: 0, gas: 21000, action: Call(0x61c6d9385a6e380d38f8c07d8578c88e80b0de42), value: 0, data: [] }, v: 15589, r: 46200213137587573852807896723916551981571758800145009323532541635400144881048, s: 14501969230625558155265972124208633765243347631739084742960239462317979787261, hash: 0xda77115d27ee19adae0be0320d121141082a445b13a60840e0f7f157687639d3 }

The 3 validators are in different servers and has the same clock time (UTC) and the same configuration:

[parity]
chain = "genesis.json"
no_persistent_txqueue = true

[account]
unlock = ["0x..."]
password = ["password.txt"]

[ui]
disable = true

[rpc]
interface = "all"

[network]
discovery = true
reserved_peers = "nodes.txt"

[mining]
author = "0x.."
engine_signer = "0x.."
min_gas_price = 0
gas_floor_target = "7000000"

[misc]
logging = "external_tx=debug,network=info,own_tx=debug,poa=info,txqueue=debug"
log_file = "parity-validator.log"
color = true

The actual behavior is the validator that is not showing this message is not sealing block anymore.
The expected behavior is all the validators sealing blocks.

Thanks.

@jam10o-new jam10o-new added F2-bug 🐞 The client fails to follow expected behavior. M4-core ⛓ Core client code / Rust. P5-sometimesoon 🌲 Issue is worth doing soon. labels May 23, 2019
@jam10o-new jam10o-new added this to Needs Assignment in Core via automation May 23, 2019
@jam10o-new jam10o-new added this to the 2.6 milestone May 23, 2019
@valar999
Copy link

We have possible the same issue.
After fail with Stage 1 block verification failed this node start to validate blocks independently.

2019-05-19 14:51:55 UTC Imported #421924 0x2907…b3d6 (5 txs, 1.76 Mgas, 36 ms, 1.30 KiB)
2019-05-19 14:52:00 UTC Imported #421925 0x5f9d…eeab (2 txs, 0.72 Mgas, 13 ms, 0.84 KiB)
2019-05-19 14:52:05 UTC Imported #421926 0xd265…4867 (3 txs, 0.94 Mgas, 16 ms, 1.06 KiB)
2019-05-19 14:52:10 UTC Imported #421927 0x3037…8981 (3 txs, 1.08 Mgas, 13 ms, 0.98 KiB)
2019-05-19 14:52:10 UTC Imported #421927 0x3037…8981 (3 txs, 1.08 Mgas, 13 ms, 0.98 KiB)
2019-05-19 14:52:12 UTC   36/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   16 µs
2019-05-19 14:52:12 UTC   36/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   16 µs
  23:     0x556df7f32103 - <no info>
  20:     0x556df7ef9803 - <no info>
  13:     0x556df7f043e2 - <no info>
  12:     0x556df7f1960f - <no info>
   6:     0x556df821df95 - <no info>
   5:     0x556df82fad46 - <no info>
   4:     0x556df838698e - <no info>
   2:     0x556df88af938 - <no info>
   0:     0x556df8b56c1d - <no info>
  29:     0x7f8cbe99541c - <no info>
  26:     0x556df7f38457 - <no info>
  19:     0x556df7ef8bba - <no info>
  18:     0x556df7f4c0e6 - <no info>
  17:     0x556df7ef9142 - <no info>
  15:     0x556df7f3a62c - <no info>
  11:     0x556df7e1929e - <no info>
   7:     0x556df81e6585 - <no info>
   3:     0x556df88afc65 - <no info>
   1:     0x556df8b55fe2 - <no info>
  28:     0x7f8cbee756b9 - <no info>
  25:     0x556df8bcf8d9 - <no info>
  24:     0x556df7f05556 - <no info>
  16:     0x556df7efd59c - <no info>
  10:     0x556df7e1ecbb - <no info>
   9:     0x556df7e2aa19 - <no info>
   8:     0x556df8369c3e - <no info>
  30:                0x0 - <no info>) } })
  22:     0x556df7ef8ef6 - <no info>
  14:     0x556df7f31661 - <no info>
  27:     0x556df8bcec1d - <no info>
  21:     0x556df7ef94da - <no info>
2019-05-19 14:52:14 UTC Stage 1 block verification failed for 0xb267…96fe: Error(Block(TimestampOverflow), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(stack backtrace:
Transactions:[Tx 0] UnverifiedTransaction { unsigned: Transaction { nonce: 2738, gas_price: 5000000000, gas: 5010000, action: Call(0x9c477161a8fa5691c2ed739c44a1d894bbecdeae), value: 0, data: [92, 35, 189, 245, 164, 55, 177, 90, 155, 245, 217, 129, 183, 126, 201, 23, 185, 229, 109, 78, 149, 234, 74, 188, 20, 9, 241, 216, 12, 217, 33, 102, 249, 96, 46, 171] }, v: 44085, r: 51413795394375614587873082501814767356217236188918532879524789190551096417778, s: 42565565547684554882278415904008247358643166104896767637850063866123175326170, hash: 0x9eebffe1750321de292e88cd6b1b1722d59dd71430d6f86e245b67862c038dbc }
RLP: f902dcf90247a03037a76eddc4c093ac47f228880b27163bb6d360e2fc98fccf737ec81b2a8981a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347947da0244aec40140c87b363a0c15f11f5734f4ee3a0339bb37d89f6d70047465b51a862a22849d45f54753f18e7a0de0c1a93328e63a0b2abf7c08f252a06e576dd4c82e06bd1dcbe3d666da07ad9db4a823bc967497ea0855f4c6775d869297e943b8860606985e7b7fcc812ed6fbf6ef4f5f1ea2eebf5b901000000000000000400000000000000000000000000000000000000000000000000000000000000100000000000200000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004000000000000000000000000000000000000800000000000000000000080000000000000000000040000000000000000000100000000000008000000000000000000000000000000002000000000000000000000000000000000000000000000000000000000000000000001000000000000000000000000000000000000000000000000000000000000000000000000000000080000000000000090fffffffffffffffffffffffffffffffe83067028837a1200830579aa845ce16d9e9fde830202098f5061726974792d457468657265756d86312e33312e31826c698412937c53b841f58b6ce8e469050e82e22f42e1f9b76bc32fd3b64034e2f8404cb67e9d1f616931134d78fbda54329e662a87bf6167867da3de1e63071d9e89981b87a849ed1d01f88ff88d820ab285012a05f200834c7250949c477161a8fa5691c2ed739c44a1d894bbecdeae80a45c23bdf5a437b15a9bf5d981b77ec917b9e56d4e95ea4abc1409f1d80cd92166f9602eab82ac35a071ab2d4d11ed414ca0abd6974683276cf0eab61f98d1b2fb60a7becb86425df2a05e1b419f5e9e34143d9929f80a42045a922abc948bb7a67b7828e4baae33f1dac0
Uncles:
Header: Header { parent_hash: 0x3037a76eddc4c093ac47f228880b27163bb6d360e2fc98fccf737ec81b2a8981, timestamp: 1558277534, number: 421928, author: 0x7da0244aec40140c87b363a0c15f11f5734f4ee3, transactions_root: 0xb2abf7c08f252a06e576dd4c82e06bd1dcbe3d666da07ad9db4a823bc967497e, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 2, 9, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 49, 46, 49, 130, 108, 105], state_root: 0x339bb37d89f6d70047465b51a862a22849d45f54753f18e7a0de0c1a93328e63, receipts_root: 0x855f4c6775d869297e943b8860606985e7b7fcc812ed6fbf6ef4f5f1ea2eebf5, log_bloom: 0x00000000000004000000000000000000000000000000000000000000000000000000000000001000000000002000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000040000000000000000000000000000000000008000000000000000000000800000000000000000000400000000000000000001000000000000080000000000000000000000000000000020000000000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000000000000000000000000000000000000000000000000000000800000000000000, gas_used: 358826, gas_limit: 8000000, difficulty: 340282366920938463463374607431768211454, seal: [[132, 18, 147, 124, 83], [184, 65, 245, 139, 108, 232, 228, 105, 5, 14, 130, 226, 47, 66, 225, 249, 183, 107, 195, 47, 211, 182, 64, 52, 226, 248, 64, 76, 182, 126, 157, 31, 97, 105, 49, 19, 77, 120, 251, 218, 84, 50, 158, 102, 42, 135, 191, 97, 103, 134, 125, 163, 222, 30, 99, 7, 29, 158, 137, 152, 27, 135, 168, 73, 237, 29, 1]], hash: Some(0xb2677c3e75f3e1426f658b2430d66a7a1eebc71befe2648a04099e6ec31296fe) }

Bad block detected: TimestampOverflow
2019-05-19 14:52:15 UTC
2019-05-19 14:52:42 UTC   24/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   16 µs
2019-05-19 14:52:45 UTC Imported #421928 0x435e…939a (9 txs, 3.12 Mgas, 9 ms, 1.94 KiB)
2019-05-19 14:53:12 UTC   23/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   16 µs
2019-05-19 14:53:12 UTC   23/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   16 µs
2019-05-19 14:53:42 UTC   25/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   16 µs
2019-05-19 14:54:10 UTC Imported #421929 0x3640…b0f9 (9 txs, 3.19 Mgas, 7 ms, 1.86 KiB)
2019-05-19 14:54:12 UTC   25/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   16 µs
2019-05-19 14:54:42 UTC   23/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
2019-05-19 14:55:12 UTC   23/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
2019-05-19 14:55:35 UTC Imported #421930 0x8381…73c1 (10 txs, 3.18 Mgas, 9 ms, 2.08 KiB)
2019-05-19 14:55:42 UTC   21/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
2019-05-19 14:56:12 UTC   25/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
2019-05-19 14:56:42 UTC   26/50 peers      5 MiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs

15 validators

[parity]
base_path = "/parity"
chain = "chain.json"
mode = "active"

[footprint]
cache_size = 95
pruning = "fast"

[network]
nat = "extip:x.x.x.x"
warp = false
reserved_peers = "reserved.txt"
min_peers = 15

[rpc]
apis = ["web3", "eth", "net", "parity"]
interface = "all"
cors = ["*"]

[websockets]
apis = ["web3", "eth", "pubsub", "net"]
interface = "all"
origins = ["all"]

[ipc]
disable = true

[misc]
logging = "own_tx=warn"

[mining]
engine_signer = "0x89442A82Da3bDdae355C41820c700C3fca44Fea0"
reseal_on_txs = "none"
force_sealing = true
min_gas_price = 1000000000
extra_data = "Apollo v2.4.5"

@jam10o-new
Copy link
Contributor

(cc @niklasad1 any ideas on what's going on here?)

@niklasad1
Copy link
Collaborator

niklasad1 commented May 23, 2019

Hey, it looks like verify_timestamp failed.

Can you run with -l trace=engine and report what timestamp you're using in your chainspec/genesis?

@valar999
Copy link

Turn on engine=trace but don't see any info about timestamp.

@niklasad1
Copy link
Collaborator

Ok, I thought this would show

@valar999
Copy link

Turn on engine=trace, but still no messages with timestamp

Got one more fork, there was no errors, no fails of parity. All other nodes in sync.

May 24 22:14:15 apollo_eu_west_1_2 :  2019-05-24 19:14:15 UTC Imported #488228 0x12dd…8492 (0 txs, 0.00 Mgas, 0 ms, 0.56 KiB)
May 24 22:14:20 apollo_eu_west_1_2 :  2019-05-24 19:14:20 UTC Imported #488229 0x0d25…5c68 (0 txs, 0.00 Mgas, 1 ms, 0.56 KiB)
May 24 22:14:20 apollo_eu_west_1_2 :  2019-05-24 19:14:20 UTC Imported #488229 0x0d25…5c68 (0 txs, 0.00 Mgas, 1 ms, 0.56 KiB)
May 24 22:14:25 apollo_eu_west_1_2 :  2019-05-24 19:14:25 UTC Imported #488230 0x316c…bdd2 (0 txs, 0.00 Mgas, 0 ms, 0.56 KiB)
May 24 22:14:25 apollo_eu_west_1_2 :  2019-05-24 19:14:25 UTC Imported #488230 0x316c…bdd2 (0 txs, 0.00 Mgas, 0 ms, 0.56 KiB)
May 24 22:14:30 apollo_eu_west_1_2 :  2019-05-24 19:14:30 UTC Imported #488231 0x8615…4f05 (0 txs, 0.00 Mgas, 0 ms, 0.56 KiB)
May 24 22:14:30 apollo_eu_west_1_2 :  2019-05-24 19:14:30 UTC Imported #488231 0x8615…4f05 (0 txs, 0.00 Mgas, 0 ms, 0.56 KiB)
May 24 22:14:35 apollo_eu_west_1_2 :  2019-05-24 19:14:35 UTC Imported #488232 0x7258…1567 (0 txs, 0.00 Mgas, 1 ms, 0.56 KiB)
May 24 22:14:35 apollo_eu_west_1_2 :  2019-05-24 19:14:35 UTC Imported #488232 0x7258…1567 (0 txs, 0.00 Mgas, 1 ms, 0.56 KiB)
May 24 22:14:35 apollo_eu_west_1_2 :  2019-05-24 19:14:35 UTC   41/50 peers    642 KiB chain   11 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    1 req/s,   15 µs
May 24 22:14:35 apollo_eu_west_1_2 :  2019-05-24 19:14:35 UTC   41/50 peers    642 KiB chain   11 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    1 req/s,   15 µs
May 24 22:14:40 apollo_eu_west_1_2 :  2019-05-24 19:14:40 UTC Imported #488233 0x851f…0e7c (0 txs, 0.00 Mgas, 1 ms, 0.56 KiB)
May 24 22:14:40 apollo_eu_west_1_2 :  2019-05-24 19:14:40 UTC Imported #488233 0x851f…0e7c (0 txs, 0.00 Mgas, 1 ms, 0.56 KiB)
May 24 22:14:45 apollo_eu_west_1_2 :  2019-05-24 19:14:45 UTC Imported #488234 0x6dc1…745a (1 txs, 0.32 Mgas, 3 ms, 0.76 KiB)
May 24 22:15:06 apollo_eu_west_1_2 :  2019-05-24 19:15:06 UTC   41/50 peers    642 KiB chain   11 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
May 24 22:15:10 apollo_eu_west_1_2 :  2019-05-24 19:15:10 UTC Imported #488235 0x56ef…9572 (1 txs, 0.39 Mgas, 3 ms, 0.70 KiB)
May 24 22:15:36 apollo_eu_west_1_2 :  2019-05-24 19:15:36 UTC   41/50 peers    642 KiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
May 24 22:16:06 apollo_eu_west_1_2 :  2019-05-24 19:16:06 UTC   37/50 peers    642 KiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
May 24 22:16:36 apollo_eu_west_1_2 :  2019-05-24 19:16:36 UTC    8/15 peers    642 KiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
May 24 22:16:40 apollo_eu_west_1_2 :  2019-05-24 19:16:40 UTC Imported #488236 0x8dc8…1242 (0 txs, 0.00 Mgas, 0 ms, 0.56 KiB)
May 24 22:17:06 apollo_eu_west_1_2 :  2019-05-24 19:17:06 UTC    5/15 peers    642 KiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs
May 24 22:17:36 apollo_eu_west_1_2 :  2019-05-24 19:17:36 UTC    0/15 peers    642 KiB chain   10 MiB db  0 bytes queue   62 KiB sync  RPC:  0 conn,    0 req/s,   15 µs

@AC0DEM0NK3Y
Copy link

AC0DEM0NK3Y commented May 25, 2019

I don't seem to be able to use parity atm because of this too, I get 1 import in and it stops. This is from a freshly started archive node using 2.4.6.

Loading config file from .\\config_src_kovan_archive.toml
2019-05-25 17:45:54  Starting Parity-Ethereum/v2.4.6-stable-94164e1ca-20190514/x86_64-windows-msvc/rustc1.34.1
2019-05-25 17:45:54  Keys path D:\Parity\src_node_archive\keys\kovan
2019-05-25 17:45:54  DB path D:\Parity\src_node_archive\chains\kovan\db\9bf388941c25ea98
2019-05-25 17:45:54  State DB configuration: archive
2019-05-25 17:45:54  Operating mode: active
2019-05-25 17:45:54  Warning: Warp Sync is disabled because of non-default pruning mode.
2019-05-25 17:45:59  Configured for Kovan Testnet using AuthorityRound engine
2019-05-25 17:45:59  Listening for new connections on 127.0.0.1:8570.
2019-05-25 17:45:59  Multi-threaded server is not available on Windows. Falling back to single thread.
2019-05-25 17:45:59  Public node URL: enode://<redacted>@127.0.0.1:30330
2019-05-25 17:46:04  Syncing #11145562 0x0f11…0805    21.60 blk/s   24.4 tx/s    3.2 Mgas/s      0+ 3446 Qed  #11149009    9/50 peers    972 KiB chain  374 KiB db    9 MiB queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:46:09  Syncing #11146164 0xcc48…2827   120.40 blk/s  146.4 tx/s   19.2 Mgas/s      0+ 6427 Qed  #11152602   10/50 peers      3 MiB chain  744 KiB db   16 MiB queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:46:14  Syncing #11147188 0x9440…50ac   204.76 blk/s  234.8 tx/s   29.5 Mgas/s      0+ 5408 Qed  #11152603   10/50 peers      3 MiB chain  942 KiB db   14 MiB queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:46:19  Syncing #11148336 0x305e…3ed5   229.55 blk/s  262.1 tx/s   32.7 Mgas/s      0+ 4257 Qed  #11152604   10/50 peers      5 MiB chain    1 MiB db   11 MiB queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:46:24  Syncing #11149284 0xebf7…901a   189.56 blk/s  209.6 tx/s   26.1 Mgas/s      0+ 3311 Qed  #11152606   10/50 peers      9 MiB chain    1 MiB db    8 MiB queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:46:29  Syncing #11150499 0x05e6…64d0   242.35 blk/s  265.9 tx/s   42.2 Mgas/s      0+ 2100 Qed  #11152607   11/50 peers     13 MiB chain    2 MiB db    5 MiB queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:46:34  Syncing #11151817 0xcb32…8acc   263.95 blk/s  287.3 tx/s   39.5 Mgas/s      0+  781 Qed  #11152608   12/50 peers     15 MiB chain    2 MiB db    2 MiB queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:46:35  Stage 1 block verification failed for 0x05e8…64c6: Error(Block(TimestampOverflow), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2019-05-25 17:46:35
Bad block detected: TimestampOverflow
RLP: f9039cf90246a02d1a356d984a129f31d9577d512e5352bde3c7e85de18eaf7c5eeacc61263e64a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794596e8221a30bfe6e7eff67fee664a01c73ba3c56a06840032fd0cac71eb3d356c74346ec4e80bfe2b018c8ac849c81e5eb68989193a07f5b18e9ba0bcdf26f7a28e45a34e56d75057d4eadf4b7f27565b32e3e2aa7dba0a68616454e1b94297c4f6624dc18a10c762833f30c1a9436cb0369e9a8c4ca09b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffe83aa2ce1837a120082c64f845ce9b7bc9fde830204058f5061726974792d457468657265756d86312e33332e30826c6984173a6defb841bac466208a9612b119a872da7b687dd2bb57a60a4419e89e0c2896797d5dc4447f305bf937df3a63da2556bf8b55d86363f117936ee987c05e083ccd41e6bbd401f9014ff9014c830771e18477359400833d0900945f54ec295ad778df2c09da51ba5e1192aab2024580b8e43742d9d9000000000000000000000000000000000000000000000000000000000000004000000000000000000000000000000000000000000000000000000000000000a000000000000000000000000000000000000000000000000000000000000000403861666462623663383031346563373230383962663566666631306532613365343961633233663038326263336664323639343238636338363234356433343100000000000000000000000000000000000000000000000000000000000000172333332a3337322d3736323a343137323639323431303500000000000000000077a0b01cdedce96b66ecdc43894dc8f25516b30fdf89546ef6399fb448dd4f29bc73a06eaca429e97ee4ee0a9d0224aced6361f95456d69da0bd9daf4c1fe61bb83df5c0
Header: Header { parent_hash: 0x2d1a356d984a129f31d9577d512e5352bde3c7e85de18eaf7c5eeacc61263e64, timestamp: 1558820796, number: 11152609, author: 0x596e8221a30bfe6e7eff67fee664a01c73ba3c56, transactions_root: 0x7f5b18e9ba0bcdf26f7a28e45a34e56d75057d4eadf4b7f27565b32e3e2aa7db, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 4, 5, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 51, 46, 48, 130, 108, 105], state_root: 0x6840032fd0cac71eb3d356c74346ec4e80bfe2b018c8ac849c81e5eb68989193, receipts_root: 0xa68616454e1b94297c4f6624dc18a10c762833f30c1a9436cb0369e9a8c4ca09, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 50767, gas_limit: 8000000, difficulty: 340282366920938463463374607431768211454, seal: [[132, 23, 58, 109, 239], [184, 65, 186, 196, 102, 32, 138, 150, 18, 177, 25, 168, 114, 218, 123, 104, 125, 210, 187, 87, 166, 10, 68, 25, 232, 158, 12, 40, 150, 121, 125, 93, 196, 68, 127, 48, 91, 249, 55, 223, 58, 99, 218, 37, 86, 191, 139, 85, 216, 99, 99, 241, 23, 147, 110, 233, 135, 192, 94, 8, 60, 205, 65, 230, 187, 212, 1]], hash: Some(0x05e8379f15aa549db9aed759dc3dc8e2ef49d9b64653e7be6eedadf9f80b64c6) }
Uncles:
Transactions:[Tx 0] UnverifiedTransaction { unsigned: Transaction { nonce: 487905, gas_price: 2000000000, gas: 4000000, action: Call(0x5f54ec295ad778df2c09da51ba5e1192aab20245), value: 0, data: [55, 66, 217, 217, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 64, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 160, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 64, 56, 97, 102, 100, 98, 98, 54, 99, 56, 48, 49, 52, 101, 99, 55, 50, 48, 56, 57, 98, 102, 53, 102, 102, 102, 49, 48, 101, 50, 97, 51, 101, 52, 57, 97, 99, 50, 51, 102, 48, 56, 50, 98, 99, 51, 102, 100, 50, 54, 57, 52, 50, 56, 99, 99, 56, 54, 50, 52, 53, 100, 51, 52, 49, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 23, 35, 51, 51, 42, 51, 55, 50, 45, 55, 54, 50, 58, 52, 49, 55, 50, 54, 57, 50, 52, 49, 48, 53, 0, 0, 0, 0, 0, 0, 0, 0, 0] }, v: 119, r: 79658071211927879993394493596939352014537590757157642467445282890095125970035, s: 50059444055649837059805339936036453085967677803774630122569248445864579972597, hash: 0x6438f455b8532019ce5c46884b497a1830ed95851b5e4cd6bd5ceb4c1e855a0d }

2019-05-25 17:46:37  Imported #11152608 0x2d1a…3e64 (0 txs, 0.00 Mgas, 0 ms, 0.57 KiB)
2019-05-25 17:47:04     2/50 peers     26 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:47:34     3/50 peers     35 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:48:04     2/50 peers     38 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:48:34     2/50 peers     45 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:49:04     2/50 peers     45 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:49:34     2/50 peers     45 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:50:09     3/50 peers     48 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:50:39     4/50 peers     50 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:51:09     5/50 peers     51 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:51:14  Syncing #11152608 0x2d1a…3e64     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #11152589    6/50 peers     51 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 17:51:44     5/50 peers     53 MiB chain    2 MiB db  0 bytes queue    4 MiB sync  RPC:  0 conn,    0 req/s,    0 µs

Possibly related to #10610 as I then just get this state:

2019-05-25 18:01:34  Syncing #11152608 0x2d1a…3e64     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #11090613   12/50 peers     67 MiB chain    2 MiB db  0 bytes queue   60 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 18:01:39  Syncing #11152608 0x2d1a…3e64     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #11111314   12/50 peers     67 MiB chain    2 MiB db  0 bytes queue   43 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 18:01:44  Syncing #11152608 0x2d1a…3e64     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #11111314   12/50 peers     67 MiB chain    2 MiB db  0 bytes queue   45 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 18:01:49  Syncing #11152608 0x2d1a…3e64     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #11111314   12/50 peers     67 MiB chain    2 MiB db  0 bytes queue   46 MiB sync  RPC:  0 conn,    0 req/s,    0 µs
2019-05-25 18:01:54  Syncing #11152608 0x2d1a…3e64     0.00 blk/s    0.0 tx/s    0.0 Mgas/s      0+    0 Qed  #11021775   12/50 peers     67 MiB chain    2 MiB db  0 bytes queue   29 MiB sync  RPC:  0 conn,    0 req/s,    0 µs

On further tests it seems I am importing fine until that TimeStamp block is hit and I drop to the 0.00 blk/s syncing state forever.

[parity]
# Blockchain and settings will be stored in D:\Parity.
base_path = "D:\\Parity\\src_node_archive"

chain = "kovan"

[network]
port = 30330
min_peers = 50
max_peers = 100

[websockets]
disable = false
port = 8570
interface = "local"
#apis = ["web3", "eth", "pubsub", "net", "parity", "parity_pubsub", "traces", "rpc", "shh", "shh_pubsub"]
apis = ["web3", "eth", "pubsub", "net", "parity", "parity_pubsub"]
hosts = ["none"]

#allow local connection with ARC
#origins = ["none"]
origins = ["file://*"]

max_connections=300

[rpc]
disable = false
port = 8571
interface = "local"
cors = []
apis = ["web3", "eth", "pubsub", "net", "parity", "parity_pubsub", "traces", "rpc", "shh", "shh_pubsub"]
hosts = ["none"]

[ipc]
disable = true

[footprint]
tracing = "off"
pruning = "archive"
db_compaction = "ssd"
cache_size = 8192

@AC0DEM0NK3Y
Copy link

AC0DEM0NK3Y commented May 27, 2019

FYI I reverted back to 2.2.9-stable and used the updated chain spec as mentioned by @joshua-mir in #10610 and this seems to unblock me.

Just to note, the error changed using 2.2.9 to:

Bad block detected: TemporarilyInvalid(OutOfBounds { min: None, max: Some(SystemTime { intervals: 147623405639893460 }), found: SystemTime { intervals: 147623405679893460 } })

@berndbohmeier
Copy link

We have the same problem at https://trustlines.network/.
We can not update the nodes on our PoA chain because of that. This is especially a problem now that you declared the end of live for 2.3.x.

For the 2.3.x line:
2.3.6 is working, 2.3.7 is not working anymore.

for the 2.4.x line:
2.4.1 is working, 2.4.2 is not working anymore.

To easy reproduce the behavior you can just run parity connected to an aura chain, and then manipulate the the time on you machine a little bit backwards, so that you will receive blocks from the future. The different behavior is then:

2.3.6, 2.4.1:

Bad block detected: TemporarilyInvalid(OutOfBounds { min: None, max: Some(SystemTime { tv_sec: 3119669140, tv_nsec: 744701536 }), found: SystemTime { tv_sec: 3119669145, tv_nsec: 744701767 } })
RLP: f90249f90244a0ca029ae403d4ae1ca295721d3575ccbdbf5e8b35e9377515dda64a2b1bd9342aa01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794b01b4f67d87b98cb1edb1572b1a3cda3191320a6a01986358e8bb45f0601abb11271b16866b08d617f8a2ec37f85d63d922ce7f7d1a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffe8329e988837a120080845cf92fcf9fde8302010b8f5061726974792d457468657265756d86312e33312e31826c698412983cc3b8411bcde4f2be2439bf7a2a2b81a17331bbfaac6d5d6628952ccfb8b63ad24f4e0607ed40f2329a770df20d32083c5e991da52a9b5f56f05aea8d0c0c769b53efcc00c0c0
Header: Header { parent_hash: 0xca029ae403d4ae1ca295721d3575ccbdbf5e8b35e9377515dda64a2b1bd9342a, timestamp: 1559834575, number: 2746760, author: 0xb01b4f67d87b98cb1edb1572b1a3cda3191320a6, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 1, 11, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 49, 46, 49, 130, 108, 105], state_root: 0x1986358e8bb45f0601abb11271b16866b08d617f8a2ec37f85d63d922ce7f7d1, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 8000000, difficulty: 340282366920938463463374607431768211454, seal: [[132, 18, 152, 60, 195], [184, 65, 27, 205, 228, 242, 190, 36, 57, 191, 122, 42, 43, 129, 161, 115, 49, 187, 250, 172, 109, 93, 102, 40, 149, 44, 207, 184, 182, 58, 210, 79, 78, 6, 7, 237, 64, 242, 50, 154, 119, 13, 242, 13, 50, 8, 60, 94, 153, 29, 165, 42, 155, 95, 86, 240, 90, 234, 141, 12, 12, 118, 155, 83, 239, 204, 0]], hash: Some(0xea373bddd59b151608b6eecac09abe9c3b241ce127fdefff33d407e26dde1f96) }
Uncles: 
Transactions:

Peers are not dropped, and after you fixed the system time everything is fine again.

2.3.7, 2.4.2:

Bad block detected: TimestampOverflow
RLP: f90249f90244a001be0ac881690def41167c8b6d58df6fe7813c89e1dc8f778842fbe492502fdfa01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794d3a22ca447f3f0b1b911b06034438bb2629af00ea02b53f3a59ef678c724a55035475e4aed1e6b29afea3d7ee2ccb1522f11055dbfa056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000090fffffffffffffffffffffffffffffffd8329e8f1837a120080845cf92bce9fde8302010b8f5061726974792d457468657265756d86312e33312e31826c698412983bf6b841dc3da19f99864b90667707ba1bdcc02753bfe83a5cb511431dbc51acc0c4fcc13ccf73812a20c0c443d04959b113578e352e27ed76c68d6c45b6c8ef8732f3d000c0c0
Header: Header { parent_hash: 0x01be0ac881690def41167c8b6d58df6fe7813c89e1dc8f778842fbe492502fdf, timestamp: 1559833550, number: 2746609, author: 0xd3a22ca447f3f0b1b911b06034438bb2629af00e, transactions_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, uncles_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, extra_data: [222, 131, 2, 1, 11, 143, 80, 97, 114, 105, 116, 121, 45, 69, 116, 104, 101, 114, 101, 117, 109, 134, 49, 46, 51, 49, 46, 49, 130, 108, 105], state_root: 0x2b53f3a59ef678c724a55035475e4aed1e6b29afea3d7ee2ccb1522f11055dbf, receipts_root: 0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421, log_bloom: 0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, gas_used: 0, gas_limit: 8000000, difficulty: 340282366920938463463374607431768211453, seal: [[132, 18, 152, 59, 246], [184, 65, 220, 61, 161, 159, 153, 134, 75, 144, 102, 119, 7, 186, 27, 220, 192, 39, 83, 191, 232, 58, 92, 181, 17, 67, 29, 188, 81, 172, 192, 196, 252, 193, 60, 207, 115, 129, 42, 32, 192, 196, 67, 208, 73, 89, 177, 19, 87, 142, 53, 46, 39, 237, 118, 198, 141, 108, 69, 182, 200, 239, 135, 50, 243, 208, 0]], hash: Some(0x8de467d42251620ffa302b475eed47c3521160dc0ef9b482ebdf324bc70c83e6) }
Uncles: 
Transactions:

After that all peers get dropped and it will not recover from it. Only a restart helps. This makes the newer version unusable for us!

@berndbohmeier
Copy link

berndbohmeier commented Jun 6, 2019

My question here would be, how strict is the aura protocol with the timestamp. How much seconds from the future are allowed? And if you receive a block with a timestamp from the future from a certain peer, is parity suppose to drop that peer?

@jam10o-new
Copy link
Contributor

jam10o-new commented Jun 6, 2019

@berndbohmeier to answer your question Aura is extremely strict - all steps must be broadcast and received within the stepduration you configure, and there is a strong assumption that peers have synchronized system clocks (I'd say within a half second). If things come "seconds from the future" they will almost certainly cause issues.

Re: dropping peers, if a peer sends a bad block, parity may drop them. If the block is just on a fork with shared ancestry, it should not. I agree this might be an issue when applied to this particular error however.

I should probably note #10720 should resolve this problem though

@berndbohmeier
Copy link

Lets hope it does :)
I understand that it might make sense to drop a peer that sends a bad block, but it should not drop all peers at the same time and not recover from it. It should at least recover from a slightly of sync clock after it is fixed again.

@zerotrustconsortium
Copy link

We have a pretty similar setup (just Ubuntu 18.04) and suddenly run into the same issue with one of the nodes.
That node throwing the errors is hosted on Azure.

The node ran fine for about 1,5 month with Parity 2.4.5 and suddenly stopped syncing blocks. We had no luck to get the node synching new blocks until we deleted the storage folder (400 GB still free space).
Node ran again for another 2 hours but stopped synching again and restart didn't help.
We stopped the node, deleted storage as well as the keypairs. Created a new keypair and started the node. It started synching again for another hour or so and then stopped.

We upgraded to 2.4.6 and instead of the stopped synching we had the TimeOverFlow error mentioned in the issue description and the node suddenly had no peers anymore.

Strange thing is, that we only have issues with virtual machines on Google Cloud and Azure so far. Dedicated hardware has no issues at all.

@danzipie
Copy link

We are observing the same issue in several nodes of our PoA-based network (Ubuntu 18.04 and Mac OS, Parity versions 2.4.6 and 2.4.5). The attached log is captured from a Ubuntu virtual machine running v2.4.5 and logging sync,network.
log.txt

The issue happens at line 483 and is being observed several times per day, causing downtimes to the infrastructure. For instance when ntp daemon detects a network configuration change like this:

Jun 12 07:32:12 ip-x systemd-timesyncd[498]: Network configuration changed, trying to establish connection.
Jun 12 07:32:12 ip-x systemd-timesyncd[498]: Synchronized to time server 91.189.91.157:123 (ntp.ubuntu.com).

Unfortunately we can't roll back to v2.4.1 as suggested by @berndbohmeier and looks like #10720 has not been merged in v2.4.7.

@niklasad1
Copy link
Collaborator

Hey, can anyone of you please try #10720 just to make sure that it actually fixes you problem?

Thanks!

@danzipie
Copy link

Hi! We tested (@marcelorocha-e) your PR by using a VirtualBox machine (Ubuntu) running on MacOS.

How do we test? We connect to our test network and pause the VM. After the resume, we observe the behaviour of Parity. There are three test cases:

  1. The current stable version (2.4.7) shows the issue when we pause the VM and, when we resume, can not recover even if we synch the clock (ntpdate).

The PR version #10720 still shows the error message when we resume the VM, but:
2) if we don't force the sync of the clock, it does not recover (same behaviour of v2.4.7 with additional log of errors).
3) if we force the sync (ntpdate), Parity recovers the peers and starts re-synching the blocks.

@dvdplm
Copy link
Collaborator

dvdplm commented Jun 14, 2019

  1. if we force the sync (ntpdate), Parity recovers the peers and starts re-synching the blocks.

@danzipie is it fair to assume that a properly configured node will correct clock drift automatically? In other words, this case (3) would be the normal case and so the fix in #10720 is good?

@danzipie
Copy link

Yes. After additional tests, we observe that with this fix the TimestampOverflow error is replaced by TemporarilyInvalid (as long as the local time is wrong) and peers are not dropped.

(there is a compilation warning: unused import)

@CremaFR
Copy link

CremaFR commented Jun 19, 2019

I've tested #10720 and TimestampOverflow error is replaced by TemporarilyInvalid . peers are not dropped and when time is corrected the node behaves correctly again.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
F2-bug 🐞 The client fails to follow expected behavior. M4-core ⛓ Core client code / Rust. P5-sometimesoon 🌲 Issue is worth doing soon.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

10 participants