Skip to content

Revert timer related changes#148

Merged
roman-khimov merged 1 commit intomasterfrom
fix-timer
Mar 21, 2025
Merged

Revert timer related changes#148
roman-khimov merged 1 commit intomasterfrom
fix-timer

Conversation

@AnnaShaleva
Copy link
Member

@AnnaShaleva AnnaShaleva commented Mar 20, 2025

This reverts commit 8dfda6b and f7a23ed.

This change is needed because external users of the library should be able to stop the dBFT timer:
https://github.com/nspcc-dev/neo-go/blob/3e54c46281237124da7fd89a90501a9d58a3aa60/pkg/consensus/consensus.go#L342

@AnnaShaleva
Copy link
Member Author

No CHANGELOG entry is required.

@codecov
Copy link

codecov bot commented Mar 20, 2025

Codecov Report

Attention: Patch coverage is 80.00000% with 1 line in your changes missing coverage. Please review.

Project coverage is 57.71%. Comparing base (5281a9a) to head (9a66da0).
Report is 2 commits behind head on master.

Files with missing lines Patch % Lines
timer/timer.go 80.00% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##           master     #148      +/-   ##
==========================================
+ Coverage   57.66%   57.71%   +0.04%     
==========================================
  Files          33       33              
  Lines        2277     2282       +5     
==========================================
+ Hits         1313     1317       +4     
- Misses        875      876       +1     
  Partials       89       89              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@AnnaShaleva
Copy link
Member Author

OK, something is not clear with this upgrade, consensus service is hanging (even if dBFT master is used).

@AnnaShaleva
Copy link
Member Author

OK, it looks like we still need to drain the timer's channel, otherwise consensus doesn't work properly.

@AnnaShaleva AnnaShaleva changed the title Revert "timer: internalize stop method" Revert timer related changes Mar 20, 2025
@roman-khimov
Copy link
Member

Just do nspcc-dev/neo-go#3553, this is not needed.

@AnnaShaleva
Copy link
Member Author

AnnaShaleva commented Mar 21, 2025

I still think that timer draining related commit should be reverted because there's a possibility that timer is requested to be reset with 0 delta:

dbft/dbft.go

Lines 157 to 159 in 5281a9a

timeout = max(0, timeout)
}
d.changeTimer(timeout)

Consider the situation when CV happens: the timer will be reset in ChangeView message handler:

dbft/check.go

Line 179 in 5281a9a

d.initializeConsensus(view, d.lastBlockTimestamp)

Which means that dBFT eventloop is still busy with CV handling and can't read from the timer's channel (given that d is 0):

dbft/timer/timer.go

Lines 60 to 65 in 5281a9a

if t.d != 0 {
t.tt = time.NewTimer(t.d)
} else {
t.tt = nil
t.ch <- t.s
}

At the same time, as it is said in the timer's documentation, this channel isn't buffered anymore:

As of Go 1.23, the channel is synchronous (unbuffered, capacity 0), eliminating the possibility of those stale values.

So we end up in a deadlock. Take a look at the test failing in nspcc-dev/neo-go@d60f35c, or, as an example, run privnet from the same commit, kill one node and see the result: nodes won't be able to process CV properly:

