IntersectMBO / IntersectMBO/ouroboros-network

inverted logging order for block fetch process

Open
#4,226 1 comment 0 reactions 0 assignees View on GitHub
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.