search

Consensys / quorum

A permissioned implementation of Ethereum supporting data privacy
https://www.goquorum.com/
GNU Lesser General Public License v3.0
4.69k stars 1.3k forks source link

Unable to join new nodes to Existing Raft Cluster #705

Closed prasad1247 closed 5 years ago

prasad1247 commented 5 years ago

System information

Geth version: Geth/v1.7.2-stable-df4267a2

OS & Version: Linux-amd64/go1.10.2 Amazon Linux

Quorum version: 2.0.2 Active Nodes: 11 Current Block Number: 7158

Expected behaviour

Node should get connected to existing cluster using raft.addPeer

Actual behaviour

Node doesn't join the existing cluster. It gets connected and starts syncing but fails to synchronize with following logs

INFO [05-07|11:34:37] QUORUM-CHECKPOINT                        name=TX-ACCEPTED                                      tx=0x48df9608d31f6c3a13ee76939d29cea00471a4cdc8fb445f65ccb0a6a2c4869c
INFO [05-07|11:34:37] Successfully extended chain              hash=0c36db…462f32
INFO [05-07|11:34:37] replaying WAL 
INFO [05-07|11:34:37] loading WAL                              term=0 index=0
INFO [05-07|11:34:37] startRaft                                raft ID=20
INFO [05-07|11:34:37] remounting an existing raft log; connecting to peers. 
raft2019/05/07 11:34:37 INFO: 14 became follower at term 23027
raft2019/05/07 11:34:37 INFO: newRaft 14 [peers: [1,2,3,4,5,6,7,8,9,a,b,13,14], term: 23027, commit: 9954, applied: 9954, lastindex: 9954, lastterm: 23027]
DEBUG[05-07|11:34:37] InProc registered *node.PrivateAdminAPI under 'admin' 
DEBUG[05-07|11:34:37] InProc registered *node.PublicAdminAPI under 'admin' 
2019-05-07 11:34:37.954891 I | rafthttp: established a TCP streaming connection with peer a (stream Message writer)
2019-05-07 11:34:37.955202 I | rafthttp: established a TCP streaming connection with peer a (stream MsgApp v2 writer)
raft2019/05/07 11:34:37 INFO: raft.node: 14 elected leader a at term 23027
INFO [05-07|11:34:37] start snapshot                           applied index=0 last snapshot index=9954
panic: requested index is older than the existing snapshot

goroutine 886 [running]:
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).triggerSnapshot(0xc420154b00, 0x0)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/snapshot.go:86 +0x44b
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).maybeTriggerSnapshot(0xc420154b00)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/snapshot.go:176 +0x82
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).eventLoop(0xc420154b00)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/handler.go:791 +0xd2c
created by github.com/ethereum/go-ethereum/raft.(*ProtocolManager).startRaft
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/handler.go:482 +0x704

Steps to reproduce the behaviour

  1. Create a new node
  2. add this new Node using raft.addPeer

When tried to restart the node, Geth fails with following log

