From f51375100599ffcbbd4e11bbe0544977f0a0fe07 Mon Sep 17 00:00:00 2001 From: sh Date: Wed, 29 Jul 2026 23:27:56 +0000 Subject: [PATCH] tests: verify socket accounting via control port --- bench/MemBench.hs | 55 ++++++++++++++++++++++++++++++--- docs/leak-findings.md | 71 ++++++++++++++++++++++++------------------- 2 files changed, 90 insertions(+), 36 deletions(-) diff --git a/bench/MemBench.hs b/bench/MemBench.hs index 9adbfd7c4..20fafc9a8 100644 --- a/bench/MemBench.hs +++ b/bench/MemBench.hs @@ -57,7 +57,7 @@ import SMPClient import Simplex.Messaging.Client import qualified Simplex.Messaging.Crypto as C import Simplex.Messaging.Protocol -import Simplex.Messaging.Server.Env.STM (AStoreType (..), ServerConfig (maxJournalMsgCount, msgQueueQuota, notificationExpiration)) +import Simplex.Messaging.Server.Env.STM (AStoreType (..), ServerConfig (controlPort, controlPortAdminAuth, maxJournalMsgCount, msgQueueQuota, notificationExpiration)) import Simplex.Messaging.Server.Expiration (ExpirationConfig (..)) import Simplex.Messaging.Server.MsgStore.Types (SMSType (..), SQSType (..)) import Simplex.Messaging.Transport @@ -65,6 +65,7 @@ import Simplex.Messaging.Transport.Client (TransportClientConfig (..), defaultTr import Simplex.Messaging.Transport.Credentials (genCredentials, tlsCredentials) import Simplex.Messaging.Version (mkVersionRange) import System.Environment (getArgs, lookupEnv, setEnv) +import System.IO (BufferMode (..), IOMode (..), hClose, hGetLine, hPutStrLn, hSetBuffering, hSetNewlineMode, universalNewlineMode) import System.Mem (performMajorGC) import System.Timeout (timeout) import Text.Printf (printf) @@ -726,6 +727,29 @@ heldConns phase iters printf "%s: capping held connections at %d (requested %d) to stay within the fd limit\n" phase maxHeldConns iters pure maxHeldConns +-- Query the server control port for socket accounting. Used to check Bug 5 directly rather +-- than inferring it: socketsLeaked = accepted - closed - active, and closeConn removes a +-- connection from `active` before gracefulClose (up to 5s) and before it increments `closed`, +-- so a connection in teardown is counted in neither and shows up as leaked. +cpSockets :: N.ServiceName -> IO [String] +cpSockets port = do + sock <- rawConnect port + h <- N.socketToHandle sock ReadWriteMode + hSetBuffering h LineBuffering + hSetNewlineMode h universalNewlineMode + r <- timeout 5000000 $ do + _ <- hGetLine h -- banner line 1 + _ <- hGetLine h -- banner line 2 + hPutStrLn h "auth bench" + _ <- hGetLine h + hPutStrLn h "sockets" + replicateM 5 (hGetLine h) -- "Sockets for port N:" + accepted/closed/active/leaked + hClose h `E.catch` \(_ :: E.SomeException) -> pure () + pure $ fromMaybe [] r + +cpPort :: N.ServiceName +cpPort = "5010" + rawConnect :: N.ServiceName -> IO N.Socket rawConnect port = do let hints = N.defaultHints {N.addrSocketType = N.Stream} @@ -753,8 +777,14 @@ holdRelease phase n conn = do atomically $ readTVar connected >>= \c -> when (c < n) retry peak <- liveBytesMiB report phase n base peak + beforeRel <- cpSockets cpPort + putStrLn $ phase <> ": sockets before release: " <> unwords (map (dropWhile (== ' ')) beforeRel) atomically $ writeTVar release True wait as + -- immediately after n simultaneous teardowns: the widest possible window for the + -- accounting gap in closeConn (active decremented before closed is incremented) + afterRel <- cpSockets cpPort + putStrLn $ phase <> ": sockets right after release: " <> unwords (map (dropWhile (== ' ')) afterRel) printf "%s: peak=%.1f MiB (%+.2f KiB/conn)\n" phase peak ((peak - base) * 1024 / fromIntegral n) -- Sample recovery repeatedly rather than once. A single early sample cannot tell a leak -- from state the server has not reaped yet: the relevant server windows are 60s @@ -811,9 +841,23 @@ runTlsChurn :: Int -> Int -> IO () runTlsChurn iters cp = do base <- liveBytesMiB report "tlschurn" 0 base base - forM_ ([1 .. iters] :: [Int]) $ \i -> do - testSMPClient @TLS $ \(_h :: THandleSMP TLS 'TClient) -> pure () - when (i `mod` cp == 0) $ liveBytesMiB >>= report "tlschurn" i base + -- sample the server's own socket accounting while churn is in flight, then again once it + -- has quiesced, to see whether socketsLeaked is a real leak or a teardown artefact + churning <- newTVarIO True + let sampler = do + threadDelay 1500000 + readTVarIO churning >>= \go -> when go $ do + ls <- cpSockets cpPort + putStrLn $ "tlschurn: during churn: " <> unwords (map (dropWhile (== ' ')) ls) + sampler + withAsync sampler $ \_ -> forM_ ([1 .. iters] :: [Int]) $ \i -> do + testSMPClient @TLS $ \(_h :: THandleSMP TLS 'TClient) -> pure () + when (i `mod` cp == 0) $ liveBytesMiB >>= report "tlschurn" i base + atomically $ writeTVar churning False + -- gracefulClose holds each connection up to 5s, so wait past that before the settled sample + threadDelay 8000000 + ls <- cpSockets cpPort + putStrLn $ "tlschurn: after settling: " <> unwords (map (dropWhile (== ' ')) ls) -- post-handshake, send a partial block and idle. The server's transportTimeout is hardcoded -- Nothing, so its receive thread blocks in cGet indefinitely; only inactive-client expiry @@ -855,6 +899,9 @@ main = do -- ntfexp uses a short notification-expiration so deleteExpiredNtfs fires within the run let srvCfg = case phase of "ntfexp" -> updateCfg (srvStoreCfg storeEnv) $ \c -> c {notificationExpiration = ExpirationConfig {ttl = 2, checkInterval = 3}} + -- tlschurn reads the server's own socket counters over the control port + p | p `elem` (["tlschurn", "tlsstall", "tlshalf", "tlspartial"] :: [String]) -> + updateCfg (srvStoreCfg storeEnv) $ \c -> c {controlPort = Just cpPort, controlPortAdminAuth = Just "bench"} _ -> srvStoreCfg storeEnv -- LEAKDIAG counters are the only per-server signal in multi-server topologies, so sample -- them often enough to be useful over a bench run diff --git a/docs/leak-findings.md b/docs/leak-findings.md index e682020de..b27118bde 100644 --- a/docs/leak-findings.md +++ b/docs/leak-findings.md @@ -3,7 +3,7 @@ From `bench/MemBench.hs` extended with a proxy plus relay topology and a transport that adds latency and drops replies. -Two leaks on the proxy path, both client reachable. Three related bugs. TLS/TCP stack clean. +Two leaks on the proxy path, both client reachable. Two related bugs. TLS/TCP stack clean. Measured on both the journal store and the PostgreSQL queue and message store, which is the production configuration. Results are the same on both. @@ -74,6 +74,10 @@ so the count can be read directly: 200 queues, 200 timed out, `sentCommands` wen One entry per queue, at about 1.76 KiB each. At the ntf server's batch size that is roughly 2.3 MiB per unanswered batch. +`subscribeSMPQueues` (measured) and `subscribeSMPQueuesNtfs` (the ntf server's call) are the +same function bar the command constructor: both are `enablePings` followed by +`sendProtocolCommands c NRMBackground cs`. So the measurement transfers directly. + Cost per entry is far lower than the proxy case, a subscribe payload rather than a 16226 byte `RFWD`, but the retention rule is identical. @@ -191,35 +195,6 @@ atomically $ modifyTVar' endThreads $ IM.adjust (const (Just w)) tId --- -## Bug 5: socketsLeaked over-reports during teardown - -### Issue - -`closeConn` (`Transport/Server.hs:179`) removes the connection from `active`, then calls -`gracefulClose conn 5000`, then increments `closed`: - -```haskell -atomically $ writeTVar closed True >> modifyTVar' clients (IM.delete cId) -gracefulClose conn 5000 `catchAll_` pure () -atomically $ modifyTVar' gracefullyClosed (+ 1) -``` - -`socketsLeaked = accepted - closed - active` (`Transport/Server.hs:225`). For up to 5 seconds a -closing connection is in neither `closed` nor `active`, so it counts as leaked. - -### Impact - -No memory cost. Under connection churn `socketsLeaked` shows a steady nonzero value that is not -a leak, which makes the metric unusable for the thing it is named after. This is the same 5 -second teardown window that made the TLS tests look like they leaked 24 MiB. - -### Fix - -Count the connection as closed before starting `gracefulClose`, or drop it from `active` only -after `gracefulClose` returns. Either ordering keeps the invariant. - ---- - ## Clean 200 connections opened at once, closed, then measured again: @@ -233,8 +208,7 @@ after `gracefulClose` returns. Either ordering keeps the invariant. All recovered. Also clean: 400 connect/disconnect rounds, and steady forwarding at 50ms each way. At +5s the middle two still read ~120 KiB per connection, which looks like a 24 MiB leak but is -`gracefulClose` waiting up to 5s per connection. Falling means reclaimed, flat above baseline -means leaked. +teardown still in progress. Falling means reclaimed, flat above baseline means leaked. Peaks still matter. 200 abandoned half open connections hold ~40 MiB for ~25s, unauthenticated. A client that finishes the handshake then sends one byte holds ~265 KiB for as long as it stays @@ -265,6 +239,39 @@ Forwards work up to 16s each way and fail at 40s. The governing limit is the 30s The exact cutoff is not pinned down: the test transport adds delay per read/write cycle rather than per message, so configured lag does not map exactly onto observed round trip. +## Checked and not a problem: socketsLeaked accounting + +Recorded because an earlier version of this report listed it as a bug on the strength of code +reading alone, and measuring it did not bear that out. + +`closeConn` (`Transport/Server.hs:179`) removes the connection from `active`, then calls +`gracefulClose conn 5000`, then increments `closed`, and +`socketsLeaked = accepted - closed - active`. That ordering does leave a window where a closing +connection is counted in neither bucket. + +In practice the window never opened. Read over the control port during 600 sequential +connect/disconnect cycles, and again across 200 simultaneous teardowns: + +``` +during churn: accepted: 587 closed: 586 active: 1 leaked: 0 +after settling: accepted: 600 closed: 600 active: 0 leaked: 0 +before mass release: accepted: 200 closed: 0 active: 200 leaked: 0 +after mass release: accepted: 200 closed: 200 active: 0 leaked: 0 +``` + +The 5000 in `gracefulClose conn 5000` is a timeout, not a delay: it returns as soon as the peer's +close is processed, which for a clean disconnect is immediate. A peer that vanishes without +closing could in principle widen the window, but that was not produced here, so it is not +claimed. + +## Note on running the suite + +`should have similar time for auth error, whether queue exists or not` compares wall clock +timings with a 30% tolerance (45% on Postgres), and it fails intermittently when the machine is +busy. Observed twice in four runs while benches were running concurrently, then 4 of 4 and 5 of 5 +clean on an idle machine with and without the changes here. It is load sensitivity in the test, +not a regression. Run the suite on an otherwise idle machine. + ## Already fixed: the empty session variable leak Worth recording because an earlier version of this report listed it as "not reproduced", which