Digging into node log files tracing block production and propagation

Staking & Delegation Operate a Stake Pool
,
1

As cardano-node offers two predefined log formats (text and json) there is a general part about how leader events, block production and propagation appear in the logs, but two different solutions to identify/filter/show them by sing scripts.

The logfiles at Info level contain a few lines for every single slot (every second) but only a few of these 21k slots every 6 hours will contain blocks produced by the own node. So how to find them.

Counting the most used first keyword after source and datetime might is a first step to find the really interesting entries.

cat logs/node-0-20200527014136.log | awk '{print($5)}' | sort | uniq -c | sort -nr

The result effectively shows a whole forest of not interesting entries

  33982 fromList
  16182 aboutToLeadSlotLast
  16181 Testing
  16162 Not
  16161 nodeNotLeader
    691 [String
    689 Chain
     27 Block
     20 nodeIsLeader
     20 Leading
     20 forgedSlotLast
     20 Forged
     20 adoptedSlotLast
     20 Adopted
     13 Switched
      7 Valid
      7 Took

fortunately nodeIsLeader and his number partners Leading forgedSlotLastand Forged looks very promising.
So lookup the first appearance in the (text) logs

[ubs92:cardano.node.Forge.metrics:Critical:54] [2020-05-27 02:55:39.01 UTC] nodeIsLeader = 215739

We see it is about Slot 215739
Now we grep all events related to this slot

cat logs/node-0-20200527014136.log | grep 215739

and get a couple of lines showing us what the node (pool) did at that time

   [ubs92:cardano.node.Forge.metrics:Critical:54] [2020-05-27 02:55:39.00 UTC] aboutToLeadSlotLast = 215739
    [ubs92:cardano.node.Forge:Info:54] [2020-05-27 02:55:39.00 UTC] Testing for leadership at slot 215739
    [ubs92:cardano.node.ForgeTime:Info:54] [2020-05-27 02:55:39.00 UTC] fromList []
    [ubs92:cardano.node.Forge.metrics:Critical:54] [2020-05-27 02:55:39.01 UTC] nodeIsLeader = 215739
    [ubs92:cardano.node.Forge:Info:54] [2020-05-27 02:55:39.01 UTC] Leading slot 215739
    [ubs92:cardano.node.ForgeTime:Info:54] [2020-05-27 02:55:39.01 UTC] fromList []
    [ubs92:cardano.node.Forge.metrics:Critical:54] [2020-05-27 02:55:39.01 UTC] forgedSlotLast = 215739
    [ubs92:cardano.node.Forge:Info:54] [2020-05-27 02:55:39.01 UTC] Forged block for slot 215739
    [ubs92:cardano.node.ForgeTime:Info:54] [2020-05-27 02:55:39.01 UTC] fromList []
    [ubs92:cardano.node.ForgeTime:Info:54] [2020-05-27 02:55:39.01 UTC] fromList [("kind",String "OutcomeTraceForgeEvent"),("difftime",Number 2.47956e8),("slot",Number 215739.0),("mempoolbytes",Number 0.0),("mempoolnumtx",Number 0.0)]
    [ubs92:cardano.node.ChainDB:Notice:44] [2020-05-27 02:55:39.25 UTC] Chain extended, new tip: (Point 215739, HashHeader {unHashHeader = 75f10e88843bf1a0e065a7410a0ccdc089dec2d6cbbf45e1d555ef5e5cfec727})
    [ubs92:cardano.node:Info:54] [2020-05-27 02:55:39.25 UTC] fromList [("time(ps)",Number 2.184932424021119e18),("kind",String "MeasureTxsTimeStop"),("slot",Number 215739.0)]
    [ubs92:cardano.node.Forge.metrics:Critical:54] [2020-05-27 02:55:39.25 UTC] adoptedSlotLast = 215739
    [ubs92:cardano.node.Forge:Info:54] [2020-05-27 02:55:39.25 UTC] Adopted forged block for slot 215739: HashHeader {unHashHeader = 75f10e88843bf1a0e065a7410a0ccdc089dec2d6cbbf45e1d555ef5e5cfec727}; TxIds: []

the second half is interesting because it shows the unHasHeader (in this example “75f10e88843bf1a0e065a7410a0ccdc089dec2d6cbbf45e1d555ef5e5cfec727”)
which we can lookup in other nodes to verify it was broadcasted and accepted by the chain.

Now the same thing for JSON log format
First grep for nodeIsLeader, pick the slotnumber and grep for it to get all related json loglines.

{"at":"2020-05-27T08:13:45.00Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge.metrics"],"data":{"kind":"LogValue","value":{"tag":"PureI","contents":234825},"name":"aboutToLeadSlotLast"},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Critical","thread":"52"}
{"at":"2020-05-27T08:13:45.00Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge"],"data":{"kind":"TraceStartLeadershipCheck","slot":234825},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.00Z","env":"1.12.0:f6ef1","ns":["cardano.node.ForgeTime"],"data":{},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.03Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge.metrics"],"data":{"kind":"LogValue","value":{"tag":"PureI","contents":234825},"name":"nodeIsLeader"},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Critical","thread":"52"}
{"at":"2020-05-27T08:13:45.03Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge"],"data":{"kind":"TraceNodeIsLeader","slot":234825},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.03Z","env":"1.12.0:f6ef1","ns":["cardano.node.ForgeTime"],"data":{},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.03Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge.metrics"],"data":{"kind":"LogValue","value":{"tag":"PureI","contents":234825},"name":"forgedSlotLast"},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Critical","thread":"52"}
{"at":"2020-05-27T08:13:45.03Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge"],"data":{"kind":"TraceForgedBlock","slot":234825},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.03Z","env":"1.12.0:f6ef1","ns":["cardano.node.ForgeTime"],"data":{},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.03Z","env":"1.12.0:f6ef1","ns":["cardano.node.ForgeTime"],"data":{"kind":"OutcomeTraceForgeEvent","difftime":52036000,"slot":234825,"mempoolbytes":0,"mempoolnumtx":0},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.27Z","env":"1.12.0:f6ef1","ns":["cardano.node.ChainDB"],"data":{"kind":"TraceAddBlockEvent.AddedToCurrentChain","newtip":"HashHeader {unHashHeader = 9a9bd98d503df4dc363815af761dba6a25223d9d6dc41b6bf84738361364e5f7}@234825","headers":[{"hash":"HashHeader {unHashHeader = 9a9bd98d503df4dc363815af761dba6a25223d9d6dc41b6bf84738361364e5f7}","kind":"ShelleyBlock","blockNo":"8362","slotNo":"234825","prevhash":"HashHeader {unHashHeader = fee78599ca253feba0df94b36a1c913d673c9d55d87cbcd40260d89fe237cf99}"}]},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Notice","thread":"42"}
{"at":"2020-05-27T08:13:45.27Z","env":"1.12.0:f6ef1","ns":["cardano.node"],"data":{"time(ps)":2204018439295297000,"kind":"MeasureTxsTimeStop","slot":234825},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}
{"at":"2020-05-27T08:13:45.27Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge.metrics"],"data":{"kind":"LogValue","value":{"tag":"PureI","contents":234825},"name":"adoptedSlotLast"},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Critical","thread":"52"}
{"at":"2020-05-27T08:13:45.27Z","env":"1.12.0:f6ef1","ns":["cardano.node.Forge"],"data":{"kind":"TraceAdoptedBlock","slot":234825,"tx ids":[],"block hash":"HashHeader {unHashHeader = 9a9bd98d503df4dc363815af761dba6a25223d9d6dc41b6bf84738361364e5f7}"},"app":[],"msg":"","pid":"9642","loc":null,"host":"ubs92","sev":"Info","thread":"52"}

In case you wonder why not simply lookup (grep) for Chain extended text log lines or AddedToCurrentChain in json logs.
This not only shows your own blocks but also all others received from the network.

I believe the logfile lines can be improved for human readability and become more parser-friendly.

2 Likes
2

I think you are looking for the something like this:

# journalctl --since today | grep -c Forged
68

Or look for that number in prometheus:

# curl -s 0.0.0.0:12798/metrics/|grep Forged
cardano_node_metrics_blocksForgedNum_int 128
3

not really
I wanted to find the hashes of the produced blocks and verify on other nodes (connected over IOHK peers only) if I can see them, which seems is the case.

2 Likes
4

Ah sorry, I misunderstood. I do not think there is any way to check that adoption right now.

1 Like
5

the idea is to identify produced blocks and have relay nodes (or a complete external, remote, independent) node, I can query for the just produced block hash. if result is zero something (whatever) is wrong and needs human attention.

1 Like
6

Wouldn’t it be much easier to have a second log file directly from the node just for the block production with all needed infos? Feature request?

1 Like