From c8df722ae8df695d8cb8038eff6cdf90377ee45e Mon Sep 17 00:00:00 2001 From: Ron Cohen Date: Fri, 20 Mar 2026 16:13:55 +0100 Subject: [PATCH 1/2] Improve node-sdk fallback logging --- packages/node-sdk/src/batch-buffer.ts | 2 +- packages/node-sdk/src/client.ts | 66 +++++++--- packages/node-sdk/test/client.test.ts | 176 +++++++++++++++++++++----- 3 files changed, 197 insertions(+), 47 deletions(-) diff --git a/packages/node-sdk/src/batch-buffer.ts b/packages/node-sdk/src/batch-buffer.ts index a249973fa..12595457a 100644 --- a/packages/node-sdk/src/batch-buffer.ts +++ b/packages/node-sdk/src/batch-buffer.ts @@ -79,7 +79,7 @@ export default class BatchBuffer { count: flushingBuffer.length, }); } catch (error) { - this.logger?.error("flush of buffered items failed; discarding items", { + this.logger?.warn("flush of buffered items failed; discarding items", { error, count: flushingBuffer.length, }); diff --git a/packages/node-sdk/src/client.ts b/packages/node-sdk/src/client.ts index aa99ed599..ea88de313 100644 --- a/packages/node-sdk/src/client.ts +++ b/packages/node-sdk/src/client.ts @@ -175,6 +175,38 @@ function createFlagsFallbackSnapshot( }; } +function formatFlagsFallbackAge(savedAt: string): string | undefined { + const savedAtMs = Date.parse(savedAt); + if (!Number.isFinite(savedAtMs)) { + return undefined; + } + + const ageMs = Math.max(0, Date.now() - savedAtMs); + const minuteMs = 60_000; + const hourMs = 60 * minuteMs; + const dayMs = 24 * hourMs; + + if (ageMs < minuteMs) { + return "<1m"; + } + + if (ageMs < hourMs) { + return `${Math.floor(ageMs / minuteMs)}m`; + } + + if (ageMs < dayMs) { + return `${Math.floor(ageMs / hourMs)}h`; + } + + return `${Math.floor(ageMs / dayMs)}d`; +} + +function createErrorWithCause(message: string, cause: unknown): Error { + const error = new Error(message) as Error & { cause?: unknown }; + error.cause = cause; + return error; +} + /** * The SDK client. * @@ -427,7 +459,6 @@ export class ReflagClient { this._config.flagsFetchRetries, ); if (!isObject(res) || !Array.isArray(res?.features)) { - this.logger.warn("flags cache: invalid response", res); return await this.loadFlagsFallbackDefinitions(); } @@ -468,6 +499,9 @@ export class ReflagClient { ); if (!snapshot) { + this.logger.warn( + "remote flags unavailable, no fallback flags found in flagsFallbackProvider", + ); return undefined; } @@ -476,9 +510,12 @@ export class ReflagClient { return undefined; } - this.logger.warn("using flag definitions from flagsFallbackProvider", { - savedAt: snapshot.savedAt, - }); + const fallbackAge = formatFlagsFallbackAge(snapshot.savedAt); + this.logger.warn( + fallbackAge + ? `remote flags unavailable, using fallback flags fetched ${fallbackAge} ago (${snapshot.savedAt})` + : `remote flags unavailable, using fallback flags (${snapshot.savedAt})`, + ); return compileFlagDefinitions(snapshot.flags); } catch (error) { @@ -977,8 +1014,6 @@ export class ReflagClient { * @param path - The path to send the request to. * @param body - The body of the request. * - * @returns A boolean indicating if the request was successful. - * * @throws An error if the path or body is invalid. **/ private async post(path: string, body: TBody) { @@ -996,16 +1031,16 @@ export class ReflagClient { this.logger.debug(`post request to "${url}"`, response); if (!response.ok || !isObject(response.body) || !response.body.success) { - this.logger.warn( + throw createErrorWithCause( `invalid response received from server for "${url}"`, JSON.stringify(response), ); - return false; } - return true; } catch (error) { - this.logger.error(`post request to "${url}" failed with error`, error); - return false; + throw createErrorWithCause( + `post request to "${url}" failed with error`, + error, + ); } } @@ -1051,7 +1086,7 @@ export class ReflagClient { 10000, ); } catch (error) { - this.logger.error( + this.logger.debug( `get request to "${path}" failed with error after ${retries} retries`, error, ); @@ -1072,9 +1107,10 @@ export class ReflagClient { "events must be a non-empty array", ); - const sent = await this.post("bulk", events); - if (!sent) { - throw new Error("Failed to send bulk events"); + try { + await this.post("bulk", events); + } catch (error) { + throw createErrorWithCause("failed to send bulk events", error); } } diff --git a/packages/node-sdk/test/client.test.ts b/packages/node-sdk/test/client.test.ts index 470aa4cd6..05e14cbee 100644 --- a/packages/node-sdk/test/client.test.ts +++ b/packages/node-sdk/test/client.test.ts @@ -593,9 +593,14 @@ describe("ReflagClient", () => { await client.updateUser(user.id); await client.flush(); - expect(logger.error).toHaveBeenCalledWith( - expect.stringMatching("post request to .* failed with error"), - error, + expect(logger.warn).toHaveBeenCalledWith( + "flush of buffered items failed; discarding items", + expect.objectContaining({ + count: 1, + error: expect.objectContaining({ + message: "failed to send bulk events", + }), + }), ); }); @@ -608,9 +613,15 @@ describe("ReflagClient", () => { await client.flush(); expect(logger.warn).toHaveBeenCalledWith( - expect.stringMatching("invalid response received from server for"), - JSON.stringify(response), + "flush of buffered items failed; discarding items", + expect.objectContaining({ + count: 1, + error: expect.objectContaining({ + message: "failed to send bulk events", + }), + }), ); + expect(logger.error).not.toHaveBeenCalled(); }); it("should throw an error if opts are not valid or the user is not set", async () => { @@ -682,9 +693,14 @@ describe("ReflagClient", () => { await client.updateCompany(company.id, {}); await client.flush(); - expect(logger.error).toHaveBeenCalledWith( - expect.stringMatching("post request to .* failed with error"), - error, + expect(logger.warn).toHaveBeenCalledWith( + "flush of buffered items failed; discarding items", + expect.objectContaining({ + count: 1, + error: expect.objectContaining({ + message: "failed to send bulk events", + }), + }), ); }); @@ -700,9 +716,15 @@ describe("ReflagClient", () => { await client.flush(); expect(logger.warn).toHaveBeenCalledWith( - expect.stringMatching("invalid response received from server for"), - JSON.stringify(response), + "flush of buffered items failed; discarding items", + expect.objectContaining({ + count: 1, + error: expect.objectContaining({ + message: "failed to send bulk events", + }), + }), ); + expect(logger.error).not.toHaveBeenCalled(); }); it("should throw an error if company is not valid", async () => { @@ -819,9 +841,14 @@ describe("ReflagClient", () => { await client.bindClient({ user }).track(event.event); await client.flush(); - expect(logger.error).toHaveBeenCalledWith( - expect.stringMatching("post request to .* failed with error"), - error, + expect(logger.warn).toHaveBeenCalledWith( + "flush of buffered items failed; discarding items", + expect.objectContaining({ + count: 2, + error: expect.objectContaining({ + message: "failed to send bulk events", + }), + }), ); }); @@ -837,9 +864,15 @@ describe("ReflagClient", () => { await client.flush(); expect(logger.warn).toHaveBeenCalledWith( - expect.stringMatching("invalid response received from server for "), - JSON.stringify(response), + "flush of buffered items failed; discarding items", + expect.objectContaining({ + count: 2, + error: expect.objectContaining({ + message: "failed to send bulk events", + }), + }), ); + expect(logger.error).not.toHaveBeenCalled(); }); it("should log if user is not set", async () => { @@ -957,10 +990,11 @@ describe("ReflagClient", () => { }); it("should load flag definitions from flagsFallbackProvider when live fetch fails", async () => { + const savedAt = "2026-03-09T00:00:00.000Z"; const flagsFallbackProvider: FlagsFallbackProvider = { load: vi.fn().mockResolvedValue({ version: 1, - savedAt: "2026-03-09T00:00:00.000Z", + savedAt, flags: flagDefinitions.features, }), save: vi.fn(), @@ -971,6 +1005,90 @@ describe("ReflagClient", () => { const client = new ReflagClient({ ...validOptions, flagsFallbackProvider, + flagsFetchRetries: 0, + }); + + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-03-09T00:20:00.000Z")); + try { + await client.initialize(); + + expect(flagsFallbackProvider.load).toHaveBeenCalledWith( + expect.objectContaining({ + secretKeyHash: expect.any(String), + }), + ); + expect(logger.warn).toHaveBeenCalledTimes(1); + expect(logger.warn).toHaveBeenCalledWith( + `remote flags unavailable, using fallback flags fetched 20m ago (${savedAt})`, + ); + + expect( + client.getFlag({ company, user, other: otherContext }, "flag1"), + ).toStrictEqual({ + key: "flag1", + isEnabled: true, + config: { + key: "config-1", + payload: { something: "else" }, + }, + track: expect.any(Function), + }); + } finally { + vi.useRealTimers(); + } + }); + + it("should log remote flag fetch failures at debug level when using fallback definitions", async () => { + const error = new Error("fetch failed"); + const savedAt = "2026-03-09T00:00:00.000Z"; + const flagsFallbackProvider: FlagsFallbackProvider = { + load: vi.fn().mockResolvedValue({ + version: 1, + savedAt, + flags: flagDefinitions.features, + }), + save: vi.fn(), + }; + + httpClient.get.mockRejectedValue(error); + + const client = new ReflagClient({ + ...validOptions, + flagsFallbackProvider, + flagsFetchRetries: 0, + }); + + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-03-09T00:20:00.000Z")); + try { + await client.initialize(); + + expect(logger.debug).toHaveBeenCalledWith( + 'get request to "features" failed with error after 0 retries', + error, + ); + expect(logger.warn).toHaveBeenCalledWith( + `remote flags unavailable, using fallback flags fetched 20m ago (${savedAt})`, + ); + expect(logger.error).not.toHaveBeenCalled(); + } finally { + vi.useRealTimers(); + } + }); + + it("should warn when live fetch fails and flagsFallbackProvider has no saved snapshot", async () => { + const flagsFallbackProvider: FlagsFallbackProvider = { + load: vi.fn().mockResolvedValue(undefined), + save: vi.fn(), + }; + + httpClient.get.mockResolvedValue({ success: false }); + + const client = new ReflagClient({ + ...validOptions, + flagsFallbackProvider, + flagsFetchRetries: 0, }); await client.initialize(); @@ -980,18 +1098,9 @@ describe("ReflagClient", () => { secretKeyHash: expect.any(String), }), ); - - expect( - client.getFlag({ company, user, other: otherContext }, "flag1"), - ).toStrictEqual({ - key: "flag1", - isEnabled: true, - config: { - key: "config-1", - payload: { something: "else" }, - }, - track: expect.any(Function), - }); + expect(logger.warn).toHaveBeenCalledWith( + "remote flags unavailable, no fallback flags found in flagsFallbackProvider", + ); }); it("should save fetched flag definitions to flagsFallbackProvider", async () => { @@ -1856,9 +1965,14 @@ describe("ReflagClient", () => { await client.flush(); - expect(logger.error).toHaveBeenCalledWith( - expect.stringMatching("post request .* failed with error"), - expect.any(Error), + expect(logger.warn).toHaveBeenCalledWith( + "flush of buffered items failed; discarding items", + expect.objectContaining({ + count: 2, + error: expect.objectContaining({ + message: "failed to send bulk events", + }), + }), ); }); From 614b343a9bbbe4ae8b6374b4b533b9588628ed95 Mon Sep 17 00:00:00 2001 From: Ron Cohen Date: Fri, 20 Mar 2026 16:36:05 +0100 Subject: [PATCH 2/2] improve logging further --- .../examples/express/reflagConfig.json | 6 +++++ packages/node-sdk/src/client.ts | 4 +-- packages/node-sdk/test/client.test.ts | 25 +++++++++++++++++++ 3 files changed, 33 insertions(+), 2 deletions(-) create mode 100644 packages/node-sdk/examples/express/reflagConfig.json diff --git a/packages/node-sdk/examples/express/reflagConfig.json b/packages/node-sdk/examples/express/reflagConfig.json new file mode 100644 index 000000000..b4f55d975 --- /dev/null +++ b/packages/node-sdk/examples/express/reflagConfig.json @@ -0,0 +1,6 @@ +{ + "overrides": { + "show-todos": true, + "create-todos": true + } +} diff --git a/packages/node-sdk/src/client.ts b/packages/node-sdk/src/client.ts index ea88de313..67cd5e326 100644 --- a/packages/node-sdk/src/client.ts +++ b/packages/node-sdk/src/client.ts @@ -1078,8 +1078,8 @@ export class ReflagClient { const { success: _, ...result } = response.body; return result as TResponse; }, - () => { - this.logger.warn("failed to fetch flags, will retry"); + (error) => { + this.logger.warn("failed to fetch flags, will retry", error); }, retries, 1000, diff --git a/packages/node-sdk/test/client.test.ts b/packages/node-sdk/test/client.test.ts index 05e14cbee..30f15a099 100644 --- a/packages/node-sdk/test/client.test.ts +++ b/packages/node-sdk/test/client.test.ts @@ -1077,6 +1077,31 @@ describe("ReflagClient", () => { } }); + it("should include the cause when warning that flag fetch will retry", async () => { + const error = new Error("fetch failed"); + httpClient.get.mockRejectedValue(error); + + const client = new ReflagClient({ + ...validOptions, + cacheStrategy: "in-request", + flagsFetchRetries: 1, + }); + + vi.useFakeTimers(); + try { + const initializePromise = client.initialize(); + await vi.runAllTimersAsync(); + await initializePromise; + + expect(logger.warn).toHaveBeenCalledWith( + "failed to fetch flags, will retry", + error, + ); + } finally { + vi.useRealTimers(); + } + }); + it("should warn when live fetch fails and flagsFallbackProvider has no saved snapshot", async () => { const flagsFallbackProvider: FlagsFallbackProvider = { load: vi.fn().mockResolvedValue(undefined),