|
| 1 | +{-# LANGUAGE LambdaCase #-} |
| 2 | +{-# LANGUAGE NumericUnderscores #-} |
| 3 | + |
| 4 | +-- | A background watchdog that fails the test as soon as the testnet chain has |
| 5 | +-- provably stalled forever, whatever the test happens to be waiting on. |
| 6 | +-- |
| 7 | +-- A @cardano-testnet@ chain permanently stops producing blocks whenever no block is |
| 8 | +-- forged for longer than the ledger view forecast horizon (see |
| 9 | +-- 'chainForecastHorizon'). |
| 10 | +module Testnet.ChainWatchdog |
| 11 | + ( ChainStallException (..) |
| 12 | + , chainForecastHorizon |
| 13 | + , chainStallTimeoutFromHorizon |
| 14 | + , chainStallWatchdog |
| 15 | + ) where |
| 16 | + |
| 17 | +import Cardano.Api (BlockNo (..), ChainTip (..), LocalNodeConnectInfo, |
| 18 | + ShelleyGenesis (..), SlotNo (..), getLocalChainTip) |
| 19 | + |
| 20 | +import qualified Cardano.Ledger.BaseTypes as SL |
| 21 | +import qualified Cardano.Ledger.Shelley.Genesis as SL |
| 22 | +import qualified Cardano.Ledger.Shelley.StabilityWindow as SL |
| 23 | + |
| 24 | +import Prelude |
| 25 | + |
| 26 | +import Control.Concurrent (ThreadId, threadDelay, throwTo) |
| 27 | +import Control.Exception (Exception (..), SomeAsyncException, SomeException, |
| 28 | + asyncExceptionFromException, asyncExceptionToException, throwIO, try) |
| 29 | +import Control.Monad (void, when) |
| 30 | +import Data.Maybe (isJust, isNothing) |
| 31 | +import qualified Data.Time.Clock as DTC |
| 32 | +import System.IO (hFlush, hPutStrLn, stderr) |
| 33 | +import System.Process (ProcessHandle) |
| 34 | +import System.Timeout (timeout) |
| 35 | + |
| 36 | +import Testnet.Process.Run (hardKillProcess) |
| 37 | + |
| 38 | +-- | Thrown to the test thread when the chain has irrecoverably stalled. Registered |
| 39 | +-- as an asynchronous exception (like the exceptions of 'Control.Exception.AsyncException') |
| 40 | +-- so that handlers for synchronous errors inside tests do not accidentally swallow it. |
| 41 | +newtype ChainStallException = ChainStallException String |
| 42 | + |
| 43 | +instance Show ChainStallException where |
| 44 | + show (ChainStallException msg) = msg |
| 45 | + |
| 46 | +instance Exception ChainStallException where |
| 47 | + toException = asyncExceptionToException |
| 48 | + fromException = asyncExceptionFromException |
| 49 | + |
| 50 | +-- | The ledger view forecast horizon of the chain described by the given genesis: |
| 51 | +-- @3 * securityParam / activeSlotsCoeff@ slots (the stability window), converted to |
| 52 | +-- wall-clock time. Nodes can only forge while the wall-clock slot is at most this far |
| 53 | +-- past the chain tip, so a chain that has not forged for longer than this can never |
| 54 | +-- produce a block again. |
| 55 | +chainForecastHorizon :: ShelleyGenesis -> DTC.NominalDiffTime |
| 56 | +chainForecastHorizon sg = |
| 57 | + fromIntegral horizonSlots * SL.fromNominalDiffTimeMicro (sgSlotLength sg) |
| 58 | + where |
| 59 | + horizonSlots = |
| 60 | + SL.computeStabilityWindow |
| 61 | + (SL.unNonZero $ sgSecurityParam sg) |
| 62 | + (SL.mkActiveSlotCoeff $ sgActiveSlotsCoeff sg) |
| 63 | + |
| 64 | +-- | Stall detection threshold for a chain with the given forecast horizon: twice the |
| 65 | +-- horizon (a chain quiet for longer than the horizon is already irrecoverable; the |
| 66 | +-- factor and the 60s floor absorb block-interval variance and detection latency). |
| 67 | +chainStallTimeoutFromHorizon :: DTC.NominalDiffTime -> DTC.NominalDiffTime |
| 68 | +chainStallTimeoutFromHorizon horizon = max 60 (2 * horizon) |
| 69 | + |
| 70 | +-- | Watch the chain through the given node connection and, when it has made no progress |
| 71 | +-- for 'chainStallTimeoutFromHorizon' of the genesis, fail the given test thread with |
| 72 | +-- a 'ChainStallException' explaining the mechanism. |
| 73 | +-- |
| 74 | +-- The full diagnosis is printed to stderr first: stderr bypasses tasty's buffered |
| 75 | +-- reporting, so the explanation is visible even if the test never manages to report |
| 76 | +-- a result. 'throwTo' blocks until the exception is delivered; if the test thread |
| 77 | +-- cannot receive it (it is stuck in a foreign call or under |
| 78 | +-- 'Control.Exception.uninterruptibleMask'), the watchdog escalates after a grace |
| 79 | +-- period by hard-killing the node processes, so that whatever the test is blocked |
| 80 | +-- on fails with an ordinary synchronous error instead. |
| 81 | +-- |
| 82 | +-- Run it in a background thread (e.g. with 'Testnet.Runtime.asyncRegister_'); it is |
| 83 | +-- stopped by cancellation like any other background resource. |
| 84 | +chainStallWatchdog |
| 85 | + :: ShelleyGenesis -- ^ the genesis backing the testnet, for the stall threshold |
| 86 | + -> LocalNodeConnectInfo -- ^ connection to the node whose chain tip is polled |
| 87 | + -> [ProcessHandle] -- ^ the testnet node processes, for the kill escalation |
| 88 | + -> ThreadId -- ^ the test thread to fail when the chain stalls |
| 89 | + -> IO () |
| 90 | +chainStallWatchdog shelleyGenesis connectInfo nodeHandles testThread = do |
| 91 | + start <- DTC.getCurrentTime |
| 92 | + go start Nothing |
| 93 | + where |
| 94 | + horizon = chainForecastHorizon shelleyGenesis |
| 95 | + stallTimeout = chainStallTimeoutFromHorizon horizon |
| 96 | + |
| 97 | + go lastAdvance lastPoint = do |
| 98 | + threadDelay pollIntervalMicros |
| 99 | + mPoint <- queryTip |
| 100 | + now <- DTC.getCurrentTime |
| 101 | + case mPoint of |
| 102 | + Just point | Just point /= lastPoint -> |
| 103 | + -- the tip moved: restart the stall clock |
| 104 | + go now (Just point) |
| 105 | + _ | now `DTC.diffUTCTime` lastAdvance >= stallTimeout -> |
| 106 | + reportStall lastPoint |
| 107 | + | otherwise -> |
| 108 | + go lastAdvance lastPoint |
| 109 | + |
| 110 | + -- One observation of the chain tip. 'Nothing' means nothing usable: the |
| 111 | + -- query failed, timed out, or the tip is still at genesis. |
| 112 | + -- |
| 113 | + -- Exceptions from the query count as "no observation" rather than being |
| 114 | + -- propagated: one failure proves nothing, and persistent failure keeps |
| 115 | + -- the stall clock running until the stall timeout fires. The query has a |
| 116 | + -- timeout of its own because an unresponsive node (e.g. starved of CPU) |
| 117 | + -- can accept the connection and then never answer, which would block the |
| 118 | + -- polling forever. |
| 119 | + -- |
| 120 | + -- Asynchronous exceptions are re-thrown: they are not query failures but |
| 121 | + -- this thread being told to stop (cancellation from the test teardown). |
| 122 | + queryTip :: IO (Maybe (SlotNo, BlockNo)) |
| 123 | + queryTip = |
| 124 | + (try (timeout queryTimeoutMicros (getLocalChainTip connectInfo)) |
| 125 | + :: IO (Either SomeException (Maybe ChainTip))) >>= \case |
| 126 | + Right (Just (ChainTip slotNo _ blockNo)) -> pure $ Just (slotNo, blockNo) |
| 127 | + Right (Just ChainTipAtGenesis) -> pure Nothing |
| 128 | + Right Nothing -> pure Nothing |
| 129 | + Left e |
| 130 | + | isJust (fromException e :: Maybe SomeAsyncException) -> throwIO e |
| 131 | + | otherwise -> pure Nothing |
| 132 | + |
| 133 | + reportStall lastPoint = do |
| 134 | + let msg = chainStallFailureMessage stallTimeout horizon lastPoint |
| 135 | + exc = ChainStallException msg |
| 136 | + hPutStrLn stderr msg |
| 137 | + hFlush stderr |
| 138 | + delivered <- timeout deliveryGraceMicros $ throwTo testThread exc |
| 139 | + when (isNothing delivered) $ do |
| 140 | + hPutStrLn stderr $ |
| 141 | + "chainStallWatchdog: could not deliver the failure to the test thread within " |
| 142 | + <> show (deliveryGraceMicros `div` 1_000_000) <> "s (it is likely stuck in a foreign " |
| 143 | + <> "call or under uninterruptibleMask, where asynchronous exceptions cannot be " |
| 144 | + <> "received); killing the testnet nodes so that whatever it is blocked on fails instead." |
| 145 | + hFlush stderr |
| 146 | + mapM_ hardKillProcess nodeHandles |
| 147 | + -- with the nodes dead the test thread should unblock shortly; try once more to |
| 148 | + -- attach the real explanation to the test failure |
| 149 | + void . timeout deliveryGraceMicros $ throwTo testThread exc |
| 150 | + |
| 151 | + pollIntervalMicros, queryTimeoutMicros, deliveryGraceMicros :: Int |
| 152 | + pollIntervalMicros = 5_000_000 |
| 153 | + queryTimeoutMicros = 5_000_000 |
| 154 | + deliveryGraceMicros = 15_000_000 |
| 155 | + |
| 156 | +-- | Failure message explaining why a chain that stopped extending will never recover. |
| 157 | +-- See https://github.com/IntersectMBO/cardano-node/issues/5762 |
| 158 | +chainStallFailureMessage |
| 159 | + :: DTC.NominalDiffTime -- ^ the stall-detection timeout that expired |
| 160 | + -> DTC.NominalDiffTime -- ^ the chain's forecast horizon |
| 161 | + -> Maybe (SlotNo, BlockNo) -- ^ last observed chain tip, if any |
| 162 | + -> String |
| 163 | +chainStallFailureMessage stallTimeout horizon lastPoint = |
| 164 | + unlines |
| 165 | + [ "The testnet chain made no progress for " <> show stallTimeout <> "." |
| 166 | + , case lastPoint of |
| 167 | + Just (SlotNo slotNo, BlockNo blockNo) -> |
| 168 | + "Last observed chain state: slot " <> show slotNo <> ", block " <> show blockNo <> "." |
| 169 | + Nothing -> "No chain state update was observed at all." |
| 170 | + , "The network is almost certainly stalled forever: nodes can only forge when the wall-clock" |
| 171 | + , "slot is at most 3 * securityParam / activeSlotsCoeff slots past the chain tip - the ledger" |
| 172 | + , "view forecast horizon, which is " <> show horizon <> " of wall clock for this testnet." |
| 173 | + , "Once no block was forged for longer than that - e.g. because node startup took too long or" |
| 174 | + , "the machine was too overloaded to produce a block in time - every node fails its leadership" |
| 175 | + , "checks and the chain can never extend again, so we fail fast instead of" |
| 176 | + , "hanging." |
| 177 | + ] |
0 commit comments