TRACE[05-07|11:43:41] Node Permissioning is Disabled. 
DEBUG[05-07|11:43:41] Adding p2p peer                          id=e45f1b23fad8d566 name=Geth/v1.7.2-stable-d...                          addr=54.172.8.68:41828    peers=1
TRACE[05-07|11:43:41] Starting protocol eth/63                 id=e45f1b23fad8d566 conn=inbound
DEBUG[05-07|11:43:41] Ethereum peer connected                  id=e45f1b23fad8d566 conn=inbound    name=Geth/v1.7.2-stable-df4267a2/linux-amd64/go1.10.2
DEBUG[05-07|11:43:41] Ethereum handshake failed                id=e45f1b23fad8d566 conn=inbound    err=EOF
DEBUG[05-07|11:43:41] Removing p2p peer                        id=e45f1b23fad8d566 conn=inbound    duration=1.345ms   peers=0 req=true  err="subprotocol error"
INFO [05-07|11:43:42] synchronizing with peer                  peer id=5                                                                                                                                hash=0c36db…462f32
WARN [05-07|11:43:42] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [05-07|11:43:42] failed to synchronize with peer          peer id=5e4f23bbb5d4214a64f477e7679ef7d2261b42c0fb9364070352d9e269ec385f3554d55c670b84ed511de2bd010076edb1ead7ed65b0f07fc006e0f874ac12bb
INFO [05-07|11:43:42] synchronizing with peer                  peer id=7                                                                                                                                hash=0c36db…462f32
WARN [05-07|11:43:42] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [05-07|11:43:42] failed to synchronize with peer          peer id=726011034d54397fffa7400fc0fac0ed2aef80ace4da5be8524f5d6a273f157eedc452e0eb9d10342ff8add23048c0da37bc5761298b4e59526cae33f342b3cc
INFO [05-07|11:43:43] synchronizing with peer                  peer id=8                                                                                                                                hash=0c36db…462f32
WARN [05-07|11:43:43] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [05-07|11:43:43] failed to synchronize with peer          peer id=9fb56809a5db09ffe5e4ffa04f55ade9a4aa5842e3a6d4ccdad62a5667a99fd81c817d9eb0f54250e7665a9da0ca7e602347d9cb8f2fc88cf08e021c0746f9a5
2019-05-07 11:43:43.772578 W | rafthttp: health check for peer 13 could not connect: dial tcp 3.215.251.193:22003: connect: connection refused
INFO [05-07|11:43:43] synchronizing with peer                  peer id=19                                                                                                                               hash=0c36db…462f32
WARN [05-07|11:43:43] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [05-07|11:43:43] failed to synchronize with peer          peer id=ea0f500f70ec9cf3b35594cc8a018199a4f0c23fed30c9e838bf3714b64418377873be775908e4e91e96ee64118d4a79a197f84a78da5117d0269d5b9eb0097c
INFO [05-07|11:43:44] synchronizing with peer                  peer id=3                                                                                                                                hash=0c36db…462f32
WARN [05-07|11:43:44] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [05-07|11:43:44] failed to synchronize with peer          peer id=fd9fb25f14f5abf2fd98c79a6c516b44d48a09a44ffc3cfaf02c3e8da151b638afb9575d2e13cbd2b436fa18881938747002a30729de7a80a415e867b2e1f683
INFO [05-07|11:43:44] synchronizing with peer                  peer id=9                                                                                                                                hash=0c36db…462f32
WARN [05-07|11:43:44] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [05-07|11:43:44] failed to synchronize with peer          peer id=08b16edfa2d40d066b4ffee7a91541f441d0c254bba69f5d0c3809f6a27f78e9a7165b28e6084d791adca3cf9cafc2d5e289966c6254c21262360739d5cee7a5
INFO [05-07|11:43:45] synchronizing with peer                  peer id=1                                                                                                                                hash=0c36db…462f32
WARN [05-07|11:43:45] Synchronisation failed, retrying         err="peer is unknown or unhealthy"
INFO [05-07|11:43:45] failed to synchronize with peer          peer id=e9468955dc02cee181699a57d7def9df46a2d087e3fc12a96a90fb28cfd17d577e0b1bd56ab7969ef72e37022a134f51b98025f570a1b741a1b93ed88c8e7fc4
INFO [05-07|11:43:45] synchronizing with peer                  peer id=4                                                                                                                                hash=0c36db…462f32

Please let me know if I can provide any additional information to assist with debugging, assuming this is not the expected behavior.

SatpalSandhu61 commented 5 years ago

This could be a node misconfiguration - see issue # 642. If you are updating the static-nodes.json file, then it is possibly the same as issue # 642, which was fixed in v2.2.3.

Note that the docs here describe the correct steps for adding a node: https://docs.goquorum.com/en/latest/Consensus/raft/#initial-configuration-and-enacting-membership-changes

I'd suggest you check your node config. It would also be worthwhile upgrading to v2.2.3.

prasad1247 commented 5 years ago

Thanks for reply, I have gone through issue #642 and I think its a different issue.

We are using static-nodes.json for creating the first node only. After network is created, to add new node we call raft.addPeer to this node and use returned raft id to start new node using flag --raftjoinexisting. (same as per above link)

this new node successfully connected to other nodes and starts syncing but after some time it crashed,

Few more lines from logs 

