Skip to content

Conversation

@chenquanyu
Copy link
Collaborator

@chenquanyu chenquanyu commented Jan 9, 2024

Close #65 Implement block verification callback.

@nicolegys
Copy link
Collaborator

CN verify block failed and keep CV after there comes a tx. (4cn scenario)
1704797054660

@chenquanyu chenquanyu closed this Jan 12, 2024
@chenquanyu chenquanyu reopened this Jan 12, 2024
@chenquanyu
Copy link
Collaborator Author

chenquanyu commented Jan 12, 2024

CN verify block failed and keep CV after there comes a tx. (4cn scenario) 1704797054660

This error VerifyBlock failed: invalid merkle root is caused by different coinbase address when FinalizeAndAssemble and VerifyBlock. The FinalizeAndAssemble reads coinbase from miner.etherbase and VerifyBlock reads coinbase from Engine.Author, current the Engine.Author is empty when VerifyBlock. It should be a part of #51 (second bullet-point from this issue). I have added some logs for it:

image
image

AnnaShaleva added a commit that referenced this pull request Jan 12, 2024
To be able to properly verify unsigned block after PrepareRequest receival
in WithVerifyBlock dBFT callback we need to ensure that (*DBFT).Author can
handle such unsugned block. Starting from the previous commit, we define
block's Coinbase as the Primary address for the dBFT round when the block
was accepted. And thus, return proper block author for proper verification.

The problem itself is described in #87 (comment).
Also ref. #51.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
AnnaShaleva added a commit that referenced this pull request Jan 12, 2024
To be able to properly verify unsigned block after PrepareRequest receival
in WithVerifyBlock dBFT callback we need to ensure that (*DBFT).Author can
handle such unsugned block. Starting from the previous commit, we define
block's Coinbase as the Primary address for the dBFT round when the block
was accepted. And thus, return proper block author for proper verification.

The problem itself is described in #87 (comment).
Also ref. #51.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@AnnaShaleva
Copy link
Member

This PR roughly depends on #93, thus waiting for #93 to settle.

@AnnaShaleva AnnaShaleva self-requested a review January 12, 2024 18:49
AnnaShaleva added a commit that referenced this pull request Jan 15, 2024
To be able to properly verify unsigned block after PrepareRequest receival
in WithVerifyBlock dBFT callback we need to ensure that (*DBFT).Author can
handle such unsugned block. Starting from the previous commit, we define
block's Coinbase as the Primary address for the dBFT round when the block
was accepted. And thus, return proper block author for proper verification.

The problem itself is described in #87 (comment).
Also ref. #51.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
AnnaShaleva added a commit that referenced this pull request Jan 17, 2024
To be able to properly verify unsigned block after PrepareRequest receival
in WithVerifyBlock dBFT callback we need to ensure that (*DBFT).Author can
handle such unsugned block. Starting from the previous commit, we define
block's Coinbase as the Primary address for the dBFT round when the block
was accepted. And thus, return proper block author for proper verification.

The problem itself is described in #87 (comment).
Also ref. #51.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
AnnaShaleva added a commit that referenced this pull request Jan 18, 2024
To be able to properly verify unsigned block after PrepareRequest receival
in WithVerifyBlock dBFT callback we need to ensure that (*DBFT).Author can
handle such unsugned block. Starting from the previous commit, we define
block's Coinbase as the Primary address for the dBFT round when the block
was accepted. And thus, return proper block author for proper verification.

The problem itself is described in #87 (comment).
Also ref. #51.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@nicolegys
Copy link
Collaborator

nicolegys commented Jan 24, 2024

CN3 failed after running for several days, may be an issue from some other place but found by this PR.

4cn-CN1

