From 3dd259de68b27cc85665e22270181df39f35db7e Mon Sep 17 00:00:00 2001 From: sh Date: Thu, 30 Jul 2026 07:47:50 +0000 Subject: [PATCH] docs: condense leak findings report --- docs/leak-findings.md | 421 +++++++++++++++--------------------------- 1 file changed, 150 insertions(+), 271 deletions(-) diff --git a/docs/leak-findings.md b/docs/leak-findings.md index fc21b7997..c962b6b90 100644 --- a/docs/leak-findings.md +++ b/docs/leak-findings.md @@ -1,145 +1,92 @@ # SMP server leak findings -From `bench/MemBench.hs` extended with a proxy plus relay topology and a transport that adds -latency and drops replies. +Found with `bench/MemBench.hs`, extended with a proxy plus relay topology and a transport that +adds latency and drops replies. Measured on both the journal store and PostgreSQL, same results. -Three leaks on the proxy path, all client reachable. Two related bugs. TLS/TCP stack clean. +Three leaks on the proxy path, all client reachable. Two related bugs. TLS/TCP stack is 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. +All three leaks are reached the same way: `PRXY` is unauthenticated unless `newQueueBasicAuth` is +set (`Server.hs:1534`) and names an arbitrary destination, so a client can point the proxy at a +relay it controls. --- -## Leak 1: forwarded commands never removed on timeout +## Leak 1: forwarded commands are never removed on timeout ### Issue Entries go into `sentCommands` in `mkTransmission_` (`Client.hs:1418`). The only removal is in `processMsg` (`Client.hs:706`), which runs when a reply arrives. `getResponse` (`Client.hs:1383`) -handles the timeout but does not receive the map, so it cannot delete. +handles the timeout but never gets the map, so it cannot delete. -Each entry holds the forwarded command, 16226 bytes. +Each entry holds the forwarded command: 16226 bytes for `RFWD`. -The session survives too. `monitor` (`Client.hs:668`) only tears the client down when -`timeoutErrorCount >= smpPingCount` and nothing has arrived for `recoverWindow` (900s), and -`receive` (`Client.hs:663`) resets both on every inbound transmission. A relay that answers some -requests and drops others therefore keeps the session healthy forever while the dropped ones -accumulate. - -`proxytmo 448`: `proxy_sentCommands` goes 64, 128, 192, 256, 320, 384, 448. Monotonic. -About 20 KiB per entry. +The session survives too. `monitor` (`Client.hs:668`) drops the client only when +`timeoutErrorCount >= smpPingCount` and nothing has arrived for 900s, and `receive` +(`Client.hs:663`) resets both on every inbound transmission. ### Impact -20 KiB per unanswered forward. How long it is held depends entirely on how the relay -misbehaves, and the three cases differ a lot. +About 20 KiB per unanswered forward. How long it is held depends on how the relay misbehaves. -**Slow relay that still replies: transient, not a leak.** A late reply removes the entry, since -`processMsg` deletes on any `corrId` match whether or not the request already timed out. -Measured at 16s each way, where forwards exceed the 30s timeout: `proxy_sentCommands` oscillates -1, 0, 1, 0 and ends at 0. Growth is bounded by in-flight commands. Latency on its own does not -leak. +| relay behaviour | result | +| --- | --- | +| slow but still replies | not a leak here, the late reply deletes the entry (but see Leak 3) | +| goes fully silent | bounded, `monitor` tears the client down at ~20 min | +| replies to some, drops others | **unbounded** | -**Relay that goes fully silent: bounded at about 20 minutes.** `monitor` (`Client.hs:668`) exits -when `timeoutErrorCount >= smpPingCount` and nothing has arrived for `recoverWindow` (900s), -checked on a 600s loop. It runs inside `raceAny_ ... \`finally\` disconnected` -(`Client.hs:649`), so exiting tears the client down and the map goes with it. Measured: -`proxy_sentCommands` sat at 128 for 20 minutes then went to 0, with one disconnect logged. +The third case is the problem. Any arriving reply resets `lastReceived` and `timeoutErrorCount`, +so the drop condition is never met. Measured with 1 in 3 relay writes dropped and forwarding +running: `proxy_sentCommands` climbed 64 to 1280 over 20 minutes, linear at 64/min, zero +disconnects. That is ~1.3 MiB/min, ~77 MiB/hour, on one session. -**Sustained traffic with some replies dropped: unbounded.** `receive` (`Client.hs:665`) resets -both `lastReceived` and `timeoutErrorCount` on every inbound transmission, so as long as traffic -continues and some of it is answered, the drop condition is never met. Measured with 1 in 3 -relay writes dropped and forwarding running continuously: `proxy_sentCommands` climbed 64, 128, -192 ... 1280 over 20 minutes, linear at 64 per minute, with zero disconnects. It goes straight -through the 20 minute point where both idle cases collapsed to 0. +Traffic has to be ongoing. Flood and stop and it is reclaimed after 20 minutes. -At that modest rate, 64 stuck commands per minute is about 1.3 MiB per minute, or 77 MiB per -hour, on a single proxy to relay session. +The ntf server uses the same client code and has the same exposure through unanswered `NSUB`. +Measured with `subtmo 200`: 200 queues, 200 timed out, `sentCommands` 0 to 200, ~1.76 KiB each. +At the ntf batch size of 1360 that is ~2.3 MiB per unanswered batch. -Note the traffic has to be ongoing. An attacker who floods and then stops gets their memory -reclaimed after 20 minutes. Holding it requires staying connected and keeping the requests -coming, which is cheap but not free. - -`PRXY` is unauthenticated unless `newQueueBasicAuth` is set (`Server.hs:1534`), and it names an -arbitrary destination, so a client can point the proxy at exactly such a relay. No rate cap, see -Bug 3. - -The ntf server uses the same client code, so it has the same exposure. Reachable through -unanswered `NSUB`: `subscribeSMPQueuesNtfs` (`Client.hs:912`) batches, and `sendBatch` calls -`getResponse` once per request, so an unanswered batch leaks one entry per queue. Batch size is -1360 (`Client/Agent.hs:131`). - -Measured with `subtmo 200`, which drives the same batched subscribe path on a bench owned client -so the count can be read directly: 200 queues, 200 timed out, `sentCommands` went from 0 to 200. -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. - -Pings are not the mitigation they look like. Subscribe paths call `enablePings` (`Client.hs:854, -861, 907, 914, 934`) and the proxy's send path does not, but that only changes liveness detection -on an otherwise idle connection. It does not bound the leak: in the unbounded case there is -sustained traffic and some replies do arrive, and every arrival resets `lastReceived` and -`timeoutErrorCount` whether or not pings are enabled. +Pings do not help. Subscribe paths call `enablePings` and the proxy send path does not, but in +the unbounded case replies are arriving anyway, which resets the counters either way. ### Fix -**Do not simply delete on timeout.** I had that here and it is wrong. +Do not just delete on timeout. Late replies are load bearing: `processMsg` forwards them as +`STResponse` (`Client.hs:713`), and `Agent.hs:3093` acts on them. A late `OK`/`SOK` to a `SUB` +calls `processSubOk`, which is what brings a connection back UP, and a late `MSG` is processed as +a real message. Deleting on timeout turns both into `STUnexpectedError` (`Client.hs:702`), so the +agent would report an error instead of recovering, and drop the message. -Late responses are load bearing for the agent. When a reply arrives for a request that already -timed out, `processMsg` takes the `wasPending == False` branch and forwards it as `STResponse` -(`Client.hs:713`). `Agent.hs:3093` acts on those: a late `OK`/`SOK` to a `SUB` calls -`processSubOk`, which is what brings the connection back UP, and a late `MSG` is processed as a -real message. Deleting the entry on timeout turns both into `STUnexpectedError` -(`Client.hs:702`), so the agent would report an error instead of recovering the subscription, -and would drop the message. The ntf server ignores `STResponse` (`Notifications/Server.hs:540`) -so it would only gain log noise, but the agent regression is real. +Bound the map by age instead: stamp `Request` on insert, sweep entries with `pending == False` +older than the window in which a late reply can still matter. Picking that window needs the +agent's recovery behaviour measured, which is not done here. -So the entry has to stay reachable for as long as a late reply is still useful, which rules out -deleting it at the timeout. The fix has to bound the map by age instead: stamp `Request` on -insert and sweep entries whose `pending` is `False` and whose stamp is older than the window in -which a late reply could still matter. That needs a window chosen against the agent's -subscription recovery behaviour, which I have not measured, so I am not proposing a number here. - -Two entry points do leak with no timeout involved and can be fixed as written, because no reply -is ever coming. `mkTransmission_` inserts the request before it is sent (`Client.hs:1361`) and -`sendRecv` then returns early at `Client.hs:1366` (transport error) and `Client.hs:1368` (block -over `blockSize - 2`) without sending or deleting. Both should delete. +Two entry points can be fixed by deleting, because no reply is ever coming. `mkTransmission_` +inserts before sending (`Client.hs:1361`) and `sendRecv` returns early at `Client.hs:1366` +(transport error) and `Client.hs:1368` (oversized block) without sending or deleting. --- -## Leak 2: failed relay connects never cleared +## Leak 2: failed relay connects are never cleared ### Issue -A failed connect is cached in `smpClients` as `Left (error, expiry)` (`Client/Agent.hs:275`), -removed only on a later lookup of the same server (`Client/Agent.hs:250`, `:411`). Nothing sweeps -on a timer. Verified by listing every `smpClients` site: the only other removals are -`clientDisconnected` (`:311`, connected clients only) and shutdown (`:427`). +A failed connect is cached in `smpClients` as `Left (error, expiry)` (`Client/Agent.hs:275`) and +removed only on a later lookup of the same server (`:250`, `:411`). Nothing sweeps on a timer. +The other removals are `clientDisconnected` (`:311`, connected clients only) and shutdown +(`:427`). -Conditional on `persistErrorInterval > 0`. At 0 the entry is removed immediately -(`Client/Agent.hs:269-272`) and there is no leak, but production sets 30 -(`Server/Main.hs:607`). - -The address comes from the client via `PRXY`. Host, port and key hash are arbitrary, so distinct -keys are effectively unlimited. - -`proxychurn 300`: `proxy_smpClients = 300`, none removed. A 1000 run settles at ~19 KiB per -entry, created in about 1 second. +Conditional on `persistErrorInterval > 0`. At 0 the entry goes immediately, but production sets +30 (`Server/Main.hs:607`). ### Impact -19 KiB per address, never freed while the process runs. +Host, port and key hash come from the client, so distinct addresses are unlimited. Measured: +`proxy_smpClients = 300` after 300 dead addresses, ~19 KiB each, never freed while the process +runs. 1000 entries created in about 1s. -About 19 MiB/s when the address refuses immediately. An address that blackholes instead waits -out the 45 second connect timeout, which throttles it heavily. - -Same unauthenticated `PRXY` as Leak 1. +That is ~19 MiB/s when the address refuses immediately. An address that blackholes waits out the +45s connect timeout, which throttles it heavily. ### Fix @@ -151,57 +98,47 @@ Sweep the map on a timer, dropping entries past their expiry. The timestamp is a ### Issue -`newSMPClientAgent` creates one `msgQ` (`Client/Agent.hs:194`) and `connectClient` hands that -same queue to every relay client it opens (`:296`). The ntf server drains its copy -(`Notifications/Server.hs:537`). The SMP server never drains its own: -`receiveFromProxyAgent` reads `agentQ` only (`Server.hs:475`). Grepping every `readTBQueue` on a -`msgQ` in `src/` returns three sites, and none of them is the proxy's. +`newSMPClientAgent` creates one `msgQ` (`Client/Agent.hs:194`) and `connectClient` gives that same +queue to every relay client (`:296`). The ntf server drains its copy +(`Notifications/Server.hs:537`). The SMP server never drains its own: `receiveFromProxyAgent` +reads `agentQ` only (`Server.hs:475`). There are three `readTBQueue` sites on a `msgQ` in `src/` +and none is the proxy's. -What fills it: `processMsg` routes a response to `msgQ` when the request is still in -`sentCommands` but `pending` is already `False` (`Client.hs:713`), meaning the reply arrived -after the proxy's own RFWD timeout. So every late reply from a relay deposits one entry that is -never taken out. +It fills from late replies. `processMsg` routes a response to `msgQ` when the request is still in +`sentCommands` but `pending` is already `False` (`Client.hs:713`), so every reply arriving after +the proxy's 30s RFWD timeout leaves an entry that nothing takes out. -When the queue is full, `processMsgs` blocks in `writeTBQueue` (`Client.hs:694`). That is the -`process` thread, and it is the only reader of `rcvQ`, so once it blocks the proxy stops -handling responses entirely and every subsequent forward times out. +When it is full, `processMsgs` blocks in `writeTBQueue` (`Client.hs:694`). That is the `process` +thread, the only reader of `rcvQ`, so the proxy stops handling responses entirely. ### Impact -Measured with the `msgqfill` phase, 4 forwards at 40s each way so the replies land after the -proxy's 30s timeout, then the lag is cleared and 3 more forwards are attempted. Only -`msgQSize` differs between the runs. +Measured with the `msgqfill` phase: 4 forwards at 40s each way so replies land after the timeout, +then lag cleared and 3 more attempted. Only `msgQSize` differs. -| `msgQSize` | `proxy_msgQ` at end | `proxy_sentCommands` at end | recovery forwards | -|---|---|---|---| +| `msgQSize` | `proxy_msgQ` at end | `sentCommands` at end | recovery forwards | +| --- | --- | --- | --- | | 2 | 2 (at cap) | 4 and climbing | **0 of 3** | | 2048 (production) | 4 | 0 | 3 of 3 | -Two separate things are shown. The queue never drains: at production size it holds the 4 late -replies for the rest of the run. And when it does fill, the stall is permanent, not a slowdown: -the recovery forwards ran with no latency at all and still got nothing back. +Two things. The queue never drains: at production size it still holds the 4 late replies at the +end of the run. And when it fills the stall is permanent, not slow: the recovery forwards ran +with no latency at all and got nothing back. -The queue is shared, not per relay. There is one `msgQ` per `SMPClientAgent` and one -`ProxyAgent` per server, so a single relay that answers slowly can stall the proxy's response -handling for every relay it talks to. This part is from the code, not measured: the bench -topology has one relay. +One `msgQ` per agent and one `ProxyAgent` per server, so one slow relay stalls the proxy for every +relay it talks to. That part is from the code, not measured: the bench has one relay. -Reachable the same way as Leak 1. `PRXY` is unauthenticated unless `newQueueBasicAuth` is set, -and names an arbitrary destination, so a client can point the proxy at a relay it controls that -answers just late enough. 2048 late replies is a cheap budget for that. +2048 late replies is a cheap budget for an attacker who controls the destination relay. -Note this is the same relay behaviour I recorded under Leak 1 as "slow relay that still replies: -transient, not a leak". That verdict was right about `sentCommands` and wrong about the session: -the late replies that clear `sentCommands` are exactly the ones that accumulate here. +This also corrects Leak 1's "slow relay is not a leak" row. That is right about `sentCommands` and +wrong about the session: the late replies that clear `sentCommands` are the ones that pile up +here. ### Fix -Drain it, or do not create it. The SMP server has no use for these transmissions, so the honest -options are to give `ProxyAgent` a reader that discards them, or to make `msgQ` optional in -`SMPClientAgent` and pass `Nothing` for the proxy, which is already supported -(`getProtocolClient` takes `Maybe`, and `sendMsg` logs instead when it is `Nothing`). - -The second is better: a discarding reader would still allocate and copy every batch. +Make `msgQ` optional in `SMPClientAgent` and pass `Nothing` for the proxy. `getProtocolClient` +already takes a `Maybe` and `sendMsg` logs instead when it is `Nothing`. A discarding reader would +also work but still allocates and copies every batch. --- @@ -218,21 +155,19 @@ bracket_ wait signal . forkClient clnt label $ action `.` binds tighter than `$`, so `signal` runs when the thread starts, not when it finishes. Only forking is limited. -Measured with `conclimit 8` and `serverClientConcurrency = 1`: eight concurrent PFWDs on one -connection, relay silent. +Measured with `conclimit 8` and `serverClientConcurrency = 1`, eight concurrent PFWDs on one +connection, relay silent: ``` conclimit: n=8 cap=1 completions first=20.0s last=20.0s spread=0.0s ``` -All eight ran concurrently. If the cap were enforced each would hold the slot for the 30s RFWD -timeout and they would need ~240s, and because `wait` blocks the client's command loop the next -command could not even be read until the previous finished. +All eight ran at once. Enforced, each would hold the slot for the 30s RFWD timeout, needing ~240s. ### Impact -No memory cost. Removes the cap on how fast Leak 1 grows, and `procThreads` reads near zero at -any load. +No memory cost of its own. Removes the cap on how fast Leak 1 grows, and `procThreads` reads near +zero at any load. ### Fix @@ -240,8 +175,8 @@ any load. wait >> forkClient clnt label (action `finally` signal) ``` -This enables the limit for the first time. Default is 32, and `wait` blocks the client's whole -command loop when hit, so check the value first. +This turns the limit on for the first time. Default is 32 and `wait` blocks the client's whole +command loop when hit, so check that value first. --- @@ -249,73 +184,50 @@ command loop when hit, so check the value first. ### Issue -`forkClient` (`Server.hs:1480`) registers the thread after `forkIO`. If the action finishes -first, its delete misses and the insert is never undone. +`forkClient` (`Server.hs:1480`) registers the thread after `forkIO`. If the action finishes first, +its delete misses and the insert is never undone. -Reproduced in isolation with a verbatim copy of the registration order, including the -`labelMyThread` the child runs before the action. 100k forks: 20% stale at `-N1`, 13% at `-N4`. -About 320 bytes per stale entry. `deRefWeak` returns `Nothing` for all of them, so no thread is -retained. +Reproduced in isolation, 100k forks: 20% stale at `-N1`, 13% at `-N4`, ~320 bytes each. +`deRefWeak` returns `Nothing` for all of them, so no thread is retained. -### What decides the race - -Not how long the child takes. How long was the obvious guess and it is wrong. Measured over -20k forks, varying only the work the child does before its delete: +What decides it is not how long the child takes. Measured over 20k forks, varying only the child's +work before its delete: | child does | -N1 | -N4 | -|---|---|---| +| --- | --- | --- | | nothing | 17.5% | 10.7% | | spins 1us | 19.2% | 9.7% | -| spins 10us | 17.3% | 9.7% | | spins 100us | 17.8% | 9.8% | | one failing `connect()` | **0%** | **0.1%** | -A spinning child does not lose the race, it *starves* the parent. What closes the window is the -child giving up the capability: a syscall, a safe FFI call, or an STM retry. So the rule is -"does the child yield before its delete", not "is the child fast". +A spinning child does not lose the race, it starves the parent. The window closes when the child +gives up the capability: syscall, safe FFI call, or STM retry. -### Which paths yield +Against that rule, of the three call sites: -There are exactly three `forkClient` call sites. - -- **`forkCmd`** (`Server.hs:1593`), used by `PFWD`/`PRXY` (`:1540`, `:1577`) and `RSLV` - (`:1639`, `:2269`). All do network IO, so all yield. `RSLV` was worth checking separately - because it is client driven at command rate, but `resolveName` has no cache - (`Server/Names.hs:62`): every call goes to `resolveHttp`. Safe. -- **`deliverServiceMessages`** (`Server.hs:1977`). Guarded by `unless hasSub`, and - `clientServiceSubscribed` is a one-way latch set at `Server.hs:2031` that is never reset - within a session. Fires at most once per connection. Safe by rate. -- **`sendPendingEvtsThread.queueEvts`** (`Server.hs:463`). This is the one that does not yield. - The child is `atomically (writeTBQueue sndQ ...)` plus three `IORef` bumps. If the queue is - still full it retries and yields, but if space appeared it commits straight through, which is - the "nothing" row above. - -The earlier oversized-`PFWD` idea does not work: the client's own transmission limit caps -`encBlock` first. Largest block the client will send is about 16270 bytes, and at that size the -proxy still forwards successfully (the relay answers `PROXY (PROTOCOL CRYPTO)`), so the no-IO -return at `Client.hs:1368` is never taken. +- `forkCmd` (`Server.hs:1593`) for `PFWD`/`PRXY`/`RSLV`: all do network IO, all yield. `RSLV` was + checked separately since it is client driven at command rate, but `resolveName` has no cache + (`Server/Names.hs:62`). +- `deliverServiceMessages` (`Server.hs:1977`): `clientServiceSubscribed` is a one-way latch + (`Server.hs:2031`), so at most once per connection. +- `sendPendingEvtsThread.queueEvts` (`Server.hs:463`): the only one that can skip yielding. The + child is `writeTBQueue sndQ` plus three `IORef` bumps, so if space appeared it commits straight + through. ### Impact -Small and self-limiting, and I have not driven it live. +Small and bounded, and not driven live. -The one non-yielding path is rate capped by construction: `sendPending` runs once per -`pendingENDInterval` (15s in production, `Server/Main.hs:581`) for each of two subscriber sets, -and forks at most once per client per run. So at most 2 forks per client per 15s, and only for a -client whose `sndQ` was full at the check and had drained by the time the child ran. At the -measured 18% that is well under one stale entry per client per 15s, about 320 bytes each. - -Everything in `endThreads` is dropped by `clientDisconnected` (`Server.hs:1237`), so nothing +The one non-yielding path forks at most twice per client per `pendingENDInterval` (15s, +`Server/Main.hs:581`), and only for a client whose `sndQ` was full at the check and drained by the +time the child ran. `clientDisconnected` (`Server.hs:1237`) drops the whole map, so nothing survives the session. -A client can influence both preconditions by stalling and resuming its socket reads, so I am no -longer claiming this is unreachable. I am also not claiming it is reachable: that needs winning -a sub-millisecond window at two attempts per 15s, and I did not build the repro, because a -session-scoped few hundred bytes does not justify it. The honest status is a real ordering -defect with one candidate trigger and a hard ceiling. +A client can influence both preconditions by stalling and resuming socket reads, so this is not +unreachable, but winning a sub-millisecond window at two attempts per 15s was not demonstrated. -The practical cost is the misleading `endThreads` counter, which conflates stale entries with -genuinely running forked commands. +Practical cost is the misleading `endThreads` counter, which mixes stale entries with genuinely +running forked commands. ### Fix @@ -328,99 +240,66 @@ atomically $ modifyTVar' endThreads $ IM.adjust (const (Just w)) tId --- -## Clean +## Clean: TLS/TCP stack 200 connections opened at once, closed, then measured again: -| test | peak per conn | after 25s | -| ------------------------------------- | ------------- | --------- | -| TCP connect, never start TLS | 48.2 KiB | 0.31 KiB | -| TLS done, no SMP handshake | 203.1 KiB | 0.71 KiB | -| Handshake done, one byte, then quiet | 264.6 KiB | 0.87 KiB | +| test | peak per conn | after 25s | +| --- | --- | --- | +| TCP connect, never start TLS | 48.2 KiB | 0.31 KiB | +| TLS done, no SMP handshake | 203.1 KiB | 0.71 KiB | +| handshake done, one byte, then quiet | 264.6 KiB | 0.87 KiB | 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 -teardown still in progress. Falling means reclaimed, flat above baseline means leaked. +Sample late. At +5s the middle two still read ~120 KiB per connection, which looks like a 24 MiB +leak but is teardown 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 -connected: no read timeout, `transportTimeout` is hardcoded `Nothing` (`Transport/Server.hs:104`). +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 +connected, since `transportTimeout` is hardcoded `Nothing` (`Transport/Server.hs:104`). -## Connectivity and sockets under latency +## Clean: connectivity and sockets under latency -Latency swept with `BENCHLAG_MS` on `proxyfwd` (one way, so a request/response pair costs twice -this). Sockets counted from `/proc//fd` during the run. +`BENCHLAG_MS` swept on `proxyfwd`, one way. Sockets counted from `/proc//fd`. | lag each way | delivered | sockets | relay connects | reconnects | timeouts | -| ------------ | --------- | ------- | -------------- | ---------- | -------- | -| 0ms | 12/12 | 8 | 1 | 0 | 0 | -| 500ms | 10/10 | 8 | 1 | 0 | 0 | -| 5s | 6/6 | 8 | 1 | 0 | 0 | -| 16s | 4/4 | 8 | 1 | 0 | 0 | -| 40s | 0/2 | 8 | 1 | 0 | 1 | +| --- | --- | --- | --- | --- | --- | +| 0ms | 12/12 | 8 | 1 | 0 | 0 | +| 500ms | 10/10 | 8 | 1 | 0 | 0 | +| 5s | 6/6 | 8 | 1 | 0 | 0 | +| 16s | 4/4 | 8 | 1 | 0 | 0 | +| 40s | 0/2 | 8 | 1 | 0 | 1 | -Nothing accumulates. The socket count is the same whether forwards succeed or time out, the -proxy to relay session is opened once and reused, and there are no reconnects at any latency. -`proxy_smpClients` and `proxy_smpSessions` stay at 1 throughout. +Nothing accumulates. Same socket count whether forwards succeed or time out, session opened once +and reused, no reconnects at any latency. -This is the bad news for Leak 1. The session holding the stuck `sentCommands` entries never -drops, so nothing ever frees them. A connection that broke under latency would at least bound -the damage. +That robustness is what makes Leak 1 unbounded: the session holding the stuck entries never drops. -Forwards work up to 16s each way and fail at 40s. The governing limit is the 30s RFWD timeout. -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. +Forwards work to 16s each way and fail at 40s, governed by the 30s RFWD timeout. The exact cutoff +is not pinned down, since the test transport delays per read/write cycle rather than per message. -## Checked and not a problem: socketsLeaked accounting +## Checked, 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 from `active`, calls `gracefulClose conn 5000`, +then increments `closed`, and `socketsLeaked = accepted - closed - active`. That ordering leaves a +window where a closing connection is in neither bucket. -`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. +The window never opened in practice. Over 600 sequential cycles and 200 simultaneous teardowns, +read from the control port, `leaked` was 0 at every sample. The 5000 is a timeout, not a delay. -In practice the window never opened. Read over the control port during 600 sequential -connect/disconnect cycles, and again across 200 simultaneous teardowns: +Listed because an earlier version of this report called it a bug on code reading alone. -``` -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 -was the wrong conclusion. It is not reproducible because it is fixed. +## Already fixed: empty session variable `withGetSessVar'` (`Session.hs:65`) wraps the session var in `bracketOnError` with -`dropEmptySessVar`, so an interrupted connect drops the empty var instead of leaving it to -poison every later request. Fixed in `c9ebf72e` ("smp: fix proxy reconnection to relay after -restart"). +`dropEmptySessVar`, so an interrupted connect drops the empty var. Fixed in `c9ebf72e`. +`SMPProxyTests` covers the proxy and agent variants and both pass. Not reproducible because it is +fixed, not because it never happened. -`SMPProxyTests` already covers both the proxy and the agent variants, and both pass: +## Running the suite -``` -recovers when unresponsive relay restarts (control, no disconnect) [OK] -reconnects to relay after sender disconnects mid-connection [OK] -reconnects after a connect is cancelled mid-flight [OK] -``` - -A load phase cannot reproduce a fixed race, so the bench does not try. +`should have similar time for auth error, whether queue exists or not` compares wall clock with a +30% tolerance (45% on Postgres) and fails intermittently on a busy machine. Seen twice in four +runs under concurrent bench load, then 4/4 and 5/5 clean when idle, with and without these +changes. Run the suite on an idle machine.