Skip to content

Commit 64aab80

Browse files
authored
Merge pull request #393 from Jaydbrown/fix/issues-364-365-366-367
Fix drain() race hardening, semaphore timer leak, Redis client health check, and silent event drops (#364, #365, #366, #367)
2 parents 262aff6 + b8a6db6 commit 64aab80

8 files changed

Lines changed: 360 additions & 10 deletions

File tree

‎src/indexer/eventParser.js‎

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
const crypto = require('crypto');
22
const { scValToNative } = require('@stellar/stellar-sdk');
3+
const logger = require('../logger');
34

45
const EVENT_FIELDS = {
56
airdrop_created: ['airdrop_id', 'creator', 'token', 'total_amount', 'expiry_ledger'],
@@ -80,7 +81,19 @@ function parseContractEvent(event) {
8081
const nativeTopics = (event.topic || []).map(decodeScVal);
8182
const eventName = nativeTopics.map(normalizeEventName).find(Boolean);
8283

83-
if (!eventName) return null;
84+
if (!eventName) {
85+
// Issue #367: previously dropped with no trace. A contract upgrade that
86+
// adds a new event type (not yet in EVENT_FIELDS) would silently stop
87+
// being indexed with nothing in the logs to explain why — logging the
88+
// raw topics is what lets an operator notice and add the new name.
89+
logger.warn('eventParser: dropping event with unrecognized name', {
90+
topics: nativeTopics,
91+
ledger: event.ledger,
92+
contract_id: contractIdToString(event.contractId),
93+
paging_token: event.pagingToken || null,
94+
});
95+
return null;
96+
}
8497

8598
const decodedValue = decodeScVal(event.value);
8699
const eventNameIndex = nativeTopics.findIndex((topic) => topic === eventName);

‎src/services/cache.js‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,22 @@ function _checkQueueBackpressure(caller) {
5555
}
5656

5757
function getClient() {
58+
// Issue #366: 'end' is ioredis's terminal state — reached after .quit()/
59+
// .disconnect(true), or after retryStrategy() returns null (MAX_RETRIES
60+
// exceeded, see below). A client in 'end' will never reconnect on its
61+
// own and rejects every command immediately with "Connection is closed."
62+
// Transient states ('connecting', 'reconnecting', 'close') are left
63+
// alone — enableOfflineQueue: true already buffers commands through
64+
// those and flushes them once the client reaches 'ready' again, so
65+
// discarding the client there would just churn connections for no
66+
// benefit.
67+
if (client && client.status === 'end') {
68+
logger.warn('Redis client reached terminal "end" state, discarding and reconnecting', {
69+
reconnectAttempts,
70+
});
71+
client = null;
72+
}
73+
5874
if (!client) {
5975
client = new Redis(config.redis.url, {
6076
lazyConnect: true,

‎src/utils/semaphore.js‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,10 @@ class Semaphore {
4949
entry.timer = setTimeout(() => {
5050
const idx = this._queue.indexOf(entry);
5151
if (idx !== -1) this._queue.splice(idx, 1);
52+
// Issue #365: drop the reference to this (now-fired) timer once
53+
// it's done its job, so the closure the timer callback holds on
54+
// `entry` isn't kept alive by `entry.timer` pointing back at it.
55+
entry.timer = null;
5256
reject(new Error(`Semaphore: timed out after ${timeoutMs}ms`));
5357
}, timeoutMs);
5458
}

‎src/ws/PriceSubscriptionManager.js‎

Lines changed: 21 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -221,14 +221,26 @@ class PriceSubscriptionManager {
221221
drain(drainTimeoutMs = 5000) {
222222
this.stopHeartbeat();
223223
this._draining = true;
224-
const clientCount = this._clients.size;
224+
225+
// Issue #364: freeze the exact set of sockets being drained right here,
226+
// in the same synchronous tick as the flag flip above — add() checks
227+
// this._draining as its very first statement, so nothing can be
228+
// inserted into this._clients after this line runs. Every later phase
229+
// below (which resumes asynchronously via setTimeout, real yield
230+
// points where a lot can happen in the live map) iterates this frozen
231+
// list rather than the live this._clients, so a client connecting
232+
// (and being rejected) mid-drain, or one that legitimately disconnects
233+
// and is removed via _remove() between phases, can never change what
234+
// this specific drain run touches.
235+
const drainedSockets = [...this._clients.keys()];
236+
const clientCount = drainedSockets.length;
225237
if (clientCount === 0) return Promise.resolve();
226238

227239
this._drainStats = { warned: clientCount, closed: 0, forceClosed: 0 };
228240
logger.info('Draining WebSocket connections', { count: clientCount, drain_timeout_ms: drainTimeoutMs });
229241

230242
// Phase 1: Broadcast shutdown warning so clients can prepare
231-
for (const [ws] of this._clients) {
243+
for (const ws of drainedSockets) {
232244
try {
233245
this._send(ws, { type: 'server_shutdown', message: 'Server is shutting down', drain_timeout_ms: drainTimeoutMs });
234246
} catch {
@@ -241,7 +253,8 @@ class PriceSubscriptionManager {
241253
const closeDelayMs = Math.min(1000, drainTimeoutMs / 2);
242254
return new Promise((resolve) => {
243255
const closeTimer = setTimeout(() => {
244-
for (const [ws] of this._clients) {
256+
for (const ws of drainedSockets) {
257+
if (!this._clients.has(ws)) continue; // already disconnected on its own
245258
try {
246259
ws.close(1001, 'Server shutting down');
247260
this._drainStats.closed++;
@@ -254,15 +267,14 @@ class PriceSubscriptionManager {
254267
closeTimer.unref();
255268

256269
const deadline = setTimeout(() => {
257-
const remaining = this._clients.size;
258-
for (const [ws] of this._clients) {
270+
let remaining = 0;
271+
for (const ws of drainedSockets) {
272+
if (!this._clients.has(ws)) continue; // already disconnected on its own
273+
remaining++;
259274
try { ws.terminate(); } catch { /* ignore */ }
275+
this._remove(ws);
260276
this._drainStats.forceClosed++;
261277
}
262-
this._clients.clear();
263-
this._clientIpBySocket.clear();
264-
this._connectionsByIp.clear();
265-
updateGauge(-clientCount);
266278
logger.info('WebSocket drain complete', {
267279
total: clientCount,
268280
gracefully_closed: this._drainStats.closed,

‎test/cache.test.js‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -70,3 +70,38 @@ describe('Redis queue warning state', () => {
7070
expect(mockLogger.info.mock.calls.map(([, metadata]) => metadata.caller)).toEqual(['get', 'set']);
7171
});
7272
});
73+
74+
// Issue #366: getClient() returned a cached client with no check that it
75+
// was still usable, so a client that had reached ioredis's terminal 'end'
76+
// state (no auto-reconnect, every command rejected immediately) would keep
77+
// being handed to every caller forever.
78+
describe('getClient health check (#366)', () => {
79+
test('returns the same client instance while it is healthy', () => {
80+
const { cache, redis } = loadCache();
81+
const again = cache.getClient();
82+
expect(again).toBe(redis);
83+
});
84+
85+
test('discards a client in the terminal "end" state and creates a fresh one', () => {
86+
const { cache, redis } = loadCache();
87+
redis.status = 'end';
88+
89+
const next = cache.getClient();
90+
91+
expect(next).not.toBe(redis);
92+
expect(next.status).toBe('ready');
93+
expect(mockLogger.warn).toHaveBeenCalledWith(
94+
expect.stringContaining('terminal "end" state'),
95+
expect.any(Object),
96+
);
97+
});
98+
99+
test('does not discard a client that is merely reconnecting (offline queue covers it)', () => {
100+
const { cache, redis } = loadCache();
101+
redis.status = 'reconnecting';
102+
103+
const next = cache.getClient();
104+
105+
expect(next).toBe(redis);
106+
});
107+
});

‎test/indexerParser.test.js‎

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,8 @@
11
'use strict';
22

3+
const mockLogger = { info: jest.fn(), warn: jest.fn(), error: jest.fn(), debug: jest.fn() };
4+
jest.mock('../src/logger', () => mockLogger);
5+
36
const { nativeToScVal, xdr } = require('@stellar/stellar-sdk');
47
const { EVENT_NAMES, parseContractEvent } = require('../src/indexer/eventParser');
58

@@ -90,4 +93,25 @@ describe('Soroban contract event parser', () => {
9093
test('ignores unsupported contract events', () => {
9194
expect(parseContractEvent(event(['unrelated_event'], ['drop-1']))).toBeNull();
9295
});
96+
97+
// Issue #367: previously dropped with zero logging anywhere in the
98+
// pipeline, so a contract upgrade adding a new event type would silently
99+
// stop being indexed with nothing to explain why.
100+
test('logs a warning naming the raw topics when dropping an unrecognized event', () => {
101+
mockLogger.warn.mockClear();
102+
const result = parseContractEvent(event(['some_future_event'], ['drop-1'], { ledger: 999 }));
103+
104+
expect(result).toBeNull();
105+
expect(mockLogger.warn).toHaveBeenCalledTimes(1);
106+
const [message, meta] = mockLogger.warn.mock.calls[0];
107+
expect(message).toContain('unrecognized name');
108+
expect(meta.ledger).toBe(999);
109+
expect(meta.topics).toContain('some_future_event');
110+
});
111+
112+
test('does not log a warning for a recognized event', () => {
113+
mockLogger.warn.mockClear();
114+
parseContractEvent(event(['airdrop_expired', 'drop-1'], [875n]));
115+
expect(mockLogger.warn).not.toHaveBeenCalled();
116+
});
93117
});
Lines changed: 161 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,161 @@
1+
'use strict';
2+
3+
const mockLogger = { info: jest.fn(), warn: jest.fn(), error: jest.fn(), debug: jest.fn() };
4+
jest.mock('../src/logger', () => mockLogger);
5+
jest.mock('../src/config', () => ({
6+
ws: { maxConnections: 100, maxConnectionsPerIp: 5 },
7+
}));
8+
9+
const { PriceSubscriptionManager } = require('../src/ws/PriceSubscriptionManager');
10+
11+
const OPEN = 1;
12+
const CLOSED = 3;
13+
14+
/** Minimal fake matching the subset of the `ws` socket API this class uses. */
15+
class FakeSocket {
16+
constructor() {
17+
this.readyState = OPEN;
18+
this._handlers = {};
19+
this.sent = [];
20+
this.closed = false;
21+
this.terminated = false;
22+
}
23+
24+
on(event, handler) {
25+
(this._handlers[event] ??= []).push(handler);
26+
}
27+
28+
emit(event, ...args) {
29+
for (const h of this._handlers[event] || []) h(...args);
30+
}
31+
32+
send(data) {
33+
this.sent.push(JSON.parse(data));
34+
}
35+
36+
close() {
37+
this.closed = true;
38+
this.readyState = CLOSED;
39+
this.emit('close');
40+
}
41+
42+
terminate() {
43+
this.terminated = true;
44+
this.readyState = CLOSED;
45+
}
46+
}
47+
// `ws.readyState !== ws.constructor.OPEN` is how the real code checks
48+
// openness — give the fake the same static shape.
49+
FakeSocket.OPEN = OPEN;
50+
51+
function req(ip) {
52+
return { socket: { remoteAddress: ip }, headers: {} };
53+
}
54+
55+
describe('PriceSubscriptionManager.drain (#364)', () => {
56+
let manager;
57+
58+
beforeEach(() => {
59+
manager = new PriceSubscriptionManager();
60+
jest.useFakeTimers();
61+
});
62+
63+
afterEach(() => {
64+
jest.useRealTimers();
65+
});
66+
67+
test('add() is rejected with 1013 once draining has started', () => {
68+
manager.drain(5000);
69+
70+
const ws = new FakeSocket();
71+
const closeSpy = jest.spyOn(ws, 'close');
72+
const accepted = manager.add(ws, req('10.0.0.9'));
73+
74+
expect(accepted).toBe(false);
75+
expect(closeSpy).toHaveBeenCalledWith(1013, 'Server shutting down');
76+
expect(manager.connectionCount).toBe(0);
77+
});
78+
79+
test('warns every pre-drain client, then closes them after the grace delay', () => {
80+
const a = new FakeSocket();
81+
const b = new FakeSocket();
82+
manager.add(a, req('10.0.0.1'));
83+
manager.add(b, req('10.0.0.2'));
84+
85+
manager.drain(4000);
86+
87+
expect(a.sent[0]).toMatchObject({ type: 'server_shutdown' });
88+
expect(b.sent[0]).toMatchObject({ type: 'server_shutdown' });
89+
expect(a.closed).toBe(false);
90+
91+
jest.advanceTimersByTime(1000); // closeDelayMs = min(1000, 4000/2) = 1000
92+
expect(a.closed).toBe(true);
93+
expect(b.closed).toBe(true);
94+
});
95+
96+
test('force-terminates anything still open once drainTimeoutMs elapses', async () => {
97+
const a = new FakeSocket();
98+
manager.add(a, req('10.0.0.1'));
99+
// Never actually closes on its own even after close() is called below —
100+
// simulate a stuck client by no-oping close().
101+
a.close = () => {};
102+
103+
const donePromise = manager.drain(2000);
104+
jest.advanceTimersByTime(1000); // grace delay -> ws.close() (no-op here)
105+
jest.advanceTimersByTime(1000); // deadline -> ws.terminate()
106+
await donePromise;
107+
108+
expect(a.terminated).toBe(true);
109+
expect(manager.drainStats.forceClosed).toBe(1);
110+
});
111+
112+
// The core of #364: even though add() already rejects connections once
113+
// _draining is true (verified above), drain() now also operates on a
114+
// snapshot of the client set taken atomically the instant draining
115+
// starts, rather than the live, mutable this._clients map. This proves
116+
// that guarantee directly: an entry inserted into the live map by some
117+
// other path *after* drain() has already captured its snapshot (bypassing
118+
// add()'s own guard, standing in for any future bug that might do so) is
119+
// never touched by any later drain phase.
120+
test('a client inserted into the live map after drain() starts is never touched by later phases', async () => {
121+
const a = new FakeSocket();
122+
manager.add(a, req('10.0.0.1'));
123+
124+
const donePromise = manager.drain(2000);
125+
126+
const intruder = new FakeSocket();
127+
manager._clients.set(intruder, { assets: new Set(), missedPings: 0 });
128+
129+
jest.advanceTimersByTime(1000);
130+
expect(a.closed).toBe(true);
131+
expect(intruder.closed).toBe(false);
132+
133+
jest.advanceTimersByTime(1000);
134+
await donePromise;
135+
136+
expect(intruder.terminated).toBe(false);
137+
expect(manager.drainStats.warned).toBe(1); // only `a`, captured at drain() start
138+
});
139+
140+
test('a client that disconnects naturally between drain phases is not double-counted', async () => {
141+
const a = new FakeSocket();
142+
const b = new FakeSocket();
143+
manager.add(a, req('10.0.0.1'));
144+
manager.add(b, req('10.0.0.2'));
145+
146+
const donePromise = manager.drain(2000);
147+
148+
jest.advanceTimersByTime(1000); // both get ws.close() -> FakeSocket emits 'close' -> _remove()
149+
expect(manager.connectionCount).toBe(0);
150+
151+
jest.advanceTimersByTime(1000); // deadline: nothing left to force-close
152+
await donePromise;
153+
154+
expect(manager.drainStats.forceClosed).toBe(0);
155+
});
156+
157+
test('drain() with no connected clients resolves immediately without scheduling timers', async () => {
158+
await expect(manager.drain(2000)).resolves.toBeUndefined();
159+
expect(manager.isDraining).toBe(true);
160+
});
161+
});

0 commit comments

Comments
 (0)