INFO [01-23|20:16:02.509] Sealing proposal updated                 number=57146 sealhash=f62584..a89036 "parent hash"=795321..466b76 txs=0
2024-01-23T20:16:02.509Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57146, "view": 0, "index": 3, "role": "Backup"}
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "28.994640724s"}
DEBUG[01-23|20:16:02.509] received message                         from=0 type=Commit
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.509] received message                         from=2 type=Commit
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.509] received message                         from=2 type=Commit
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.509] received message                         from=0 type=Commit
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.509] received message                         from=2 type=Commit
2024-01-23T20:16:02.509Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.510Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
INFO [01-23|20:16:05.037] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:08.409] ENR request failed                       id=8047e06fad43a846 addr=127.0.0.1:30305 err="invalid IP in response record: invalid IP"
DEBUG[01-23|20:16:08.409] Revalidated node                         b=14 id=8047e06fad43a846 checks=1
INFO [01-23|20:16:15.054] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:15.926] Revalidated node                         b=16 id=6598eeabf8cd7462 checks=1
DEBUG[01-23|20:16:16.497] received message                         from=2 type=PrepareRequest
2024-01-23T20:16:16.497Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 2, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.498Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:325     received empty PrepareRequest
2024-01-23T20:16:16.498Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:333     received PrepareRequest {"validator": 2, "tx": 0}
2024-01-23T20:16:16.498Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:106     sending PrepareResponse {"height": 57146, "view": 0}
2024-01-23T20:16:16.498Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "PrepareResponse", "height": 57146, "view": 0}
2024-01-23T20:16:16.498Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 2, "M": 3}
DEBUG[01-23|20:16:16.498] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:16.498Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.498Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 0}
2024-01-23T20:16:16.499Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 3, "M": 3}
2024-01-23T20:16:16.499Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:134     sending Commit  {"height": 57146, "view": 0}
2024-01-23T20:16:16.499Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "Commit", "height": 57146, "view": 0}
2024-01-23T20:16:16.499Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "15s"}
2024-01-23T20:16:16.499Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 1}
DEBUG[01-23|20:16:16.501] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:16.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:425     ignoring PrepareResponse because of view changing
DEBUG[01-23|20:16:16.506] received message                         from=0 type=Commit
2024-01-23T20:16:16.506Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.506Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 0}
2024-01-23T20:16:16.507Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 2}
DEBUG[01-23|20:16:16.507] received message                         from=0 type=Commit
2024-01-23T20:16:16.507Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
DEBUG[01-23|20:16:16.508] received message                         from=1 type=PrepareResponse
2024-01-23T20:16:16.508Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.508Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 1}
DEBUG[01-23|20:16:16.508] received message                         from=1 type=Commit
2024-01-23T20:16:16.508Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.509Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 1}
2024-01-23T20:16:16.509Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:66     approving block {"height": 57146, "hash": "0350c7ab6e3d0f351beab477e827c3bc2c8d799c9027e6e9ce10d1e99ad0cd44", "tx_count": 0, "merkle": "908bb324e43c3665e4b5de2bb73639bc96e48fda2c1ed7abe4a5a1437
fb880b7", "prev": "a4d4d0102f1479081437766dc15b64b8ff20b9536b26dc5e89cb7f4d72fd6692"}
DEBUG[01-23|20:16:16.513] Dereferenced trie from memory database   nodes=0  size=0.00B   time=735ns       gcnodes=6102 gcsize=1.45MiB    gctime=72.247702ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:16.513] Dereferenced trie from memory database   nodes=0  size=0.00B   time=372ns       gcnodes=6102 gcsize=1.45MiB    gctime=72.247956ms livenodes=1353 livesize=145.46KiB
INFO [01-23|20:16:16.513] Chain reorg detected                     number=57144 hash=dba9d3..324298 drop=1 dropfrom=795321..466b76 add=2 addfrom=1af70e..748e77
DEBUG[01-23|20:16:16.517] Queued delivered header or block         peer=dee0c36193bcfd14db29dba5914ca355b8b88d2f97c1bbba382585adf36cafd9 number=57146 hash=5c7396..49328c queued=1
DEBUG[01-23|20:16:16.518] Importing propagated block               peer=dee0c36193bcfd14db29dba5914ca355b8b88d2f97c1bbba382585adf36cafd9 number=57146 hash=5c7396..49328c
INFO [01-23|20:16:16.517] Imported new chain segment               number=57146 hash=1af70e..748e77 blocks=1 txs=0  mgas=0.000 elapsed=7.353ms     mgasps=0.000   snapdiffs=196.61KiB triedirty=282.93KiB
DEBUG[01-23|20:16:16.519] Inserted new block                       number=57146 hash=1af70e..748e77 uncles=0 txs=0  gas=0         elapsed=8.070ms     root=908bb3..b880b7
INFO [01-23|20:16:16.519] New block in the chain                   "dbft index"=57146 "chain index"=57146 hash=0x1af70e4b425c0be7025f81294d5480e3d9f9a400cc80c83df2f8e3d1a8748e77 "parent hash"=0xa4d4d0102f1479081437766dc15b64b8ff20b9536b26dc5e89cb7f4d72fd6692 primary=2 coinbase=0x121210000
0000000000000000000000000000001
INFO [01-23|20:16:16.519] Fetching latest sealing proposal         "desired number"=57147
INFO [01-23|20:16:16.521] Commit new sealing work                  number=57147 sealhash=be5aca..3c2853 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="193.354µs"
DEBUG[01-23|20:16:16.521] Reinjecting stale transactions           count=0
INFO [01-23|20:16:16.521] Imported new chain segment               number=57146 hash=5c7396..49328c blocks=1 txs=0  mgas=0.000 elapsed=1.755ms     mgasps=0.000   snapdiffs=196.61KiB triedirty=282.93KiB
DEBUG[01-23|20:16:16.521] Inserted forked block                    number=57146 hash=5c7396..49328c diff=2         elapsed=1.339ms     txs=0  gas=0         uncles=0 root=908bb3..b880b7
INFO [01-23|20:16:17.519] Sealing proposal updated                 number=57147 sealhash=be5aca..3c2853 "parent hash"=1af70e..748e77 txs=0
2024-01-23T20:16:17.519Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57147, "view": 0, "index": 3, "role": "Primary"}
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "13.990076992s"}
DEBUG[01-23|20:16:17.519] received message                         from=1 type=PrepareResponse
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 1, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:17.519] received message                         from=2 type=Commit
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:17.519] received message                         from=1 type=PrepareResponse
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 1, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:17.519] received message                         from=2 type=Commit
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:17.519] received message                         from=2 type=Commit
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:17.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:18.745] ENR request failed                       id=8047e06fad43a846 addr=127.0.0.1:30305 err="invalid IP in response record: invalid IP"
DEBUG[01-23|20:16:18.745] Revalidated node                         b=14 id=8047e06fad43a846 checks=2
INFO [01-23|20:16:25.073] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:25.221] ENR request failed                       id=8047e06fad43a846 addr=127.0.0.1:30305 err="invalid IP in response record: invalid IP"
DEBUG[01-23|20:16:25.221] Revalidated node                         b=14 id=8047e06fad43a846 checks=3
DEBUG[01-23|20:16:25.959] Current full block not old enough        number=57146 hash=1af70e..748e77 delay=90000
DEBUG[01-23|20:16:31.510] timer fired                              height=57147 view=0
2024-01-23T20:16:31.511Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:185     timeout {"height": 57147, "view": 0}
2024-01-23T20:16:31.511Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "PrepareRequest", "height": 57147, "view": 0}
2024-01-23T20:16:31.511Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:40      sending PrepareRequest  {"height": 57147, "view": 0}
2024-01-23T20:16:31.511Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "15s"}
2024-01-23T20:16:31.511Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 1, "M": 3}
DEBUG[01-23|20:16:31.516] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:31.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.516Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 0}
2024-01-23T20:16:31.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 2, "M": 3}
DEBUG[01-23|20:16:31.518] received message                         from=2 type=PrepareResponse
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 2, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.518Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 2}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 3, "M": 3}
2024-01-23T20:16:31.518Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:134     sending Commit  {"height": 57147, "view": 0}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "Commit", "height": 57147, "view": 0}
2024-01-23T20:16:31.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "15s"}
2024-01-23T20:16:31.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 1}
DEBUG[01-23|20:16:31.519] received message                         from=2 type=Commit
2024-01-23T20:16:31.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.519Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 2}
2024-01-23T20:16:31.519Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 2}
DEBUG[01-23|20:16:31.521] received message                         from=2 type=PrepareResponse
2024-01-23T20:16:31.521Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 2, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.521Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:425     ignoring PrepareResponse because of view changing
DEBUG[01-23|20:16:31.521] received message                         from=0 type=Commit
2024-01-23T20:16:31.521Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.521Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 0}
2024-01-23T20:16:31.521Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:66     approving block {"height": 57147, "hash": "be5acac77009104762c6804d48ebf158e53551a44e2da8cae1ebbe3e903c2853", "tx_count": 0, "merkle": "908bb324e43c3665e4b5de2bb73639bc96e48fda2c1ed7abe4a5a1437
fb880b7", "prev": "1af70e4b425c0be7025f81294d5480e3d9f9a400cc80c83df2f8e3d1a8748e77"}
DEBUG[01-23|20:16:31.524] Dereferenced trie from memory database   nodes=0  size=0.00B   time="1µs"       gcnodes=6102 gcsize=1.45MiB    gctime=72.248279ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:31.524] Dereferenced trie from memory database   nodes=0  size=0.00B   time=507ns       gcnodes=6102 gcsize=1.45MiB    gctime=72.24858ms  livenodes=1353 livesize=145.46KiB
INFO [01-23|20:16:31.526] Successfully sealed new block            number=57147 sealhash=be5aca..3c2853 hash=04fb80..e09071 elapsed=15.005s
INFO [01-23|20:16:31.526] New block in the chain                   "dbft index"=57147 "chain index"=57147 hash=0x04fb80c45090127cfe0617686ab206489bdf555e2aa5edb2fe09490c9fe09071 "parent hash"=0x1af70e4b425c0be7025f81294d5480e3d9f9a400cc80c83df2f8e3d1a8748e77 primary=3 coinbase=0x121210000
0000000000000000000000000000001

