Skip to content

Commit bed25e2

Browse files
fix(realtime): keep the file-doc store reconnecting instead of dying quietly (#6661)
* fix(realtime): keep the file-doc store reconnecting instead of dying quietly A relay that lost Redis for longer than its retry budget did not degrade — it went silently split-brain and stayed that way. The reconnect strategy returned an `Error` after ten attempts, which tells node-redis to give up and CLOSE the client, and a closed client rejects every command with "The client is closed" for the rest of the process's life. From that point the task kept serving clients while its rooms stopped receiving other tasks' updates, its own edits stopped reaching the shared stream (also the crash buffer between persists), and seeds, locks and the persist If-Match token all failed. The tail loop then treated that as a transient read error — `running` is only false during shutdown, so it retried every 500ms forever, one warning per attempt. A tab left open overnight produced thousands of identical lines, which is how the actual failure stayed invisible. - Never stop reconnecting. This process holds live documents whose only convergence path is that connection, so a connection it can rebuild is always worth rebuilding. Same capped backoff, now via the shared `backoffWithJitter`, and no error return. - Back the reader off after a failed read (500ms → 10s) instead of retrying at the read cadence, re-open a client that was CLOSED — node-redis reconnects a dropped client, never a closed one — and log the first failure of a streak then one in twenty, carrying the streak length, so an outage stays visible without burying itself. Pinned by a test that models a closed connection: six read attempts in three seconds before, about three after, and proof the reader is re-opened rather than abandoned. * fix(realtime): end the reader's failure streak on an idle read, not a busy one Review findings, both accurate. The streak reset sat after the entries were applied, so a blocking read that timed out with nothing new — the idle steady state — skipped it via `continue`. A healed outage's count therefore survived through normal polling, and the next unrelated blip opened at the backoff cap: minutes of avoidable split-brain, and a log line claiming a failure count it never earned. The streak now ends on the read RETURNING, which is what proves the connection works. Also: the new test built a raw `setTimeout` promise instead of the shared `sleep`, which CLAUDE.md calls out by name. * test(realtime): assert the retry delay, not a count inside a window The streak-reset guard could pass on the very regression it exists to catch. It counted read attempts inside a 1900ms window, and the jittered delay for a carried streak is 1600–2400ms — so whenever jitter landed below about 0.95, a second read fell inside the window and the assertion held even though the idle reads had never cleared `failures`. A single falsification run happened to draw a long delay, which is exactly how a guard like this goes quiet. Assert the delay itself instead. The first retry after a reset is 500ms ±20% (400–600ms); carried over it is the third, 2000ms ±20% (1600–2400ms). Those ranges are disjoint, so the check no longer depends on which jitter is drawn: against the old placement it now fails every time (measured 2160ms, 1925ms, 2046ms against the 1000ms bound).
1 parent 6de8ba2 commit bed25e2

2 files changed

Lines changed: 147 additions & 9 deletions

File tree

apps/realtime/src/handlers/file-doc-store.test.ts

Lines changed: 93 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
/**
22
* @vitest-environment node
33
*/
4+
import { sleep } from '@sim/utils/helpers'
45
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'
56
import * as Y from 'yjs'
67

@@ -15,6 +16,14 @@ interface Backing {
1516
seq: number
1617
/** Number of upcoming xAdd calls to fail with a transient error (to exercise publish retry). */
1718
failXAdd: number
19+
/** Set to fail every xRead the way node-redis does once a client has been closed. */
20+
readerClosed: boolean
21+
/** Failed reads served, so a test can prove the loop is not spinning at the read cadence. */
22+
reads: number
23+
/** When each read was attempted, so a test can assert the BACKOFF rather than a count in a window. */
24+
readTimes: number[]
25+
/** `connect()` calls, so a test can prove a closed reader is re-opened rather than abandoned. */
26+
connects: number
1827
}
1928

2029
const state = vi.hoisted(() => ({ backing: null as Backing | null }))
@@ -27,7 +36,11 @@ function makeClient(): any {
2736
return state.backing
2837
}
2938
const client: any = {
30-
connect: async () => {},
39+
isOpen: true,
40+
connect: async () => {
41+
client.isOpen = true
42+
b().connects++
43+
},
3144
quit: async () => {},
3245
on: () => client,
3346
duplicate: () => makeClient(),
@@ -52,14 +65,20 @@ function makeClient(): any {
5265
)
5366
},
5467
xRead: async (streams: { key: string; id: string }[]) => {
68+
b().reads++
69+
b().readTimes.push(Date.now())
70+
if (b().readerClosed) {
71+
client.isOpen = false
72+
throw new Error('The client is closed')
73+
}
5574
const res: { name: string; messages: { id: string; message: Record<string, string> }[] }[] =
5675
[]
5776
for (const { key, id } of streams) {
5877
const after = (b().streams.get(key) ?? []).filter((e) => seqOf(e.id) > seqOf(id))
5978
if (after.length) res.push({ name: key, messages: after.map((e) => ({ ...e })) })
6079
}
6180
if (res.length) return res
62-
await new Promise((r) => setTimeout(r, 5))
81+
await sleep(5)
6382
return null
6483
},
6584
set: async (key: string, val: string, opts?: { NX?: boolean }) => {
@@ -129,14 +148,85 @@ async function newStore(): Promise<FileDocStore> {
129148

130149
describe('FileDocStore', () => {
131150
beforeEach(() => {
132-
state.backing = { streams: new Map(), kv: new Map(), seq: 0, failXAdd: 0 }
151+
state.backing = {
152+
streams: new Map(),
153+
kv: new Map(),
154+
seq: 0,
155+
failXAdd: 0,
156+
readerClosed: false,
157+
reads: 0,
158+
readTimes: [],
159+
connects: 0,
160+
}
133161
stores = []
134162
})
135163

136164
afterEach(async () => {
137165
await Promise.all(stores.map((s) => s.shutdown()))
138166
})
139167

168+
/**
169+
* A connection that stops serving reads used to spin the tailer at the read cadence — two attempts a
170+
* second, one warning each, forever — while the task quietly stopped converging with every other one.
171+
* The loop must back off instead, and re-open a client that was closed rather than reading a dead one.
172+
*/
173+
it('backs off and re-opens the reader when its connection is closed, instead of spinning', async () => {
174+
const store = await newStore()
175+
const doc = new Y.Doc()
176+
await store.attachRoom(NAME, doc)
177+
state.backing!.readerClosed = true
178+
179+
state.backing!.connects = 0 // ignore the two `init` connects; count only recovery attempts
180+
const before = state.backing!.reads
181+
await sleep(3000)
182+
const attempts = state.backing!.reads - before
183+
184+
// A fixed 500ms retry manages 6–7 attempts in this window; backing off (500 → 1s → 2s → …) manages
185+
// about 3. Exact counts are timing-dependent, so assert the property — it slowed down — not a number.
186+
expect(attempts).toBeGreaterThan(0)
187+
expect(attempts).toBeLessThanOrEqual(4)
188+
// …and it tried to bring the connection back rather than leaving the tailer dead forever.
189+
expect(state.backing!.connects).toBeGreaterThan(0)
190+
doc.destroy()
191+
})
192+
193+
/**
194+
* The streak has to end on a read that RETURNS, not on one that carries messages: a blocking read
195+
* timing out with nothing new is the idle steady state. Counting only message-bearing reads would
196+
* keep a healed outage's streak alive through normal polling, so the next unrelated blip would open
197+
* at the backoff cap — minutes of unnecessary split-brain — and log a count it never earned.
198+
*/
199+
it('ends the failure streak on an idle read, so a later blip starts over', async () => {
200+
const store = await newStore()
201+
const doc = new Y.Doc()
202+
await store.attachRoom(NAME, doc)
203+
204+
// Build a streak of two failures (retries back off ~0.5s, then ~1s).
205+
state.backing!.readerClosed = true
206+
await sleep(800)
207+
// Redis comes back. Wait past the pending backoff so a read actually lands — and it returns
208+
// nothing new, which is the idle case this test is about.
209+
state.backing!.readerClosed = false
210+
await sleep(1000)
211+
212+
// A fresh blip must retry at the START of the backoff curve, not partway up it. Assert the DELAY
213+
// itself: counting attempts inside a fixed window cannot tell the two apart, because the jittered
214+
// delay for a carried streak (1.6–2.4s) overlaps any window wide enough to catch a reset one.
215+
state.backing!.readerClosed = true
216+
state.backing!.readTimes.length = 0
217+
await vi.waitFor(() => expect(state.backing!.readTimes.length).toBeGreaterThanOrEqual(2), {
218+
timeout: 5000,
219+
interval: 50,
220+
})
221+
const [first, second] = state.backing!.readTimes
222+
223+
// Streak reset ⇒ the first delay is 500ms ±20% ⇒ 400–600ms. Streak carried over ⇒ it is the third
224+
// delay, 2000ms ±20% ⇒ 1600–2400ms. Disjoint ranges, so this cannot pass on the wrong one without
225+
// the machine stalling the shorter sleep by 65%.
226+
expect(second - first).toBeLessThan(1000)
227+
doc.destroy()
228+
})
229+
140230
it('elects exactly one seeder across tasks (no split-brain seed)', async () => {
141231
const a = await newStore()
142232
const b = await newStore()

apps/realtime/src/handlers/file-doc-store.ts

Lines changed: 54 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -160,6 +160,12 @@ const SEED_LOCK_TTL_MS = FILE_DOC_TIMEOUTS.seedRequestMs + 4_000
160160
const STREAM_TTL_SEC = 600
161161
/** Refresh every occupied stream's TTL on this cadence, so a live doc's stream never expires. */
162162
const HEARTBEAT_MS = 60_000
163+
/** Cap on the delay between reconnection attempts — the strategy retries indefinitely (see `init`). */
164+
const RECONNECT_MAX_DELAY_MS = 3_000
165+
/** Cap on the reader's own retry backoff after a failed read. */
166+
const READER_RETRY_MAX_MS = 10_000
167+
/** After the first failure of a streak, log one reader failure in this many. */
168+
const READER_ERROR_LOG_EVERY = 20
163169

164170
const streamKey = (name: string) => `${STREAM_PREFIX}${name}`
165171

@@ -246,10 +252,17 @@ export class FileDocStore {
246252
const options = {
247253
url: this.redisUrl,
248254
socket: {
249-
reconnectStrategy: (retries: number) => {
250-
if (retries > 10) return new Error('FileDocStore Redis reconnection failed')
251-
return Math.min(retries * 100, 3000)
252-
},
255+
/**
256+
* Never stop reconnecting. Returning an `Error` here tells node-redis to give up and CLOSE the
257+
* client — and a closed client rejects every command with "The client is closed" for the rest of
258+
* the process's life. So an outage longer than the retry budget does not degrade this task, it
259+
* takes it out silently: its rooms stop receiving other tasks' updates, its own edits stop
260+
* reaching the shared stream, seeds and locks fail, and the only symptom is a warning per retry.
261+
* This process holds live documents whose sole convergence path is this connection, so a
262+
* connection it can rebuild is always worth rebuilding.
263+
*/
264+
reconnectStrategy: (retries: number) =>
265+
backoffWithJitter(retries + 1, null, { baseMs: 100, maxMs: RECONNECT_MAX_DELAY_MS }),
253266
},
254267
}
255268
this.write = createClient(options)
@@ -651,6 +664,7 @@ export class FileDocStore {
651664
* apply new entries. One blocking connection for the whole process regardless of open-file count.
652665
*/
653666
private async runReader(): Promise<void> {
667+
let failures = 0
654668
while (this.running && this.read) {
655669
const snapshot = new Map(this.rooms)
656670
if (snapshot.size === 0) {
@@ -662,6 +676,12 @@ export class FileDocStore {
662676
[...snapshot].map(([name, room]) => ({ key: streamKey(name), id: room.lastId })),
663677
{ BLOCK: READ_BLOCK_MS, COUNT: READ_COUNT }
664678
)
679+
// The streak ends HERE, on the read returning at all — not further down once entries are
680+
// applied. A blocking read that times out with nothing new is the idle steady state, and it
681+
// proves the connection works just as well as one carrying messages; leaving the streak
682+
// standing through it would keep an old outage's count alive indefinitely, so the next
683+
// unrelated blip would open at the backoff cap and log a failure count it never earned.
684+
failures = 0
665685
if (!res) continue
666686
for (const stream of res) {
667687
const name = stream.name.slice(STREAM_PREFIX.length)
@@ -674,12 +694,40 @@ export class FileDocStore {
674694
}
675695
} catch (error) {
676696
if (!this.running) break
677-
logger.warn('FileDocStore reader error; retrying', { error: getErrorMessage(error) })
678-
await sleep(500)
697+
await this.recoverReader(++failures, error)
679698
}
680699
}
681700
}
682701

702+
/**
703+
* A failed read is either a transient blip or a connection that is gone, and this loop cannot tell
704+
* them apart — so it backs off instead of retrying at the read cadence. Without that, a connection
705+
* that cannot serve reads spins this loop forever at two attempts a second, one warning each, which
706+
* is how an outage turns into thousands of identical log lines that bury the reason for it.
707+
*
708+
* It also re-opens a CLOSED client. node-redis reconnects a client that merely dropped, but never one
709+
* it has closed; the strategy above no longer closes one, so this covers a client closed some other
710+
* way (an explicit disconnect, a shutdown that raced a read) rather than leaving the tailer dead.
711+
*
712+
* Logs the first failure of a streak and then one in every {@link READER_ERROR_LOG_EVERY}, carrying
713+
* the streak length, so a real outage stays visible without filling the log.
714+
*/
715+
private async recoverReader(failures: number, error: unknown): Promise<void> {
716+
if (failures === 1 || failures % READER_ERROR_LOG_EVERY === 0) {
717+
logger.warn(`FileDocStore reader failed ${failures}x in a row; retrying`, {
718+
error: getErrorMessage(error),
719+
})
720+
}
721+
await sleep(backoffWithJitter(failures, null, { baseMs: 500, maxMs: READER_RETRY_MAX_MS }))
722+
if (this.running && this.read && !this.read.isOpen) {
723+
await this.read.connect().catch((reconnectError) => {
724+
logger.warn('FileDocStore could not re-open the reader connection', {
725+
error: getErrorMessage(reconnectError),
726+
})
727+
})
728+
}
729+
}
730+
683731
/**
684732
* Snapshot-then-trim compaction: append a full-state snapshot and drop the older deltas it subsumes,
685733
* so the stream stays bounded while a fresh task can still catch up from the head. Lock-guarded so

0 commit comments

Comments
 (0)