CardanoSolutions/ogmios

Block in new fork sent before rollback event?

eddiemundo opened this issue · 4 comments

eddiemundo commented

What Git revision / release tag are you using?

d6e1164

Do you use any client SDK? If yes, which one?

None

Describe what the problem is?

We're using 5.5.5, and it looks like this might be already fixed in a newer version, but we noticed an instance where:

  1. a block goes onchain at slot A
  2. a different block goes onchain at slot A
  3. rollback event occurs to a slot < A

whereas we expected

  1. a block goes onchain at slot A
  2. rollback event occurs to a slot < A
  3. a different block goes onchain at slot A

Just want to know if something like this could be fixed by a newer version, or if it's supposed to be like that.

What should be the expected behavior?

  1. a block goes onchain at slot A
  2. rollback event occurs to a slot < A
  3. a different block goes onchain at slot A

If applicable, what are the logs from the server around the occurence of the problem?

Didn't have debug on in the logs so they dont show much but the logs in question. They are directly after the other.

{"severity":"Info","timestamp":"2023-08-27T22:39:07.276384843Z","thread":"960","message":{"Health":{"tag":"HealthTick","status":{"startTime":"2023-07-14T05:28:58.655292433Z","lastKnownTip":{"slot":101609656,"hash":"73fe2fcce8b685efa69cc037a687c6d47f7b42f06706ee0a2494397d3c3b5c39","blockNo":9214733},"lastTipUpdate":"2023-08-27T22:39:07.276116025Z","networkSynchronization":1.00000,"currentEra":"Babbage","metrics":{"activeConnections":2,"runtimeStats":{"cpuTime":14443407193305,"currentHeapSize":16227,"gcCpuTime":11124837668369,"maxHeapSize":16234},"sessionDurations":{"max":0,"mean":7.511538665811965e7,"min":0},"totalConnections":119,"totalMessages":372050,"totalUnrouted":0},"connectionStatus":"connected","currentEpoch":432,"slotInEpoch":348856}}},"version":"v5.5.5"}

{"severity":"Info","timestamp":"2023-08-27T22:39:07.541457027Z","thread":"960","message":{"Health":{"tag":"HealthTick","status":{"startTime":"2023-07-14T05:28:58.655292433Z","lastKnownTip":{"slot":101609656,"hash":"b7a061de5e247e48144492401c1342f4139d8e7e597df406eb799b5e60214152","blockNo":9214733},"lastTipUpdate":"2023-08-27T22:39:07.539957923Z","networkSynchronization":0.99999,"currentEra":"Babbage","metrics":{"activeConnections":2,"runtimeStats":{"cpuTime":14443411462184,"currentHeapSize":16227,"gcCpuTime":11124837668369,"maxHeapSize":16234},"sessionDurations":{"max":0,"mean":7.511538665811965e7,"min":0},"totalConnections":119,"totalMessages":372051,"totalUnrouted":0},"connectionStatus":"connected","currentEpoch":432,"slotInEpoch":348856}}},"version":"v5.5.5"}

edit: here are the corresponding node logs

[cardano-:cardano.node.ChainDB:Notice:4741] [2023-08-27 22:39:07.27 UTC] Chain extended, new tip: 73fe2fcce8b685efa69cc037a687c6d47f7b42f06706ee0a2494397d3c3b5c39 at slot 101609656
[cardano-:cardano.node.Mempool:Info:4749] [2023-08-27 22:39:07.27 UTC] fromList [("kind",String "TraceMempoolRemoveTxs"),("mempoolSize",Object (fromList [("bytes",Number 0.0),("numTxs",Number 0.0)])),("txs",Array [Object (fromList [("txid",String "ab611965")])])]
[cardano-:cardano.node.ChainDB:Info:4741] [2023-08-27 22:39:07.51 UTC] Block fits onto some fork: b7a061de5e247e48144492401c1342f4139d8e7e597df406eb799b5e60214152 at slot 101609656
[cardano-:cardano.node.ChainDB:Notice:4741] [2023-08-27 22:39:07.53 UTC] Switched to a fork, new tip: b7a061de5e247e48144492401c1342f4139d8e7e597df406eb799b5e60214152 at slot 101609656
[cardano-:cardano.node.ChainDB:Notice:4741] [2023-08-27 22:39:33.28 UTC] Chain extended, new tip: a22d516ba9309fda7fa13edc0e18bdd9a1e21a191253182482fa52c0f13d892e at slot 101609682
eddiemundo commented

Maybe this is my misunderstanding then.
It seems like
"block fits onto some fork: ..." is mapped to a RollForward block
"Switched to a fork..." is mapped to RollBackward point tip

This means I can't just wait until a RollBackward and then just repeatedly requestNext and expect to get every block of the new fork. The first block of the fork may have been a RollForward that happened before the RollBackward. I need to also consider whether an incoming block has replaced an existing block by comparing slots, or assume that the block before the RollBackward is part of the new fork? Doesn't seem right...

eddiemundo commented

Nevermind I think this was a bug on my side ew.

KtorZ commented

That is strange. Especially if this claim is true:

    a block goes onchain at slot A
    a different block goes onchain at slot A
    rollback event occurs to a slot < A

In principle, the local-chain-sync protocol is built so that clients can be completely "dumb". Clients can / should blindly follow the instructions from the server which is aware of where the client is at. So In the event of a rollback, the expected sequence from the server would be: RollForward (slot A) -> RollBackward (slot < A) -> RollForward (slot A). So your assumption is correct.

Now, I am asking "if this claim is true" because, this may also be due to how you process events in your application? Are you sure those events occured in this order and not in the expected order?

KtorZ commented

Nevermind I think this was a bug on my side ew.

Ah! 😌

  • 😄1