4cn-CN2

INFO [01-23|20:16:01.501] Commit new sealing work                  number=57146 sealhash=0350c7..d0cd44 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="99.431µs"
DEBUG[01-23|20:16:01.502] Queued delivered header or block         peer=ed61da493415ec5c46c47abbaf18d03918db9c7357bcc5a5f0a652102dd6e0b4 number=57145 hash=a4d4d0..fd6692 queued=1
DEBUG[01-23|20:16:02.007] Queued delivered header or block         peer=a51ac92f1d9ae391b57e9f16b27766f03b369630295929ffa47fcafedcfc29d9 number=57145 hash=a4d4d0..fd6692 queued=1
INFO [01-23|20:16:02.501] Sealing proposal updated                 number=57146 sealhash=0350c7..d0cd44 "parent hash"=a4d4d0..fd6692 txs=0
2024-01-23T20:16:02.501Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57146, "view": 0, "index": 2, "role": "Primary"}
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "13.993649207s"}
DEBUG[01-23|20:16:02.501] received message                         from=1 type=PrepareRequest
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 1, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.501] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.501] received message                         from=3 type=Commit
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.501] received message                         from=3 type=Commit
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.501] received message                         from=3 type=Commit
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
INFO [01-23|20:16:04.072] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:04.896] Revalidated node                         b=10 id=ed61da493415ec5c checks=1
INFO [01-23|20:16:14.086] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:14.323] Revalidated node                         b=16 id=6598eeabf8cd7462 checks=1
DEBUG[01-23|20:16:16.495] timer fired                              height=57146 view=0
2024-01-23T20:16:16.495Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:185     timeout {"height": 57146, "view": 0}
2024-01-23T20:16:16.495Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "PrepareRequest", "height": 57146, "view": 0}
2024-01-23T20:16:16.496Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:40      sending PrepareRequest  {"height": 57146, "view": 0}
2024-01-23T20:16:16.496Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "15s"}
2024-01-23T20:16:16.496Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 1, "M": 3}
DEBUG[01-23|20:16:16.499] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:16.499Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.499Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 0}
2024-01-23T20:16:16.499Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 2, "M": 3}
DEBUG[01-23|20:16:16.503] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:16.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:425     ignoring PrepareResponse because of view changing
DEBUG[01-23|20:16:16.503] received message                         from=3 type=PrepareResponse
2024-01-23T20:16:16.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.503Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 3}
2024-01-23T20:16:16.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 3, "M": 3}
2024-01-23T20:16:16.503Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:134     sending Commit  {"height": 57146, "view": 0}
2024-01-23T20:16:16.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "Commit", "height": 57146, "view": 0}
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "15s"}
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 1}
DEBUG[01-23|20:16:16.504] received message                         from=3 type=PrepareResponse
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:425     ignoring PrepareResponse because of view changing
DEBUG[01-23|20:16:16.504] received message                         from=3 type=Commit
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.504Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 3}
2024-01-23T20:16:16.505Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 2}
DEBUG[01-23|20:16:16.505] received message                         from=3 type=Commit
2024-01-23T20:16:16.505Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
DEBUG[01-23|20:16:16.505] received message                         from=0 type=Commit
2024-01-23T20:16:16.506Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.506Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 0}
2024-01-23T20:16:16.506Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:66     approving block {"height": 57146, "hash": "0350c7ab6e3d0f351beab477e827c3bc2c8d799c9027e6e9ce10d1e99ad0cd44", "tx_count": 0, "merkle": "908bb324e43c3665e4b5de2bb73639bc96e48fda2c1ed7abe4a5a1437
fb880b7", "prev": "a4d4d0102f1479081437766dc15b64b8ff20b9536b26dc5e89cb7f4d72fd6692"}
DEBUG[01-23|20:16:16.513] received message                         from=1 type=PrepareResponse
2024-01-23T20:16:16.514Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
DEBUG[01-23|20:16:16.514] received message                         from=1 type=Commit
2024-01-23T20:16:16.514Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
DEBUG[01-23|20:16:16.514] Dereferenced trie from memory database   nodes=0  size=0.00B   time="1.093µs"   gcnodes=6102 gcsize=1.45MiB    gctime=63.280992ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:16.514] Dereferenced trie from memory database   nodes=0  size=0.00B   time=475ns       gcnodes=6102 gcsize=1.45MiB    gctime=63.281264ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:16.514] received message                         from=1 type=Commit
2024-01-23T20:16:16.515Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
INFO [01-23|20:16:16.515] Successfully sealed new block            number=57146 sealhash=0350c7..d0cd44 hash=5c7396..49328c elapsed=15.014s
DEBUG[01-23|20:16:16.515] Reinjecting stale transactions           count=0
INFO [01-23|20:16:16.515] Commit new sealing work                  number=57147 sealhash=b26dcb..326726 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="91.623µs"
INFO [01-23|20:16:16.515] New block in the chain                   "dbft index"=57146 "chain index"=57146 hash=0x5c7396bdbee6284db34e221043e4d3a02a058ae1011b91a8b645102bed49328c "parent hash"=0xa4d4d0102f1479081437766dc15b64b8ff20b9536b26dc5e89cb7f4d72fd6692 primary=2 coinbase=0x121210000
0000000000000000000000000000001
INFO [01-23|20:16:16.516] Fetching latest sealing proposal         "desired number"=57147
INFO [01-23|20:16:16.516] Sealing proposal updated                 number=57147 sealhash=b26dcb..326726 "parent hash"=5c7396..49328c txs=0
2024-01-23T20:16:16.516Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57147, "view": 0, "index": 2, "role": "Backup"}
2024-01-23T20:16:16.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "29.99068147s"}
DEBUG[01-23|20:16:16.516] received message                         from=1 type=Commit
2024-01-23T20:16:16.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.517] Queued delivered header or block         peer=ed61da493415ec5c46c47abbaf18d03918db9c7357bcc5a5f0a652102dd6e0b4 number=57146 hash=5c7396..49328c queued=1
DEBUG[01-23|20:16:16.518] received message                         from=1 type=Commit
2024-01-23T20:16:16.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:21.148] Revalidated node                         b=10 id=ed61da493415ec5c checks=1
INFO [01-23|20:16:24.102] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:25.845] Current full block not old enough        number=57146 hash=5c7396..49328c delay=90000
DEBUG[01-23|20:16:30.570] Revalidated node                         b=15 id=a51ac92f1d9ae391 checks=6
DEBUG[01-23|20:16:31.512] received message                         from=3 type=PrepareRequest
2024-01-23T20:16:31.512Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 3, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
INFO [01-23|20:16:31.515] Imported new chain segment               number=57146 hash=1af70e..748e77 blocks=1 txs=0  mgas=0.000 elapsed=2.426ms     mgasps=0.000   snapdiffs=196.61KiB triedirty=282.93KiB
DEBUG[01-23|20:16:31.515] Inserted forked block                    number=57146 hash=1af70e..748e77 diff=2         elapsed=2.017ms     txs=0  gas=0         uncles=0 root=908bb3..b880b7
2024-01-23T20:16:31.515Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:325     received empty PrepareRequest
2024-01-23T20:16:31.515Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:333     received PrepareRequest {"validator": 3, "tx": 0}
2024-01-23T20:16:31.515Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:106     sending PrepareResponse {"height": 57147, "view": 0}
2024-01-23T20:16:31.515Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "PrepareResponse", "height": 57147, "view": 0}
2024-01-23T20:16:31.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 2, "M": 3}
DEBUG[01-23|20:16:31.517] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:31.517Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.517Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 0}
2024-01-23T20:16:31.517Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 3, "M": 3}
2024-01-23T20:16:31.517Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:134     sending Commit  {"height": 57147, "view": 0}
2024-01-23T20:16:31.517Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "Commit", "height": 57147, "view": 0}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "15s"}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 1}
DEBUG[01-23|20:16:31.518] received message                         from=0 type=PrepareResponse
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:425     ignoring PrepareResponse because of view changing
DEBUG[01-23|20:16:31.520] received message                         from=3 type=Commit
2024-01-23T20:16:31.520Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.520Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 3}
2024-01-23T20:16:31.520Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 2}
DEBUG[01-23|20:16:31.522] received message                         from=0 type=Commit
2024-01-23T20:16:31.522Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.522Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 0}
2024-01-23T20:16:31.522Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:66     approving block {"height": 57147, "hash": "be5acac77009104762c6804d48ebf158e53551a44e2da8cae1ebbe3e903c2853", "tx_count": 0, "merkle": "908bb324e43c3665e4b5de2bb73639bc96e48fda2c1ed7abe4a5a1437
fb880b7", "prev": "1af70e4b425c0be7025f81294d5480e3d9f9a400cc80c83df2f8e3d1a8748e77"}
DEBUG[01-23|20:16:31.525] Dereferenced trie from memory database   nodes=0  size=0.00B   time=765ns       gcnodes=6102 gcsize=1.45MiB    gctime=63.281499ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:31.525] Dereferenced trie from memory database   nodes=0  size=0.00B   time="1.264µs"   gcnodes=6102 gcsize=1.45MiB    gctime=63.282382ms livenodes=1353 livesize=145.46KiB
INFO [01-23|20:16:31.525] Chain reorg detected                     number=57145 hash=a4d4d0..fd6692 drop=1 dropfrom=5c7396..49328c add=2 addfrom=04fb80..e09071
INFO [01-23|20:16:31.529] Imported new chain segment               number=57147 hash=04fb80..e09071 blocks=1 txs=0  mgas=0.000 elapsed=7.644ms     mgasps=0.000   snapdiffs=196.61KiB triedirty=282.93KiB
DEBUG[01-23|20:16:31.529] Inserted new block                       number=57147 hash=04fb80..e09071 uncles=0 txs=0  gas=0         elapsed=6.836ms     root=908bb3..b880b7
INFO [01-23|20:16:31.530] New block in the chain                   "dbft index"=57147 "chain index"=57147 hash=0x04fb80c45090127cfe0617686ab206489bdf555e2aa5edb2fe09490c9fe09071 "parent hash"=0x1af70e4b425c0be7025f81294d5480e3d9f9a400cc80c83df2f8e3d1a8748e77 primary=3 coinbase=0x121210000
0000000000000000000000000000001
INFO [01-23|20:16:31.530] Fetching latest sealing proposal         "desired number"=57148
DEBUG[01-23|20:16:31.530] Reinjecting stale transactions           count=0
INFO [01-23|20:16:31.530] Commit new sealing work                  number=57148 sealhash=bf4c8d..1a6ac2 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="92.45µs"
DEBUG[01-23|20:16:31.548] Message handling failed in `snap`        peer=ed61da49 err=EOF
DEBUG[01-23|20:16:31.548] Message handling failed in `dbft`        id=ed61da493415ec5c conn=dyndial            err=EOF
DEBUG[01-23|20:16:31.548] Message handling failed in `eth`         id=ed61da493415ec5c conn=dyndial            err=EOF
DEBUG[01-23|20:16:31.548] Removing Ethereum peer                   peer=ed61da49 snap=true
DEBUG[01-23|20:16:31.548] Removing p2p peer                        peercount=3 id=ed61da493415ec5c duration=16h30m5.383s req=false err="read tcp 127.0.0.1:52516->127.0.0.1:30308: read: connection reset by peer"

