Comments (4)
roman-khimov
commented on August 16, 2024
2336997 is a boring regular one:
Oct 14 21:11:23 267045 neogo-n3c[20321]: 2022-10-14T21:11:23.117+0300#011INFO#011initializing dbft#011{"height": 2336997, "view": 0, "index": 5, "role": "Primary"}
Oct 14 21:11:23 267045 neogo-n3c[20321]: 2022-10-14T21:11:23.201+0300#011INFO#011persisted to disk#011{"blocks": 1, "keys": 24, "headerHeight": 2336996, "blockHeight": 2336996, "took": "5.128348ms"}
Oct 14 21:11:27 267045 neogo-n3c[20321]: 2022-10-14T21:11:27.203+0300#011INFO#011persisted to disk#011{"blocks": 0, "keys": 2, "headerHeight": 2336996, "blockHeight": 2336996, "took": "3.861498ms"}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.076+0300#011INFO#011sending PrepareRequest#011{"height": 2336997, "view": 0}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.482+0300#011INFO#011received PrepareResponse#011{"validator": 4}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.494+0300#011INFO#011received PrepareResponse#011{"validator": 2}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.532+0300#011INFO#011received PrepareResponse#011{"validator": 1}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.533+0300#011INFO#011received PrepareResponse#011{"validator": 0}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.534+0300#011INFO#011sending Commit#011{"height": 2336997, "view": 0}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.878+0300#011INFO#011received Commit#011{"validator": 2}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.887+0300#011INFO#011received Commit#011{"validator": 1}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.981+0300#011INFO#011received Commit#011{"validator": 0}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.989+0300#011INFO#011received Commit#011{"validator": 4}
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.989+0300#011INFO#011approving block#011{"height": 2336997, "hash": "dbb0913c32edd179d9d7e85315de92f5166060ade658b9efe7e620efd1fe9ab4", "tx_count": 1, "merkle": "a95b9f9ed242bcb10cb8aebef6a4e705756dba4876839dc85ebd84bd024a7e48", "prev": "740f5278d7011ec045e2545ed9ad9ae92dcb02ec5cfbbad3a8e78505ed27ad22"}
2336998 is a bit more interesting:
Oct 14 21:11:39 267045 neogo-n3c[20321]: 2022-10-14T21:11:39.039+0300#011INFO#011initializing dbft#011{"height": 2336998, "view": 0, "index": 5, "role": "Backup"}
Oct 14 21:11:39 267045 neogo-n3c[20321]: 2022-10-14T21:11:39.213+0300#011INFO#011persisted to disk#011{"blocks": 1, "keys": 102, "headerHeight": 2336997, "blockHeight": 2336997, "took": "4.97205ms"}
Oct 14 21:11:45 267045 neogo-n3c[20321]: 2022-10-14T21:11:45.217+0300#011INFO#011persisted to disk#011{"blocks": 0, "keys": 2, "headerHeight": 2336997, "blockHeight": 2336997, "took": "3.608943ms"}
Oct 14 21:12:08 267045 neogo-n3c[20321]: 2022-10-14T21:12:08.989+0300#011INFO#011skip change view#011{"nc": 0, "nf": 6}
Oct 14 21:12:09 267045 neogo-n3c[20321]: 2022-10-14T21:12:09.463+0300#011INFO#011received ChangeView#011{"validator": 1, "reason": "Timeout", "new view": 1}
Oct 14 21:12:09 267045 neogo-n3c[20321]: 2022-10-14T21:12:09.564+0300#011INFO#011received ChangeView#011{"validator": 0, "reason": "Timeout", "new view": 1}
Oct 14 21:12:09 267045 neogo-n3c[20321]: 2022-10-14T21:12:09.961+0300#011INFO#011received ChangeView#011{"validator": 2, "reason": "Timeout", "new view": 1}
Oct 14 21:12:11 267045 neogo-n3c[20321]: 2022-10-14T21:12:11.201+0300#011INFO#011received ChangeView#011{"validator": 4, "reason": "Timeout", "new view": 1}
Oct 14 21:13:08 267045 neogo-n3c[20321]: 2022-10-14T21:13:08.990+0300#011INFO#011request change view#011{"view": 0, "height": 2336998, "reason": "Timeout", "new_view": 1, "nc": 0, "nf": 1}
Oct 14 21:13:08 267045 neogo-n3c[20321]: 2022-10-14T21:13:08.991+0300#011INFO#011changing dbft view#011{"height": 2336998, "view": 1, "index": 5, "role": "Primary"}
Oct 14 21:13:08 267045 neogo-n3c[20321]: 2022-10-14T21:13:08.991+0300#011INFO#011sending PrepareRequest#011{"height": 2336998, "view": 1}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.409+0300#011INFO#011received PrepareResponse#011{"validator": 2}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.446+0300#011INFO#011received PrepareResponse#011{"validator": 1}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.456+0300#011INFO#011received PrepareResponse#011{"validator": 0}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.493+0300#011INFO#011received PrepareResponse#011{"validator": 4}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.494+0300#011INFO#011sending Commit#011{"height": 2336998, "view": 1}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.903+0300#011INFO#011received Commit#011{"validator": 0}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.929+0300#011INFO#011received Commit#011{"validator": 1}
Oct 14 21:13:09 267045 neogo-n3c[20321]: 2022-10-14T21:13:09.942+0300#011INFO#011received Commit#011{"validator": 4}
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.225+0300#011INFO#011received PrepareResponse#011{"validator": 3}
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.391+0300#011INFO#011received Commit#011{"validator": 0}
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.391+0300#011INFO#011received Commit#011{"validator": 1}
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.391+0300#011INFO#011received Commit#011{"validator": 4}
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.391+0300#011INFO#011received Commit#011{"validator": 5}
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.583+0300#011INFO#011received Commit#011{"validator": 3}
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.584+0300#011INFO#011approving block#011{"height": 2336998, "hash": "69b7bfde3dedebe667846a3a5798b09630a21528b67f91a19472fe201757d324", "tx_count": 2, "merkle": "2493ffa02ef83ddc6ccdb4517d8eeecc48640e6177194916dc774b18767ee446", "prev": "dbb0913c32edd179d9d7e85315de92f5166060ade658b9efe7e620efd1fe9ab4"}
One simple view change and we're done. It just happened so that for this block/view number combination our node is the one to create PrepareRequest. The only thing that might be interesting is this line:
Oct 14 21:12:08 267045 neogo-n3c[20321]: 2022-10-14T21:12:08.989+0300#011INFO#011skip change view#011{"nc": 0, "nf": 6}
but that's neo-project/neo#2057, the node has not seen any traffic from other nodes, so it's a little shy to send CV, instead it sends a recovery requests and waits for other messages. Then 4 CVs are delivered and then after the second timer event (+60 seconds) it feels brave enough to join the CV party.
I would expect this validator to only propose a new block after exponential time, i.e., waiting a lot longer than 90 seconds (6*15 seconds, with 15 seconds block time).
I think this expectation is not a correct one, once we're past 15s blocks will be produced right after the view change (if primary node is alive for this view of course). Exponential backoff doesn't mean that the first view change will happen after 6*15, in fact it could happen right after 30s, but then timers will be adjusted to give more and more time after each CV.
The current assumption is that the 6 validators that run a C# node could somehow not manage to include an OracleResponse for the corresponding previous OracleRequest in a block, i.e., there might be an issue with the Oracle plugin there
- While technically it's possible to have an oracle node that at the same time is a CN, I don't think that's the setup we have (at least at NSPCC those are two different node instances). And if they're properly separated, then CNs get the response transaction via P2P, they don't care much about what oracle nodes do to create this transaction.
- In this particular case it's one C# node that failed to create a proposal for a new block. It happens, maybe it was down at this moment, not the end of the world. I'd worry if I'm to see that this happens with every oracle request/response, but I doubt that's the case, at least in some previous tests we've seen C# nodes including oracle response transactions into blocks without any issues.
from neo-node.
mialbu
commented on August 16, 2024
Hey @roman-khimov thanks for the logs and the explanation! Okay, then it seems everything is fine. 🙏🏼
So, just to get this straight:
As the NSPCC node was speaker for the last block, it sets its timeout to 15 << 0+1 (=30s) with view=0. So, after not receiving anything until this timeout was reached, i.e., 30s after the last block was approved, it sent a recovery request (skip change view log).
T21:11:38.989 (0s)
Oct 14 21:11:38 267045 neogo-n3c[20321]: 2022-10-14T21:11:38.989+0300#011INFO#011approving block#011{"height": 2336997, "hash": "dbb0913c32edd179d9d7e85315de92f5166060ade658b9efe7e620efd1fe9ab4", "tx_count": 1, "merkle": "a95b9f9ed242bcb10cb8aebef6a4e705756dba4876839dc85ebd84bd024a7e48", "prev": "740f5278d7011ec045e2545ed9ad9ae92dcb02ec5cfbbad3a8e78505ed27ad22"}
T21:12:08.989 (+30s)
Oct 14 21:12:08 267045 neogo-n3c[20321]: 2022-10-14T21:12:08.989+0300#011INFO#011skip change view#011{"nc": 0, "nf": 6}
Then, the timeout is set to 15 << 1+1 (= 60s), and 60s after that recovery request, the node actually changes the view (request change view and changing dbft view logs) and then immediately sends a PrepareRequest to propose the next block.
T21:13:08.990 (+60s -> +90s in total)
Oct 14 21:13:08 267045 neogo-n3c[20321]: 2022-10-14T21:13:08.990+0300#011INFO#011request change view#011{"view": 0, "height": 2336998, "reason": "Timeout", "new_view": 1, "nc": 0, "nf": 1}
Oct 14 21:13:08 267045 neogo-n3c[20321]: 2022-10-14T21:13:08.991+0300#011INFO#011changing dbft view#011{"height": 2336998, "view": 1, "index": 5, "role": "Primary"}
Oct 14 21:13:08 267045 neogo-n3c[20321]: 2022-10-14T21:13:08.991+0300#011INFO#011sending PrepareRequest#011{"height": 2336998, "view": 1}
...
Oct 14 21:13:11 267045 neogo-n3c[20321]: 2022-10-14T21:13:11.584+0300#011INFO#011approving block#011{"height": 2336998, "hash": "69b7bfde3dedebe667846a3a5798b09630a21528b67f91a19472fe201757d324", "tx_count": 2, "merkle": "2493ffa02ef83ddc6ccdb4517d8eeecc48640e6177194916dc774b18767ee446", "prev": "dbb0913c32edd179d9d7e85315de92f5166060ade658b9efe7e620efd1fe9ab4"}
Note: By now, I know for a fact that actually a node was not running at the time.
Did I get this right?
from neo-node.
roman-khimov
commented on August 16, 2024
Yep, that's how it all has happened.
from neo-node.
mialbu
commented on August 16, 2024
Yep, that's how it all has happened.
All right, thanks for verifying. 👍🏼
from neo-node.
Related Issues (20)
- node: Testnet blockcount stuck at 558261 HOT 1
- state height HOT 2
- node: How to get transaction more a details ? HOT 2
- Please provide release for Mac Apple Silicon
- Neo-Cli - Ubuntu 20.04 LTS support
- node: macOs monterey support HOT 3
- Mode System HOT 3
- Neo CLI v3.3.0 - LevelDBStore was not found in the dictionary
- I'm stuck at 290070 HOT 7
- "BindAddress": "0.0.0.0", 配置这个参数 并安装rpc-server 插件 仍然不能被其他机器访问
- neo 节点开放rpc的时候 安装了插件 配置 BindAddress:"0.0.0.0" 不生效. ./neo-cli 启动
- node: get application log 2022/07/13 20:13:27 Unknown transaction/blockhash (-100) - , ???????? , ???????????? ???????? HOT 2
- node: not syncing HOT 5
- node: 3.4.0 ????????? HOT 4
- node: The given key 'LevelDBStore' was not present in the dictionary. HOT 2
- Neo node is down
- neo-cli not ssynchronizating
- node: docker cant run HOT 2
- Arithmetic operation resulted in an overflow. HOT 1
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from neo-node.