Peer stuck trying to enter a safe state.

[karknu]

While trying to reproduce the poison pig attack with cardano-ignite one of my peers got stuck trying to enter the safe state.

    "targets": {
      "active": 0,
      "activeBigLedgerPeers": 0,
      "established": 0,
      "establishedBigLedgerPeers": 0,
      "knownBigLedgerPeers": 0,
      "knownPeers": 0,
      "roots": 0
    },
    "ledgerStateJudgement": "TooOld",

In the debug data it claims to have 172.16.4.122 as hot. But there is no traffic to that peer when checking TCP dump and ss doesn’t list that socket.
The peer itself was last mentioned about 24h ago.

{"app":[],"at":"2025-12-04T11:35:48.893Z","data":{"connectionId":{"localAddress":{"address":"172.16.4.104","port":"3001"},"remoteAddress":{"address":"172.16.4.122","port":"3001"}},"kind":"PeerMonitoringError","reason":"MiniProtocolExceptions [MiniProtocolException {mpeMiniProtocolNumber = MiniProtocolNum 2, mpeMiniProtocolException = ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) ServerHasAgency (SingNext SingMustReply)}]"},"env":"10.5.3:00000","host":"p3r3","loc":null,"msg":"","ns":["cardano.node.PeerSelectionActions"],"pid":"128","sev":"Error","thread":"5153"}
{"app":[],"at":"2025-12-04T11:35:48.893Z","data":{"kind":"PeerStatusChangeFailure","peerStatusChangeType":"HotToCooling (ConnectionId {localAddress = 172.16.4.104:3001, remoteAddress = 172.16.4.122:3001})","reason":"ApplicationFailure [MiniProtocolException {mpeMiniProtocolNumber = MiniProtocolNum 2, mpeMiniProtocolException = ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) ServerHasAgency (SingNext SingMustReply)}]"},"env":"10.5.3:00000","host":"p3r3","loc":null,"msg":"","ns":["cardano.node.PeerSelectionActions"],"pid":"128","sev":"Error","thread":"6513"}
{"app":[],"at":"2025-12-04T11:45:48.895Z","data":{"actualActive":1,"kind":"DemoteHotFailed","peer":{"address":"172.16.4.122","port":"3001"},"reason":"DemotionTimeoutException (Just (MiniProtocolExceptions [MiniProtocolException {mpeMiniProtocolNumber = MiniProtocolNum 2, mpeMiniProtocolException = ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) ServerHasAgency (SingNext SingMustReply)}]))","targetActive":0},"env":"10.5.3:00000","host":"p3r3","loc":null,"msg":"","ns":["cardano.node.PeerSelection"],"pid":"128","sev":"Info","thread":"59"}
{"app":[],"at":"2025-12-04T11:45:48.895Z","data":{"kind":"DemoteAsynchronous","state":[[{"address":"172.16.4.122","port":"3001"},["PeerCooling",null]]]},"env":"10.5.3:00000","host":"p3r3","loc":null,"msg":"","ns":["cardano.node.PeerSelection"],"pid":"128","sev":"Info","thread":"59"}

I suspect that the node has failed to enter a safe state after 20minutes without blocks. The 15minute timeout for entering safe mode also didn't trigger.

stuck.log

[crocodile-dentist]

On line 5193 in the log:

{"app":[],"at":"2025-12-04T11:45:48.895Z","data":{"actualActive":1,"kind":"DemoteHotFailed","peer":{"address":"172.16.4.122","port":"3001"},"reason":"DemotionTimeoutException (Just (MiniProtocolExceptions [MiniProtocolException {mpeMiniProtocolNumber = MiniProtocolNum 2, mpeMiniProtocolException = ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) ServerHasAgency (SingNext SingMustReply)}]))","targetActive":0},"env":"10.5.3:00000","host":"p3r3","loc":null,"msg":"","ns":["cardano.node.PeerSelection"],"pid":"128","sev":"Info","thread":"59"}