4cn-CN3

INFO [01-23|20:16:01.501] Commit new sealing work                  number=57146 sealhash=0350c7..d0cd44 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="90.607µs"
DEBUG[01-23|20:16:02.125] Revalidated node                         b=10 id=ef026152bd54da8d checks=2
INFO [01-23|20:16:02.502] Sealing proposal updated                 number=57146 sealhash=0350c7..d0cd44 "parent hash"=a4d4d0..fd6692 txs=0
2024-01-23T20:16:02.502Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57146, "view": 0, "index": 1, "role": "Backup"}
2024-01-23T20:16:02.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "28.995491105s"}
DEBUG[01-23|20:16:02.502] received message                         from=3     type=Commit
2024-01-23T20:16:02.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.502] received message                         from=3     type=Commit
2024-01-23T20:16:02.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:02.502] received message                         from=3     type=Commit
2024-01-23T20:16:02.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:03.154] Revalidated node                         b=10 id=ef026152bd54da8d checks=3
INFO [01-23|20:16:04.065] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:07.182] Revalidated node                         b=10 id=ef026152bd54da8d checks=1
DEBUG[01-23|20:16:07.574] Revalidated node                         b=16 id=6598eeabf8cd7462 checks=1
DEBUG[01-23|20:16:07.882] Revalidated node                         b=15 id=a51ac92f1d9ae391 checks=1
INFO [01-23|20:16:14.081] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:16.501] received message                         from=2     type=PrepareRequest
2024-01-23T20:16:16.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 2, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:325     received empty PrepareRequest
2024-01-23T20:16:16.501Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:333     received PrepareRequest {"validator": 2, "tx": 0}
2024-01-23T20:16:16.501Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:106     sending PrepareResponse {"height": 57146, "view": 0}
2024-01-23T20:16:16.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "PrepareResponse", "height": 57146, "view": 0}
2024-01-23T20:16:16.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 2, "M": 3}
DEBUG[01-23|20:16:16.501] received message                         from=0     type=PrepareResponse
2024-01-23T20:16:16.501Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 0, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.502Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 0}
2024-01-23T20:16:16.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 3, "M": 3}
2024-01-23T20:16:16.502Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:134     sending Commit  {"height": 57146, "view": 0}
2024-01-23T20:16:16.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "Commit", "height": 57146, "view": 0}
2024-01-23T20:16:16.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "15s"}
2024-01-23T20:16:16.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 1}
DEBUG[01-23|20:16:16.502] received message                         from=3     type=PrepareResponse
2024-01-23T20:16:16.502Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.502Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 3}
DEBUG[01-23|20:16:16.505] received message                         from=3     type=Commit
2024-01-23T20:16:16.505Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.505Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 3}
DEBUG[01-23|20:16:16.514] Queued delivered header or block         peer=6598eeabf8cd74624ba79e764e0e76398155b9c90b420ff6263b8c7b05825d54 number=57146 hash=5c7396..49328c queued=1
DEBUG[01-23|20:16:16.516] Importing propagated block               peer=6598eeabf8cd74624ba79e764e0e76398155b9c90b420ff6263b8c7b05825d54 number=57146 hash=5c7396..49328c
DEBUG[01-23|20:16:16.520] Dereferenced trie from memory database   nodes=0  size=0.00B   time=524ns       gcnodes=6102 gcsize=1.45MiB    gctime=66.97062ms  livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:16.520] Dereferenced trie from memory database   nodes=0  size=0.00B   time=410ns       gcnodes=6102 gcsize=1.45MiB    gctime=66.970871ms livenodes=1353 livesize=145.46KiB
INFO [01-23|20:16:16.521] Imported new chain segment               number=57146 hash=5c7396..49328c blocks=1   txs=0  mgas=0.000 elapsed=4.520ms     mgasps=0.000   snapdiffs=196.61KiB triedirty=282.93KiB
DEBUG[01-23|20:16:16.521] Inserted new block                       number=57146 hash=5c7396..49328c uncles=0 txs=0  gas=0         elapsed=3.755ms     root=908bb3..b880b7
DEBUG[01-23|20:16:16.521] Reinjecting stale transactions           count=0
INFO [01-23|20:16:16.522] Commit new sealing work                  number=57147 sealhash=b26dcb..326726 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="109.307µs"
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 2}
INFO [01-23|20:16:16.528] New block in the chain                   "dbft index"=57146 "chain index"=57146 hash=0x5c7396bdbee6284db34e221043e4d3a02a058ae1011b91a8b645102bed49328c "parent hash"=0xa4d4d0102f1479081437766dc15b64b8ff20b9536b26dc5e89cb7f4d72fd6692 primary=2 coinbase=0x1212100000000000000000000000000000000001
INFO [01-23|20:16:16.528] Fetching latest sealing proposal         "desired number"=57147
INFO [01-23|20:16:16.528] Sealing proposal updated                 number=57147 sealhash=b26dcb..326726 "parent hash"=5c7396..49328c txs=0
2024-01-23T20:16:16.528Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57147, "view": 0, "index": 1, "role": "Backup"}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "30s"}
DEBUG[01-23|20:16:16.528] received message                         from=2     type=PrepareRequest
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=0     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=0     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=0     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=2     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=2     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=0     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 0, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=2     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.528] received message                         from=2     type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:17.311] Revalidated node                         b=10 id=ef026152bd54da8d checks=2
DEBUG[01-23|20:16:23.057] Revalidated node                         b=14 id=dee0c36193bcfd14 checks=2
INFO [01-23|20:16:24.099] Looking for peers                        peercount=4 tried=0 static=0
DEBUG[01-23|20:16:25.869] Current full block not old enough        number=57146 hash=5c7396..49328c delay=90000
DEBUG[01-23|20:16:28.273] Revalidated node                         b=10 id=ef026152bd54da8d checks=1
DEBUG[01-23|20:16:30.282] Revalidated node                         b=10 id=ef026152bd54da8d checks=2
DEBUG[01-23|20:16:31.514] received message                         from=3     type=PrepareRequest
2024-01-23T20:16:31.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 3, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:325     received empty PrepareRequest
2024-01-23T20:16:31.518Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:333     received PrepareRequest {"validator": 3, "tx": 0}
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0xd3afb6]