raft2019/05/07 11:22:34 INFO: 14 became follower at term 23027
raft2019/05/07 11:22:34 INFO: raft.node: 14 elected leader a at term 23027
INFO [05-07|11:22:34] QUORUM-CHECKPOINT                        name=BECAME-VERIFIER
2019-05-07 11:22:34.165013 E | rafthttp: failed to find member 5 in cluster 1000
2019-05-07 11:22:34.166685 E | rafthttp: failed to find member 7 in cluster 1000
2019-05-07 11:22:34.339305 E | rafthttp: failed to find member 1 in cluster 1000
2019-05-07 11:22:34.339428 E | rafthttp: failed to find member 1 in cluster 1000
raft2019/05/07 11:22:34 INFO: 14 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 9954, term: 23027]
raft2019/05/07 11:22:34 INFO: log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 9954, term: 23027]
raft2019/05/07 11:22:34 INFO: 14 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 9954, term: 23027]
raft2019/05/07 11:22:34 INFO: log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 9954, term: 23027]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 1 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 2 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 3 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 4 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 5 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 6 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 7 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 8 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 9 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of a [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of b [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 13 [next = 9955, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 restored progress of 14 [next = 9955, match = 9954, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
raft2019/05/07 11:22:34 INFO: 14 [commit: 9954] restored snapshot [index: 9954, term: 23027]
INFO [05-07|11:22:34] applying snapshot to raft storage 
INFO [05-07|11:22:34] updating cluster membership per raft snapshot 
INFO [05-07|11:22:34] adding new raft peer                     raft id=1
2019-05-07 11:22:34.346905 I | rafthttp: starting peer 1...
2019-05-07 11:22:34.346966 I | rafthttp: started HTTP pipelining with peer 1
DEBUG[05-07|11:22:34] Adding static node                       node="enode://e9468955dc02cee181699a57d7def9df46a2d087e3fc12a96a90fb28cfd17d577e0b1bd56ab7969ef72e37022a134f51b98025f570a1b741a1b93ed88c8e7fc4@34.192.92.70:22001?discport=0"
TRACE[05-07|11:22:34] New dial task                            task="staticdial e9468955dc02cee1 34.192.92.70:22001"
2019-05-07 11:22:34.348203 I | rafthttp: started streaming with peer 1 (writer)
2019-05-07 11:22:34.349259 I | rafthttp: started streaming with peer 1 (writer)
2019-05-07 11:22:34.350065 I | rafthttp: started peer 1
2019-05-07 11:22:34.350085 I | rafthttp: added peer 1
INFO [05-07|11:22:34] adding new raft peer                     raft id=2
2019-05-07 11:22:34.350111 E | rafthttp: failed to find member 2 in cluster 1000
2019-05-07 11:22:34.350144 I | rafthttp: started streaming with peer 1 (stream Message reader)
2019-05-07 11:22:34.350210 I | rafthttp: starting peer 2...
2019-05-07 11:22:34.350233 I | rafthttp: started HTTP pipelining with peer 2
2019-05-07 11:22:34.350309 I | rafthttp: started streaming with peer 1 (stream MsgApp v2 reader)
.
.
.

DEBUG[05-07|11:22:43] Trie cache stats after commit            misses=1429 unloads=139
DEBUG[05-07|11:22:43] Trie cache stats after commit            misses=1429 unloads=139
DEBUG[05-07|11:22:43] Inserted new block                       number=1840 hash=3afb82…db5ea0 uncles=0   txs=1   gas=0       elapsed=949.933µs
DEBUG[05-07|11:22:43] Trie cache stats after commit            misses=1429 unloads=139
DEBUG[05-07|11:22:43] Trie cache stats after commit            misses=1429 unloads=139
DEBUG[05-07|11:22:43] Inserted new block                       number=1841 hash=e1ef05…b19e24 uncles=0   txs=3   gas=0       elapsed=2.297ms
2019-05-07 11:22:44.454503 W | rafthttp: health check for peer 13 could not connect: dial tcp 3.215.251.193:22003: connect: connection refused
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0x93aef5]

goroutine 102 [running]:
github.com/ethereum/go-ethereum/private/constellation.(*Client).ReceivePayload(0xc4201a46a0, 0xc43a1c0700, 0x40, 0x40, 0x0, 0x0, 0x0, 0x0, 0x0)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/private/constellation/node.go:112 +0x135
github.com/ethereum/go-ethereum/private/constellation.(*Constellation).Receive(0xc42003cac0, 0xc43a1c0700, 0x40, 0x40, 0xc442385d40, 0x1, 0x0, 0x0, 0x0)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/private/constellation/constellation.go:38 +0x13e
github.com/ethereum/go-ethereum/core.(*StateTransition).TransitionDb(0xc439ac6e70, 0x116b0c0, 0xc442385d40, 0xc441978a40, 0xc439ac6e70, 0xc43c788e98, 0xc442385d40, 0xc442385d40, 0xf72280)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/core/state_transition.go:235 +0xd28
github.com/ethereum/go-ethereum/core.ApplyMessage(0xc43bab8000, 0x116b0c0, 0xc442385d40, 0xc441978a40, 0x993f14bfc51cf5fa, 0xa6bda07f, 0xc441978bc0, 0x0, 0x0, 0x0, ...)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/core/state_transition.go:138 +0x5b
github.com/ethereum/go-ethereum/core.ApplyTransaction(0xc420130000, 0xc420266000, 0x0, 0xc441978a40, 0xc43af5be00, 0xc43af5bef0, 0xc44197e6c0, 0xc43a1b9b00, 0xc441978980, 0x0, ...)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/core/state_processor.go:121 +0x4e4
github.com/ethereum/go-ethereum/core.(*StateProcessor).Process(0xc42021e4a0, 0xc43e99f0e0, 0xc43af5be00, 0xc43af5bef0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/core/state_processor.go:78 +0x69a
github.com/ethereum/go-ethereum/core.(*BlockChain).insertChain(0xc420266000, 0xc43e5d0000, 0x800, 0x800, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/core/blockchain.go:1026 +0x1d69
github.com/ethereum/go-ethereum/core.(*BlockChain).InsertChain(0xc420266000, 0xc43e5d0000, 0x800, 0x800, 0x19dcae0, 0x0, 0x0)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/core/blockchain.go:885 +0x67
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).importBlockResults(0xc4201641a0, 0xc43dcd2000, 0x1bf5, 0x1bf5, 0xc42003df70, 0xde41a0)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:1366 +0x163
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).processFullSyncContent(0xc4201641a0, 0xc42001a0f0, 0xb8e46d28cedb360c)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:1341 +0x74
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).synchronise(0xc4201641a0, 0xc420c93610, 0x10, 0xb8e46d28cedb360c, 0x47b7b46d3e13093d, 0x8b5c14acc3de1dff, 0x322f4610f31269a9, 0xc42021e8e0, 0x64, 0x0, ...)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:400 +0x412
github.com/ethereum/go-ethereum/eth/downloader.(*Downloader).Synchronise(0xc4201641a0, 0xc420c93610, 0x10, 0xb8e46d28cedb360c, 0x47b7b46d3e13093d, 0x8b5c14acc3de1dff, 0x322f4610f31269a9, 0xc42021e8e0, 0x64, 0x80, ...)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/eth/downloader/downloader.go:318 +0x94
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).syncBlockchainUntil(0xc420156000, 0xb8e46d28cedb360c, 0x47b7b46d3e13093d, 0x8b5c14acc3de1dff, 0x322f4610f31269a9)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/snapshot.go:304 +0x575
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).applyRaftSnapshot(0xc420156000, 0xc4200cc480, 0x43f, 0x480, 0xc42009a900, 0xd, 0x10, 0x0, 0x0, 0x0, ...)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/snapshot.go:274 +0x360
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).eventLoop(0xc420156000)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/handler.go:685 +0x11b8
created by github.com/ethereum/go-ethereum/raft.(*ProtocolManager).startRaft
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/handler.go:482 +0x704

