4

Yesterday we missed an endorsement. Upon investigations of our endorser logs:

Apr 18 23:20:53 - client.blocks: Saw head BLwEarjr2QpV
Apr 18 23:20:53 - client.endorsement: Received new block BLwEarjr2QpV
Apr 18 23:20:53 - client.endorsement: Checking if allowed to endorse block BLwEarjr2QpV for tbaker
Apr 18 23:20:53 - client.endorsement: No slot found for BLwEarjr2QpV/tbaker
Apr 18 23:20:53 - client.endorsement: Waiting until 2019-04-18T23:20:58Z (5s) to inject endorsements
Apr 18 23:20:58 - client.scheduling: Waking up for endorser.
Apr 18 23:23:10 - client.blocks: Saw head BLH13u3yntd7
Apr 18 23:23:10 - client.endorsement: Received new block BLH13u3yntd7

Above, there's an almost 2 minute gap between seeing BLwEarjr2QpV and BLH13u3yntd7. What's missing in between is BLT1fnWqW. Endorser just flat out skipped seeing it.

So we looked at the node log, since endorser gets information from node.

Apr 18 23:20:44 - validator.peer(29947): Worker terminated [NetXdQprcVkpa:idtXRW3QvUFA]
Apr 18 23:20:53 - validator.block: Block BLwEarjr2QpVvE27gpgoAqSe7Z5h5MEJCT4b3mJ4KFgPr55imJd successfully validated
Apr 18 23:20:53 - validator.block: Pushed: 2019-04-18T23:20:53Z, Treated: 2019-04-18T23:20:53Z, Completed: 2019-04-18T23:20:53Z
Apr 18 23:20:53 - prevalidator.NetXdQprcVkpa.PsddFKi32cMJ(1): switching to new head BLwEarjr2QpVvE27gpgoAqSe7Z5h5MEJCT4b3mJ4KFgPr55imJd
Apr 18 23:20:53 - prevalidator.NetXdQprcVkpa.PsddFKi32cMJ(1): Pushed: 2019-04-18T23:20:53Z, Treated: 2019-04-18T23:20:53Z, Completed: 2019-04-18T23:20:53Z
Apr 18 23:20:53 - validator.chain(1): Update current head to BLwEarjr2QpVvE27gpgoAqSe7Z5h5MEJCT4b3mJ4KFgPr55imJd (fitness 00::0000000000bf0afc), same branch
Apr 18 23:20:53 - validator.chain(1): Pushed: 2019-04-18T23:20:53Z, Treated: 2019-04-18T23:20:53Z, Completed: 2019-04-18T23:20:53Z
...
Apr 18 23:21:40 - validator.peer(29960): Worker started for NetXdQprcVkpa:idrEbUWhUuix
Apr 18 23:21:42 - validator.peer(29960): Worker terminated [NetXdQprcVkpa:idrEbUWhUuix]
Apr 18 23:21:55 - validator.block: Block BLT1fnWqWygbKRnwG6G17ntDTXfPb2oH9TkeDTthrErmBEgNaeD successfully validated
Apr 18 23:21:55 - validator.block: Pushed: 2019-04-18T23:21:54Z, Treated: 2019-04-18T23:21:54Z, Completed: 2019-04-18T23:21:55Z
Apr 18 23:21:55 - validator.peer(29961): Worker started for NetXdQprcVkpa:idqpZEwJJ67K
Apr 18 23:21:55 - validator.peer(29953): Worker terminated [NetXdQprcVkpa:idqyQm7QPWx8]
...
Apr 18 23:22:43 - validator.block: Block BLH13u3yntd7X4CChejM5F1zDfeBoKUWssbqqTBRFxPt2tDJ9xS successfully validated
Apr 18 23:22:43 - validator.block: Pushed: 2019-04-18T23:22:43Z, Treated: 2019-04-18T23:22:43Z, Completed: 2019-04-18T23:22:43Z
Apr 18 23:23:10 - prevalidator.NetXdQprcVkpa.PsddFKi32cMJ(1): switching to new head BLH13u3yntd7X4CChejM5F1zDfeBoKUWssbqqTBRFxPt2tDJ9xS
Apr 18 23:23:10 - prevalidator.NetXdQprcVkpa.PsddFKi32cMJ(1): Pushed: 2019-04-18T23:23:10Z, Treated: 2019-04-18T23:23:10Z, Completed: 2019-04-18T23:23:10Z
Apr 18 23:23:10 - validator.chain(1): Update current head to BLH13u3yntd7X4CChejM5F1zDfeBoKUWssbqqTBRFxPt2tDJ9xS (fitness 00::0000000000bf0b28), changing branch
Apr 18 23:23:10 - validator.chain(1): Pushed: 2019-04-18T23:22:43Z, Treated: 2019-04-18T23:22:43Z, Completed: 2019-04-18T23:23:10Z
Apr 18 23:23:11 - validator.peer(29968): Worker terminated [NetXdQprcVkpa:idrxsLJ2kPmy]
Apr 18 23:23:12 - validator.peer(29285): Worker terminated [NetXdQprcVkpa:idqb62apXCvN]

In the node logs, for BLwEarjr (at the top), you can see the block validated, then pushed, then switching to new head, pushed again, updating head to BLwEarjr, and pushed again.

In the middle section for BLT1fnW, there are not as many lines of output. I redacted a bunch 'Worker started/terminated' for brevity. This is the missing "problem" block.

The 3rd section, looks just like the top. So what happened in the middle with BLT1fnW? Why did my node not switch heads?

I cannot imagine this is a connectivity issue. We maintain 250-300 connections with scripts checking this every 15 minutes. The only thing of note is that we are running the nomadic-snapshots branch of the mainnet code.

1
  • 1
    One hypothesis: the node ignored the block because it was less fit than expected, e.g. an extra endorsement (not included in the block) arrived in your mempool just before the baked block arrived. Are you able to disconfirm? – Tom Apr 19 '19 at 15:00

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.