goroutine 4460 [running]:
github.com/ethereum/go-ethereum/core/types.(*Block).Root(...)
        github.com/ethereum/go-ethereum/core/types/block.go:382
github.com/ethereum/go-ethereum/core.(*BlockChain).VerifyBlock(0xc00043b400, 0xc00275caa0)
        github.com/ethereum/go-ethereum/core/blockchain.go:2612 +0x56
github.com/ethereum/go-ethereum/consensus/dbft.New.func20({0x1fed4a0?, 0xc000356d40})
        github.com/ethereum/go-ethereum/consensus/dbft/dbft.go:521 +0xb4
github.com/nspcc-dev/dbft.(*DBFT).createAndCheckBlock(0xc00028d340)
        github.com/nspcc-dev/dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:382 +0x1fe
github.com/nspcc-dev/dbft.(*DBFT).onPrepareRequest(0xc00028d340, {0x1ff09a0?, 0xc000a67b80?})
        github.com/nspcc-dev/dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:338 +0x9b4
github.com/nspcc-dev/dbft.(*DBFT).OnReceive(0xc00028d340, {0x1ff09a0, 0xc000a67b80?})
        github.com/nspcc-dev/dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:256 +0xd49
github.com/ethereum/go-ethereum/consensus/dbft.(*DBFT).eventLoop(0xc00043b000)
        github.com/ethereum/go-ethereum/consensus/dbft/dbft.go:1103 +0x94d
