I have a private network running the GoQuorum client from Consensys (Version: 1.10.3-stable).
The network runs within a K8s cluster.
There used to be 6 validators, a bootnode and and 2 rpc nodes.
As is typical for goquorum, there are no transaction fees involved, gasPrice is 0.
4 validators are the minimum required for qbft to work. The network used to work well, with automining enabled (1 block per 60 seconds).
The only anomaly was the presence of 3 queued transactions which had been there from the start, probably due to my first experiments on the blockchain.
At some point one of the validators had a crash, the pod restarted and the network stopped adding new blocks.
I began restarting the validators one by one (by deleting the K8s pods, so once again ungraceful shutdowns) and it seemed the peers weren't able to find any other. Every validator would only connect to the bootnode. Once restarted, every validator seemed to be syncing the chaindata with the bootnode, starting from genesis, then remained looking for peers.
I changed configuration so that peers find each other statically. (put static-nodes.json in every validator's data directory). Also, I only kept 4 of the validators. Among the 2 validators I eliminated is also the one that had had the initial ungraceful shutdown.
Now the 4 validators are all able to find each other and also the rpc node. So every peer has 4 peers.
Still, no new blocks are added.
Just as before, all the validators seem to have their chaindata in order (they sync up til the latest block - 359732). Something seems to be wrong with the block proposal though:
...
INFO [07-05|15:52:28.009] start QBFT
INFO [07-05|15:52:28.009] BFT: activate QBFT
INFO [07-05|15:52:28.009] QBFT: start address=0xDe3D6071e672369b8eb05E7f598442d15160bf38
INFO [07-05|15:52:28.009] QBFT: initialize new round address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 old.round=-1 old.seq=0 target.round=0 lastProposal.number=359,732 lastProposal.hash=981f9f..d8bf70
DEBUG[07-05|15:52:28.009] QBFT: start at the initial round address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 old.round=-1 old.seq=0 target.round=0 lastProposal.number=359,732 lastProposal.hash=981f9f..d8bf70
DEBUG[07-05|15:52:28.009] QBFT: lookup for pending block proposal requests address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=0 current.sequence=359,733 state="Accept request"
INFO [07-05|15:52:28.009] QBFT: start new round address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 old.round=-1 old.seq=0 next.round=0 next.seq=359,733 next.proposer=0xB461A79AF12F0CAC3A99c3dA8c350f75C21f8dA3 next.valSet="[0x51D24D4d1ec651aaDeF92a3Ee5CD72bD71Cb5950 0x5A7F9d60c7f05e9c8a1EBB9262470686aC2fFcA0 0x6617d0162F4E4374A31593cd515725B8e42f73bb 0x8256C48FbDc67811ad7c0C864B11E3EDb5e9Bd3A 0xB461A79AF12F0CAC3A99c3dA8c350f75C21f8dA3 0xC10980120a086F19Ddc7ca27678E563d10f97A24 0xDe01CC1713D7f0Bda9Ec63C6A0bb6ca9fA51DBAd 0xDe3D6071e672369b8eb05E7f598442d15160bf38]" next.size=8 next.IsProposer=false
DEBUG[07-05|15:52:28.010] Adding p2p peer peercount=1 id=bc2390ffc03d12bf conn=staticdial addr=172.20.254.45:30303 name=Geth/v1.10.3-stable-...
DEBUG[07-05|15:52:28.010] Account Extra Data root hash=000000..000000
DEBUG[07-05|15:52:28.010] Account Extra Data root hash=000000..000000
INFO [07-05|15:52:28.010] Commit new mining work number=359,733 sealhash=ae31db..bb0436 uncles=0 txs=0 gas=0 fees=0 elapsed="493.015µs"
DEBUG[07-05|15:52:28.012] Adding p2p peer peercount=2 id=a489a2f1c08e1dc6 conn=staticdial addr=172.20.249.87:30303 name=Geth/v1.10.3-stable-...
DEBUG[07-05|15:52:28.013] Ethereum peer connected id=bc2390ffc03d12bf conn=staticdial name=Geth/v1.10.3-stable-...
WARN [07-05|15:52:28.013] full p2p peer id=bc2390ffc03d12bfc34b4fb68256c48fbdc67811ad7c0c864b11e3edb5e9bd3a ethPeer="Peer bc2390ffc03d12bf 172.20.254.45:30303"
DEBUG[07-05|15:52:28.014] consensus subprotocol retrieved eth peer from peerset id=bc2390ffc03d12bf conn=staticdial ethPeer.id=bc2390ffc03d12bfc34b4fb68256c48fbdc67811ad7c0c864b11e3edb5e9bd3a ProtoName=istanbul
INFO [07-05|15:52:28.014] QBFT: handle block proposal request address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=0 current.sequence=359,733 state="Accept request"
INFO [07-05|15:52:28.014] EmptyBlockPeriod detected adding delay to request EmptyBlockPeriod=60 BlockTime=1,688,572,348
DEBUG[07-05|15:52:28.015] Ethereum peer connected id=a489a2f1c08e1dc6 conn=staticdial name=Geth/v1.10.3-stable-...
DEBUG[07-05|15:52:28.015] Relaxed downloader QoS values rtt=20s confidence=0.500 ttl=1m0s
WARN [07-05|15:52:28.015] full p2p peer id=a489a2f1c08e1dc63f14273b51d24d4d1ec651aadef92a3ee5
cd72bd71cb5950 ethPeer="Peer a489a2f1c08e1dc6 172.20.249.87:30303"
DEBUG[07-05|15:52:28.015] consensus subprotocol retrieved eth peer from peerset id=a489a2f1c08e1dc6 conn=staticdial ethPeer.id=a489a2f1c08e1dc63f14273b51d24d4d1ec651aadef92a3ee5cd72bd71cb5950 ProtoName=istanbul
DEBUG[07-05|15:52:28.016] Adding p2p peer peercount=3 id=0074d629f91d85a7 conn=staticdial addr=172.20.61.13:30303 name=Geth/v1.10.3-stable-...
DEBUG[07-05|15:52:28.017] Ethereum peer connected id=0074d629f91d85a7 conn=staticdial name=Geth/v1.10.3-stable-...
DEBUG[07-05|15:52:28.018] Relaxed downloader QoS values rtt=20s confidence=0.333 ttl=1m0s
WARN [07-05|15:52:28.018] full p2p peer id=0074d629f91d85a7cd081584b461a79af12f0cac3a99c3da8c350f75c21f8da3 ethPeer="Peer 0074d629f91d85a7 172.20.61.13:30303"
DEBUG[07-05|15:52:28.018] consensus subprotocol retrieved eth peer from peerset id=0074d629f91d85a7 conn=staticdial ethPeer.id=0074d629f91d85a7cd081584b461a79af12f0cac3a99c3da8c350f75c21f8da3 ProtoName=istanbul
DEBUG[07-05|15:52:28.020] Adding p2p peer peercount=4 id=34fa68ba0e4e6aff conn=staticdial addr=172.20.142.183:30303 name=Geth/v1.10.3-stable-...
DEBUG[07-05|15:52:28.022] Ethereum peer connected id=34fa68ba0e4e6aff conn=staticdial name=Geth/v1.10.3-stable-...
DEBUG[07-05|15:52:28.022] Relaxed downloader QoS values rtt=20s confidence=0.250 ttl=1m0s
WARN [07-05|15:52:28.022] full p2p peer id=34fa68ba0e4e6aff4fd2bdc1f4800578539cf60abe69430f40f91092fd749a7f ethPeer="Peer 34fa68ba0e4e6aff 172.20.142.183:30303"
DEBUG[07-05|15:52:28.022] consensus subprotocol retrieved eth peer from peerset id=34fa68ba0e4e6aff conn=staticdial ethPeer.id=34fa68ba0e4e6aff4fd2bdc1f4800578539cf60abe69430f40f91092fd749a7f ProtoName=istanbul
DEBUG[07-05|15:52:28.514] Fetching batch of transactions id=bc2390ffc03d12bf conn=staticdial count=1
DEBUG[07-05|15:52:28.516] Transaction broadcast txs=1 announce packs=0 announced hashes=0 tx packs=2 broadcast txs=2
DEBUG[07-05|15:52:30.104] Couldn't add port mapping proto=tcp extport=30303 intport=30303 interface="UPnP or NAT-PMP" err="no UPnP or NAT-PMP router discovered"
DEBUG[07-05|15:52:31.010] Account Extra Data root hash=000000..000000
DEBUG[07-05|15:52:31.010] Account Extra Data root hash=000000..000000
WARN [07-05|15:52:31.073] WARNING: The attribute config.maxCodeSizeConfig is deprecated and will be removed in the future, please use config.transitions.contractsizelimit on genesis file
INFO [07-05|15:52:31.087] QUORUM-CHECKPOINT name=TX-COMPLETED tx=0xcc7a7f6291d97d2a4e658c792fd9335a643fd9b58cdacf24777fcdd139161203 time=76.742968ms
INFO [07-05|15:52:31.088] Commit new mining work number=359,733 sealhash=c24f4e..264f61 uncles=0 txs=1 gas=2,425,614 fees=0 elapsed=77.676ms
INFO [07-05|15:52:31.088] QBFT: handle block proposal request address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=0 current.sequence=359,733 state="Accept request"
DEBUG[07-05|15:52:35.964] Transaction pool status report executable=1 queued=0 stales=0
WARN [07-05|15:52:41.088] QBFT: TIMER CHANGING ROUND address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=0 current.sequence=359,733 state="Accept request" pr=<nil>
INFO [07-05|15:52:41.088] QBFT: initialize new round address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=0 current.sequence=359,733 target.round=1 lastProposal.number=359,732 lastProposal.hash=981f9f..d8bf70
DEBUG[07-05|15:52:41.088] QBFT: lookup for pending block proposal requests address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=1 current.sequence=359,733 state="Accept request"
INFO [07-05|15:52:41.088] QBFT: start new round address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 old.round=0 old.sequence=359,733 old.state="Accept request" old.proposer=0xB461A79AF12F0CAC3A99c3dA8c350f75C21f8dA3 next.round=1 next.seq=359,733 next.proposer=0xC10980120a086F19Ddc7ca27678E563d10f97A24 next.valSet="[0x51D24D4d1ec651aaDeF92a3Ee5CD72bD71Cb5950 0x5A7F9d60c7f05e9c8a1EBB9262470686aC2fFcA0 0x6617d0162F4E4374A31593cd515725B8e42f73bb 0x8256C48FbDc67811ad7c0C864B11E3EDb5e9Bd3A 0xB461A79AF12F0CAC3A99c3dA8c350f75C21f8dA3 0xC10980120a086F19Ddc7ca27678E563d10f97A24 0xDe01CC1713D7f0Bda9Ec63C6A0bb6ca9fA51DBAd 0xDe3D6071e672369b8eb05E7f598442d15160bf38]" next.size=8 next.IsProposer=false
WARN [07-05|15:52:41.088] QBFT: TIMER CHANGED ROUND address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=0 current.sequence=359,733 state="Accept request" pr=<nil>
INFO [07-05|15:52:41.089] QBFT: broadcast ROUND-CHANGE message address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=1 current.sequence=359,733 state="Accept request" msg.code=21 msg.source=0x0000000000000000000000000000000000000000 msg.round=1 msg.sequence=359,733 payload=0xf84ef84ac683057d3501c0b841f39513474df12e24c2b7239be85656d51424f390c6fb421ff0cf3efdfd4487a457dcb8d3f395be60bd48a6ebdaa21b93b6447c6b69ba3eef76a09ce47620015c01c0c0
INFO [07-05|15:52:41.089] QBFT: handle ROUND-CHANGE message address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=1 current.sequence=359,733 state="Accept request" msg.code=21 msg.source=0xDe3D6071e672369b8eb05E7f598442d15160bf38 msg.round=1 msg.sequence=359,733 higherRoundChanges.count=0 currentRoundChanges.count=0
DEBUG[07-05|15:52:41.089] QBFT: accepted ROUND-CHANGE messages address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=1 current.sequence=359,733 state="Accept request" msg.code=21 msg.source=0xDe3D6071e672369b8eb05E7f598442d15160bf38 msg.round=1 msg.sequence=359,733 higherRoundChanges.count=0 currentRoundChanges.count=1
DEBUG[07-05|15:52:47.964] Recalculated downloader QoS values rtt=20s confidence=0.625 ttl=1m0s
WARN [07-05|15:53:01.089] QBFT: TIMER CHANGING ROUND address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=1 current.sequence=359,733 state="Accept request" pr=<nil>
INFO [07-05|15:53:01.089] QBFT: initialize new round
...
and so on
.. after a while it keeps logging this ..
DEBUG[07-05|16:14:26.385] Current full block not old enough number=359,732 hash=981f9f..d8bf70 delay=3,162,240
DEBUG[07-05|16:14:28.005] Recalculated downloader QoS values rtt=20s confidence=1.000 ttl=1m0s
:
or NAT-PMP" err="no UPnP or NAT-PMP router discovered"
DEBUG[07-05|16:12:28.001] Recalculated downloader QoS values rtt=20s confidence=1.000 ttl=1m0s
DEBUG[07-05|16:12:48.001] Recalculated downloader QoS values rtt=20s confidence=1.000 ttl=1m0s
DEBUG[07-05|16:13:08.002] Recalculated downloader QoS values rtt=20s confidence=1.000 ttl=1m0s
DEBUG[07-05|16:13:26.384] Current full block not old enough number=359,732 hash=981f9f..d8bf70 delay=3,162,240
DEBUG[07-05|16:13:28.003] Recalculated downloader QoS values rtt=20s confidence=1.000 ttl=1m0s
WARN [07-05|16:13:41.093] QBFT: TIMER CHANGING ROUND address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=6 current.sequence=359,733 state="Accept request" pr=<nil>
INFO [07-05|16:13:41.093] QBFT: initialize new round address=0xDe3D6071e672369b8eb05E7f598442d15160bf38 current.round=6 current.sequence=359,733 target.round=7 lastProposal.number=359,732 lastProposal.hash=981f9f..d8bf70
For some of the validators I also see output like
DEBUG[07-06|03:41:11.797] consensus message was handled by consensus engine id=a489a2f1c08e1dc6 conn=inbound msg=21 quorumConsensusProtocolName=istanbul err=nil
Can you figure out what's wrong here?
Can this be a port mapping issue? (see the error message "no UPnP or NAT-PMP router discovered")
Can there be anything corrupted within the chaindata if the participation in new block proposal rounds is effectively attempted?
During all this time, the rpc node can't process the txs in its mempool...
...
WARN [07-05|17:23:26.165] Served eth_sendRawTransaction conn=10.50.212.243:46248 reqid=72170 t="542.923µs" err="replacement transaction underpriced"
WARN [07-05|17:23:26.420] Served eth_sendRawTransaction conn=10.50.212.243:41234 reqid=476377 t="511.412µs" err="replacement transaction underpriced"
...