Looks like some async demotion bug perhaps? I wonder if my changes in #5167 would have prevented this.

[crocodile-dentist]

Looking at the logs, there doesn't appear that the governor had to do anything after that as it was the last outbound peer at that point, and so there wasn't another loop go-around to respond to the timeout.

[crocodile-dentist]

There's also these two traces:

{"app":[],"at":"2025-12-04T11:35:48.892Z","data":{"kind":"PeerStatusChangeFailure","peerStatusChangeType":"HotToCooling (ConnectionId {localAddress = 172.16.4.104:3001, remoteAddress = 172.16.4.122:3001})","reason":"ApplicationFailure [MiniProtocolException {mpeMiniProtocolNumber = MiniProtocolNum 2, mpeMiniProtocolException = ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) ServerHasAgency (SingNext SingMustReply)}]"},"env":"10.5.3:00000","host":"p3r3","loc":null,"msg":"","ns":["cardano.node.PeerSelectionActions"],"pid":"128","sev":"Error","thread":"5153"}
...
{"app":[],"at":"2025-12-04T11:35:48.893Z","data":{"kind":"PeerStatusChangeFailure","peerStatusChangeType":"HotToCooling (ConnectionId {localAddress = 172.16.4.104:3001, remoteAddress = 172.16.4.122:3001})","reason":"ApplicationFailure [MiniProtocolException {mpeMiniProtocolNumber = MiniProtocolNum 2, mpeMiniProtocolException = ExceededTimeLimit (ChainSync (Header (HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) (Tip HardForkBlock (': * ByronBlock (': * (ShelleyBlock (TPraos StandardCrypto) ShelleyEra) (': * (ShelleyBlock (TPraos StandardCrypto) AllegraEra) (': * (ShelleyBlock (TPraos StandardCrypto) MaryEra) (': * (ShelleyBlock (TPraos StandardCrypto) AlonzoEra) (': * (ShelleyBlock (Praos StandardCrypto) BabbageEra) (': * (ShelleyBlock (Praos StandardCrypto) ConwayEra) ('[] *)))))))))) ServerHasAgency (SingNext SingMustReply)}]"},"env":"10.5.3:00000","host":"p3r3","loc":null,"msg":"","ns":["cardano.node.PeerSelectionActions"],"pid":"128","sev":"Error","thread":"6513"}

It could be a race between OG hot demotion and peerMonitoringLoop.

I'd imagine that the failure was first detected by peerMonitoringLoop, which traced the first message above, and then it did:

              PeerCooling -> do
                waitForOutboundDemotion spsConnectionManager pchConnectionId
                writeTVar pchPeerStatus PeerCold
                return Nothing

But the demotion job reset pchPeerStatus via a call to `deactivatePeerConnection':

        Just (SomeErrored errs) -> do
          -- we don't need to notify the connection manager, we can instead
          -- relay on mux property: if any of the mini-protocols errors, mux
          -- throws an exception as well.
          atomically (writeTVar pchPeerStatus PeerCooling) <--- here
          traceWith spsTracer (PeerStatusChangeFailure
                                (HotToCooling pchConnectionId)
                                (ApplicationFailure errs))
          throwIO (MiniProtocolExceptions errs)

But the check requires PeerCold in ActivePeers:

    handler :: SomeException -> m (Completion m extraState extraDebugState extraFlags extraPeers extraTrace peeraddr peerconn)
    handler e = do
      -- cf. issue #5111 - we wait for the connection to be forgotten by the CM
      -- before we return. Otherwise, if the same peer is promoted too quickly by
      -- eg. churn, the connection will fail.
      (timeoutFault, e') <- do
        res <-
          timeout c_PEER_DEMOTION_TIMEOUT $
                  atomically $
                    monitorPeerConnection peerconn >>= check . (== PeerCold) . fst
        case res of
          Nothing -> return (True, toException $ DemotionTimeoutException (Just e))
          Just _ -> return (False, e)

[edit] I guard against this in #5167 so if this is the root cause then it would not have happened with that patch.