created by github.com/ethereum/go-ethereum/consensus/dbft.(*DBFT).Start in goroutine 4427
        github.com/ethereum/go-ethereum/consensus/dbft/dbft.go:966 +0x4b6

4cn-CN4

INFO [01-23|20:16:01.502] Fetching latest sealing proposal         "desired number"=57146
DEBUG[01-23|20:16:01.502] Reinjecting stale transactions           count=0
DEBUG[01-23|20:16:01.502] Queued delivered header or block         peer=ed61da493415ec5c46c47abbaf18d03918db9c7357bcc5a5f0a652102dd6e0b4 number=57145 hash=a4d4d0..fd6692 queued=1
INFO [01-23|20:16:01.502] Commit new sealing work                  number=57146 sealhash=0350c7..d0cd44 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="87.127µs"
DEBUG[01-23|20:16:01.529] Revalidated node                         b=16 id=ed61da493415ec5c checks=1
INFO [01-23|20:16:02.503] Sealing proposal updated                 number=57146 sealhash=0350c7..d0cd44 "parent hash"=a4d4d0..fd6692 txs=0
2024-01-23T20:16:02.503Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57146, "view": 0, "index": 0, "role": "Backup"}
2024-01-23T20:16:02.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "28.991931943s"}
DEBUG[01-23|20:16:02.503] received message                         from=3 type=Commit
2024-01-23T20:16:02.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57145, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:02.503Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57145}
DEBUG[01-23|20:16:03.314] Revalidated node                         b=16 id=ef026152bd54da8d checks=2
DEBUG[01-23|20:16:05.655] Revalidated node                         b=16 id=a51ac92f1d9ae391 checks=1
DEBUG[01-23|20:16:09.777] ENR request failed                       id=8047e06fad43a846 addr=127.0.0.1:30305 err="invalid IP in response record: invalid IP"
DEBUG[01-23|20:16:09.777] Revalidated node                         b=16 id=8047e06fad43a846 checks=1
DEBUG[01-23|20:16:16.496] received message                         from=2 type=PrepareRequest
2024-01-23T20:16:16.496Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 2, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.496Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:325     received empty PrepareRequest
2024-01-23T20:16:16.496Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:333     received PrepareRequest {"validator": 2, "tx": 0}
2024-01-23T20:16:16.496Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:106     sending PrepareResponse {"height": 57146, "view": 0}
2024-01-23T20:16:16.496Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "PrepareResponse", "height": 57146, "view": 0}
2024-01-23T20:16:16.497Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 2, "M": 3}
DEBUG[01-23|20:16:16.500] received message                         from=3 type=PrepareResponse
2024-01-23T20:16:16.500Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.500Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 3}
2024-01-23T20:16:16.500Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 3, "M": 3}
2024-01-23T20:16:16.500Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:134     sending Commit  {"height": 57146, "view": 0}
2024-01-23T20:16:16.500Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "Commit", "height": 57146, "view": 0}
2024-01-23T20:16:16.500Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57146, "v": 0, "delay": "15s"}
2024-01-23T20:16:16.500Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 1}
DEBUG[01-23|20:16:16.504] received message                         from=3 type=PrepareResponse
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:425     ignoring PrepareResponse because of view changing
DEBUG[01-23|20:16:16.504] received message                         from=3 type=Commit
2024-01-23T20:16:16.504Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.504Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 3}
2024-01-23T20:16:16.505Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 2}
DEBUG[01-23|20:16:16.507] received message                         from=1 type=PrepareResponse
2024-01-23T20:16:16.507Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.507Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 1}
DEBUG[01-23|20:16:16.507] received message                         from=2 type=Commit
2024-01-23T20:16:16.507Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
2024-01-23T20:16:16.507Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 2}
2024-01-23T20:16:16.507Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:66     approving block {"height": 57146, "hash": "0350c7ab6e3d0f351beab477e827c3bc2c8d799c9027e6e9ce10d1e99ad0cd44", "tx_count": 0, "merkle": "908bb324e43c3665e4b5de2bb73639bc96e48fda2c1ed7abe4a5a1437fb880b7", "prev": "a4d4d0102f1479081437766dc15b64b8ff20b9536b26dc5e89cb7f4d72fd6692"}
DEBUG[01-23|20:16:16.511] received message                         from=1 type=PrepareResponse
2024-01-23T20:16:16.511Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
DEBUG[01-23|20:16:16.511] Dereferenced trie from memory database   nodes=0  size=0.00B   time="1.01µs"    gcnodes=6102 gcsize=1.45MiB    gctime=57.278378ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:16.511] Dereferenced trie from memory database   nodes=0  size=0.00B   time=327ns       gcnodes=6102 gcsize=1.45MiB    gctime=57.278547ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:16.512] received message                         from=1 type=Commit
2024-01-23T20:16:16.512Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
DEBUG[01-23|20:16:16.512] received message                         from=1 type=Commit
2024-01-23T20:16:16.512Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57146, "my_view": 0}
INFO [01-23|20:16:16.513] Successfully sealed new block            number=57146 sealhash=0350c7..d0cd44 hash=5c7396..49328c elapsed=15.010s
DEBUG[01-23|20:16:16.513] Reinjecting stale transactions           count=0
INFO [01-23|20:16:16.514] Commit new sealing work                  number=57147 sealhash=b26dcb..326726 etherbase=0x1212100000000000000000000000000000000001 txs=0  gas=0         fees=0               elapsed="137.387µs"
INFO [01-23|20:16:16.514] New block in the chain                   "dbft index"=57146 "chain index"=57146 hash=0x5c7396bdbee6284db34e221043e4d3a02a058ae1011b91a8b645102bed49328c "parent hash"=0xa4d4d0102f1479081437766dc15b64b8ff20b9536b26dc5e89cb7f4d72fd6692 primary=2 coinbase=0x121210000
0000000000000000000000000000001
INFO [01-23|20:16:16.514] Fetching latest sealing proposal         "desired number"=57147
INFO [01-23|20:16:16.514] Sealing proposal updated                 number=57147 sealhash=b26dcb..326726 "parent hash"=5c7396..49328c txs=0
2024-01-23T20:16:16.514Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:107     initializing dbft       {"height": 57147, "view": 0, "index": 0, "role": "Backup"}
2024-01-23T20:16:16.514Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "29.993295972s"}
DEBUG[01-23|20:16:16.516] Queued delivered header or block         peer=ef026152bd54da8d41d4d009303a5b8608c76d292d730cba79dbef4e9fa22736 number=57146 hash=5c7396..49328c queued=1
DEBUG[01-23|20:16:16.528] received message                         from=1 type=Commit
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 1, "height": 57146, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:16.528Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:223     ignoring old height     {"height": 57146}
DEBUG[01-23|20:16:16.817] Revalidated node                         b=16 id=ed61da493415ec5c checks=1
DEBUG[01-23|20:16:21.546] ENR request failed                       id=8047e06fad43a846 addr=127.0.0.1:30305 err="invalid IP in response record: invalid IP"
DEBUG[01-23|20:16:21.546] Revalidated node                         b=16 id=8047e06fad43a846 checks=2
DEBUG[01-23|20:16:26.043] Current full block not old enough        number=57146 hash=5c7396..49328c delay=90000
DEBUG[01-23|20:16:27.614] Revalidated node                         b=16 id=dee0c36193bcfd14 checks=1
DEBUG[01-23|20:16:31.512] received message                         from=3 type=PrepareRequest
2024-01-23T20:16:31.512Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareRequest", "from": 3, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
INFO [01-23|20:16:31.515] Imported new chain segment               number=57146 hash=1af70e..748e77 blocks=1 txs=0  mgas=0.000 elapsed=2.437ms     mgasps=0.000   snapdiffs=196.61KiB triedirty=282.93KiB
DEBUG[01-23|20:16:31.515] Inserted forked block                    number=57146 hash=1af70e..748e77 diff=2         elapsed=2.056ms     txs=0  gas=0         uncles=0 root=908bb3..b880b7
2024-01-23T20:16:31.515Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:325     received empty PrepareRequest
2024-01-23T20:16:31.515Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:333     received PrepareRequest {"validator": 3, "tx": 0}
2024-01-23T20:16:31.515Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:106     sending PrepareResponse {"height": 57147, "view": 0}
2024-01-23T20:16:31.515Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "PrepareResponse", "height": 57147, "view": 0}
2024-01-23T20:16:31.516Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 2, "M": 3}
DEBUG[01-23|20:16:31.517] received message                         from=2 type=PrepareResponse
2024-01-23T20:16:31.517Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "PrepareResponse", "from": 2, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.517Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:433     received PrepareResponse        {"validator": 2}
2024-01-23T20:16:31.517Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:29     check preparations      {"hasReq": true, "count": 3, "M": 3}
2024-01-23T20:16:31.517Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:134     sending Commit  {"height": 57147, "view": 0}
2024-01-23T20:16:31.517Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/send.go:9       broadcasting message    {"type": "Commit", "height": 57147, "view": 0}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:617     reset timer     {"h": 57147, "v": 0, "delay": "15s"}
2024-01-23T20:16:31.518Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 1}
DEBUG[01-23|20:16:31.520] received message                         from=2 type=Commit
2024-01-23T20:16:31.520Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 2, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.520Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 2}
2024-01-23T20:16:31.521Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:57     not enough to commit    {"count": 2}
DEBUG[01-23|20:16:31.523] received message                         from=3 type=Commit
2024-01-23T20:16:31.523Z        DEBUG   dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:214     received message        {"type": "Commit", "from": 3, "height": 57147, "view": 0, "my_height": 57147, "my_view": 0}
2024-01-23T20:16:31.523Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/dbft.go:507     received Commit {"validator": 3}
2024-01-23T20:16:31.523Z        INFO    dbft@v0.0.0-20230515113611-25db6ba61d5c/check.go:66     approving block {"height": 57147, "hash": "be5acac77009104762c6804d48ebf158e53551a44e2da8cae1ebbe3e903c2853", "tx_count": 0, "merkle": "908bb324e43c3665e4b5de2bb73639bc96e48fda2c1ed7abe4a5a1437
fb880b7", "prev": "1af70e4b425c0be7025f81294d5480e3d9f9a400cc80c83df2f8e3d1a8748e77"}
DEBUG[01-23|20:16:31.525] Dereferenced trie from memory database   nodes=0  size=0.00B   time=705ns       gcnodes=6102 gcsize=1.45MiB    gctime=57.278681ms livenodes=1353 livesize=145.46KiB
DEBUG[01-23|20:16:31.525] Dereferenced trie from memory database   nodes=0  size=0.00B   time=208ns       gcnodes=6102 gcsize=1.45MiB    gctime=57.278785ms livenodes=1353 livesize=145.46KiB
INFO [01-23|20:16:31.525] Chain reorg detected                     number=57145 hash=a4d4d0..fd6692 drop=1 dropfrom=5c7396..49328c add=2 addfrom=04fb80..e09071
INFO [01-23|20:16:31.529] Imported new chain segment               number=57147 hash=04fb80..e09071 blocks=1 txs=0  mgas=0.000 elapsed=5.729ms     mgasps=0.000   snapdiffs=196.61KiB triedirty=282.93KiB
DEBUG[01-23|20:16:31.529] Inserted new block                       number=57147 hash=04fb80..e09071 uncles=0 txs=0  gas=0         elapsed=4.998ms     root=908bb3..b880b7
INFO [01-23|20:16:31.529] New block in the chain                   "dbft index"=57147 "chain index"=57147 hash=0x04fb80c45090127cfe0617686ab206489bdf555e2aa5edb2fe09490c9fe09071 "parent hash"=0x1af70e4b425c0be7025f81294d5480e3d9f9a400cc80c83df2f8e3d1a8748e77 primary=3 coinbase=0x121210000
0000000000000000000000000000001

@AnnaShaleva
Copy link
Member

may be an issue from some other place but found by this PR.

Good, thanks, it's definitely from this PR since there's no verification callback set in the previous versions. I'll get back to review & test this PR in a few days.

Copy link
Member

@AnnaShaleva AnnaShaleva left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you, please, reformat the commit message and add Close #65. message to the commit and PR description.

Copy link
Member

@AnnaShaleva AnnaShaleva left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One important thing I worry about is transactions verification. We need not only verify storage state after in-block transactions execution, but also verify that all transactions included in block are valid, i.e. have valid fees set and etc. This should be provided by mempool, but we need to ensure that no "bad" transaction can be accepted.

For example, take a look at the way how in-block transactions are being checked in NeoGo during block verification: https://github.com/nspcc-dev/neo-go/blob/51ac153a7b009f8f69117ed987038a08dc78f261/pkg/consensus/consensus.go#L509

The difference is that NeoGo's transactions come to the consensus bypassing mempool. And Eth transactions come to consensus from mempool. However, we need to ensure that there are no conflicting transactions in the block.

@AnnaShaleva
Copy link
Member

CN3 failed after running for several days,

@nicolegys, could you please provide the git revision (commit sha) you've used to run nodes when this error occurred?

@roman-khimov
Copy link
Contributor

And Eth transactions come to consensus from mempool

Consider nonce conflict, btw. Proposal (PrepareRequest) can have a different transaction for the same sender/nonce combination and it'd be valid, while you may never get this transaction from the mempool because we have some there already with a bigger fee.

@AnnaShaleva
Copy link
Member

while you may never get this transaction from the mempool

We need to refactor this and send requested transactions right to the consensus bypassing mempool. This task may be done in #98, since this change should be applicable only to requested transactions.

@chenquanyu
Copy link
Collaborator Author

chenquanyu commented Feb 1, 2024

One important thing I worry about is transactions verification. We need not only verify storage state after in-block transactions execution, but also verify that all transactions included in block are valid, i.e. have valid fees set and etc.

Consider nonce conflict, btw. Proposal (PrepareRequest) can have a different transaction for the same sender/nonce combination and it'd be valid, while you may never get this transaction from the mempool because we have some there already with a bigger fee.

We have the transaction nonce and gas verify in func (st *StateTransition) TransitionDb(). And we may also add policy checks in this method. For the same sender and nonce transaction with a bigger fee, it should be dropped if the pre transaction has been included in Proposal.

image

@AnnaShaleva
Copy link
Member

AnnaShaleva commented Feb 1, 2024

@chenquanyu, could you please rebase onto the current bane-main?

We have the transaction nonce and gas verify in func (st *StateTransition) TransitionDb(). And we may also add policy checks in this method. For the same sender and nonce transaction with a bigger fee, it should be dropped if the pre transaction has been included in Proposal.

Will check this, but the overall idea is that during WithVerifyBlock we need to re-run the set of mempool checks for in-block transactions got from the proposal.

Copy link
Member

@AnnaShaleva AnnaShaleva left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One major issue left with block's parent. Otherwose LGTM. I'll create a separate issue for in-block transactions reverification.

@AnnaShaleva
Copy link
Member

@chenquanyu, take a look at #127, you may add some comments if needed.

@nicolegys
Copy link
Collaborator

CN3 failed after running for several days,

@nicolegys, could you please provide the git revision (commit sha) you've used to run nodes when this error occurred?

Oh, now I see this. It's commit 558b719517dbce91fc193ad0517a5fc00b756089

Copy link
Member

@AnnaShaleva AnnaShaleva left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@chenquanyu, please, fix the last comment, squash commits and we'll merge this PR. I'll create a separate issue to track the problem with missing parent and we'll track if it's reproduced on the real network with the updated state retrieval code.

Also, please, create PR with the same block verification to https://github.com/bane-labs/go-ethereum/tree/t2.

@AnnaShaleva
Copy link
Member

@chenquanyu, could you, please, update this PR according to the comments above?

@AnnaShaleva
Copy link
Member

I'll create a separate issue to track the problem with missing parent and we'll track if it's reproduced on the real network with the updated state retrieval code.

Ref. #142

@chenquanyu chenquanyu force-pushed the dbft-verify-block branch 2 times, most recently from c587e7f to 858a6f6 Compare February 27, 2024 16:01
@AnnaShaleva AnnaShaleva merged commit f84d16a into bane-main Feb 29, 2024
@AnnaShaleva AnnaShaleva deleted the dbft-verify-block branch February 29, 2024 07:08
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Implement block verification callback

5 participants