diff --git a/packages/shared/sdk-server/__tests__/store/TransactionalFeatureStoreRecovery.test.ts b/packages/shared/sdk-server/__tests__/store/TransactionalFeatureStoreRecovery.test.ts new file mode 100644 index 0000000000..93a649998a --- /dev/null +++ b/packages/shared/sdk-server/__tests__/store/TransactionalFeatureStoreRecovery.test.ts @@ -0,0 +1,1425 @@ +import { LDLogger } from '@launchdarkly/js-sdk-common'; + +import { + DataKind, + PersistentDataStore, + PersistentStoreDataKind, + SerializedItemDescriptor, +} from '../../src/api/interfaces'; +import KeyedItem from '../../src/api/interfaces/persistent_store/KeyedItem'; +import { KindKeyedStore } from '../../src/api/interfaces/persistent_store/PersistentDataStore'; +import { + LDFeatureStore, + LDFeatureStoreDataStorage, + LDFeatureStoreItem, + LDFeatureStoreKindData, + LDKeyedFeatureStoreItem, +} from '../../src/api/subsystems'; +import AsyncTransactionalStoreFacade from '../../src/store/AsyncTransactionalStoreFacade'; +import PersistentDataStoreWrapper from '../../src/store/PersistentDataStoreWrapper'; +import TransactionalFeatureStore from '../../src/store/TransactionalFeatureStore'; +import VersionedDataKinds from '../../src/store/VersionedDataKinds'; + +class MockPersistenceStore implements LDFeatureStore { + failInits = false; + + failUpserts = false; + + // Throws synchronously from init() instead of reporting failure through the + // callback. Simulates a persistence client that raises before it can call back. + throwOnInit = false; + + // Returns a rejected promise from init() instead of calling back. Simulates an + // `async` persistence client whose promise rejects before it reaches its callback. + rejectOnInit = false; + + // Throws synchronously from upsert() instead of reporting failure through the + // callback. Simulates a persistence client that raises before it can call back. + throwOnUpsert = false; + + // Returns a rejected promise from upsert() instead of calling back. Simulates an + // `async` persistence client whose promise rejects before it reaches its callback. + rejectOnUpsert = false; + + // Defers the init() callback instead of invoking it. Lets a test hold a write-back + // attempt open, e.g. to simulate one completing after the store is closed. + deferInit = false; + + pendingInitCallbacks: ((err?: Error) => void)[] = []; + + initCalls: LDFeatureStoreDataStorage[] = []; + + upsertCalls: LDKeyedFeatureStoreItem[] = []; + + closeCalls = 0; + + isStoreAvailable?: (callback: (isAvailable: boolean) => void) => void; + + get(_kind: DataKind, _key: string, callback: (res: LDFeatureStoreItem | null) => void): void { + callback(null); + } + + all(_kind: DataKind, callback: (res: LDFeatureStoreKindData) => void): void { + callback({}); + } + + init(allData: LDFeatureStoreDataStorage, callback: (err?: Error) => void): void { + if (this.throwOnInit) { + throw new Error('init exploded'); + } + this.initCalls.push(allData); + if (this.rejectOnInit) { + // Cast needed: the interface types init() as returning void, but a persistence + // client that is actually `async` can return a rejected promise at runtime. + return Promise.reject(new Error('init rejected')) as unknown as void; + } + if (this.deferInit) { + this.pendingInitCallbacks.push(callback); + return; + } + callback(this.failInits ? new Error('init failed') : undefined); + } + + delete(_kind: DataKind, _key: string, _version: number, callback: () => void): void { + callback(); + } + + upsert(_kind: DataKind, data: LDKeyedFeatureStoreItem, callback: (err?: Error) => void): void { + if (this.throwOnUpsert) { + throw new Error('upsert exploded'); + } + this.upsertCalls.push(data); + if (this.rejectOnUpsert) { + // Cast needed: the interface types upsert() as returning void, but a + // persistence client that is actually `async` can return a rejected promise + // at runtime. + return Promise.reject(new Error('upsert rejected')) as unknown as void; + } + callback(this.failUpserts ? new Error('upsert failed') : undefined); + } + + initialized(callback: (isInitialized: boolean) => void): void { + callback(true); + } + + close(): void { + this.closeCalls += 1; + } + + getDescription(): string { + return 'mock persistence store'; + } +} + +function makeLogger(): LDLogger { + return { + error: jest.fn(), + warn: jest.fn(), + info: jest.fn(), + debug: jest.fn(), + }; +} + +it('marks the store available without a write-back when a pre-basis write recovers', async () => { + const persistence = new MockPersistenceStore(); + const logger = makeLogger(); + const store = new TransactionalFeatureStore(persistence, logger); + const facade = new AsyncTransactionalStoreFacade(store); + try { + persistence.failUpserts = true; + await facade.applyChanges(false, { features: { flagA: { version: 1 } } }, undefined, 's1'); + expect(logger.warn).toHaveBeenCalledTimes(1); + + persistence.failUpserts = false; + const initCallsBefore = persistence.initCalls.length; + await facade.applyChanges(false, { features: { flagB: { version: 1 } } }, undefined, 's2'); + + expect(logger.info).toHaveBeenCalledTimes(1); + // No basis was ever received, so there is no full data set to write back. + expect(persistence.initCalls.length).toEqual(initCallsBefore); + } finally { + store.close(); + } +}); + +describe('given a transactional store over a persistence store that can fail writes', () => { + let persistence: MockPersistenceStore; + let logger: LDLogger; + let recoveryStore: TransactionalFeatureStore; + let recoveryFacade: AsyncTransactionalStoreFacade; + + beforeEach(async () => { + persistence = new MockPersistenceStore(); + logger = makeLogger(); + recoveryStore = new TransactionalFeatureStore(persistence, logger); + recoveryFacade = new AsyncTransactionalStoreFacade(recoveryStore); + + await recoveryFacade.applyChanges( + true, + { + features: { + flagA: { key: 'flagA', version: 1 }, + }, + segments: {}, + }, + undefined, + 'selector1', + ); + // Delete flagA so the memory store holds a tombstone. + await recoveryFacade.delete(VersionedDataKinds.Features, 'flagA', 2); + }); + + afterEach(() => { + recoveryStore.close(); + }); + + it('logs one warning when writes start failing', async () => { + persistence.failUpserts = true; + await recoveryFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + await recoveryFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + expect(logger.warn).toHaveBeenCalledTimes(1); + expect(logger.warn).toHaveBeenCalledWith( + 'Persistent store is unavailable. Updates will be kept in memory until it recovers.', + ); + }); + + it('marks the store unavailable when a basis write fails and still completes the change', async () => { + persistence.failInits = true; + await recoveryFacade.applyChanges( + true, + { features: { flagB: { version: 5 } } }, + undefined, + 's2', + ); + expect(logger.warn).toHaveBeenCalledTimes(1); + expect(await recoveryFacade.all(VersionedDataKinds.Features)).toEqual({ + flagB: { version: 5 }, + }); + }); + + it('continues to serve reads from memory while the persistence store is unavailable', async () => { + persistence.failUpserts = true; + await recoveryFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + expect(await recoveryFacade.all(VersionedDataKinds.Features)).toEqual({ + flagB: { key: 'flagB', version: 1 }, + }); + }); + + it('continues to mirror writes while the persistence store is unavailable', async () => { + persistence.failUpserts = true; + const countBefore = persistence.upsertCalls.length; + await recoveryFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + await recoveryFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + expect(persistence.upsertCalls.length).toEqual(countBefore + 2); + }); + + it('writes the full data set, including tombstones, after a mirrored write succeeds', async () => { + persistence.failUpserts = true; + await recoveryFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + + persistence.failUpserts = false; + await recoveryFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + + const lastInit = persistence.initCalls[persistence.initCalls.length - 1]; + expect(lastInit).toEqual({ + features: { + flagA: { key: 'flagA', version: 2, deleted: true }, + flagB: { key: 'flagB', version: 1 }, + flagC: { key: 'flagC', version: 1 }, + }, + segments: {}, + }); + }); + + it('logs one message when the store recovers', async () => { + persistence.failUpserts = true; + await recoveryFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + persistence.failUpserts = false; + await recoveryFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + await recoveryFacade.applyChanges( + false, + { features: { flagD: { version: 1 } } }, + undefined, + 's4', + ); + expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.info).toHaveBeenCalledWith('Persistent store is available again.'); + }); + + it('stays unavailable when the write-back fails and recovers on a later attempt', async () => { + jest.useFakeTimers(); + try { + persistence.failUpserts = true; + persistence.failInits = true; + await recoveryFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + expect(logger.warn).toHaveBeenCalledTimes(1); + + // Mirrored writes succeed again, but the write-back init still fails. + persistence.failUpserts = false; + await recoveryFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + expect(logger.error).toHaveBeenCalledTimes(1); + expect(logger.info).not.toHaveBeenCalled(); + + persistence.failInits = false; + // The failed attempt embargoes retries for 1000ms before the next real + // attempt is allowed to run. + await jest.advanceTimersByTimeAsync(1000); + await recoveryFacade.applyChanges( + false, + { features: { flagD: { version: 1 } } }, + undefined, + 's4', + ); + expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.warn).toHaveBeenCalledTimes(1); + } finally { + jest.useRealTimers(); + } + }); + + it('ignores a write-back init that completes after close', async () => { + persistence.failUpserts = true; + persistence.failInits = true; + await recoveryFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + expect(logger.warn).toHaveBeenCalledTimes(1); + + // The next mirrored write succeeds and triggers a write-back attempt, but the + // persistence store holds the init callback open instead of calling it back. + persistence.deferInit = true; + persistence.failUpserts = false; + await recoveryFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + expect(persistence.pendingInitCallbacks.length).toEqual(1); + + recoveryStore.close(); + // The deferred write-back init finally completes after close. + persistence.pendingInitCallbacks[0](); + + expect(logger.info).not.toHaveBeenCalled(); + expect(logger.warn).toHaveBeenCalledTimes(1); + }); + + it('closes the underlying persistence store exactly once even if close is called twice', () => { + recoveryStore.close(); + recoveryStore.close(); + expect(persistence.closeCalls).toEqual(1); + }); + + it('fires the callback exactly once for a basis write whose init promise rejects', async () => { + const unhandled = jest.fn(); + process.on('unhandledRejection', unhandled); + try { + persistence.rejectOnInit = true; + let callbackCalls = 0; + await new Promise((resolve) => { + recoveryStore.applyChanges( + true, + { features: { flagB: { version: 5 } } }, + () => { + callbackCalls += 1; + resolve(); + }, + undefined, + 's2', + ); + }); + // Flush any pending microtask that might invoke the callback a second time. + await Promise.resolve(); + await Promise.resolve(); + expect(callbackCalls).toEqual(1); + expect(logger.warn).toHaveBeenCalledTimes(1); + expect(unhandled).not.toHaveBeenCalled(); + } finally { + process.off('unhandledRejection', unhandled); + } + }); + + it('fires the callback exactly once for a mirrored upsert whose promise rejects', async () => { + const unhandled = jest.fn(); + process.on('unhandledRejection', unhandled); + try { + persistence.rejectOnUpsert = true; + let callbackCalls = 0; + await new Promise((resolve) => { + recoveryStore.upsert(VersionedDataKinds.Features, { key: 'flagB', version: 1 }, () => { + callbackCalls += 1; + resolve(); + }); + }); + await Promise.resolve(); + await Promise.resolve(); + expect(callbackCalls).toEqual(1); + expect(logger.warn).toHaveBeenCalledTimes(1); + expect(unhandled).not.toHaveBeenCalled(); + } finally { + process.off('unhandledRejection', unhandled); + } + }); + + it('fires the callback exactly once when a basis write init throws synchronously', async () => { + persistence.throwOnInit = true; + let callbackCalls = 0; + await new Promise((resolve) => { + recoveryStore.applyChanges( + true, + { features: { flagB: { version: 5 } } }, + () => { + callbackCalls += 1; + resolve(); + }, + undefined, + 's2', + ); + }); + expect(callbackCalls).toEqual(1); + expect(logger.warn).toHaveBeenCalledTimes(1); + }); + + it('fires the callback exactly once when a mirrored upsert throws synchronously', async () => { + persistence.throwOnUpsert = true; + let callbackCalls = 0; + await new Promise((resolve) => { + recoveryStore.upsert(VersionedDataKinds.Features, { key: 'flagB', version: 1 }, () => { + callbackCalls += 1; + resolve(); + }); + }); + expect(callbackCalls).toEqual(1); + expect(logger.warn).toHaveBeenCalledTimes(1); + }); +}); + +describe('given a transactional store whose persistence store has an availability check', () => { + let persistence: MockPersistenceStore; + let probeResult: boolean; + let probeCalls: number; + let logger: LDLogger; + let pollingStore: TransactionalFeatureStore; + let pollingFacade: AsyncTransactionalStoreFacade; + + beforeEach(async () => { + jest.useFakeTimers(); + persistence = new MockPersistenceStore(); + probeResult = false; + probeCalls = 0; + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + callback(probeResult); + }; + logger = makeLogger(); + pollingStore = new TransactionalFeatureStore(persistence, logger); + pollingFacade = new AsyncTransactionalStoreFacade(pollingStore); + + await pollingFacade.applyChanges( + true, + { features: { flagA: { key: 'flagA', version: 1 } } }, + undefined, + 'selector1', + ); + persistence.failUpserts = true; + persistence.failInits = true; + await pollingFacade.applyChanges( + false, + { features: { flagB: { version: 1 } } }, + undefined, + 's2', + ); + }); + + afterEach(() => { + pollingStore.close(); + jest.useRealTimers(); + }); + + it('polls the availability check every 500 milliseconds while unavailable', async () => { + await jest.advanceTimersByTimeAsync(1500); + expect(probeCalls).toEqual(3); + }); + + it('stays unavailable while the check reports the store is not available', async () => { + await jest.advanceTimersByTimeAsync(2000); + expect(logger.info).not.toHaveBeenCalled(); + // Only the basis write happened before the outage. No write-back was attempted. + expect(persistence.initCalls.length).toEqual(1); + }); + + it('writes the full data set back when the check reports the store is available', async () => { + persistence.failInits = false; + persistence.failUpserts = false; + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + + const lastInit = persistence.initCalls[persistence.initCalls.length - 1]; + expect(lastInit).toEqual({ + features: { + flagA: { key: 'flagA', version: 1 }, + flagB: { key: 'flagB', version: 1 }, + }, + }); + expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.info).toHaveBeenCalledWith('Persistent store is available again.'); + }); + + it('stops polling after recovery', async () => { + persistence.failInits = false; + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + const callsAfterRecovery = probeCalls; + await jest.advanceTimersByTimeAsync(5000); + expect(probeCalls).toEqual(callsAfterRecovery); + }); + + it('logs an error and keeps polling when the write-back fails', async () => { + // The check passes, but writes still fail. + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + expect(logger.error).toHaveBeenCalledTimes(1); + expect(logger.info).not.toHaveBeenCalled(); + + persistence.failInits = false; + // The failed attempt backs off for 2 ticks before the next real attempt runs. + await jest.advanceTimersByTimeAsync(1500); + expect(logger.info).toHaveBeenCalledTimes(1); + }); + + it('bounds write-back attempts and logs with backoff at the exact retry schedule', async () => { + // The check always passes, but the write-back init always fails. + probeResult = true; + const testStart = Date.now(); + const timestamps: number[] = []; + const originalInit = persistence.init.bind(persistence); + jest.spyOn(persistence, 'init').mockImplementation((allData, callback) => { + timestamps.push(Date.now() - testStart); + return originalInit(allData, callback); + }); + await jest.advanceTimersByTimeAsync(10000); + // Only the first failure of the outage logs at error level. + expect(logger.error).toHaveBeenCalledTimes(1); + // Asserting the exact attempt timestamps, not just the count, catches a + // boundary regression in the backoff formula that a count-only assertion + // would miss. Backoff bounds attempts at t=500, 1500, 3500, 7500ms - far + // below the 20 a fixed 500ms retry would produce over the same window. + expect(timestamps).toEqual([500, 1500, 3500, 7500]); + }); + + it('recovers through a successful mirrored write even while a probe never answers', async () => { + // Simulates a hung socket: the probe is invoked but never calls back. + persistence.isStoreAvailable = () => { + probeCalls += 1; + }; + await jest.advanceTimersByTimeAsync(500); + expect(probeCalls).toEqual(1); + + persistence.failUpserts = false; + persistence.failInits = false; + await pollingFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + + expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.info).toHaveBeenCalledWith('Persistent store is available again.'); + }); + + it('does not let a synchronously throwing probe escape the poll timer', async () => { + let throwProbe = true; + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + if (throwProbe) { + throw new Error('probe exploded'); + } + callback(probeResult); + }; + + await expect(jest.advanceTimersByTimeAsync(1000)).resolves.toBeUndefined(); + // Polling was not stranded by the throw. + expect(probeCalls).toBeGreaterThanOrEqual(2); + + throwProbe = false; + probeResult = true; + persistence.failInits = false; + persistence.failUpserts = false; + await jest.advanceTimersByTimeAsync(500); + expect(logger.info).toHaveBeenCalledTimes(1); + }); + + it('does not let a synchronously throwing write-back init escape the poll timer', async () => { + persistence.throwOnInit = true; + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + expect(logger.error).toHaveBeenCalledTimes(1); + expect(logger.info).not.toHaveBeenCalled(); + + persistence.throwOnInit = false; + persistence.failInits = false; + // The failed attempt backs off for 2 ticks before the next real attempt runs. + await jest.advanceTimersByTimeAsync(1500); + expect(logger.info).toHaveBeenCalledTimes(1); + }); + + it('does not let a probe that throws a value with no toString escape the poll timer', async () => { + let throwProbe = true; + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + if (throwProbe) { + // A null-prototype object has no toString(), so interpolating it directly + // into a template literal throws. + throw Object.create(null); + } + callback(probeResult); + }; + + await expect(jest.advanceTimersByTimeAsync(1000)).resolves.toBeUndefined(); + // Polling was not stranded by the throw. + expect(probeCalls).toBeGreaterThanOrEqual(2); + + throwProbe = false; + probeResult = true; + persistence.failInits = false; + persistence.failUpserts = false; + await jest.advanceTimersByTimeAsync(500); + expect(logger.info).toHaveBeenCalledTimes(1); + }); + + it('produces exactly one write-back when the probe callback is invoked twice', async () => { + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + callback(true); + callback(true); + }; + persistence.failInits = false; + persistence.failUpserts = false; + const initCallsBefore = persistence.initCalls.length; + + await jest.advanceTimersByTimeAsync(500); + + expect(persistence.initCalls.length - initCallsBefore).toEqual(1); + expect(logger.info).toHaveBeenCalledTimes(1); + }); + + it('does not start an overlapping check while one is in flight', async () => { + const pendingCallbacks: ((isAvailable: boolean) => void)[] = []; + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + pendingCallbacks.push(callback); + }; + await jest.advanceTimersByTimeAsync(2000); + expect(probeCalls).toEqual(1); + pendingCallbacks.forEach((cb) => cb(false)); + await jest.advanceTimersByTimeAsync(500); + expect(probeCalls).toEqual(2); + }); + + it('stops polling when the store is closed', async () => { + pollingStore.close(); + await jest.advanceTimersByTimeAsync(5000); + expect(probeCalls).toEqual(0); + }); + + it('does not log or poll for write results after close', async () => { + // Recover first so the store is available again. + persistence.failInits = false; + persistence.failUpserts = false; + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + expect(logger.info).toHaveBeenCalledTimes(1); + + pollingStore.close(); + persistence.failUpserts = true; + await pollingFacade.applyChanges( + false, + { features: { flagC: { version: 2 } } }, + undefined, + 's3', + ); + + // Only the original outage warning was logged, and no new checks run. + expect(logger.warn).toHaveBeenCalledTimes(1); + await jest.advanceTimersByTimeAsync(5000); + expect(probeCalls).toEqual(1); + }); + + it('does not let an async-rejecting probe escape as an unhandled rejection', async () => { + const unhandled = jest.fn(); + process.on('unhandledRejection', unhandled); + try { + let healed = false; + persistence.isStoreAvailable = ((callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + if (!healed) { + return Promise.reject(new Error('probe rejected')); + } + callback(true); + return undefined; + }) as unknown as (callback: (isAvailable: boolean) => void) => void; + + await jest.advanceTimersByTimeAsync(1500); + // The poller kept ticking; the rejection did not strand it. + expect(probeCalls).toBeGreaterThanOrEqual(2); + expect(logger.info).not.toHaveBeenCalled(); + + healed = true; + persistence.failInits = false; + persistence.failUpserts = false; + await jest.advanceTimersByTimeAsync(500); + expect(logger.info).toHaveBeenCalledTimes(1); + expect(unhandled).not.toHaveBeenCalled(); + } finally { + process.off('unhandledRejection', unhandled); + } + }); + + it('handles an async-rejecting write-back init as a write-back failure', async () => { + const unhandled = jest.fn(); + process.on('unhandledRejection', unhandled); + try { + persistence.rejectOnInit = true; + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + expect(logger.error).toHaveBeenCalledTimes(1); + expect(logger.info).not.toHaveBeenCalled(); + + persistence.rejectOnInit = false; + persistence.failInits = false; + // The failed attempt embargoes retries for 1000ms before the next real + // attempt is allowed to run. + await jest.advanceTimersByTimeAsync(1000); + expect(logger.info).toHaveBeenCalledTimes(1); + expect(unhandled).not.toHaveBeenCalled(); + } finally { + process.off('unhandledRejection', unhandled); + } + }); + + it('recovers a second outage after a first outage left a hung probe unanswered', async () => { + // Outage 1 (already underway from beforeEach): the probe is invoked but never + // answers, simulating a hung socket. + persistence.isStoreAvailable = () => { + probeCalls += 1; + }; + await jest.advanceTimersByTimeAsync(500); + expect(probeCalls).toEqual(1); + + // Recovery happens through a successful mirrored write instead of the probe. + persistence.failUpserts = false; + persistence.failInits = false; + await pollingFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + expect(logger.info).toHaveBeenCalledTimes(1); + + // Outage 2: a healthy probe now answers immediately. If the hung outage-1 probe + // had left the poller permanently stranded, this outage would see zero probes. + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + callback(true); + }; + const probeCallsBeforeOutage2 = probeCalls; + persistence.failUpserts = true; + await pollingFacade.applyChanges( + false, + { features: { flagD: { version: 1 } } }, + undefined, + 's4', + ); + expect(logger.warn).toHaveBeenCalledTimes(2); + + persistence.failUpserts = false; + persistence.failInits = false; + // Outage 1's write-back success armed its own 1s floor embargo, which persists + // across the transition, so wait past it before expecting outage 2 to probe. + await jest.advanceTimersByTimeAsync(1500); + expect(probeCalls).toBeGreaterThan(probeCallsBeforeOutage2); + expect(logger.info).toHaveBeenCalledTimes(2); + }); + + it('releases a hung write-back after its deadline and retries', async () => { + persistence.deferInit = true; + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + expect(persistence.pendingInitCallbacks.length).toEqual(1); + const staleCallback = persistence.pendingInitCallbacks[0]; + + persistence.deferInit = false; + persistence.failInits = false; + persistence.failUpserts = false; + // Advance past the 30 second hung write-back deadline. The probe keeps + // answering true every tick, but the poller must not retry until the + // outstanding write-back is treated as abandoned. Releasing it also arms a + // 1 second failure embargo, so the retry lands just after the deadline, not + // exactly on it. + await jest.advanceTimersByTimeAsync(31500); + expect(logger.info).toHaveBeenCalledTimes(1); + + const initCallsAfterRecovery = persistence.initCalls.length; + const logInfoCallsAfterRecovery = (logger.info as jest.Mock).mock.calls.length; + // The original, now-abandoned write-back finally calls back. It must be ignored. + staleCallback(); + expect(persistence.initCalls.length).toEqual(initCallsAfterRecovery); + expect((logger.info as jest.Mock).mock.calls.length).toEqual(logInfoCallsAfterRecovery); + }); + + it('logs at error level for the first genuine write-back failure even when the outage started with a hung write-back', async () => { + persistence.deferInit = true; + probeResult = true; + await jest.advanceTimersByTimeAsync(500); + expect(persistence.pendingInitCallbacks.length).toEqual(1); + + // Advance past the 30 second hung write-back deadline (releasing it, which logs + // only at debug level and arms a failure embargo) and past that embargo, so a + // fresh, non-hung write-back attempt runs and genuinely fails. This must still + // be the outage's first ERROR-level log: the hung release must not have + // consumed it. + persistence.deferInit = false; + await jest.advanceTimersByTimeAsync(31500); + expect(logger.error).toHaveBeenCalledTimes(1); + expect(logger.info).not.toHaveBeenCalled(); + + // A later write-back failure in the same outage logs at debug level only. + await jest.advanceTimersByTimeAsync(2000); + expect(logger.error).toHaveBeenCalledTimes(1); + }); + + it('bounds write-back attempts triggered by successful writes to the embargo schedule', async () => { + // Keep the poller out of this test entirely; only the write-signal path matters. + probeResult = false; + persistence.failUpserts = false; + persistence.failInits = true; + const initCallsBefore = persistence.initCalls.length; + + // 10 consecutive successful mirrored writes, with no time passing between them. + await Array.from({ length: 10 }, (_, i) => i).reduce( + (previous, i) => + previous.then(() => + pollingFacade.applyChanges( + false, + { features: { [`flag${i}`]: { version: 1 } } }, + undefined, + `s${i}`, + ), + ), + Promise.resolve(), + ); + + // Every successful write signals recovery, but the embargo armed by the first + // attempt's failure blocks the other 9 since no time passed. + expect(persistence.initCalls.length - initCallsBefore).toEqual(1); + expect(logger.error).toHaveBeenCalledTimes(1); + }); + + it('recovers directly from a successful basis write during an outage without a redundant write-back', async () => { + probeResult = false; + persistence.failInits = false; + const initCallsBefore = persistence.initCalls.length; + + await pollingFacade.applyChanges( + true, + { features: { flagE: { key: 'flagE', version: 9 } } }, + undefined, + 's-basis', + ); + + // Only the basis write itself happened; no separate write-back was issued for + // the identical payload. + expect(persistence.initCalls.length - initCallsBefore).toEqual(1); + expect(persistence.initCalls[persistence.initCalls.length - 1]).toEqual({ + features: { flagE: { key: 'flagE', version: 9 } }, + }); + expect(logger.info).toHaveBeenCalledTimes(1); + }); + + it('ignores a stale tick-1 probe answer that arrives after tick-2 issued a new probe', async () => { + const callbacks: ((isAvailable: boolean) => void)[] = []; + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + callbacks.push(callback); + if (probeCalls === 1) { + // Tick 1 answers immediately, like a normal probe. + callback(false); + } + // Tick 2's probe intentionally does not answer here; the test answers it + // manually below, after replaying tick 1's stale callback. + }; + + await jest.advanceTimersByTimeAsync(500); // tick 1: answers false immediately + await jest.advanceTimersByTimeAsync(500); // tick 2: issues a new probe, pending + expect(probeCalls).toEqual(2); + + // Tick 1's callback fires again (a double-invocation bug in the probe), falsely + // claiming the store is available. It must not trigger recovery. + callbacks[0](true); + expect(logger.info).not.toHaveBeenCalled(); + + // Tick 2's real, current answer is honored. + persistence.failInits = false; + persistence.failUpserts = false; + callbacks[1](true); + expect(logger.info).toHaveBeenCalledTimes(1); + }); + + it('ignores a stale probe answer that arrives after write-signal recovery already completed', async () => { + let pendingCallback: ((isAvailable: boolean) => void) | undefined; + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + pendingCallback = callback; + }; + await jest.advanceTimersByTimeAsync(500); + expect(probeCalls).toEqual(1); + + persistence.failUpserts = false; + persistence.failInits = false; + await pollingFacade.applyChanges( + false, + { features: { flagC: { version: 1 } } }, + undefined, + 's3', + ); + expect(logger.info).toHaveBeenCalledTimes(1); + + const initCallsAfterRecovery = persistence.initCalls.length; + pendingCallback?.(true); + expect(logger.info).toHaveBeenCalledTimes(1); + expect(persistence.initCalls.length).toEqual(initCallsAfterRecovery); + }); + + it('bounds write-backs from a flapping store to the 1 second success embargo floor', async () => { + probeResult = false; + persistence.failInits = false; + const initCallsBefore = persistence.initCalls.length; + + await Array.from({ length: 20 }, (_, i) => i).reduce( + (previous, i) => + previous.then(async () => { + persistence.failUpserts = i % 2 === 0; + await pollingFacade.applyChanges( + false, + { features: { [`flag${i}`]: { version: 1 } } }, + undefined, + `s${i}`, + ); + // 100ms between writes; 20 cycles span 2000ms of wall-clock time. + await jest.advanceTimersByTimeAsync(100); + }), + Promise.resolve(), + ); + + // Without the 1 second floor, this would produce 10 write-backs (one per + // successful write, at i=1,3,5,...,19). With it, only the successful writes at + // t=100ms and t=1100ms fall outside the still-armed embargo from the previous + // write-back, so exactly 2 attempts are made over the 2 second window. + expect(persistence.initCalls.length - initCallsBefore).toEqual(2); + }); + + it('ignores a write-back that settles after a stale generation from a prior outage', async () => { + // Outage 1 is already underway from beforeEach (flagB's upsert failed). Issue a + // write-back for it and leave it pending. + persistence.deferInit = true; + persistence.failUpserts = false; + await pollingFacade.applyChanges( + false, + { features: { flagX: { version: 1 } } }, + undefined, + 's-outage1-writeback', + ); + expect(persistence.pendingInitCallbacks.length).toEqual(1); + const staleWriteBack = persistence.pendingInitCallbacks[0]; + + // Recovery happens through a direct basis write (the shortcut path), not + // through the pending write-back. + persistence.deferInit = false; + persistence.failInits = false; + await pollingFacade.applyChanges( + true, + { features: { flagA: { key: 'flagA', version: 2 } } }, + undefined, + 'selector-outage1-recovery', + ); + expect(logger.info).toHaveBeenCalledTimes(1); + + // Outage 2 begins. + persistence.failUpserts = true; + await pollingFacade.applyChanges( + false, + { features: { flagY: { version: 1 } } }, + undefined, + 's-outage2', + ); + expect(logger.warn).toHaveBeenCalledTimes(2); + + // The stale outage-1 write-back finally settles successfully. Its generation + // is long gone, so it must be ignored. + staleWriteBack(); + expect(logger.info).toHaveBeenCalledTimes(1); + + // A genuine write-back failure in outage 2 must log at error level, proving + // the counter/log gate was not left contaminated by the ignored settle. This + // also proves the store is still unavailable: if the stale settle had + // incorrectly recovered it, _attemptRecovery() would have returned early and + // no write-back (and so no failure) would have been attempted here. + persistence.failUpserts = false; + persistence.failInits = true; + await pollingFacade.applyChanges( + false, + { features: { flagZ: { version: 1 } } }, + undefined, + 's-outage2-writeback', + ); + expect(logger.error).toHaveBeenCalledTimes(1); + }); + + it('releases a hung probe after its deadline and issues a fresh one', async () => { + const pendingCallbacks: ((isAvailable: boolean) => void)[] = []; + persistence.isStoreAvailable = (callback: (isAvailable: boolean) => void) => { + probeCalls += 1; + pendingCallbacks.push(callback); + }; + await jest.advanceTimersByTimeAsync(500); + expect(probeCalls).toEqual(1); + const staleProbe = pendingCallbacks[0]; + + // Advance past the 30 second hung probe deadline. A fresh probe must be issued. + await jest.advanceTimersByTimeAsync(30000); + expect(probeCalls).toBeGreaterThan(1); + + persistence.failInits = false; + persistence.failUpserts = false; + pendingCallbacks[pendingCallbacks.length - 1](true); + expect(logger.info).toHaveBeenCalledTimes(1); + + // The stale probe's late answer must be ignored. + const infoCallsAfterRecovery = (logger.info as jest.Mock).mock.calls.length; + staleProbe(true); + expect((logger.info as jest.Mock).mock.calls.length).toEqual(infoCallsAfterRecovery); + }); + + it('bounds retries against a write-back that never answers to the deadline-plus-embargo schedule', async () => { + // The check always passes, but the write-back init never calls back. + probeResult = true; + persistence.deferInit = true; + const initCallsBefore = persistence.initCalls.length; + + await jest.advanceTimersByTimeAsync(100000); + + // Each cycle is the 30 second hung deadline plus the exponential embargo the + // release arms, not a fixed 500ms retry (which would produce 200 attempts over + // this window). Value confirmed against the actual schedule produced by the + // implementation. + expect(persistence.initCalls.length - initCallsBefore).toEqual(4); + }); + + it('clears an accumulated failure embargo when a basis write recovers the store directly', async () => { + // The check always passes, but the write-back init always fails, building the + // backoff embargo up over the outage until it is pinned near its 30 second cap. + probeResult = true; + await jest.advanceTimersByTimeAsync(32000); + + // Recover directly via a basis write (the shortcut path), not through a + // write-back. + persistence.failInits = false; + persistence.failUpserts = false; + await pollingFacade.applyChanges( + true, + { features: { flagA: { key: 'flagA', version: 2 } } }, + undefined, + 'selector-recovery', + ); + expect(logger.info).toHaveBeenCalledTimes(1); + + // Outage 2 begins. + persistence.failUpserts = true; + await pollingFacade.applyChanges( + false, + { features: { flagE: { version: 1 } } }, + undefined, + 's-outage2', + ); + expect(logger.warn).toHaveBeenCalledTimes(2); + + // The first write-back of outage 2 must be allowed well within the 1500ms + // window below, not held back by the 30 second embargo accumulated in outage 1. + persistence.failUpserts = false; + const initCallsBefore = persistence.initCalls.length; + await jest.advanceTimersByTimeAsync(1500); + expect(persistence.initCalls.length).toBeGreaterThan(initCallsBefore); + }); + + it('does not log after close for a probe rejection that arrives late', async () => { + let rejectProbe: (() => void) | undefined; + persistence.isStoreAvailable = (() => + new Promise((_resolve, reject) => { + rejectProbe = () => reject(new Error('late rejection')); + })) as unknown as (callback: (isAvailable: boolean) => void) => void; + + await jest.advanceTimersByTimeAsync(500); + expect(rejectProbe).toBeDefined(); + + pollingStore.close(); + const debugCallsBeforeReject = (logger.debug as jest.Mock).mock.calls.length; + rejectProbe!(); + await jest.advanceTimersByTimeAsync(0); + expect((logger.debug as jest.Mock).mock.calls.length).toEqual(debugCallsBeforeReject); + }); + + it('does not crash when a rejection reason cannot be converted to a string', async () => { + const unhandled = jest.fn(); + process.on('unhandledRejection', unhandled); + try { + persistence.isStoreAvailable = (() => Promise.reject(Object.create(null))) as unknown as ( + callback: (isAvailable: boolean) => void, + ) => void; + await jest.advanceTimersByTimeAsync(500); + expect(unhandled).not.toHaveBeenCalled(); + } finally { + process.off('unhandledRejection', unhandled); + } + }); +}); + +it('does not schedule availability checks when the persistence store has no check', async () => { + jest.useFakeTimers(); + try { + const persistence = new MockPersistenceStore(); + const logger = makeLogger(); + const store = new TransactionalFeatureStore(persistence, logger); + const facade = new AsyncTransactionalStoreFacade(store); + await facade.applyChanges(true, { features: {} }, undefined, 's1'); + persistence.failUpserts = true; + await facade.applyChanges(false, { features: { flagB: { version: 1 } } }, undefined, 's2'); + expect(jest.getTimerCount()).toEqual(0); + store.close(); + } finally { + jest.useRealTimers(); + } +}); + +type RecordedOp = + | { type: 'init'; allData: KindKeyedStore } + | { type: 'upsert'; namespace: string; key: string; descriptor: SerializedItemDescriptor }; + +// Models the core of a real PersistentDataStoreWrapper, the way MockPersistentStore does in +// PersistentStoreWrapper.test.ts, but also records every operation it receives (in order) so +// a test can assert on ordering, not just final state. +class RecordingPersistentStore implements PersistentDataStore { + allData: KindKeyedStore = []; + + ops: RecordedOp[] = []; + + failInits = false; + + failUpserts = false; + + // Defers the init() callback instead of invoking it, so a test can hold a write-back + // attempt open while driving a concurrent update through the wrapper's queue. + deferInit = false; + + pendingInitCallbacks: (() => void)[] = []; + + isStoreAvailable?: (callback: (isAvailable: boolean) => void) => void; + + init(allData: KindKeyedStore, callback: (err?: Error) => void): void { + this.ops.push({ type: 'init', allData }); + const settle = () => { + if (this.failInits) { + callback(new Error('init failed')); + return; + } + this.allData = allData; + callback(); + }; + if (this.deferInit) { + this.pendingInitCallbacks.push(settle); + return; + } + settle(); + } + + get( + kind: PersistentStoreDataKind, + key: string, + callback: (descriptor: SerializedItemDescriptor | undefined) => void, + ): void { + const itemsForKind = this.allData.find((kvp) => kvp.key.namespace === kind.namespace)?.item; + callback(itemsForKind?.find((kvp) => kvp.key === key)?.item ?? undefined); + } + + getAll( + kind: PersistentStoreDataKind, + callback: (descriptors: KeyedItem[] | undefined) => void, + ): void { + callback(this.allData.find((kvp) => kvp.key.namespace === kind.namespace)?.item); + } + + upsert( + kind: PersistentStoreDataKind, + key: string, + descriptor: SerializedItemDescriptor, + callback: (err?: Error, updatedDescriptor?: SerializedItemDescriptor) => void, + ): void { + this.ops.push({ type: 'upsert', namespace: kind.namespace, key, descriptor }); + if (this.failUpserts) { + callback(new Error('upsert failed')); + return; + } + let kindEntry = this.allData.find((kvp) => kvp.key.namespace === kind.namespace); + if (!kindEntry) { + kindEntry = { key: kind, item: [] }; + this.allData.push(kindEntry); + } + const slot = kindEntry.item.find((kvp) => kvp.key === key); + if (slot) { + slot.item = descriptor; + } else { + kindEntry.item.push({ key, item: descriptor }); + } + callback(undefined, descriptor); + } + + initialized(callback: (isInitialized: boolean) => void): void { + callback(true); + } + + close(): void {} + + getDescription(): string { + return 'recording persistence store'; + } +} + +it('captures a snapshot of a key before a concurrent newer write to that key reaches persistence', async () => { + const persistence = new MockPersistenceStore(); + const logger = makeLogger(); + const store = new TransactionalFeatureStore(persistence, logger); + const facade = new AsyncTransactionalStoreFacade(store); + try { + await facade.applyChanges( + true, + { features: { flagA: { key: 'flagA', version: 1 } } }, + undefined, + 'basis', + ); + + persistence.failUpserts = true; + await facade.applyChanges(false, { features: { flagB: { version: 1 } } }, undefined, 's2'); + expect(logger.warn).toHaveBeenCalledTimes(1); + + persistence.failUpserts = false; + const initCallsBeforeRecovery = persistence.initCalls.length; + const upsertCallsBeforeRecovery = persistence.upsertCalls.length; + + // Trigger recovery with a successful mirrored write, and wait only for that write's own + // callback: by the time it fires, the write-back it triggered has already run to + // completion, since both happen synchronously in the same chain, with nothing in between + // that could let a newer write for the same key land first. + let recoveryCallbackCalls = 0; + await new Promise((resolve) => { + store.upsert(VersionedDataKinds.Features, { key: 'flagC', version: 1 }, () => { + recoveryCallbackCalls += 1; + resolve(); + }); + }); + + expect(persistence.initCalls.length).toEqual(initCallsBeforeRecovery + 1); + // Only flagC's own mirrored write has reached persistence so far - the recovery trigger + // itself. flagA's newer write below has not been issued yet. + expect(persistence.upsertCalls.length).toEqual(upsertCallsBeforeRecovery + 1); + const writeBack = persistence.initCalls[persistence.initCalls.length - 1]; + // The write-back's snapshot was taken before the newer write below was ever issued. + expect(writeBack.features.flagA).toEqual({ key: 'flagA', version: 1 }); + + // Immediately apply a newer version of flagA, in the very next statement. + let deltaCallbackCalls = 0; + await new Promise((resolve) => { + store.upsert(VersionedDataKinds.Features, { key: 'flagA', version: 5 }, () => { + deltaCallbackCalls += 1; + resolve(); + }); + }); + + // The newer write's own mirrored upsert reached persistence only after the write-back. + expect(persistence.initCalls.length).toEqual(initCallsBeforeRecovery + 1); + expect(persistence.upsertCalls[persistence.upsertCalls.length - 1]).toEqual({ + key: 'flagA', + version: 5, + }); + + expect(recoveryCallbackCalls).toEqual(1); + expect(deltaCallbackCalls).toEqual(1); + } finally { + store.close(); + } +}); + +describe('given a transactional store composed over the real persistent store wrapper', () => { + let core: RecordingPersistentStore; + let probeAvailable: boolean; + let logger: LDLogger; + let wrapper: PersistentDataStoreWrapper; + let store: TransactionalFeatureStore; + + beforeEach(() => { + jest.useFakeTimers(); + core = new RecordingPersistentStore(); + probeAvailable = false; + core.isStoreAvailable = (callback) => callback(probeAvailable); + logger = makeLogger(); + wrapper = new PersistentDataStoreWrapper(core, 0, logger); + store = new TransactionalFeatureStore(wrapper, logger); + }); + + afterEach(() => { + store.close(); + jest.useRealTimers(); + }); + + it('queues writes behind an in-flight full write in order', async () => { + core.deferInit = true; + store.applyChanges( + true, + { features: { flagA: { key: 'flagA', version: 1 } } }, + () => {}, + undefined, + 'basis', + ); + expect(core.ops.map((op) => op.type)).toEqual(['init']); + + let upsertCallbackCalls = 0; + const upsertDone = new Promise((resolve) => { + store.upsert(VersionedDataKinds.Features, { key: 'flagB', version: 1 }, () => { + upsertCallbackCalls += 1; + resolve(); + }); + }); + await jest.advanceTimersByTimeAsync(0); + + // The upsert is queued behind the in-flight init; it has not reached the core yet. + expect(core.ops.map((op) => op.type)).toEqual(['init']); + + const pendingInit = core.pendingInitCallbacks.slice(); + core.pendingInitCallbacks = []; + pendingInit.forEach((settle) => settle()); + + await jest.advanceTimersByTimeAsync(0); + await upsertDone; + + expect(core.ops.map((op) => op.type)).toEqual(['init', 'upsert']); + expect(upsertCallbackCalls).toEqual(1); + }); + + it('recovers through the full persistence chain and writes back a tombstone for a flag deleted during the outage', async () => { + const facade = new AsyncTransactionalStoreFacade(store); + await facade.applyChanges( + true, + { + features: { + flagA: { key: 'flagA', version: 1 }, + flagB: { key: 'flagB', version: 1 }, + }, + segments: {}, + }, + undefined, + 'basis', + ); + expect(core.ops.filter((op) => op.type === 'init')).toHaveLength(1); + + core.failUpserts = true; + await facade.applyChanges(false, { features: { flagC: { version: 1 } } }, undefined, 's2'); + expect(logger.warn).toHaveBeenCalledTimes(1); + + // Delete flagB during the outage, so the memory store holds a tombstone for it. + await facade.delete(VersionedDataKinds.Features, 'flagB', 2); + + await jest.advanceTimersByTimeAsync(500); + expect(logger.info).not.toHaveBeenCalled(); + + probeAvailable = true; + core.failUpserts = false; + await jest.advanceTimersByTimeAsync(500); + + expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.info).toHaveBeenCalledWith('Persistent store is available again.'); + expect(logger.warn).toHaveBeenCalledTimes(1); + + const featuresEntry = core.allData.find( + (kvp) => kvp.key.namespace === VersionedDataKinds.Features.namespace, + ); + expect(featuresEntry?.item.map((kvp) => kvp.key)).toEqual( + expect.arrayContaining(['flagA', 'flagB', 'flagC']), + ); + + const flagBSlot = featuresEntry?.item.find((kvp) => kvp.key === 'flagB'); + expect(flagBSlot?.item.deleted).toBe(true); + expect(flagBSlot?.item.serializedItem).toContain('"deleted":true'); + + const flagASlot = featuresEntry?.item.find((kvp) => kvp.key === 'flagA'); + expect(flagASlot?.item.deleted).toBeFalsy(); + }); +}); diff --git a/packages/shared/sdk-server/src/options/Configuration.ts b/packages/shared/sdk-server/src/options/Configuration.ts index ff7e7ecfde..87617c14c0 100644 --- a/packages/shared/sdk-server/src/options/Configuration.ts +++ b/packages/shared/sdk-server/src/options/Configuration.ts @@ -498,7 +498,7 @@ export default class Configuration { if (TypeValidators.Function.is((store as LDTransactionalFeatureStore).applyChanges)) { return store as LDTransactionalFeatureStore; } - return new TransactionalFeatureStore(store); + return new TransactionalFeatureStore(store, this.logger); }, }; dsErrors.forEach((error) => { diff --git a/packages/shared/sdk-server/src/store/TransactionalFeatureStore.ts b/packages/shared/sdk-server/src/store/TransactionalFeatureStore.ts index 3b2a6d8c5f..30db67cc5d 100644 --- a/packages/shared/sdk-server/src/store/TransactionalFeatureStore.ts +++ b/packages/shared/sdk-server/src/store/TransactionalFeatureStore.ts @@ -1,4 +1,4 @@ -import { internal } from '@launchdarkly/js-sdk-common'; +import { internal, LDLogger } from '@launchdarkly/js-sdk-common'; import { DataKind } from '../api/interfaces'; import { @@ -11,17 +11,119 @@ import { } from '../api/subsystems'; import InMemoryFeatureStore from './InMemoryFeatureStore'; +// How often to check the persistence store for recovery while it is unavailable. +const RECOVERY_POLL_INTERVAL_MS = 500; + +// Ceiling on the exponential backoff between write-back attempts. +const MAX_WRITE_BACK_BACKOFF_MS = 30000; + +// Delay after a successful write-back. Limits a flapping store to about one +// write-back per second instead of one per successful mirrored write. +const WRITE_BACK_SUCCESS_EMBARGO_MS = 1000; + +// Deadline for a write-back or availability probe to answer. Past this, treat it as +// abandoned so a persistence client that never calls back cannot block recovery. +const HUNG_TIMEOUT_MS = 30000; + +// True when a value looks like a Promise. +// Some persistence store implementations declare a callback but are actually async. If +// their promise rejects before the callback runs, this handles it here so it cannot +// surface as an unhandled rejection and crash the process. +function isThenable(value: unknown): value is PromiseLike { + return ( + typeof value === 'object' && + value !== null && + typeof (value as { then?: unknown }).then === 'function' + ); +} + +function toError(reason: unknown): Error { + if (reason instanceof Error) { + return reason; + } + try { + return new Error(String(reason)); + } catch { + // The reason cannot be converted to a string, for example a null-prototype object + // or a value whose toString() throws. Fall back to a fixed message rather than + // let this conversion itself become a second, unhandled failure. + return new Error( + 'Persistent store operation failed with a reason that could not be described.', + ); + } +} + /** - * This decorator can take a non-transactional {@link LDFeatureStore} implementation - * and adapt it to be transactional through the use of an in-memory store acting as - * cache. + * Wraps a non-transactional {@link LDFeatureStore} and makes it transactional through + * an in-memory store acting as a cache. + * + * It also monitors the mirrored writes to the persistence store. A failed write marks + * the store unavailable. When the store recovers, this writes the full in-memory data + * set back to it. + * + * Persistence stores that do not serialize writes internally may see overlapping + * full-store writes after an abandoned write-back. */ export default class TransactionalFeatureStore implements LDTransactionalFeatureStore { - private _memoryStore: LDTransactionalFeatureStore; + private _memoryStore: InMemoryFeatureStore; private _activeStore: LDFeatureStore; - constructor(private readonly _nonTransPersistenceStore: LDFeatureStore) { - // persistence store is inital active store + // The persistence store is considered available until a write reports an error. + private _persistenceAvailable = true; + + // True while a poll tick's availability probe is outstanding. Guards only the + // poller, so a hung probe cannot block write-signal-triggered recovery. + private _probeInFlight = false; + + // Bumped on every new probe and on every availability transition. A probe answer + // is honored only when its generation still matches, so a stale or duplicate + // answer from an earlier probe can never be mistaken for the current one. + private _probeGeneration = 0; + + // Date.now() when the outstanding probe was issued. Detects a probe whose callback + // never fires. + private _probeStartedAt = 0; + + // True while a write-back attempt is outstanding. Guards both the probe-triggered + // and write-signal-triggered recovery paths, so at most one write-back runs at a + // time. + private _writeBackInFlight = false; + + // Bumped on every new write-back and when a hung one is abandoned. Same role as + // _probeGeneration, for write-back callbacks. + private _writeBackGeneration = 0; + + // Date.now() when the outstanding write-back was issued. Detects a write-back + // whose callback never fires. + private _writeBackStartedAt = 0; + + // Consecutive write-back failures in the current outage, including hung + // write-backs abandoned at their deadline. Drives the retry backoff. Reset only on + // recovery, since that is the only proof the store is healthy again. + private _consecutiveWriteBackFailures = 0; + + // Epoch ms before which a new write-back attempt is not issued. Persists across + // flapping available/unavailable cycles instead of resetting on each transition, + // so a fast-flapping store cannot dodge the backoff. Recovery only lowers it, + // capping it to the success embargo floor in _markAvailable. + private _writeBackEmbargoUntil = 0; + + // True once the current outage has logged a write-back failure at error level. A + // hung write-back that gets released by its deadline also counts toward + // _consecutiveWriteBackFailures but never logs, so this flag tracks the log + // separately and keeps the outage's first genuine failure at error level. + private _failureLoggedThisOutage = false; + + private _closed = false; + + private _pollHandle?: ReturnType; + + constructor( + private readonly _nonTransPersistenceStore: LDFeatureStore, + private readonly _logger?: LDLogger, + ) { + // The persistence store starts as the active store. It may already hold data + // from a previous run, so reads go there until a basis write arrives. this._activeStore = this._nonTransPersistenceStore; this._memoryStore = new InMemoryFeatureStore(); } @@ -79,10 +181,33 @@ export default class TransactionalFeatureStore implements LDTransactionalFeature () => { // TODO: SDK-1047 conditional propgation to persistence based on parameter if (basis) { - // basis causes memory store to become the active store + // Only a basis carries the full data set, so only a basis switches reads + // over to the memory store. this._activeStore = this._memoryStore; - this._nonTransPersistenceStore.init(data, callback); + // Settles exactly once no matter how the store answers: callback, a rejected + // promise if it is actually async, or a synchronous throw. Whichever fires + // first wins. + // + // A persistence failure must not fail the change. The memory store already + // holds the data, so the change's own callback must still fire. + let settled = false; + const settleOnce = (err?: Error) => { + if (settled) { + return; + } + settled = true; + this._handleWriteResult(err, true); + callback(); + }; + try { + const result = this._nonTransPersistenceStore.init(data, settleOnce); + if (isThenable(result)) { + result.then(undefined, (err: unknown) => settleOnce(toError(err))); + } + } catch (err) { + settleOnce(toError(err)); + } } else { const params: { dataKind: DataKind; item: LDKeyedFeatureStoreItem }[] = []; Object.entries(data).forEach(([namespace, items]) => { @@ -97,17 +222,36 @@ export default class TransactionalFeatureStore implements LDTransactionalFeature previousPromise.then( () => new Promise((resolve) => { - // Drop the callback arguments so a store error cannot become - // the resolved value of this void promise. - this._nonTransPersistenceStore.upsert( - nextParams.dataKind, - nextParams.item, - () => resolve(), - ); + // Same once-only containment as the basis write above, applied + // per mirrored item. + let settled = false; + const settleOnce = (err?: Error) => { + if (settled) { + return; + } + settled = true; + this._handleWriteResult(err, false); + resolve(); + }; + try { + const result = this._nonTransPersistenceStore.upsert( + nextParams.dataKind, + nextParams.item, + settleOnce, + ); + if (isThenable(result)) { + result.then(undefined, (err: unknown) => settleOnce(toError(err))); + } + } catch (err) { + settleOnce(toError(err)); + } }), ), Promise.resolve(), ) + // Defensive: settleOnce never rejects the chain, so this should be + // unreachable. If it ever runs, the change's callback must still fire. + .catch(() => {}) .then(callback); } }, @@ -117,12 +261,17 @@ export default class TransactionalFeatureStore implements LDTransactionalFeature } initialized(callback: (isInitialized: boolean) => void): void { - // this is valid because the active store will only switch to the in memory store - // after it has already been initialized itself + // Delegating here is safe: _activeStore only switches to the memory store after + // the memory store has already been initialized. this._activeStore.initialized(callback); } close(): void { + if (this._closed) { + return; + } + this._closed = true; + this._stopRecoveryPolling(); this._nonTransPersistenceStore.close(); this._memoryStore.close(); } @@ -131,9 +280,10 @@ export default class TransactionalFeatureStore implements LDTransactionalFeature return 'transactional persistent store'; } - // applyChanges always writes here first, so the memory store has the latest - // metadata/selector even while _activeStore still points at the persistence - // store; the plain LDFeatureStore contract has no equivalent to read them from + // applyChanges always writes to the memory store first, so it always has the + // latest metadata and selector, even while _activeStore still points at the + // persistence store. The plain LDFeatureStore contract has no way to read them + // from there. getInitMetaData(): internal.InitMetadata | undefined { return this._memoryStore.getInitMetaData?.(); } @@ -141,4 +291,319 @@ export default class TransactionalFeatureStore implements LDTransactionalFeature getSelector(): string | undefined { return this._memoryStore.getSelector?.(); } + + /** + * Record the result of a mirrored write to the persistence store. + * + * The first failed write marks the store unavailable. A successful write while the + * store is unavailable starts recovery. + * + * A basis write already wrote the full data set, so it recovers directly. Any + * other write starts a write-back of the full in-memory data set instead. + */ + private _handleWriteResult(err: Error | undefined, isBasisWrite: boolean): void { + if (this._closed) { + return; + } + if (err) { + this._markUnavailable(); + } else if (!this._persistenceAvailable) { + if (isBasisWrite) { + // Already wrote the full data set as the basis; a write-back would repeat it. + this._markAvailable(); + } else { + this._attemptRecovery(); + } + } + } + + private _markUnavailable(): void { + if (!this._persistenceAvailable) { + return; + } + this._persistenceAvailable = false; + // A stale probe from before this outage must never answer into it. + this._probeGeneration += 1; + this._probeInFlight = false; + // No write-back can be in flight here, since a write-back only starts once the + // store is already unavailable. This bump is a no-op today, kept only for + // symmetry with the probe reset above. The guard that matters lives in + // _markAvailable() below. + this._writeBackGeneration += 1; + this._writeBackInFlight = false; + this._failureLoggedThisOutage = false; + this._logger?.warn( + 'Persistent store is unavailable. Updates will be kept in memory until it recovers.', + ); + this._startRecoveryPolling(); + } + + private _markAvailable(): void { + if (this._persistenceAvailable) { + return; + } + this._persistenceAvailable = true; + // The store just proved it is healthy. + // Failures left over from this outage must not carry into the next one, or + // suppress its first error log. + this._consecutiveWriteBackFailures = 0; + this._failureLoggedThisOutage = false; + // A stale probe answer from this outage must never fire a redundant write-back. + this._probeGeneration += 1; + this._probeInFlight = false; + // A stale write-back from this outage must never be honored after recovery, or + // flip state out from under the next outage. + this._writeBackGeneration += 1; + this._writeBackInFlight = false; + // A failure embargo built up during this outage must not delay the next + // outage's first write-back attempt. Recovery just proved the store is healthy. + // The success floor below already covers flap damping. + this._writeBackEmbargoUntil = Math.min( + this._writeBackEmbargoUntil, + Date.now() + WRITE_BACK_SUCCESS_EMBARGO_MS, + ); + this._stopRecoveryPolling(); + this._logger?.info('Persistent store is available again.'); + } + + /** + * Poll the persistence store availability check, when it has one, until the store + * recovers. Stores without an availability check recover through the next successful + * mirrored write instead. The check is read-only. A write is never used as a check. + */ + private _startRecoveryPolling(): void { + if (this._pollHandle || this._closed) { + return; + } + if (typeof this._nonTransPersistenceStore.isStoreAvailable !== 'function') { + return; + } + this._pollHandle = setInterval(() => { + if (this._writeBackInFlight) { + if (!this._releaseWriteBackIfHung()) { + // Still within the deadline. Wait for it to answer before probing again. + return; + } + } + if (this._probeInFlight) { + if (!this._releaseProbeIfHung()) { + // Still within the deadline. Wait for it to answer before probing again. + return; + } + } + if (this._persistenceAvailable) { + return; + } + if (Date.now() < this._writeBackEmbargoUntil) { + // Backing off after a write-back failure. + return; + } + const probe = this._nonTransPersistenceStore.isStoreAvailable?.bind( + this._nonTransPersistenceStore, + ); + if (!probe) { + return; + } + this._probeGeneration += 1; + const generation = this._probeGeneration; + this._probeInFlight = true; + this._probeStartedAt = Date.now(); + const onAnswer = (isAvailable: boolean) => { + // Ignore a stale or duplicate answer from a superseded probe. + if (generation !== this._probeGeneration || !this._probeInFlight) { + return; + } + this._probeInFlight = false; + if (this._closed) { + return; + } + if (isAvailable) { + this._attemptRecovery(); + } + }; + try { + const result = probe(onAnswer); + if (isThenable(result)) { + result.then(undefined, (err: unknown) => { + // A rejected probe promise is treated as an unavailable answer. It is + // not a write-back failure, so it does not affect the error log or backoff. + if (generation !== this._probeGeneration || !this._probeInFlight) { + return; + } + this._probeInFlight = false; + if (this._closed) { + return; + } + this._logger?.debug(`Persistent store availability check rejected: ${toError(err)}`); + }); + } + } catch (err) { + // A probe that throws synchronously is treated as an unavailable answer. It is + // not a write-back failure, so it does not affect the error log or backoff. + this._probeInFlight = false; + this._logger?.debug(`Persistent store availability check threw: ${toError(err)}`); + } + }, RECOVERY_POLL_INTERVAL_MS); + } + + private _stopRecoveryPolling(): void { + if (this._pollHandle) { + clearInterval(this._pollHandle); + this._pollHandle = undefined; + } + } + + /** + * Abandons the outstanding write-back once it is past its deadline. + * + * Bumps the generation so a late callback is ignored, and clears the in-flight + * flag so a fresh attempt can proceed. Also arms the failure embargo, so a + * persistence store that never answers backs off on the same schedule as a real + * failure instead of retrying every poll tick. Returns whether it was released. + */ + private _releaseWriteBackIfHung(): boolean { + if (Date.now() - this._writeBackStartedAt < HUNG_TIMEOUT_MS) { + return false; + } + this._writeBackGeneration += 1; + this._writeBackInFlight = false; + this._armFailureEmbargo(); + this._logger?.debug('A write-back to the persistent store did not complete in time. Retrying.'); + return true; + } + + /** + * Abandons the outstanding availability probe once it is past its deadline. + * + * Bumps the generation so a late answer is ignored, and clears the in-flight flag + * so a fresh probe can be issued. Returns whether it was released. + */ + private _releaseProbeIfHung(): boolean { + if (Date.now() - this._probeStartedAt < HUNG_TIMEOUT_MS) { + return false; + } + this._probeGeneration += 1; + this._probeInFlight = false; + this._logger?.debug( + 'A persistent store availability check did not complete in time. Retrying.', + ); + return true; + } + + private _attemptRecovery(): void { + if (this._writeBackInFlight && !this._releaseWriteBackIfHung()) { + return; + } + if (this._persistenceAvailable) { + return; + } + if (Date.now() < this._writeBackEmbargoUntil) { + // Backing off after a write-back failure. A write-signal or probe answer that + // arrives inside the embargo must not flood the persistence store with retries. + return; + } + this._writeBackGeneration += 1; + const generation = this._writeBackGeneration; + this._writeBackInFlight = true; + this._writeBackStartedAt = Date.now(); + this._writeBack(generation); + } + + /** + * Write the full in-memory data set, including tombstones, to the persistence store. + * The caller must set _writeBackInFlight and capture _writeBackGeneration before + * calling this method. + */ + private _writeBack(generation: number): void { + if (this._closed) { + this._writeBackInFlight = false; + return; + } + if (this._activeStore !== this._memoryStore) { + // No basis has been received, so there is no full data set to write. The next + // basis fully populates the persistence store. _markAvailable() below already + // clears _writeBackInFlight. + this._markAvailable(); + return; + } + const onSettled = (err?: Error) => { + // Ignore a late callback from an abandoned (timed-out) write-back. + // It must not flip state out from under a newer one. + if (generation !== this._writeBackGeneration || !this._writeBackInFlight) { + return; + } + this._writeBackInFlight = false; + if (this._closed) { + return; + } + if (err) { + this._handleWriteBackFailure(); + return; + } + this._handleWriteBackSuccess(); + }; + try { + const result = this._nonTransPersistenceStore.init(this._memoryStore.getAllRaw(), onSettled); + if (isThenable(result)) { + result.then(undefined, (err: unknown) => onSettled(toError(err))); + } + } catch (err) { + // A synchronous throw from init(), or from getAllRaw(), is handled the same way + // as a failed write-back. This way it cannot escape the poll timer or the + // write path. + onSettled(toError(err)); + } + } + + /** + * Records a successful write-back. + * + * Clears the failure count and arms a short embargo, so a flapping store cannot + * trigger more than about one write-back per second. + */ + private _handleWriteBackSuccess(): void { + this._writeBackEmbargoUntil = Date.now() + WRITE_BACK_SUCCESS_EMBARGO_MS; + this._markAvailable(); + } + + /** + * Increments the current outage's failure count. + * + * Sets the exponential backoff embargo that gates the next write-back attempt. + */ + private _armFailureEmbargo(): void { + this._consecutiveWriteBackFailures += 1; + const backoffMs = Math.min( + 2 ** this._consecutiveWriteBackFailures * 500, + MAX_WRITE_BACK_BACKOFF_MS, + ); + this._writeBackEmbargoUntil = Date.now() + backoffMs; + } + + /** + * Records a failed write-back attempt: backs off the next attempt and logs. + * + * Only the first failure of an outage logs at error level. Later failures in the + * same outage log at debug level, so an unhealthy store cannot flood the log + * every poll tick. See _failureLoggedThisOutage for why this is tracked + * separately from _consecutiveWriteBackFailures. + */ + private _handleWriteBackFailure(): void { + if (this._persistenceAvailable) { + // A stale write-back from a prior, already-recovered outage. + // The generation guard in _writeBack() should already have dropped this. + // This check is a second, cheap defense against a spurious failure log while + // the store is healthy. + return; + } + this._armFailureEmbargo(); + const message = + 'Failed to write the in-memory data to the persistent store. The persistent store remains unavailable.'; + if (!this._failureLoggedThisOutage) { + this._failureLoggedThisOutage = true; + this._logger?.error(message); + } else { + this._logger?.debug(message); + } + } }