Crashed first time at block 1841, After Restarting Node, It completed syncing from block 1842 but again failed with different error 

.
.
.                                                                                                                                                                                                                                                                        hps=1045.311 bps=939.806  rps=0.000 sps=0.000 miss=0 rtt=9.587901272s
TRACE[05-07|11:34:21] Delivered new batch of data              peer=fd9fb25f14f5abf2                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             type=bodies   count=98:98
DEBUG[05-07|11:34:21] Data fetching completed                  type=bodies
DEBUG[05-07|11:34:21] Block body download terminated           err=nil
INFO [05-07|11:34:21] Synchronisation terminated               duration=452.086383ms
DEBUG[05-07|11:34:21] Inserting downloaded chain               items=5316 firstnum=1842 firsthash=429d4e…38d02b lastnum=3889 lasthash=b8a19b…82b024
TRACE[05-07|11:34:21] Requiring new ethash cache               epoch=0
TRACE[05-07|11:34:21] Requiring new future ethash cache        epoch=1
DEBUG[05-07|11:34:21] Loaded old ethash cache from disk        epoch=0
DEBUG[05-07|11:34:21] Loaded old ethash cache from disk        epoch=1
2019-05-07 11:34:21.570934 I | rafthttp: established a TCP streaming connection with peer a (stream Message reader)
DEBUG[05-07|11:34:21] Trie cache stats after commit            misses=25 unloads=0
DEBUG[05-07|11:34:21] Trie cache stats after commit            misses=25 unloads=0
DEBUG[05-07|11:34:21] Inserted new block                       number=1842 hash=429d4e…38d02b uncles=0   txs=2   gas=0 elapsed=318.428ms
DEBUG[05-07|11:34:21] Trie cache stats after commit            misses=25 unloads=0
DEBUG[05-07|11:34:21] Trie cache stats after commit            misses=25 unloads=0
DEBUG[05-07|11:34:21] Inserted new block                       number=1843 hash=2347e7…7dd1d9 uncles=0   txs=1   gas=0 elapsed=20.330ms
DEBUG[05-07|11:34:21] Trie cache stats after commit            misses=26 unloads=0
DEBUG[05-07|11:34:21] Trie cache stats after commit            misses=26 unloads=0
DEBUG[05-07|11:34:21] Inserted new block                       number=1844 hash=37e5bc…3539d8 uncles=0   txs=1   gas=0 elapsed=20.422ms
.   
.
.   
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=268
DEBUG[05-07|11:34:37] Inserted new block                       number=7141 hash=1b20ff…0e5291 uncles=0   txs=1    gas=0      elapsed=1.006ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=268
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=268
DEBUG[05-07|11:34:37] Inserted new block                       number=7142 hash=91bd49…dc6bf4 uncles=0   txs=1    gas=0      elapsed=1.305ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=268
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=268
DEBUG[05-07|11:34:37] Inserted new block                       number=7143 hash=8bf3f9…95c13b uncles=0   txs=1    gas=0      elapsed=1.036ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=268
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7144 hash=7d8b4a…90a529 uncles=0   txs=1    gas=0      elapsed=982.745µs
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7145 hash=ab716e…7d20ab uncles=0   txs=2    gas=0      elapsed=1.580ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7146 hash=f0816b…1d04d0 uncles=0   txs=2    gas=0      elapsed=1.785ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7147 hash=bd1454…8585c6 uncles=0   txs=1    gas=0      elapsed=1.254ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7148 hash=229ce6…f1a13a uncles=0   txs=1    gas=0      elapsed=1.142ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7149 hash=52fd60…7a54bb uncles=0   txs=1    gas=0      elapsed=1.056ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7150 hash=37b508…c048cd uncles=0   txs=1    gas=0      elapsed=1.060ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7151 hash=be7d91…aff61e uncles=0   txs=1    gas=0      elapsed=1.187ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7152 hash=5fb0aa…77a38a uncles=0   txs=1    gas=0      elapsed=1.039ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7153 hash=ad7d13…039290 uncles=0   txs=1    gas=0      elapsed=1.422ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7154 hash=396720…df609a uncles=0   txs=1    gas=0      elapsed=1.136ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7155 hash=f10e1a…29e000 uncles=0   txs=1    gas=0      elapsed=993.093µs
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7156 hash=f94b71…036150 uncles=0   txs=2    gas=0      elapsed=1.794ms
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Trie cache stats after commit            misses=1724 unloads=270
DEBUG[05-07|11:34:37] Inserted new block                       number=7157 hash=0c36db…462f32 uncles=0   txs=2    gas=0      elapsed=1.613ms
INFO [05-07|11:34:37] Imported new chain segment               blocks=1220 txs=1587 mgas=2.099 elapsed=3.635s    mgasps=0.577 number=7157 hash=0c36db…462f32
WARN [05-07|11:34:37] Skipping deep transaction reorg          depth=1220
DEBUG[05-07|11:34:37] Reinjecting stale transactions           count=0
INFO [05-07|11:34:37] QUORUM-CHECKPOINT                        name=TX-ACCEPTED                                      tx=0x3695697980c9e1e6e71f7a6954a224619f866c87a4485e35a595ae3de7c628be
INFO [05-07|11:34:37] QUORUM-CHECKPOINT                        name=TX-ACCEPTED                                      tx=0x9419bb194c0933630fd6f8837ac71047e79c49551a83e6febdad02e439988c61
INFO [05-07|11:34:37] QUORUM-CHECKPOINT                        name=TX-ACCEPTED                                      tx=0xd8af3cacc81c4e6d9c48a49ee88cba972637fc70bb7f4f41f1f5d8b37e8e3fec
.
.
.
tx=0x2a6827c6e438b52cf63a2a3a3849e07f8b048cd9ca1e5ece5923c610f4e4498e
INFO [05-07|11:34:37] QUORUM-CHECKPOINT                        name=TX-ACCEPTED                                      tx=0x48df9608d31f6c3a13ee76939d29cea00471a4cdc8fb445f65ccb0a6a2c4869c
INFO [05-07|11:34:37] Successfully extended chain              hash=0c36db…462f32
INFO [05-07|11:34:37] replaying WAL 
INFO [05-07|11:34:37] loading WAL                              term=0 index=0
INFO [05-07|11:34:37] startRaft                                raft ID=20
INFO [05-07|11:34:37] remounting an existing raft log; connecting to peers. 
raft2019/05/07 11:34:37 INFO: 14 became follower at term 23027
raft2019/05/07 11:34:37 INFO: newRaft 14 [peers: [1,2,3,4,5,6,7,8,9,a,b,13,14], term: 23027, commit: 9954, applied: 9954, lastindex: 9954, lastterm: 23027]
DEBUG[05-07|11:34:37] InProc registered *node.PrivateAdminAPI under 'admin' 
DEBUG[05-07|11:34:37] InProc registered *node.PublicAdminAPI under 'admin' 
2019-05-07 11:34:37.954891 I | rafthttp: established a TCP streaming connection with peer a (stream Message writer)
2019-05-07 11:34:37.955202 I | rafthttp: established a TCP streaming connection with peer a (stream MsgApp v2 writer)
raft2019/05/07 11:34:37 INFO: raft.node: 14 elected leader a at term 23027
INFO [05-07|11:34:37] start snapshot                           applied index=0 last snapshot index=9954
panic: requested index is older than the existing snapshot

