|
| 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 | + , stderrTracer |
| 16 | + ) where |
| 17 | + |
| 18 | +import Cardano.Api (BlockNo (..), ChainTip (..), LocalNodeConnectInfo, |
| 19 | + ShelleyGenesis (..), SlotNo (..), getLocalChainTip) |
| 20 | + |
| 21 | +import qualified Cardano.Ledger.BaseTypes as SL |
| 22 | +import qualified Cardano.Ledger.Shelley.Genesis as SL |
| 23 | +import qualified Cardano.Ledger.Shelley.StabilityWindow as SL |
| 24 | + |
| 25 | +import Prelude |
| 26 | + |
| 27 | +import Control.Applicative ((<|>)) |
| 28 | +import Control.Concurrent (ThreadId, threadDelay, throwTo) |
| 29 | +import Control.Exception (Exception (..), asyncExceptionFromException, |
| 30 | + asyncExceptionToException) |
| 31 | +import Control.Exception.Safe (SomeException, try) |
| 32 | +import Control.Monad (void, when) |
| 33 | +import Control.Tracer (Tracer (..), traceWith) |
| 34 | +import Data.List.NonEmpty (NonEmpty) |
| 35 | +import Data.Maybe (isNothing) |
| 36 | +import Data.Text (Text) |
| 37 | +import qualified Data.Text as Text |
| 38 | +import qualified Data.Text.IO as Text |
| 39 | +import qualified Data.Time.Clock as DTC |
| 40 | +import System.IO (hFlush, stderr) |
| 41 | +import System.Process (ProcessHandle) |
| 42 | +import System.Timeout (timeout) |
| 43 | + |
| 44 | +import Testnet.Signal (hardKillProcess) |
| 45 | + |
| 46 | +-- | Thrown to the test thread when the chain has irrecoverably stalled. Registered |
| 47 | +-- as an asynchronous exception (like the exceptions of 'Control.Exception.AsyncException') |
| 48 | +-- so that handlers for synchronous errors inside tests do not accidentally swallow it. |
| 49 | +newtype ChainStallException = ChainStallException String |
| 50 | + |
| 51 | +instance Show ChainStallException where |
| 52 | + show (ChainStallException msg) = msg |
| 53 | + |
| 54 | +instance Exception ChainStallException where |
| 55 | + toException = asyncExceptionToException |
| 56 | + fromException = asyncExceptionFromException |
| 57 | + |
| 58 | +-- | The ledger view forecast horizon of the chain described by the given genesis: |
| 59 | +-- @3 * securityParam / activeSlotsCoeff@ slots (the stability window), converted to |
| 60 | +-- wall-clock time. Nodes can only forge while the wall-clock slot is at most this far |
| 61 | +-- past the chain tip, so a chain that has not forged for longer than this can never |
| 62 | +-- produce a block again. |
| 63 | +chainForecastHorizon :: ShelleyGenesis -> DTC.NominalDiffTime |
| 64 | +chainForecastHorizon sg = |
| 65 | + fromIntegral horizonSlots * SL.fromNominalDiffTimeMicro (sgSlotLength sg) |
| 66 | + where |
| 67 | + horizonSlots = |
| 68 | + SL.computeStabilityWindow |
| 69 | + (SL.unNonZero $ sgSecurityParam sg) |
| 70 | + (SL.mkActiveSlotCoeff $ sgActiveSlotsCoeff sg) |
| 71 | + |
| 72 | +-- | Stall detection threshold for a chain with the given forecast horizon: twice the |
| 73 | +-- horizon (a chain quiet for longer than the horizon is already irrecoverable; the |
| 74 | +-- factor and the 60s floor absorb block-interval variance and detection latency). |
| 75 | +chainStallTimeoutFromHorizon :: DTC.NominalDiffTime -> DTC.NominalDiffTime |
| 76 | +chainStallTimeoutFromHorizon horizon = max 60 (2 * horizon) |
| 77 | + |
| 78 | +-- | Watch the chain through the given node connection and, when it has made no progress |
| 79 | +-- for 'chainStallTimeoutFromHorizon' of the genesis, fail the given test thread with |
| 80 | +-- a 'ChainStallException' explaining the mechanism. |
| 81 | +-- |
| 82 | +-- The full diagnosis is emitted through the given tracer first, so the explanation |
| 83 | +-- can outlive the test thread (see 'stderrTracer' for the standard sink and why). |
| 84 | +-- 'throwTo' blocks until the exception is delivered; if the test thread |
| 85 | +-- cannot receive it (it is stuck in a foreign call or under |
| 86 | +-- 'Control.Exception.uninterruptibleMask'), the watchdog escalates after a grace |
| 87 | +-- period by hard-killing the node processes, so that whatever the test is blocked |
| 88 | +-- on fails with an ordinary synchronous error instead. |
| 89 | +-- |
| 90 | +-- Run it in a background thread (e.g. with 'Testnet.Runtime.asyncRegister_'); it is |
| 91 | +-- stopped by cancellation like any other background resource. |
| 92 | +chainStallWatchdog |
| 93 | + :: Tracer IO Text -- ^ sink for the diagnosis and escalation notices |
| 94 | + -> ShelleyGenesis -- ^ the genesis backing the testnet, for the stall threshold |
| 95 | + -> LocalNodeConnectInfo -- ^ connection to the node whose chain tip is polled |
| 96 | + -> NonEmpty ProcessHandle -- ^ the testnet node processes, for the kill escalation |
| 97 | + -> ThreadId -- ^ the test thread to fail when the chain stalls |
| 98 | + -> IO () |
| 99 | +chainStallWatchdog tracer shelleyGenesis connectInfo nodeHandles testThread = do |
| 100 | + start <- DTC.getCurrentTime |
| 101 | + go start Nothing |
| 102 | + where |
| 103 | + horizon = chainForecastHorizon shelleyGenesis |
| 104 | + stallTimeout = chainStallTimeoutFromHorizon horizon |
| 105 | + |
| 106 | + go :: DTC.UTCTime -> Maybe (SlotNo, BlockNo) -> IO () |
| 107 | + go lastAdvance mLastTip = do |
| 108 | + threadDelay pollIntervalMicros |
| 109 | + mTip <- queryTip |
| 110 | + now <- DTC.getCurrentTime |
| 111 | + case (,) <$> mTip <*> mLastTip of |
| 112 | + Just (tip@(_, blockNo), (_, lastBlockNo)) | lastBlockNo /= blockNo -> |
| 113 | + -- Restart the stall clock only when the chain height changes: a reorg |
| 114 | + -- can change the tip's slot and hash without the chain growing, so |
| 115 | + -- those fields prove nothing about progress. Any height change counts |
| 116 | + -- (not just an increase): a node replaying its chain after a restart |
| 117 | + -- is activity rather than proof of death, and a truly dead chain |
| 118 | + -- freezes the height anyway. |
| 119 | + go now (Just tip) |
| 120 | + _ | now `DTC.diffUTCTime` lastAdvance >= stallTimeout -> |
| 121 | + reportStall (mLastTip <|> mTip) |
| 122 | + | otherwise -> |
| 123 | + -- No height change proven; keep the clock running, but hold on to |
| 124 | + -- the freshest observation so the very first tip seen becomes the |
| 125 | + -- baseline for the comparison above. |
| 126 | + go lastAdvance (mLastTip <|> mTip) |
| 127 | + |
| 128 | + -- One observation of the chain tip. 'Nothing' means nothing usable: the |
| 129 | + -- query failed, timed out, or the tip is still at genesis. |
| 130 | + -- |
| 131 | + -- Exceptions from the query count as "no observation" rather than being |
| 132 | + -- propagated: one failure proves nothing, and persistent failure keeps |
| 133 | + -- the stall clock running until the stall timeout fires. The query has a |
| 134 | + -- timeout of its own because an unresponsive node (e.g. starved of CPU) |
| 135 | + -- can accept the connection and then never answer, which would block the |
| 136 | + -- polling forever. |
| 137 | + queryTip :: IO (Maybe (SlotNo, BlockNo)) |
| 138 | + queryTip = |
| 139 | + (try (timeout queryTimeoutMicros (getLocalChainTip connectInfo)) |
| 140 | + :: IO (Either SomeException (Maybe ChainTip))) >>= \case |
| 141 | + Right (Just (ChainTip slotNo _ blockNo)) -> pure $ Just (slotNo, blockNo) |
| 142 | + Right (Just ChainTipAtGenesis) -> pure Nothing |
| 143 | + Right Nothing -> pure Nothing |
| 144 | + Left _ -> pure Nothing |
| 145 | + |
| 146 | + reportStall :: Maybe (SlotNo, BlockNo) -> IO () |
| 147 | + reportStall mLastTip = do |
| 148 | + let msg = chainStallFailureMessage stallTimeout horizon mLastTip |
| 149 | + exc = ChainStallException msg |
| 150 | + traceWith tracer $ Text.pack msg |
| 151 | + delivered <- timeout deliveryGraceMicros $ throwTo testThread exc |
| 152 | + when (isNothing delivered) $ do |
| 153 | + traceWith tracer $ Text.pack $ mconcat |
| 154 | + [ "chainStallWatchdog: could not deliver the failure to the test thread within " |
| 155 | + , show (deliveryGraceMicros `div` 1_000_000), "s (it is likely stuck in a foreign " |
| 156 | + , "call or under uninterruptibleMask, where asynchronous exceptions cannot be " |
| 157 | + , "received); killing the testnet nodes so that whatever it is blocked on fails instead." |
| 158 | + ] |
| 159 | + mapM_ hardKillProcess nodeHandles |
| 160 | + -- with the nodes dead the test thread should unblock shortly; try once more to |
| 161 | + -- attach the real explanation to the test failure |
| 162 | + void . timeout deliveryGraceMicros $ throwTo testThread exc |
| 163 | + |
| 164 | + pollIntervalMicros, queryTimeoutMicros, deliveryGraceMicros :: Int |
| 165 | + pollIntervalMicros = 5_000_000 |
| 166 | + queryTimeoutMicros = 5_000_000 |
| 167 | + deliveryGraceMicros = 15_000_000 |
| 168 | + |
| 169 | +-- | The standard sink for the watchdog's output: write each message to stderr and |
| 170 | +-- flush. stderr bypasses tasty's buffered reporting, so the diagnosis is visible |
| 171 | +-- even if the test never manages to report a result. |
| 172 | +-- |
| 173 | +-- Like 'Control.Tracer.stdoutTracer', this tracer does not serialise writers: |
| 174 | +-- messages traced from several threads can interleave. Each message is emitted |
| 175 | +-- with a single 'Text.hPutStrLn', so this only matters alongside other writers |
| 176 | +-- to stderr. |
| 177 | +-- |
| 178 | +-- TODO: this tracer is temporary: it should move up into the testnet |
| 179 | +-- orchestration configuration and be used everywhere in the orchestration code |
| 180 | +-- instead of ad-hoc printing. |
| 181 | +stderrTracer :: Tracer IO Text |
| 182 | +stderrTracer = Tracer $ \msg -> Text.hPutStrLn stderr msg >> hFlush stderr |
| 183 | + |
| 184 | +-- | Failure message explaining why a chain that stopped extending will never recover. |
| 185 | +-- See https://github.com/IntersectMBO/cardano-node/issues/5762 |
| 186 | +chainStallFailureMessage |
| 187 | + :: DTC.NominalDiffTime -- ^ the stall-detection timeout that expired |
| 188 | + -> DTC.NominalDiffTime -- ^ the chain's forecast horizon |
| 189 | + -> Maybe (SlotNo, BlockNo) -- ^ last observed chain tip, if any |
| 190 | + -> String |
| 191 | +chainStallFailureMessage stallTimeout horizon lastPoint = |
| 192 | + unlines |
| 193 | + [ "The testnet chain made no progress for " <> show stallTimeout <> "." |
| 194 | + , case lastPoint of |
| 195 | + Just (SlotNo slotNo, BlockNo blockNo) -> |
| 196 | + "Last observed chain state: slot " <> show slotNo <> ", block " <> show blockNo <> "." |
| 197 | + Nothing -> "No chain state update was observed at all." |
| 198 | + , "The network is almost certainly stalled forever: nodes can only forge when the wall-clock" |
| 199 | + , "slot is at most 3 * securityParam / activeSlotsCoeff slots past the chain tip - the ledger" |
| 200 | + , "view forecast horizon, which is " <> show horizon <> " of wall clock for this testnet." |
| 201 | + , "Once no block was forged for longer than that - e.g. because node startup took too long or" |
| 202 | + , "the machine was too overloaded to produce a block in time - every node fails its leadership" |
| 203 | + , "checks and the chain can never extend again, so we fail fast instead of" |
| 204 | + , "hanging." |
| 205 | + ] |
0 commit comments