No blocks during the epoch for almost 5 minutes?!

Staking & Delegation Operate a Stake Pool
21

This is the error on my relay for the block I was supposed to produce:

{"app":[],"at":"2022-12-07T07:17:15.04Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.xxx.xxx.xxx","port":"44609"},"remote":{"addr":"77.20.194.126","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"3546"}

Than I see a lot of messages similar to this. RolledBack. Starts about 3 seconds later

{"app":[],"at":"2022-12-07T07:20:15.57Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.IPofRelay.xxx","port":"43693"},"remote":{"addr":"xxx.xxx.xxx.xxx","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34767"}
1 Like
22

Then I see a bunch of these:

{
    "app":[],"at":"2022-12-07T07:20:14.51Z","
    data":
    {
        "address":"10.10.110.50:6000",
        "event":"ErrorPolicySuspendConsumer (Just (ApplicationExceptionTrace ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyEra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Allegra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Mary StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (AlonzoEra StandardCrypto)) (': * (ShelleyBlock (Praos StandardCrypto) (BabbageEra StandardCrypto)) ('[] *))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyEra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Allegra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Mary StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (AlonzoEra StandardCrypto)) (': * (ShelleyBlock (Praos StandardCrypto) (BabbageEra StandardCrypto)) ('[] *))))))))) (ServerAgency TokNext TokMustReply))) 20s",
        "kind":"ErrorPolicyTrace"
    },
    "env":"1.35.3:950c4",
    "host":"bbhmm-re",
    "loc":null,
    "msg":"",
    "ns":["cardano.node.ErrorPolicy"],
    "pid":"1551935",
    "sev":"Notice",
    "thread":"240"
}
1 Like
23

so your pool was slot leader for 78831128 ?

1 Like
24

@werkof , I have really appreciated the insight and analytics.

As I sat back and thought about this for the future of Ouroborus and Cardano I would like retain secret leaders with a the block to block timing histogram looking like a normal distribution with a mean of 20.0s and a standard deviation of ~2s without any >5 sigma block timing anomalies. Iā€™m not happy with this long tail of uncertain block to block production timing. @Terminada is doing a CIP and Iā€™m trying to have a good influence on CIP-Leios. I believe we can make our blockchain run like clockworkā€¦

2 Likes
25

All my 7 relays use both topologyupdater AND about 20 custom peers. It looks like all the topology updater nodes fell off, although I am not sure. And as you can see in my peer graph I never lost all peers.

Our active stake is 50m+
All our relays have 20+ incoming connections. Some have 50+ incoming connections.

26

Can you provide log segments of that time range from 1-2relays? Also via DM

27

It was 78821181. Sorry, let me find those logs again.

28

@werkof from here - 78831181

29

@werkof - Here are my logs from BP and RELAY

FROM BP

{"app":[],"at":"2022-12-07T07:17:52.00Z","data":{"chainDensity":4.78205e-2,"credentials":"Cardano","delegMapSize":1237930,"kind":"TraceStartLeadershipCheck","slot":78831181,"utxoSize":9404848},"env":"1.35.3:950c4","host":"bbhmm-bp","loc":null,"msg":"","ns":["cardano.node.LeadershipCheck"],"pid":"1429","sev":"Info","thread":"214"}

{"app":[],"at":"2022-12-07T07:17:52.03Z","data":{"credentials":"Cardano","val":{"kind":"TraceNodeIsLeader","slot":78831181}},"env":"1.35.3:950c4","host":"bbhmm-bp","loc":null,"msg":"","ns":["cardano.node.Forge"],"pid":"1429","sev":"Info","thread":"214"}

{"app":[],"at":"2022-12-07T07:17:52.04Z","data":{"credentials":"Cardano","val":{"block":"15c3003320feb493e2a6eebeaa34d7c206dcb23c4bd8bbcc05443de542681803","blockNo":8107959,"blockPrev":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"TraceForgedBlock","slot":78831181}},"env":"1.35.3:950c4","host":"bbhmm-bp","loc":null,"msg":"","ns":["cardano.node.Forge"],"pid":"1429","sev":"Info","thread":"214"}

{"app":[],"at":"2022-12-07T07:17:52.05Z","data":{"block":{"hash":"15c3003320feb493e2a6eebeaa34d7c206dcb23c4bd8bbcc05443de542681803","kind":"Point","slot":78831181},"kind":"TraceAddBlockEvent.TrySwitchToAFork"},"env":"1.35.3:950c4","host":"bbhmm-bp","loc":null,"msg":"","ns":["cardano.node.ChainDB"],"pid":"1429","sev":"Info","thread":"204"}

{"app":[],"at":"2022-12-07T07:17:52.05Z","data":{"credentials":"Cardano","val":{"kind":"TraceDidntAdoptBlock","slot":78831181}},"env":"1.35.3:950c4","host":"bbhmm-bp","loc":null,"msg":"","ns":["cardano.node.Forge"],"pid":"1429","sev":"Error","thread":"214"}

FROM RELAY

{"app":[],"at":"2022-12-07T07:16:59.32Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"45157"},"remote":{"addr":"104.248.117.19","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"29278"}

{"app":[],"at":"2022-12-07T07:16:59.33Z","data":{"head":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"SendFetchRequest","length":1,"peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"45157"},"remote":{"addr":"104.248.117.19","port":"6000"}}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"1551935","sev":"Info","thread":"29280"}

{"app":[],"at":"2022-12-07T07:16:59.36Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"36415"},"remote":{"addr":"5.161.53.97","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"13801"}

{"app":[],"at":"2022-12-07T07:16:59.36Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"35363"},"remote":{"addr":"133.125.37.175","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"7400"}

{"app":[],"at":"2022-12-07T07:16:59.37Z","data":{"head":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"SendFetchRequest","length":1,"peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"36415"},"remote":{"addr":"5.161.53.97","port":"6000"}}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"1551935","sev":"Info","thread":"13803"}

{"app":[],"at":"2022-12-07T07:16:59.38Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"34325"},"remote":{"addr":"155.138.221.106","port":"3001"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"9248"}

{"app":[],"at":"2022-12-07T07:16:59.40Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"43833"},"remote":{"addr":"143.198.34.140","port":"3001"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"295"}

{"app":[],"at":"2022-12-07T07:16:59.41Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"41971"},"remote":{"addr":"xxx.relay2.IP.xxx","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"9596"}

{"app":[],"at":"2022-12-07T07:16:59.41Z","data":{"head":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"SendFetchRequest","length":1,"peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"41971"},"remote":{"addr":"xxx.relay2.IP.xxx","port":"6000"}}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"1551935","sev":"Info","thread":"9593"}

{"app":[],"at":"2022-12-07T07:16:59.43Z","data":{"chainLengthDelta":1,"kind":"TraceAddBlockEvent.AddedToCurrentChain","newtip":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac@78831128"},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainDB"],"pid":"1551935","sev":"Notice","thread":"222"}

{"app":[],"at":"2022-12-07T07:16:59.43Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","delay":0.41568095,"kind":"CompletedBlockFetch","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"41971"},"remote":{"addr":"xxx.relay2.IP.xxx","port":"6000"}},"size":13761},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"1551935","sev":"Info","thread":"9592"}

{"app":[],"at":"2022-12-07T07:16:59.44Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","delay":0.441174506,"kind":"CompletedBlockFetch","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"45157"},"remote":{"addr":"104.248.117.19","port":"6000"}},"size":13761},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"1551935","sev":"Info","thread":"29279"}

{"app":[],"at":"2022-12-07T07:16:59.44Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"46229"},"remote":{"addr":"xxx.BP.IP.xxx","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"414"}

{"app":[],"at":"2022-12-07T07:16:59.47Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"33519"},"remote":{"addr":"23.91.85.93","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"7387"}

{"app":[],"at":"2022-12-07T07:16:59.47Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","delay":0.478012583,"kind":"CompletedBlockFetch","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"36415"},"remote":{"addr":"5.161.53.97","port":"6000"}},"size":13761},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.BlockFetchClient"],"pid":"1551935","sev":"Info","thread":"13802"}

{"app":[],"at":"2022-12-07T07:16:59.54Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"38205"},"remote":{"addr":"138.68.252.24","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"9924"}

{"app":[],"at":"2022-12-07T07:16:59.55Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"40301"},"remote":{"addr":"82.165.61.251","port":"6001"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"7465"}

{"app":[],"at":"2022-12-07T07:16:59.56Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"43249"},"remote":{"addr":"62.171.160.73","port":"3001"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"537"}

{"app":[],"at":"2022-12-07T07:16:59.58Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"39113"},"remote":{"addr":"34.96.187.194","port":"1338"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"524"}

{"app":[],"at":"2022-12-07T07:16:59.60Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"38377"},"remote":{"addr":"145.1.205.128","port":"5999"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"509"}

{"app":[],"at":"2022-12-07T07:16:59.62Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"34207"},"remote":{"addr":"149.102.131.186","port":"3001"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"31284"}

{"app":[],"at":"2022-12-07T07:16:59.64Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"46097"},"remote":{"addr":"213.34.102.83","port":"6001"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"562"}

{"app":[],"at":"2022-12-07T07:16:59.69Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"44609"},"remote":{"addr":"77.20.194.126","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"3546"}

{"app":[],"at":"2022-12-07T07:16:59.76Z","data":{"block":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","blockNo":{"unBlockNo":8107958},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"39223"},"remote":{"addr":"3.17.232.35","port":"6000"}},"slot":78831128},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"3590"}

{"app":[],"at":"2022-12-07T07:17:14.50Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"41971"},"remote":{"addr":"xxx.relay2.IP.xxx","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"9596"}

{"app":[],"at":"2022-12-07T07:17:14.50Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"46229"},"remote":{"addr":"xxx.BP.IP.xxx","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"414"}

{"app":[],"at":"2022-12-07T07:17:14.51Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"43833"},"remote":{"addr":"143.198.34.140","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"295"}

{"app":[],"at":"2022-12-07T07:17:14.52Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"45157"},"remote":{"addr":"104.248.117.19","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"29278"}

{"app":[],"at":"2022-12-07T07:17:14.55Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"36415"},"remote":{"addr":"5.161.53.97","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"13801"}

{"app":[],"at":"2022-12-07T07:17:14.58Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"34325"},"remote":{"addr":"155.138.221.106","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"9248"}

{"app":[],"at":"2022-12-07T07:17:14.64Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"33519"},"remote":{"addr":"23.91.85.93","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"7387"}

{"app":[],"at":"2022-12-07T07:17:14.71Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"39223"},"remote":{"addr":"3.17.232.35","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"3590"}

{"app":[],"at":"2022-12-07T07:17:14.73Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"38205"},"remote":{"addr":"138.68.252.24","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"9924"}

{"app":[],"at":"2022-12-07T07:17:14.83Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"40301"},"remote":{"addr":"82.165.61.251","port":"6001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"7465"}

{"app":[],"at":"2022-12-07T07:17:14.85Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"43249"},"remote":{"addr":"62.171.160.73","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"537"}

{"app":[],"at":"2022-12-07T07:17:14.86Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"34207"},"remote":{"addr":"149.102.131.186","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"31284"}

{"app":[],"at":"2022-12-07T07:17:14.91Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"38377"},"remote":{"addr":"145.1.205.128","port":"5999"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"509"}

{"app":[],"at":"2022-12-07T07:17:14.92Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"35363"},"remote":{"addr":"133.125.37.175","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"7400"}

{"app":[],"at":"2022-12-07T07:17:15.03Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"39113"},"remote":{"addr":"34.96.187.194","port":"1338"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"524"}

{"app":[],"at":"2022-12-07T07:17:15.04Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"44609"},"remote":{"addr":"77.20.194.126","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"3546"}

{"app":[],"at":"2022-12-07T07:17:15.25Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"46097"},"remote":{"addr":"213.34.102.83","port":"6001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"562"}

{"app":[],"at":"2022-12-07T07:20:15.69Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"37677"},"remote":{"addr":"143.198.34.140","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34781"}

{"app":[],"at":"2022-12-07T07:20:15.74Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"46101"},"remote":{"addr":"3.17.232.35","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34794"}

{"app":[],"at":"2022-12-07T07:20:35.58Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"45035"},"remote":{"addr":"155.138.221.106","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34841"}

{"app":[],"at":"2022-12-07T07:20:36.10Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"45811"},"remote":{"addr":"149.102.131.186","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34866"}

{"app":[],"at":"2022-12-07T07:21:00.03Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"40165"},"remote":{"addr":"145.1.205.128","port":"5999"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34943"}

{"app":[],"at":"2022-12-07T07:21:00.06Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"33033"},"remote":{"addr":"77.20.194.126","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34956"}

{"app":[],"at":"2022-12-07T07:21:00.23Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"44187"},"remote":{"addr":"133.125.37.175","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34969"}

{"app":[],"at":"2022-12-07T07:21:19.54Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"41781"},"remote":{"addr":"xxx.relay2.IP.xxx","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"34997"}

{"app":[],"at":"2022-12-07T07:21:20.08Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"38971"},"remote":{"addr":"82.165.61.251","port":"6001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"35030"}

{"app":[],"at":"2022-12-07T07:21:37.07Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"34445"},"remote":{"addr":"xxx.BP.IP.xxx","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"35068"}

{"app":[],"at":"2022-12-07T07:21:46.13Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"46815"},"remote":{"addr":"34.96.187.194","port":"1338"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"35175"}

{"app":[],"at":"2022-12-07T07:21:47.27Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"43191"},"remote":{"addr":"5.161.53.97","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"35218"}

{"app":[],"at":"2022-12-07T07:21:47.27Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"40253"},"remote":{"addr":"104.248.117.19","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"35197"}

{"app":[],"at":"2022-12-07T07:21:47.33Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"39437"},"remote":{"addr":"138.68.252.24","port":"6000"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"35246"}

{"app":[],"at":"2022-12-07T07:21:47.70Z","data":{"kind":"ChainSyncClientEvent.TraceRolledBack","peer":{"local":{"addr":"xxx.relay1.IP.xxx","port":"43193"},"remote":{"addr":"62.171.160.73","port":"3001"}},"tip":{"headerHash":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"BlockPoint","slot":78831128}},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Notice","thread":"35258"}
30

Correct. I also lost a block, ā€œslotā€: 78831317, ā€œslotInEpochā€: 34517, ā€œatā€: ā€œ2022-12-07T08:20:08+01:00ā€ to be exact. All my relays are using hand-picked peers only. I have also been wondering what had happened during this periodā€¦ See my grafana output below (I donā€™t have the node logs anymore).

image

1 Like
31

You show similar stats as I had.
So thatā€™s the 3rth block that was lost during this period. I donā€™t understand how we could lose the blocks while we had hand picked relays (and I also had 15 topologyupdater relays).

1 Like
32

I donā€™t have a clear answer here.
A fundamental concept of Ouroboros is randomness (S.Micaliā€™s VRF) and a random-related slot leader election. Not exactly predictable but on average not less dense than a ā€œclockworkā€ setup.

Albeit the discussion about changes and potential improved behaviour is important, I - for now - will focus first on the request from the so far 3 SPOs reporting their blocks not adopted.

We had the last block (8107959) before this ā€œpauseā€ at 07:17:15am GMT for slot 78831144
Then the next block (8107960) was adopted at 07:21:59am GMT for slot 78831428
So 284 Seconds or almost 5 minutes without a new block adopted on chain

One such potential block was scheduled for slot at 07:17:52am GMT as reported by @BBHMM

This was 37 seconds after the previous block, and so before nodes will have started dropping and re-establishing connections.

It becomes interesting at the block producers log:

At relay sideā€™s logs, there is no trace for block 15c3003320feb493e2a6eebeaa34d7c206dcb23c4bd8bbcc05443de542681803
So this block has never left the producer, because it already failed at the own local adoption stage.
His logs say he run v1.35.3 builds.

We have another reported slotleader event by @staking4ada.org for slot 78831317 at 07:20:08am GMT

Itā€™s still not clear to me which slot was scheduled for @ADA4Good but it looks to me like he mentioned to run v1.35.4 builds.

Not sure if you guys still have the block producing nodesā€™ logs from 6 days ago. would be interesting to see your TraceNodeIsLeader and following loglines. Was the block adopted locally, and if yes did it appear then on your relays?

3 Likes
33

Unfortunately no logs anymore, but in gliveview I remember the block was marked as ā€œinvalidā€. I am running cardano-node 1.35.4 - linux-x86_64 - ghc-8.10, git rev ebc7be471b30e5931b35f9bbc236d21c375b91bb.

34

My slot was 78831351 and yes, all nodes on 1.35.4

{"app":[],"at":"2022-12-07T07:20:42.00Z","data":{"chainDensity":4.78205e-2,"credentials":"test123","delegMapSize":1237930,"kind":"TraceStartLeadershipCheck","slot":78831351,"utxoSize":9404848},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.LeadershipCheck"],"pid":"82143","sev":"Info","thread":"375"}
{"app":[],"at":"2022-12-07T07:20:42.03Z","data":{"credentials":"test123","val":{"kind":"TraceNodeIsLeader","slot":78831351}},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.Forge"],"pid":"82143","sev":"Info","thread":"375"}
{"app":[],"at":"2022-12-07T07:20:42.05Z","data":{"credentials":"test123","val":{"block":"0a22def6da84e6fc0e65ee2d96ce0086a5d25c176d9ce056f066fe529ce0d139","blockNo":8107959,"blockPrev":"9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aac","kind":"TraceForgedBlock","slot":78831351}},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.Forge"],"pid":"82143","sev":"Info","thread":"375"}
{"app":[],"at":"2022-12-07T07:20:42.06Z","data":{"chainLengthDelta":1,"kind":"TraceAddBlockEvent.AddedToCurrentChain","newtip":"14aa389d1f9ac49a50b4991ce24f2e0c276f22143bbfead582f5cff63bfa1e1c@78831144"},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.ChainDB"],"pid":"82143","sev":"Notice","thread":"365"}
{"app":[],"at":"2022-12-07T07:20:42.06Z","data":{"kind":"LogValue","name":"before next, messages elided","value":{"contents":427653286419604,"tag":"PureI"}},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.ChainDB"],"pid":"82143","sev":"Notice","thread":"365"}
{"app":[],"at":"2022-12-07T07:20:42.06Z","data":{"chainLengthDelta":1,"kind":"TraceAddBlockEvent.AddedToCurrentChain","newtip":"14aa389d1f9ac49a50b4991ce24f2e0c276f22143bbfead582f5cff63bfa1e1c@78831144"},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.ChainDB"],"pid":"82143","sev":"Notice","thread":"365"}
{"app":[],"at":"2022-12-07T07:20:42.06Z","data":{"block":{"hash":"0a22def6da84e6fc0e65ee2d96ce0086a5d25c176d9ce056f066fe529ce0d139","kind":"Point","slot":78831351},"kind":"TraceAddBlockEvent.TrySwitchToAFork"},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.ChainDB"],"pid":"82143","sev":"Info","thread":"365"}
{"app":[],"at":"2022-12-07T07:20:42.06Z","data":{"credentials":"test123","val":{"kind":"TraceDidntAdoptBlock","slot":78831351}},"env":"1.35.4:ebc7b","host":"BPxxx","loc":null,"msg":"","ns":["cardano.node.Forge"],"pid":"82143","sev":"Error","thread":"375"}
1 Like
35

Thanks for the detailed analysis of the logs.

Adding a bit more logs from my relay after the block was forged on my BP. My first logs were sent in from the relay on time before where I Greped the block ā€œ9c1a0cbe38f4a32ef55a0426dcacfcb8bf005defdca46710e5d5a7f0fc193aacā€ matching the BP block. So maybe that is not useful and not sure why that would show up before the forge. Anyways here are some logs on the relay after the forge.
Also my relays are on the same LAN as BP, so no external WAN hops.

{"app":[],"at":"2022-12-07T07:17:52.05Z","data":{"block":"14aa389d1f9ac49a50b4991ce24f2e0c276f22143bbfead582f5cff63bfa1e1c","blockNo":{"unBlockNo":8107959},"kind":"ChainSyncClientEvent.TraceDownloadedHeader","peer":{"local":{"addr":"xxx.relay.IP.xxx","port":"46229"},"remote":{"addr":"xxx.BP.IP.xxx","port":"6000"}},"slot":78831144},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ChainSyncClient"],"pid":"1551935","sev":"Info","thread":"414"}

Then I see about 15 events like this.

{"app":[],"at":"2022-12-07T07:18:04.00Z","data":{"address":"139.144.61.192:6758","event":"ErrorPolicySuspendPeer (Just (ApplicationExceptionTrace (MuxError MuxBearerClosed \"<socket: 50> closed when reading data, waiting on next header True\"))) 20s 20s","kind":"ErrorPolicyTrace"},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"1551935","sev":"Warning","thread":"259"}

{"app":[],"at":"2022-12-07T07:18:15.34Z","data":{"address":"206.81.13.177:50096","event":"ErrorPolicySuspendPeer (Just (ApplicationExceptionTrace (MuxError MuxBearerClosed \"<socket: 57> closed when reading data, waiting on next header True\"))) 20s 20s","kind":"ErrorPolicyTrace"},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"1551935","sev":"Warning","thread":"259"}

{"app":[],"at":"2022-12-07T07:18:17.57Z","data":{"address":"139.144.33.70:36034","event":"ErrorPolicySuspendPeer (Just (ApplicationExceptionTrace (MuxError MuxBearerClosed \"<socket: 40> closed when reading data, waiting on next header True\"))) 20s 20s","kind":"ErrorPolicyTrace"},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"1551935","sev":"Warning","thread":"259"}

Then about 3 seconds after I start seeing more of these


{"app":[],"at":"2022-12-07T07:20:14.51Z","data":{"address":"xxx.realy4.IP.xxx:41537","event":"ErrorPolicySuspendPeer (Just (ApplicationExceptionTrace (MuxError (MuxIOException Network.Socket.recvBuf: resource vanished (Connection reset by peer)) \"(recv errored)\"))) 20s 20s","kind":"ErrorPolicyTrace"},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"1551935","sev":"Warning","thread":"259"}`

{"app":[],"at":"2022-12-07T07:20:14.51Z","data":{"address":"xxx.realy4.IP.xxx:6000","event":"ErrorPolicySuspendConsumer (Just (ApplicationExceptionTrace ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyEra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Allegra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Mary StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (AlonzoEra StandardCrypto)) (': * (ShelleyBlock (Praos StandardCrypto) (BabbageEra StandardCrypto)) ('[] *))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyEra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Allegra StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (ShelleyMAEra 'Mary StandardCrypto)) (': * (ShelleyBlock (TPraos StandardCrypto) (AlonzoEra StandardCrypto)) (': * (ShelleyBlock (Praos StandardCrypto) (BabbageEra StandardCrypto)) ('[] *))))))))) (ServerAgency TokNext TokMustReply))) 20s","kind":"ErrorPolicyTrace"},"env":"1.35.3:950c4","host":"bbhmm-re","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"1551935","sev":"Notice","thread":"240"}
36

Interesting! Exact same behaviour.

At https://input-output-hk.github.io/ouroboros-network/ouroboros-consensus/Ouroboros-Consensus-NodeKernel.html there are 3 possible outcomes for TraceForgedBlock

  • TraceAdoptedBlock (normally)
  • TraceDidntAdoptBlock (rarely)
  • TraceForgedInvalidBlock (hopefully never ā€“ this would indicate a bug)

ā€¦and this particular description for TraceDidntAdoptBlock

We did not adopt the block we produced, but the block was valid. We must have adopted a block that another leader of the same slot produced before we got the chance of adopting our own block. This is very rare, this warrants a warning.

Interesting because this ā€œrarelyā€ seems to have happened for around 15 slot leaders in a row.

3 Likes
37

Iā€™m only loosely following this thread, but as far as I understood, there were no blocks at all in these five minutes. How could there then have been a block of another leader?

1 Like
38

The blocks were forged but not adopted. Why were all these blocks not adopted during those 5 minutes.

3 Likes
39

These are the questions.

There is maybe more in a more complete log sequence. For example some of the previously shared log snippets had rollbacks, that didnā€™t make sense to me. But I would need more context and time to look into.

2 Likes
40

Sounds more and more like a bug to me. Somehow all block producers independently of each other seem to erroneously think they already adopted a block for the slot they were assigned. All in the same five minute window, but all in different slots in that window.

3 Likes