goroutine 886 [running]:
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).triggerSnapshot(0xc420154b00, 0x0)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/snapshot.go:86 +0x44b
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).maybeTriggerSnapshot(0xc420154b00)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/snapshot.go:176 +0x82
github.com/ethereum/go-ethereum/raft.(*ProtocolManager).eventLoop(0xc420154b00)
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/handler.go:791 +0xd2c
created by github.com/ethereum/go-ethereum/raft.(*ProtocolManager).startRaft
    /quorum/build/_workspace/src/github.com/ethereum/go-ethereum/raft/handler.go:482 +0x704
jbhurat commented 5 years ago

Hi @prasad1247, I believe the issue you are seeing is a side effect of the earlier panic which happened before the node crashed. The panic issue was fixed a while back in #491. I see that you are using Quorum v2.0.2 and the fix went in Quorum v2.1.0, is it possible to test against Quorum v.2.1.0 or later

prasad1247 commented 5 years ago

Hi @jbhurat, Thanks for reply. I guess this is the issue because I tried 4 times to create the new node but each time received the #491 issue and also we have 11 nodes and around 7000 blocks to sync.

Will try with latest version of Quorum

jbhurat commented 5 years ago

Hi @prasad1247, did you get a chance to test this with the latest version of quorum

jbhurat commented 5 years ago

Hi @prasad1247, please test this against the latest version of quorum and let us know if you still see the issue.

abhib3012 commented 3 years ago

Hi @jbhurat, Thanks for reply. I guess this is the issue because I tried 4 times to create the new node but each time received the #491 issue and also we have 11 nodes and around 7000 blocks to sync.

Will try with latest version of Quorum

Hello,

Not able to find a simple method/straightforward command to upgrade GoQuorum. Please help.

Thanks.

jbhurat commented 3 years ago

Hi @abhib3012, please do not comment on closed issues. Please open a new issue or reach out to us on slack.

abhib3012 commented 3 years ago

Noted. Thanks.