fix(lightning): survive bad LND WebSocket frames and keep the streams reconnecting - #210
Conversation
The three LND WebSocket streams were piped through `map(this.mapXMessage)`, which passes the mappers unbound. RxJS then calls them with `this === undefined`. The happy path never touches `this`, so this went unnoticed. The `result`-missing path does: it logs via `this.logger`, which throws a TypeError. RxJS converts a throw inside a map projection into an error notification, the subscribers register no error handler, so it reaches `reportUnhandledError` and takes the process down — tearing down all three WebSocket connections with it. LND's REST gateway ends a stream with an error frame that carries no `result`, so a cancelled TrackPayments subscription was enough to trigger it. - bind the mappers via arrow functions - route them through `safeMap` so a mapping failure stays local and the stream survives instead of terminating - log the offending frame as JSON; the template literal rendered `[object Object]`
Surviving a bad frame instead of crashing only helps if the reconnect path can still recover. `retryAttempt` was reset solely when a message arrived, never when a connection opened, so the 30-strike budget drained monotonically for any stream that reconnects but stays quiet — LND sends no backlog on subscribe. Previously each such frame killed the process and the restart reset the counter; now the process survives, so the budget has to be restored on `open` or ingestion stops for good with nothing erroring and nothing alerting. Also address two ways the recovery paths could still take the process down: - `createWebSocket()` reads the TLS certificate per instantiation and throws on a missing file. In a bare `setTimeout` that throw is uncaught, and with no socket created no `close` event arrives to drive the next attempt. Retry now catches, logs and re-arms. - `JSON.stringify` was the one unguarded statement inside the mapping-failure handler, so an unserializable frame reproduced the crash from inside the guard meant to prevent it. `safeMap` now takes a zero-argument mapper: a bare `this.mapXMessage` reference does not satisfy `() => T`, so the unbound call this fix is about cannot be written at the call site any more. Tests: retry-budget restore, retry after a throwing socket construction, invoice mapping incl. both settle_date branches, and assertions on the logged frame. Verified all nine fail against the previous behaviour.
The previous commit reset the retry budget on `open`, which fixed the quiet stream but left both remaining paths ending in a silent, permanently dead subscription: - A connection that opens and drops straight back reset the budget every cycle, so it retried forever at info level and the only error the client can emit never fired. LND sends no backlog on subscribe, so such a stream delivers nothing at all. - A connection that never opens still gave up for good after 30 attempts. That was survivable before only because a broken stream killed the process and the restart built fresh connections; without that accidental safety net, an LND outage longer than five minutes ended ingestion until the next deploy. The budget now measures consecutive failures to hold a connection: it resets only after a connection has stood for a while, so a flap drains it like a failed connect. Retries no longer stop; instead every 30 attempts without a stable connection raise an error, so a stuck stream keeps trying and stays visible. Also: - register the socket handlers against the socket they belong to rather than the field, so a retired socket cannot drive its successor — the same aliasing class this branch set out to fix - make `describe()` total; `String()` throws on a null-prototype object, which would have escaped the very handler that keeps mapping failures off the stream - type the message handler as `WebSocket.Data` and parse via `toString()`; ws delivers a Buffer, not a string, and the spec now emits one Of the tests, 13 fail against the previous behaviour on develop and 5 against the preceding commit. The earlier claim that all nine of that commit's tests were discriminating was wrong: four were, the rest characterise existing behaviour.
…e failures A budget of consecutive failures resets on any good cycle, so a single connection that holds hides everything around it. A stream alternating 28 short connections with one long one ran at 17% uptime without logging anything, and a steady 31s-up/10s-down loop — what an idle timeout in front of LND produces — reconnected 2107 times in a simulated day, also silently. Counting reconnects within a rolling hour has no such blind spot, and it covers both shapes the previous version needed separate handling for: a stream that cannot connect and one that connects and drops straight back both reconnect far more often than a healthy stream, which only does so on an LND restart or a deploy. That removes the hold-duration threshold, the consecutive counter and its off-by-one after a reset. Measured against the same simulations: mixed flap 580 reconnects -> 19 errors, steady loop 2107 -> 70, and a healthy stream reconnecting every two hours for a week stays silent. Also: assert the inspected output in the unserializable-frame test rather than only that logging happened, and drop a comment claiming a test covers the Buffer message path — JSON.parse already coerced a Buffer, so that change is type-only.
Judging health purely by reconnect rate has a floor: 30 reconnects per hour means any repeating failure cycle of 125 sec. or longer never registers. That band is occupied. No handshake timeout was set, so a connect attempt against a dropped (rather than refused) port fails at the TCP SYN timeout, ~127 sec., giving a 137 sec. cycle — 26 reconnects an hour on a stream that is completely dead, and the previous commit reported it as healthy. The consecutive counter it replaced had no such floor, so that was a regression within this branch. Worse, a rate cannot see a stream with no reconnects at all. Without a handshake timeout a stalled upgrade emits neither 'error' nor 'close', and a half-open connection never closes either, since ws disables the socket timeout and this client answers pings but never sends any. Both leave a stream delivering nothing while every signal reads it as healthy and quiet. - track how long the stream has been disconnected, reset on 'open'. This is immune to how slowly each attempt fails, and covers what the rate cannot - set handshakeTimeout, so a stalled upgrade becomes an 'error' and a 'close' that the retry chain can act on - ping on an interval and terminate when a pong does not come back, which turns a half-open connection into a reconnect - report the observed span in the reconnect alert rather than the configured window, which was constant by construction - log a repeating construction failure once instead of every 10 sec.; the signals above already carry the repetition - measure with the monotonic clock, so a backwards NTP or DST correction cannot fabricate a window's worth of reconnects Simulated over 24 h: SYN blackhole 630 reconnects, 0 alerts before, 209 now; half-open goes from silent forever to detected in 60 sec.; a healthy stream reconnecting every two hours for a week still logs nothing. 18 tests fail against develop and 5 against the preceding commit.
The heartbeat added in the previous commit rests on LND answering client pings, and that does not hold. lnd's WebSocket proxy installs no ping handler, so a ping is answered only by gorilla's default, which runs while the read loop is active and writes the pong with a one second deadline — and a write timeout is treated as temporary and swallowed. Tolerating exactly one missed pong then makes any event-loop stall longer than the interval enough to terminate a healthy stream, which loses events because LND sends no backlog on subscribe. Detecting a half-open connection is worth doing, but not on an assumption that cannot be checked from here and whose failure mode is a reconnect storm on all three streams at once. Left as a follow-up, noted in the PR. handshakeTimeout stays: a stalled upgrade emitting neither 'error' nor 'close' is the one liveness gap that needed no assumption about the peer. Retrying forever also made the socket 'error' handler unbounded. Previously the client gave up after 30 attempts and went quiet; now an unreachable LND logs at error level every 10 sec. indefinitely, which is the same defect the last commit fixed one line away for the construction failure. Both are now reported once per outage, and the throttled signals carry the repetition. Also: - report the downtime actually observed rather than the configured threshold, which was constant by construction — the same fix the last commit applied to the reconnect message but not to its sibling. Throttling now uses its own field, so re-arming no longer discards when the outage started - clear the construction latch on a successful construction rather than on a later 'open': construction can start succeeding while LND is still down, so 'open' never arrives and a second, different failure went unreported Every branch is now mutation-checked: negating either signal, dropping either throttle, either re-arm, the handshake timeout, the monotonic clock or the socket binding each break at least one test. 21 tests fail against develop, 5 against the preceding commit.
`connectErrorLogged` was a boolean cleared only on 'open', so during an outage that never opens, only the first cause was ever recorded. LND going down logs ECONNREFUSED; if it comes back with a rotated macaroon, every upgrade is rejected with a 401 that never reaches the log, and the operator keeps seeing an hour-old network error and chases a fault that no longer exists. That is the same asymmetry the previous commit fixed one line away for the construction failure. Both latches now key on the cause rather than on a boolean, so a repeat stays quiet and a change is reported. The set of causes is small and bounded — refused, timed out, unreachable, handshake rejected — so this cannot grow into per-attempt logging. Also closes three gaps that mutation testing found unpinned: - resetting the outage start on 'open'. Without it a fresh five-minute outage after a day of uptime reports the time since the process started, which is the constant-by-construction fault this branch has now fixed twice elsewhere - sending the subscribe body on 'open'. Dropping it leaves the client connected and silent, LND with nothing to send back, and both health signals reading a dead stream as healthy and quiet — the most complete silent death in the file - sending it on the socket that opened rather than on the field. Only the pong half of that binding was covered, though both are load-bearing: ws throws synchronously from send() and pong() while a socket is still connecting Also drops a test helper left over from the removed heartbeat, and a comment citing a two-minute connect that handshakeTimeout now bounds. 23 tests fail against develop, 2 against the preceding commit.
The previous commit keyed both error latches on the cause so that a change mid outage still reported, and justified it with "the set of causes is small and bounded, so this cannot grow into per-attempt logging". That does not follow: a bounded set of size two, alternating, defeats a single remembered value entirely. A crash-looping LND produces exactly that on the retry cadence — refused while the process is down, rejected while the REST gateway boots — and measured on the branch it logged on all 100 of 100 attempts, restoring the per-attempt volume that commit set out to remove. Each outage now remembers the causes it has already reported, capped, so a repeat stays quiet, a change is still reported, and neither alternation nor a message that varies can push it back to one line per attempt. errorCause also needed hardening, since it runs inside the catch that keeps the reconnect chain alive: - it could throw. String() throws on a null-prototype object, and a throw there skips the reschedule and escapes the timer, which is a dead stream plus an uncaught exception — the two failure modes this branch exists to remove. The sibling helper in the service was already guarded against exactly this - it collapsed every connect errno onto one key. From Node 20 autoSelectFamily is on by default and a connect failure to a hostname arrives as an AggregateError whose message is empty, so refused and unreachable were indistinguishable. The code is now part of the key. Latent on the pinned Node 18 base image, live on the next bump Also states the real reason both health signals exist. handshakeTimeout bounds a cycle at 25 sec., so a stream that cannot connect does now register as a rate — the downtime signal earns its place by reporting the size of an outage, reaching one twice as fast, and not depending on that bound holding. 26 tests fail against develop, 5 against the preceding commit.
…ports Capping the reported causes stopped the per-attempt logging, but saturating is silent: whichever five causes arrive first become the whole story. Measured with five gateway errors followed by an expired macaroon, the 401 never appeared once across 200 attempts, and nothing in the log said anything had been dropped — the operator reads five transient, self-healing-looking causes and concludes LND is restarting. That is the wrong-fault trap the cause set was meant to remove, narrowed from one stale cause to five rather than closed. A saturated set now says so once. Detection was never affected; this is about the log being honest about its own completeness. Also tightens two test assertions that were too loose to pin what they claimed: the cap tests bounded the count from above only, so a cap of 2, 3 or 4 — or a regression silencing the log entirely — passed the whole suite. And errors carrying neither a code nor a message now have a test, since without the String() fallback they would all collapse onto one key and only the first would be logged. Two mutants inside the cause-key helper survive and are left there deliberately: dropping the empty-string filter is behaviourally equivalent, and dropping the message from the key needs two errors that share a code but differ in message, which cannot arise against a fixed URL. 27 tests fail against develop, 1 against the preceding commit.
…e suppressed log
The guard this branch exists for was pinned on one stream of three. Removing
safeMap from the onchain and payment pipes left the whole service suite green,
because those two mappers cannot throw on any input the tests fed them. The frame
`null` is legal — `JSON.parse('null')` — and `null.result` throws in all three,
which is what tells an unguarded pipe from a guarded one. Without it the headline
claim rested on the invoice path alone.
The suppression notice could not say what it was about. Both cause sets share the
reporting helper and emitted identical text, so two saturating in one outage read
as a doubled line rather than one truncated connect log and one truncated retry
log. It now names which. Dropped "this outage" as well: the construction set is
cleared by a successful construction, not by the end of an outage, so the phrase
was wrong on that path.
Saturation is now tracked beside the causes instead of as an entry among them.
The sentinel's justifying comment was wrong — a JavaScript string holds a NUL
perfectly well, and an error message that happened to equal the marker would have
silently disabled the notice, which is the failure it was added to remove.
Two claims of mine in the previous commit did not survive review, both corrected
here rather than argued:
- "dropping the message from the cause key needs two errors that share a code but
differ in message, which cannot arise against a fixed URL" is false. read and
write ECONNRESET share a code and differ in message with no DNS involved, and
Node's connect message carries the resolved address, which changes when a
container is recreated mid-outage. The mutant is killed by a test now
- errorCause was unpinned at the construction call site — the one its own comment
is written for — so substituting String() there passed the whole suite while
reintroducing the throw that skips the reschedule
32 tests fail against develop, 2 against the preceding commit.
|
Nine review passes were needed to get this to zero findings, which is a lot for a fix that started Removing the crash removed an accidental safety net: the process dying and restarting was what Things that were found and fixed rather than shipped:
Reviewers to point at the sharpest parts: the two health signals and their thresholds Deliberately out of scope, listed in the description: half-open connection detection (needs one |
Problem
The API process died with an uncaught exception:
lightning-ws.service.tspiped all three LND streams throughmap(this.mapXMessage), passing themappers unbound — RxJS calls them with
this === undefined.The happy path never dereferences
this, which is why this survived unnoticed. Theresult-missingpath does, on the very line meant to report the problem:
LND's REST gateway terminates a stream with an error frame that carries no
result, so a cancelledTrackPaymentssubscription was enough to hit it. The process exit tore down all three WebSocketconnections; LND logged the matching
TrackPayments: context canceled,close 1006andwrite to closed pipeerrors on its side. The container restarted ~4 s later and reconnected.The same latent bug sat in
mapOnchainMessageandmapInvoiceMessage.Why the existing try/catch did not help
lightning-ws-client.tswrapsthis.next(JSON.parse(message))in a try/catch, which looks like itcovers this. It does not: RxJS catches a throw inside a
mapprojection and converts it into anerror notification on the subject, so it never propagates back to that catch. The subscribers in
lightning-transaction.service.tsregister no error handler, so the notification ends up inreportUnhandledError, which rethrows on a timer and kills the process.Binding alone is therefore not sufficient — any future throw in a projection would terminate the
subscription permanently, leaving the socket connected while nothing gets processed.
The part that is easy to miss
Removing the crash also removes an accidental safety net. The process dying and restarting was
what rebuilt dead WebSocket connections. Once the process survives, every path that gives up
reconnecting becomes permanent, and every one of them was silent. Most of this PR is about that.
Changes
Mapping (
lightning-ws.service.ts)safeMap, so a mapping failure logs and yieldsundefinedinstead ofterminating the stream.
undefinedis already the established "skip this message" signal — thehandlers in
lightning-transaction.service.tsall guard withif (message)safeMaptakes a zero-argument mapper, so a barethis.mapXMessagereference is a compile errorrather than a convention
describe(), which is total:JSON.stringifyrejects circularstructures and
String()throws on a null-prototype object, and this runs inside the handlerwhose whole job is to keep failures off the stream. The old template literal rendered
[object Object], which is why the incident left no record of what LND actually sentReconnection (
lightning-ws-client.ts)because the process died and came back. An LND outage longer than five minutes would now end
ingestion for the lifetime of the process
straight back — downtime stays short, but LND sends no backlog on subscribe so every gap loses
events. How long it has been down reports the size of an outage rather than just its existence,
reaches a stream that cannot connect about 2.4x sooner (300 s against ~725 s), and does not depend
on
handshakeTimeoutcontinuing to keep each attempt short enough to register as a rate. (A ratealone once had a real blind spot — a cycle longer than ~124 s never reaches 30 in an hour, and
before
handshakeTimeouta dropped port sat in exactly that band at ~137 s. That band is closednow; the downtime signal earns its place on the three reasons above.)
handshakeTimeout. A stalled upgrade emitted neithererrornorclose, so the retry chainhad nothing to react to and the stream stopped for good without reconnecting. Measured against a
blackholed SYN with the shipped 15 s value:
error+closeat 15021 ms with the option, noevent at all for 30 s without it
errorhandlerand the construction-failure log into one error-level trace per attempt, forever, for an
unreachable LND. Each outage now reports each distinct cause once, capped — so a repeat stays
quiet, a cause that changes mid-outage (a refused connection becoming a rejected macaroon) is
still reported, an LND crash-loop alternating two causes cannot push it back to one line per
attempt, and a set that saturates says so once rather than letting whichever causes arrived first
read as the complete story
no connection for N sec.(at most once per 300 s, N being the observedoutage),
N reconnects within M sec.(at most once per 30 reconnects, M being the observed span),and
further <connection error|retry failure> causes suppressed(once per cause set per reset,and only after 5 distinct causes have already been logged). This is new alert surface — a healthy
stream reconnects only on an LND restart or a deploy and stays silent
createWebSocket()reads the TLS certificate perinstantiation and throws on a missing file, so a cert rotation during a reconnect was an uncaught
exit — and with no socket created, no
closeevent would ever drive the next attemptthis.webSocket, so a retired socketcannot drive its successor.
wsthrows synchronously fromsend()/pong()while a socket isstill
CONNECTING, so this was a live process-exit path of the same aliasing class as theoriginal bug
WebSocket.Dataand parses viatoString();wsdelivers a Buffer.Behaviour is unchanged —
JSON.parsealready coerced it — this is a type honesty fixerr.codeas well aserr.message.String()throws on a null-prototype object, and it runs inside the retry catch, where a throwskips the reschedule and escapes the timer — a dead stream plus an uncaught exception. Separately,
from Node 20
autoSelectFamilyis on by default and a connect failure to a hostname arrives as anAggregateErrorwith an empty message, so without the code every errno collapsed onto one key.Latent on the pinned Node 18 image, live on the next bump
Tests
Two new specs. Measured per test rather than asserted:
developCovered: every mapper's
result-missing path, an unmappable frame, a circular frame, a frame thatneither
JSON.stringifynorString()can render, anullframe on each of the three streams(the one input that makes every mapper throw, and so the only one that tells a guarded pipe from an
unguarded one), stream survival afterwards, invoice mapping
including both
settle_datebranches, reconnect-after-close, retry past the alert threshold, retrywhen socket construction throws, retired-socket isolation, and the three reconnect-rate shapes
(cannot connect however slowly it fails / constant reconnects despite good cycles / healthy stream
stays silent), each alert's throttle and reported figure, the monotonic clock, the subscribe body
being sent on the socket that opened, and — for the two per-outage cause sets — their distinct reset
points, the cap in both directions, an alternating cause, two errors differing only by
code, anerror carrying neither, an error that cannot be described at all, and the notice emitted once when a
set saturates.
Every branch is mutation-checked: removing
safeMapfrom any of the three pipes, negating eithersignal, dropping either alert throttle or its re-arm, either cause set's dedup, cap, reset, notice
or its label, the handshake timeout, the monotonic clock, either socket binding, the subscribe send,
or the cause key's
codeormessagecomponent each break at least one test. The survivors left inplace are equivalent for every input
wsor Node can produce — argument order and separator withinthe cause key, and the empty-string filter, which changes the key text but not the partition.
Simulated over 24 h, except the healthy row, which runs a week. The first row is the shape that motivated the downtime signal — a dropped port
used to cycle every ~137 s (a ~127 s TCP SYN timeout plus the 10 s retry wait), under any
reconnect-rate threshold;
handshakeTimeoutnow bounds it, and the signal covers it either way:developThe
developcolumn is measured against that branch, not against an intermediate state of this one:its retry budget resets only when a message arrives, so any stream that reconnects without
delivering anything drains it and stops for good. That is the behaviour the process crash used to
paper over.
Local run of the PR CI steps:
npm run build,npm run lint,npm run test(78/78) all pass.Deliberately not in this PR
subscribe()call sites register no error handler. Adding a log-only handler wouldconvert a crash-and-restart, which recovers, into a silently dead subscription, since an error
notification terminates it permanently.
safeMapremoves the known producer; the rest wants aresubscribe strategy, not a swallow.
alchemy-webhook.service.ts:51has the same unguarded-projection shape:.pipe(filter((data) => network === Network[data.event.network]));. Different subsystem, and itsits behind an HMAC check.
mapPaymentMessageon a truthy-but-emptyresultemits a NaN-filled DTO. It is containeddownstream by an existing
if (!state) throwand its behaviour is unchanged by this PR.traffic and no
close, so both signals above read it as a healthy quiet stream. The obvious fix isa ping heartbeat, but lnd's WebSocket proxy installs no ping handler — a client ping is answered
only by gorilla's default, which writes the pong with a 1 s deadline and swallows a timeout — so
terminating on a missed pong risks reconnecting all three streams on a healthy node. This needs
one observation against a live LND (does an unsolicited client ping come back?) before it can be
built safely.
height
0and replay;TrackPaymentsdoes not, so a payment reaching a terminal state during agap is not re-emitted. The daily sync jobs backfill, but the gap is real.