IntersectMBO / IntersectMBO/ouroboros-network
inverted logging order for block fetch process
- Dominant language
- Haskell
- Stars
- 296
- Forks
- 104
- Avg merge
- 2d 10h
- Merged PRs (30d)
- 4
Description
In rare cases (1-2 times per hour) the node seems to log `TraceAddBlockEvent.AddedToCurrentChain` before the first appearance of `CompletedBlockFetch`
This seems somehow reversed and impossible with the timestamps given.
For example
```
{"app":[],"at":"2022-12-13T10:32:53.10Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","blockNo":{"unBlockNo":8133942},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"12.34.56.92","port":"43441"},"remote":{"addr":"1.2.3.68","port":"3001"}},"slot":79361282},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"758372","sev":"Info","thread":"323"}
{"app":[],"at":"2022-12-13T10:32:53.10Z","data":{"head":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","kind":"SendFetchRequest","length":1,"peer":{"local":{"addr":"12.34.56.92","port":"43441"},"remote":{"addr":"1.2.3.68","port":"3001"}}},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"758372","sev":"Info","thread":"325"}
{"app":[],"at":"2022-12-13T10:32:53.13Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","blockNo":{"unBlockNo":8133942},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"12.34.56.92","port":"39153"},"remote":{"addr":"1.2.3.41","port":"6000"}},"slot":79361282},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"758372","sev":"Info","thread":"450"}
{"app":[],"at":"2022-12-13T10:32:53.14Z","data":{"head":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","kind":"SendFetchRequest","length":1,"peer":{"local":{"addr":"12.34.56.92","port":"39153"},"remote":{"addr":"35.158.110.41","port":"6000"}}},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"758372","sev":"Info","thread":"452"}
{"app":[],"at":"2022-12-13T10:32:53.14Z","data":{"chainLengthDelta":1,"kind":"TraceAddBlockEvent.AddedToCurrentChain","newtip":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19@79361282"},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainDB"],"pid":"758372","sev":"Notice","thread":"101"}
{"app":[],"at":"2022-12-13T10:32:53.15Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","blockNo":{"unBlockNo":8133942},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"12.34.56.92","port":"43429"},"remote":{"addr":"12.34.56.90","port":"6011"}},"slot":79361282},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"758372","sev":"Info","thread":"255"}
{"app":[],"at":"2022-12-13T10:32:53.15Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","delay":0.142282489,"kind":"CompletedBlockFetch","peer":{"local":{"addr":"12.34.56.92","port":"43441"},"remote":{"addr":"18.158.99.68","port":"3001"}},"size":871},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"758372","sev":"Info","thread":"324"}
{"app":[],"at":"2022-12-13T10:32:53.15Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","blockNo":{"unBlockNo":8133942},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"12.34.56.92","port":"36503"},"remote":{"addr":"1.2.3.55","port":"6001"}},"slot":79361282},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"758372","sev":"Info","thread":"175"}
{"app":[],"at":"2022-12-13T10:32:53.16Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","delay":0.162256288,"kind":"CompletedBlockFetch","peer":{"local":{"addr":"12.34.56.92","port":"39153"},"remote":{"addr":"35.158.110.41","port":"6000"}},"size":871},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"758372","sev":"Info","thread":"451"}
{"app":[],"at":"2022-12-13T10:32:53.16Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","blockNo":{"unBlockNo":8133942},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"12.34.56.92","port":"45017"},"remote":{"addr":"1.2.3.212","port":"6000"}},"slot":79361282},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"758372","sev":"Info","thread":"1085"}
{"app":[],"at":"2022-12-13T10:32:53.16Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","blockNo":{"unBlockNo":8133942},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"12.34.56.92","port":"42825"},"remote":{"addr":"1.2.3.183","port":"6000"}},"slot":79361282},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"758372","sev":"Info","thread":"694"}
{"app":[],"at":"2022-12-13T10:32:53.18Z","data":{"block":"c10908ea80f1dd92f90566d1c41d54a24100dec5a890da86de94140bbd286e19","blockNo":{"unBlockNo":8133942},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"12.34.56.92","port":"34027"},"remote":{"addr":"1.2.3.154","port":"3001"}},"slot":79361282},"env":"1.35.4:ebc7b","host":"relay04","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"758372","sev":"Info","thread":"236"}
```
Contributor guide
Assessment
This issue has not been assessed yet.