workbench | macOS: node fails with divide-by-zero

[deepfire]

@mgmeier reported that running the default profile (make default-autostay) fails on macOS, with nodes bombing out with a divide by zero exception:

workbench:  run:  allocated 2022-08-24-08.20.9b5fe.default-bage @ /Users/michael/IOG/cardano-node/run/2022-08-24-08.20.9b5fe.default-bage
  - run dir:         /Users/michael/IOG/cardano-node/run/2022-08-24-08.20.9b5fe.default-bage
  - profile JSON:    /Users/michael/IOG/cardano-node/run/2022-08-24-08.20.9b5fe.default-bage/profile.json
  - node specs:      /Users/michael/IOG/cardano-node/run/2022-08-24-08.20.9b5fe.default-bage/node-specs.json
  - topology:        /Users/michael/IOG/cardano-node/run/2022-08-24-08.20.9b5fe.default-bage/topology/topology.pdf
  - node base port:  30000
  - RTView URL:              http://localhost:30300
  - EKG URL (node-0):        http://localhost:30100/
  - Prometheus URL (node-0): http://localhost:30200/metrics
  - era:                babbage
  - epoch slots:        600
  - slot duration:      1
  - k:                  3
  - active slots coeff: 0.05
  - hosts:              6
  - pools:              6
    - normal:             6
    - dense:              0
  - UTxO:               0, of which:
    - delegated:          6
    - generated:          43200
    - stuffed:            0
  - delegators:         6
  - generator duration: 1800s
    - requested epochs:   3ep
    - effective epochs:   3ep
    - transaction count:  22kTx
    - full blocks:        119


workbench:  run:  starting 2022-08-24-08.20.9b5fe.default-bage
workbench:  run | scenario:  starting fixed-loaded
tracer: started
workbench:  supervisor:  waiting for cardano-tracer to create socket:OK
node-0: ERROR (spawn error)
node-1: ERROR (spawn error)
node-2: ERROR (spawn error)
node-3: ERROR (spawn error)
node-4: ERROR (spawn error)
node-5: ERROR (spawn error)

workbench:  scenario:  exit trap triggered
tracer: stopped

[deepfire]

Michael also provided these node log files:

2022-08-24-07.50.9b5fe.default-bage_logs_node0.tar.gz

[deepfire]

Ok, so the node fails prior to the tracing system initialisation -- this is the last two lines in stdout, after the config dump:

New tracer configuration: TraceConfig {tcOptions = fromList [([],[ConfSeverity {severity = Notice},ConfBackend {backends = [Stdout MachineFormat,EKGBackend,Forwarder]}]),(["BlockFetch","Client"],[ConfSeverity {severity = Info},ConfDetail {detail = DMinimal}]),(["BlockFetch","Client","CompletedBlockFetch"],[ConfLimiter {maxFrequency = 2.0}]),(["BlockFetch","Server"],[ConfSeverity {severity = Info}]),(["ChainDB"],[ConfSeverity {severity = Info}]),(["ChainDB","AddBlockEvent","AddBlockValidation","ValidCandidate"],[ConfLimiter {maxFrequency = 2.0}]),(["ChainDB","AddBlockEvent","AddedBlockToQueue"],[ConfLimiter {maxFrequency = 2.0}]),(["ChainDB","AddBlockEvent","AddedBlockToVolatileDB"],[ConfLimiter {maxFrequency = 2.0}]),(["ChainDB","CopyToImmutableDBEvent","CopiedBlockToImmutableDB"],[ConfLimiter {maxFrequency = 2.0}]),(["ChainSync","Client"],[ConfSeverity {severity = Info},ConfDetail {detail = DMinimal}]),(["ChainSync","ServerBlock"],[ConfSeverity {severity = Info}]),(["ChainSync","ServerHeader"],[ConfSeverity {severity = Info}]),(["Forge"],[ConfSeverity {severity = Info}]),(["Mempool"],[ConfSeverity {severity = Info}]),(["Net","AcceptPolicy"],[ConfSeverity {severity = Info}]),(["Net","DNSResolver"],[ConfSeverity {severity = Info}]),(["Net","ErrorPolicy"],[ConfSeverity {severity = Info}]),(["Net","Subscription"],[ConfSeverity {severity = Info}]),(["Resources"],[ConfSeverity {severity = Info}]),(["Startup","DiffusionInit"],[ConfSeverity {severity = Info}]),(["TxSubmission","Remote"],[ConfDetail {detail = DMinimal}])], tcForwarder = TraceOptionForwarder {tofConnQueueSize = 2000, tofDisconnQueueSize = 200000, tofVerbosity = Minimum}, tcNodeName = Nothing, tcPeerFrequency = Nothing, tcResourceFrequency = Nothing}
"connection with \"../tracer/tracer.socket\" failed: divide by zero"

[mgmeier]

• All nodes of a local cluster fail the exact same way
• smoking gun from a node's stderr: cardano-node: ExceptionInLinkedThread (ThreadId 16) divide by zero
• smoking gun from a node's stdout: "connection with \"../tracer/tracer.socket\" failed: divide by zero" after New tracer configuration: TraceConfig {..}

[deepfire]

Full logs:

2022-08-24-07.50.9b5fe.default-bage_logs.tar.gz

[deepfire]

Stack:

1. https://github.com/input-output-hk/cardano-node/blob/bench-master2/trace-dispatcher/src/Cardano/Logging/Utils.hs#L20
2. https://github.com/input-output-hk/cardano-node/blob/bench-master2/trace-dispatcher/src/Cardano/Logging/Forwarding.hs#L135-L147
3. https://github.com/input-output-hk/cardano-node/blob/bench-master2/trace-dispatcher/src/Cardano/Logging/Forwarding.hs#L164-L167
4. Ouroboros.Network.Socket.connectToNode: https://github.com/input-output-hk/cardano-node/blob/bench-master2/trace-dispatcher/src/Cardano/Logging/Forwarding.hs#L183-L198

I don't see any divisions on this code path..

[deepfire]

Another puzzling bit is that runInLoop is expected to gobble up this exception and continue. Yet the node dies (which, in this case is a good outcome, since we have a correctness failure, not a correctable runtime failure) -- but only after the trace IO action succeeds?!:

https://github.com/input-output-hk/cardano-node/blob/bench-master2/trace-dispatcher/src/Cardano/Logging/Utils.hs#L18-L23

[coot]

The divide by zero exception is thrown in some thread, it could be that this exception is propagated to the main thread (with something like link which wrapps exceptions in ExceptionInLinkedThread), which you're tryJust does not handle (as it ignore all async exceptions), and thus the runInLoop errors.

[mgmeier]

The node's resource tracer started a linked async thread in startResourceTracer which in the end, on Darwin, queried readResourceStatsInternal from Darwin.hsc. This faulty calculation caused a division-by-zero: https://github.com/input-output-hk/cardano-node/blob/bench-master2/trace-resources/src/Cardano/Logging/Resources/Darwin.hsc#L108-L109

The remaining issue is why Darwin reports user_time and system_time as zero at all, which will be handled seperately.