2025-03-21T12:01:32.840Z	INFO	approving block	{"height": 2, "hash": "30bf61f7fc9c220861c7f3d22a7aa90a1f9de62509329138a99aaa99379ca9c9", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "a92768f029d42c2200327b80f4078f6424a107d614761742bcdbb9ed8f1dcf67"}
2025-03-21T12:01:32.840Z	DEBUG	got msg	{"addr": "172.200.0.4:20334", "type": "CMDExtensible"}
2025-03-21T12:01:32.840Z	DEBUG	received message	{"from": 0, "type": "Commit"}
2025-03-21T12:01:32.840Z	DEBUG	received message	{"type": "Commit", "from": 0, "height": 2, "view": 0, "my_height": 2, "my_view": 0}
2025-03-21T12:01:32.840Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:32.840Z	DEBUG	done processing headers	{"headerIndex": 2, "blockHeight": 1, "took": "233.977µs"}
2025-03-21T12:01:32.840Z	DEBUG	new block in the chain	{"dbft index": 2, "chain index": 2}
2025-03-21T12:01:32.840Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:32.840Z	INFO	initializing dbft	{"height": 3, "view": 0, "index": 2, "role": "Backup"}
2025-03-21T12:01:32.840Z	DEBUG	reset timer	{"h": 3, "v": 0, "delay": "29.997206175s"}
2025-03-21T12:01:32.840Z	DEBUG	got msg	{"addr": "172.200.0.4:20334", "type": "CMDInv"}
2025-03-21T12:01:32.840Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:01:32.840Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:33.456Z	INFO	persisted to disk	{"blocks": 1, "keys": 19, "headerHeight": 2, "blockHeight": 2, "took": "7.413517ms"}
2025-03-21T12:01:45.359Z	INFO	peer disconnected	{"addr": "172.200.0.4:20334", "error": "EOF", "peerCount": 2}
2025-03-21T12:01:45.359Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetAddr"}
2025-03-21T12:01:45.359Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetAddr"}
2025-03-21T12:01:45.359Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDAddr"}
2025-03-21T12:01:45.359Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDAddr"}
2025-03-21T12:01:47.840Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:47.840Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:01:47.841Z	DEBUG	received message	{"from": 3, "type": "PrepareRequest"}
2025-03-21T12:01:47.841Z	DEBUG	received message	{"type": "PrepareRequest", "from": 3, "height": 3, "view": 0, "my_height": 3, "my_view": 0}
2025-03-21T12:01:47.841Z	INFO	received PrepareRequest	{"validator": 3, "tx": 0}
2025-03-21T12:01:47.841Z	INFO	sending PrepareResponse	{"height": 3, "view": 0}
2025-03-21T12:01:47.841Z	DEBUG	broadcasting message	{"type": "PrepareResponse", "height": 3, "view": 0}
2025-03-21T12:01:47.841Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:47.841Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:47.841Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDExtensible"}
2025-03-21T12:01:47.841Z	DEBUG	check preparations	{"hasReq": true, "count": 2, "M": 3}
2025-03-21T12:01:47.841Z	DEBUG	received message	{"from": 1, "type": "PrepareResponse"}
2025-03-21T12:01:47.841Z	DEBUG	received message	{"type": "PrepareResponse", "from": 1, "height": 3, "view": 0, "my_height": 3, "my_view": 0}
2025-03-21T12:01:47.841Z	INFO	received PrepareResponse	{"validator": 1}
2025-03-21T12:01:47.841Z	DEBUG	check preparations	{"hasReq": true, "count": 3, "M": 3}
2025-03-21T12:01:47.841Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:01:47.841Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:01:47.841Z	INFO	sending Commit	{"height": 3, "view": 0}
2025-03-21T12:01:47.841Z	DEBUG	broadcasting message	{"type": "Commit", "height": 3, "view": 0}
2025-03-21T12:01:47.841Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	reset timer	{"h": 3, "v": 0, "delay": "15s"}
2025-03-21T12:01:47.842Z	DEBUG	not enough to commit	{"count": 1}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDExtensible"}
2025-03-21T12:01:47.842Z	DEBUG	received message	{"from": 3, "type": "Commit"}
2025-03-21T12:01:47.842Z	DEBUG	received message	{"type": "Commit", "from": 3, "height": 3, "view": 0, "my_height": 3, "my_view": 0}
2025-03-21T12:01:47.842Z	INFO	received Commit	{"validator": 3}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	DEBUG	not enough to commit	{"count": 2}
2025-03-21T12:01:47.842Z	DEBUG	received message	{"from": 1, "type": "Commit"}
2025-03-21T12:01:47.842Z	DEBUG	received message	{"type": "Commit", "from": 1, "height": 3, "view": 0, "my_height": 3, "my_view": 0}
2025-03-21T12:01:47.842Z	INFO	received Commit	{"validator": 1}
2025-03-21T12:01:47.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:47.842Z	INFO	approving block	{"height": 3, "hash": "1f16cd2e1c030f9c58d0400190712bdc87567fdf7d453e6285737ac2c795a38e", "tx_count": 0, "merkle": "0000000000000000000000000000000000000000000000000000000000000000", "prev": "30bf61f7fc9c220861c7f3d22a7aa90a1f9de62509329138a99aaa99379ca9c9"}
2025-03-21T12:01:47.843Z	DEBUG	done processing headers	{"headerIndex": 3, "blockHeight": 2, "took": "327.847µs"}
2025-03-21T12:01:47.843Z	DEBUG	new block in the chain	{"dbft index": 3, "chain index": 3}
2025-03-21T12:01:47.843Z	INFO	initializing dbft	{"height": 4, "view": 0, "index": 2, "role": "Backup"}
2025-03-21T12:01:47.843Z	DEBUG	reset timer	{"h": 4, "v": 0, "delay": "29.998411749s"}
2025-03-21T12:01:47.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:01:47.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:01:48.463Z	INFO	persisted to disk	{"blocks": 1, "keys": 19, "headerHeight": 3, "blockHeight": 3, "took": "6.026797ms"}
2025-03-21T12:02:17.841Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:02:17.841Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:02:17.841Z	DEBUG	timer fired	{"height": 4, "view": 0}
2025-03-21T12:02:17.841Z	DEBUG	timeout	{"height": 4, "view": 0}
2025-03-21T12:02:17.841Z	DEBUG	reset timer	{"h": 4, "v": 0, "delay": "1m0s"}
2025-03-21T12:02:17.841Z	INFO	skip change view	{"nc": 0, "nf": 3}
2025-03-21T12:02:17.841Z	DEBUG	broadcasting message	{"type": "RecoveryRequest", "height": 4, "view": 0}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:02:17.842Z	DEBUG	received message	{"from": 3, "type": "RecoveryRequest"}
2025-03-21T12:02:17.842Z	DEBUG	received message	{"type": "RecoveryRequest", "from": 3, "height": 4, "view": 0, "my_height": 4, "my_view": 0}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDExtensible"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDExtensible"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:02:17.842Z	DEBUG	received message	{"from": 1, "type": "RecoveryRequest"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:02:17.842Z	DEBUG	received message	{"type": "RecoveryRequest", "from": 1, "height": 4, "view": 0, "my_height": 4, "my_view": 0}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:02:17.842Z	DEBUG	broadcasting message	{"type": "RecoveryMessage", "height": 4, "view": 0}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:02:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDExtensible"}
2025-03-21T12:02:17.843Z	DEBUG	received message	{"from": 3, "type": "RecoveryMessage", "#preparation": 0, "#commit": 0, "#changeview": 0, "#request": false, "#hash": false}
2025-03-21T12:02:17.843Z	DEBUG	received message	{"type": "RecoveryMessage", "from": 3, "height": 4, "view": 0, "my_height": 4, "my_view": 0}
2025-03-21T12:02:17.843Z	DEBUG	recovery message received	{"dump": {"Category":"dBFT","ValidBlockStart":0,"ValidBlockEnd":4,"Sender":"0xe9ed23b8a5557494f9ffa1a65a9a7a19166a2cc6","Data":"QQQAAAADAAAAAAAA","Witness":{"invocation":"DEBncGgMmrIJ66LwAI9u99fHtsaG39BluXfaD3b9Sed5Q29El7BknK3fsJFbrYLbpcp1MFtPXrk8ZIsHMZzzHrvs","verification":"DCED2QwH32PmkM53kS4Qq1GsyUS2aGAje2CMT4+DCece5plBVuezJw=="},"Type":65,"BlockIndex":4,"ValidatorIndex":3,"ViewNumber":0}}
2025-03-21T12:02:17.843Z	DEBUG	recovering finished cv=0/4 preq=0/0 presp=0/4 pco=0/4 co=0/4
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:02:17.843Z	DEBUG	received message	{"from": 1, "type": "RecoveryMessage", "#preparation": 0, "#commit": 0, "#changeview": 0, "#request": false, "#hash": false}
2025-03-21T12:02:17.843Z	DEBUG	received message	{"type": "RecoveryMessage", "from": 1, "height": 4, "view": 0, "my_height": 4, "my_view": 0}
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:02:17.843Z	DEBUG	recovery message received	{"dump": {"Category":"dBFT","ValidBlockStart":0,"ValidBlockEnd":4,"Sender":"0xc586f763445e4bb42386d7666244b5e765ca282b","Data":"QQQAAAABAAAAAAAA","Witness":{"invocation":"DEBTATDbr6Jrr0qfmhJz8EfSo1wYtpMzGHJRmCx7qTdEmZ8IW47R+IX9DE3sAHZGwmuWDJm6S92tQDQNj1a7xJ8u","verification":"DCECp7xV/oaE4BGXaNEEujB5W9zIZhnoZK3SYVZyPtGFzWJBVuezJw=="},"Type":65,"BlockIndex":4,"ValidatorIndex":1,"ViewNumber":0}}
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:02:17.843Z	DEBUG	recovering finished cv=0/4 preq=0/0 presp=0/4 pco=0/4 co=0/4
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:02:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:02:47.694Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:02:47.694Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:02:47.694Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:02:47.695Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:03:17.694Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:03:17.695Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:03:17.695Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:03:17.696Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:03:17.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:03:17.842Z	DEBUG	timer fired	{"height": 4, "view": 0}
2025-03-21T12:03:17.842Z	DEBUG	timeout	{"height": 4, "view": 0}
2025-03-21T12:03:17.842Z	DEBUG	reset timer	{"h": 4, "v": 0, "delay": "1m0s"}
2025-03-21T12:03:17.842Z	INFO	request change view	{"view": 0, "height": 4, "reason": "Timeout", "new_view": 1, "nc": 0, "nf": 1}
2025-03-21T12:03:17.842Z	DEBUG	broadcasting message	{"type": "ChangeView", "height": 4, "view": 0}
2025-03-21T12:03:17.842Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:03:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:03:17.842Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDExtensible"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:03:17.843Z	DEBUG	received message	{"from": 3, "type": "ChangeView"}
2025-03-21T12:03:17.843Z	DEBUG	received message	{"type": "ChangeView", "from": 3, "height": 4, "view": 0, "my_height": 4, "my_view": 0}
2025-03-21T12:03:17.843Z	INFO	received ChangeView	{"validator": 3, "reason": "Timeout", "new view": 1}
2025-03-21T12:03:17.843Z	DEBUG	received message	{"from": 1, "type": "ChangeView"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:03:17.843Z	DEBUG	received message	{"type": "ChangeView", "from": 1, "height": 4, "view": 0, "my_height": 4, "my_view": 0}
2025-03-21T12:03:17.843Z	INFO	received ChangeView	{"validator": 1, "reason": "Timeout", "new view": 1}
2025-03-21T12:03:17.843Z	INFO	changing dbft view	{"height": 4, "view": 1, "index": 2, "role": "Backup"}
2025-03-21T12:03:17.843Z	DEBUG	reset timer	{"h": 4, "v": 1, "delay": "0s"}
2025-03-21T12:03:17.843Z	DEBUG	timer fired	{"height": 4, "view": 1}
2025-03-21T12:03:17.843Z	DEBUG	timeout	{"height": 4, "view": 1}
2025-03-21T12:03:17.843Z	DEBUG	reset timer	{"h": 4, "v": 1, "delay": "2m0s"}
2025-03-21T12:03:17.843Z	INFO	skip change view	{"nc": 0, "nf": 3}
2025-03-21T12:03:17.843Z	DEBUG	broadcasting message	{"type": "RecoveryRequest", "height": 4, "view": 1}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	received message	{"from": 3, "type": "PrepareRequest"}
2025-03-21T12:03:17.843Z	DEBUG	received message	{"type": "PrepareRequest", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:03:17.843Z	INFO	received PrepareRequest	{"validator": 3, "tx": 0}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	INFO	sending PrepareResponse	{"height": 4, "view": 1}
2025-03-21T12:03:17.843Z	DEBUG	broadcasting message	{"type": "PrepareResponse", "height": 4, "view": 1}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:03:17.843Z	DEBUG	check preparations	{"hasReq": true, "count": 2, "M": 3}
2025-03-21T12:03:17.844Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:03:17.844Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:03:17.844Z	DEBUG	received message	{"from": 3, "type": "RecoveryMessage", "#preparation": 1, "#commit": 0, "#changeview": 3, "#request": true, "#hash": true}
2025-03-21T12:03:17.844Z	DEBUG	received message	{"type": "RecoveryMessage", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:03:17.844Z	DEBUG	recovery message received	{"dump": {"Category":"dBFT","ValidBlockStart":0,"ValidBlockEnd":4,"Sender":"0xe9ed23b8a5557494f9ffa1a65a9a7a19166a2cc6","Data":"QQQAAAADAQMBANISlriVAQAAQgxAC8UMxGhPaHgYr8XS6tEFxjGbHyqFnCa2S8WeOlp/kZh7aGq0GHN/H62uHl3Alhg7KWlxS+vJLeqQkUEmRzqHJQIA0hKWuJUBAABCDECtvKVtYo82h9P6BZgnmslTu9fvWnnzaZejpFAK/swT4kdVkWPstVXqx2YSSz4Dd4kpZT9KOjd3Ifjb/lHFMONAAwDREpa4lQEAAEIMQHS2VMBDWruO+S5u26dSTWyZlLSba96Tzfl5/c8Jo2toRALL02B/Ihqzhl7VPl0Qqx94ft5vvUFGce3xMRw1E5oBIAAAAAAAAQAAAAAfFs0uHAMPnFjQQAGQcSvch1Z/331FPmKFc3rCx5WjjtMSlriVAQAAQYbqOEjijVsAAQNCDECe/qkN7RIjGK2DYPUhou0Oyu0QXij3mBrSbgVGHCRGmuwexMna0Ye2UFZ/y2LfmzUhcFbUYSyU6nTj06lteImFAA==","Witness":{"invocation":"DECGvpCmxhIwUfKE51JkUFOmjY4htpCdgtZl9BW9Dob3CgI79SM+vflskx+qZKfqnR79bIOXGLZLb5AtzI+/HHpE","verification":"DCED2QwH32PmkM53kS4Qq1GsyUS2aGAje2CMT4+DCece5plBVuezJw=="},"Type":65,"BlockIndex":4,"ValidatorIndex":3,"ViewNumber":1}}
2025-03-21T12:03:17.844Z	DEBUG	received message	{"type": "PrepareResponse", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:03:17.844Z	DEBUG	ignoring PrepareResponse from primary node	{"from": 3}
2025-03-21T12:03:17.844Z	DEBUG	recovering finished cv=0/4 preq=0/0 presp=1/4 pco=0/4 co=0/4
2025-03-21T12:03:17.844Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:03:17.844Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:03:17.844Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:03:17.844Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:03:47.695Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:03:47.695Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:03:47.695Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:03:47.696Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:04:17.695Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:04:17.695Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:04:17.695Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:04:17.696Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:04:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:04:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:04:27.845Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:04:27.845Z	DEBUG	received message	{"from": 3, "type": "RecoveryRequest"}
2025-03-21T12:04:27.845Z	DEBUG	received message	{"type": "RecoveryRequest", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:04:47.695Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:04:47.696Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:04:47.696Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:04:47.697Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:05:17.696Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:05:17.696Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:05:17.696Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:05:17.697Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:05:27.843Z	DEBUG	timer fired	{"height": 4, "view": 1}
2025-03-21T12:05:27.843Z	DEBUG	timeout	{"height": 4, "view": 1}
2025-03-21T12:05:27.843Z	DEBUG	reset timer	{"h": 4, "v": 1, "delay": "2m0s"}
2025-03-21T12:05:27.843Z	INFO	skip change view	{"nc": 0, "nf": 2}
2025-03-21T12:05:27.843Z	DEBUG	broadcasting message	{"type": "RecoveryRequest", "height": 4, "view": 1}
2025-03-21T12:05:27.844Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:05:27.844Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:05:27.844Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:05:27.844Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:05:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:05:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:05:27.845Z	DEBUG	received message	{"from": 3, "type": "RecoveryMessage", "#preparation": 2, "#commit": 0, "#changeview": 3, "#request": true, "#hash": true}
2025-03-21T12:05:27.845Z	DEBUG	received message	{"type": "RecoveryMessage", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:05:27.845Z	DEBUG	recovery message received	{"dump": {"Category":"dBFT","ValidBlockStart":0,"ValidBlockEnd":4,"Sender":"0xe9ed23b8a5557494f9ffa1a65a9a7a19166a2cc6","Data":"QQQAAAADAQMBANISlriVAQAAQgxAC8UMxGhPaHgYr8XS6tEFxjGbHyqFnCa2S8WeOlp/kZh7aGq0GHN/H62uHl3Alhg7KWlxS+vJLeqQkUEmRzqHJQIA0hKWuJUBAABCDECtvKVtYo82h9P6BZgnmslTu9fvWnnzaZejpFAK/swT4kdVkWPstVXqx2YSSz4Dd4kpZT9KOjd3Ifjb/lHFMONAAwDREpa4lQEAAEIMQHS2VMBDWruO+S5u26dSTWyZlLSba96Tzfl5/c8Jo2toRALL02B/Ihqzhl7VPl0Qqx94ft5vvUFGce3xMRw1E5oBIAAAAAAAAQAAAAAfFs0uHAMPnFjQQAGQcSvch1Z/331FPmKFc3rCx5WjjtMSlriVAQAAQYbqOEjijVsAAgJCDECLneY53HBr/re9B7WYII85A54XkzfCUrytMN5O5dnrF2VtaDKbeBbkXLw66iqvG36r2t04NjUHwwVQ2uxpqMSjA0IMQJ7+qQ3tEiMYrYNg9SGi7Q7K7RBeKPeYGtJuBUYcJEaa7B7EydrRh7ZQVn/LYt+bNSFwVtRhLJTqdOPTqW14iYUA","Witness":{"invocation":"DEBi2OncGOazPZDmSf4TFbEWWSOmW4Gl22/G4IVS/uR2ciIYH997fsm1fsKcqsUz+zH6nP0kFOnWtnuEHOejUWFT","verification":"DCED2QwH32PmkM53kS4Qq1GsyUS2aGAje2CMT4+DCece5plBVuezJw=="},"Type":65,"BlockIndex":4,"ValidatorIndex":3,"ViewNumber":1}}
2025-03-21T12:05:27.845Z	DEBUG	received message	{"type": "PrepareResponse", "from": 2, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:05:27.845Z	DEBUG	ignoring PrepareResponse	{"dup": true, "sor": true, "viewChanging": false, "moreThanF": true}
2025-03-21T12:05:27.845Z	DEBUG	received message	{"type": "PrepareResponse", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:05:27.845Z	DEBUG	ignoring PrepareResponse from primary node	{"from": 3}
2025-03-21T12:05:27.845Z	DEBUG	recovering finished cv=0/4 preq=0/0 presp=2/4 pco=0/4 co=0/4
2025-03-21T12:05:27.845Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:05:27.845Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:05:47.696Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:05:47.697Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:05:47.697Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:05:47.698Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:06:17.697Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:06:17.697Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:06:17.697Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:06:17.698Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:06:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:06:27.846Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:06:27.846Z	DEBUG	received message	{"from": 3, "type": "RecoveryRequest"}
2025-03-21T12:06:27.846Z	DEBUG	received message	{"type": "RecoveryRequest", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:06:27.846Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:06:47.697Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:06:47.697Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:06:47.698Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:06:47.699Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:07:17.698Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:07:17.698Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:07:17.698Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:07:17.699Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:07:27.843Z	DEBUG	timer fired	{"height": 4, "view": 1}
2025-03-21T12:07:27.843Z	DEBUG	timeout	{"height": 4, "view": 1}
2025-03-21T12:07:27.844Z	DEBUG	reset timer	{"h": 4, "v": 1, "delay": "2m0s"}
2025-03-21T12:07:27.844Z	INFO	skip change view	{"nc": 0, "nf": 2}
2025-03-21T12:07:27.844Z	DEBUG	broadcasting message	{"type": "RecoveryRequest", "height": 4, "view": 1}
2025-03-21T12:07:27.844Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:07:27.844Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:07:27.845Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:07:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:07:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:07:47.698Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:07:47.698Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:07:47.698Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:07:47.699Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:08:17.699Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:08:17.699Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:08:17.699Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:08:17.700Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:08:27.846Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:08:27.846Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:08:27.847Z	DEBUG	received message	{"from": 3, "type": "RecoveryRequest"}
2025-03-21T12:08:27.847Z	DEBUG	received message	{"type": "RecoveryRequest", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:08:27.847Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:08:47.700Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:08:47.700Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:08:47.700Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:08:47.701Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:09:17.700Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:09:17.700Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:09:17.701Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:09:17.701Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:09:27.844Z	DEBUG	timer fired	{"height": 4, "view": 1}
2025-03-21T12:09:27.844Z	DEBUG	timeout	{"height": 4, "view": 1}
2025-03-21T12:09:27.844Z	DEBUG	reset timer	{"h": 4, "v": 1, "delay": "2m0s"}
2025-03-21T12:09:27.844Z	INFO	skip change view	{"nc": 0, "nf": 2}
2025-03-21T12:09:27.844Z	DEBUG	broadcasting message	{"type": "RecoveryRequest", "height": 4, "view": 1}
2025-03-21T12:09:27.845Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDGetData"}
2025-03-21T12:09:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDGetData"}
2025-03-21T12:09:27.845Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:09:27.845Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:09:27.846Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:09:47.701Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:09:47.701Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:09:47.702Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:09:47.702Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:10:17.702Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:10:17.702Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:10:17.702Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:10:17.702Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:10:27.846Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDInv"}
2025-03-21T12:10:27.847Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDExtensible"}
2025-03-21T12:10:27.847Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDInv"}
2025-03-21T12:10:27.847Z	DEBUG	received message	{"from": 3, "type": "RecoveryRequest"}
2025-03-21T12:10:27.847Z	DEBUG	received message	{"type": "RecoveryRequest", "from": 3, "height": 4, "view": 1, "my_height": 4, "my_view": 1}
2025-03-21T12:10:47.702Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:10:47.702Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:10:47.702Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:10:47.702Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:11:17.703Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPing"}
2025-03-21T12:11:17.703Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPing"}
2025-03-21T12:11:17.703Z	DEBUG	got msg	{"addr": "172.200.0.3:43780", "type": "CMDPong"}
2025-03-21T12:11:17.703Z	DEBUG	got msg	{"addr": "172.200.0.1:20336", "type": "CMDPong"}
2025-03-21T12:11:27.844Z	DEBUG	timer fired	{"height": 4, "view": 1}
2025-03-21T12:11:27.844Z	DEBUG	timeout	{"height": 4, "view": 1}
2025-03-21T12:11:27.844Z	DEBUG	reset timer	{"h": 4, "v": 1, "delay": "2m0s"}
2025-03-21T12:11:27.844Z	INFO	skip change view	{"nc": 0, "nf": 2}
2025-03-21T12:11:27.844Z	DEBUG	broadcasting message	{"type": "RecoveryRequest", "height": 4, "view": 1}

This reverts commit f7a23ed.

Draining is needed because there's a possibility that timer is requested to be reset with `0` delta:
https://github.com/nspcc-dev/dbft/blob/5281a9ae584e866e6dfa2a99313f7db6818c8e9d/dbft.go#L157-L159

Consider the situation when CV happens:  the timer will be reset in ChangeView message handler:
https://github.com/nspcc-dev/dbft/blob/5281a9ae584e866e6dfa2a99313f7db6818c8e9d/check.go#L179

Which means that dBFT eventloop is still busy with CV handling and can't read from the timer's channel (given that `d` is `0`):
https://github.com/nspcc-dev/dbft/blob/5281a9ae584e866e6dfa2a99313f7db6818c8e9d/timer/timer.go#L60-L65

And this channel has a buffer of `1` in case if it's internal Timer-bound
channel, which is not enough to finish CV processing. So we end up in a deadlock.

Signed-off-by: Anna Shaleva <shaleva.ann@nspcc.ru>
@roman-khimov roman-khimov merged commit 7462b47 into master Mar 21, 2025
11 of 12 checks passed
@roman-khimov roman-khimov deleted the fix-timer branch March 21, 2025 14:01
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.

2 participants