From d377986010fc357e90724cf01be837c0c0445474 Mon Sep 17 00:00:00 2001 From: adams85 <31276480+adams85@users.noreply.github.com> Date: Fri, 6 Sep 2024 16:32:47 +0200 Subject: [PATCH] Fix cache expiration-related issues in Auto Polling mode (#106) * Make auto polling loop fault-tolerant + make timing more accurate * Check for expiration on every iteration in Auto Polling mode + allow a tolerance of 500ms to prevent missing fetches due to timer inaccuracy + sync with cache even in offline mode * Fix a few broken tests * Fix CI * npm audit fix * Bump version --- .github/workflows/common-js-ci.yml | 3 + package-lock.json | 20 +++---- package.json | 2 +- src/AutoPollConfigService.ts | 89 +++++++++++++++++------------- src/ConfigCatLogger.ts | 8 +++ src/Utils.ts | 51 +++++++++++++++-- test/ConfigCatClientTests.ts | 20 ++++--- test/ConfigServiceBaseTests.ts | 21 ++++--- test/helpers/fakes.ts | 4 +- 9 files changed, 145 insertions(+), 73 deletions(-) diff --git a/.github/workflows/common-js-ci.yml b/.github/workflows/common-js-ci.yml index 0049ae1..de07762 100644 --- a/.github/workflows/common-js-ci.yml +++ b/.github/workflows/common-js-ci.yml @@ -18,6 +18,9 @@ jobs: matrix: node: [ 14, 16, 18, 20 ] os: [ macos-latest, ubuntu-latest, windows-latest ] + exclude: + - node: 14 + os: macos-latest fail-fast: false name: Test [${{ matrix.os }}, Node ${{ matrix.node }}] steps: diff --git a/package-lock.json b/package-lock.json index 34cea8a..c71c8fb 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "configcat-common", - "version": "9.3.0", + "version": "9.3.1", "lockfileVersion": 2, "requires": true, "packages": { "": { "name": "configcat-common", - "version": "9.3.0", + "version": "9.3.1", "license": "MIT", "dependencies": { "tslib": "^2.4.1" @@ -3018,12 +3018,12 @@ } }, "node_modules/micromatch": { - "version": "4.0.5", - "resolved": "https://registry.npmjs.org/micromatch/-/micromatch-4.0.5.tgz", - "integrity": "sha512-DMy+ERcEW2q8Z2Po+WNXuw3c5YaUSFjAO5GsJqfEl7UjvtIuFKO6ZrKvcItdy98dwFI2N1tg3zNIdKaQT+aNdA==", + "version": "4.0.8", + "resolved": "https://registry.npmjs.org/micromatch/-/micromatch-4.0.8.tgz", + "integrity": "sha512-PXwfBhYu0hBCPw8Dn0E+WDYb7af3dSLVWKi3HGv84IdF4TyFoC0ysxFd0Goxw7nSv4T/PzEJQxsYsEiFCKo2BA==", "dev": true, "dependencies": { - "braces": "^3.0.2", + "braces": "^3.0.3", "picomatch": "^2.3.1" }, "engines": { @@ -7269,12 +7269,12 @@ "dev": true }, "micromatch": { - "version": "4.0.5", - "resolved": "https://registry.npmjs.org/micromatch/-/micromatch-4.0.5.tgz", - "integrity": "sha512-DMy+ERcEW2q8Z2Po+WNXuw3c5YaUSFjAO5GsJqfEl7UjvtIuFKO6ZrKvcItdy98dwFI2N1tg3zNIdKaQT+aNdA==", + "version": "4.0.8", + "resolved": "https://registry.npmjs.org/micromatch/-/micromatch-4.0.8.tgz", + "integrity": "sha512-PXwfBhYu0hBCPw8Dn0E+WDYb7af3dSLVWKi3HGv84IdF4TyFoC0ysxFd0Goxw7nSv4T/PzEJQxsYsEiFCKo2BA==", "dev": true, "requires": { - "braces": "^3.0.2", + "braces": "^3.0.3", "picomatch": "^2.3.1" } }, diff --git a/package.json b/package.json index e42385f..cfef6de 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "configcat-common", - "version": "9.3.0", + "version": "9.3.1", "description": "ConfigCat is a configuration as a service that lets you manage your features and configurations without actually deploying new code.", "main": "lib/index.js", "types": "lib/index.d.ts", diff --git a/src/AutoPollConfigService.ts b/src/AutoPollConfigService.ts index 7065ac9..9c454e9 100644 --- a/src/AutoPollConfigService.ts +++ b/src/AutoPollConfigService.ts @@ -4,15 +4,18 @@ import type { IConfigFetcher } from "./ConfigFetcher"; import type { IConfigService, RefreshResult } from "./ConfigServiceBase"; import { ClientCacheState, ConfigServiceBase } from "./ConfigServiceBase"; import type { ProjectConfig } from "./ProjectConfig"; -import { delay } from "./Utils"; +import { AbortToken, delay } from "./Utils"; + +export const POLL_EXPIRATION_TOLERANCE_MS = 500; export class AutoPollConfigService extends ConfigServiceBase implements IConfigService { private initialized: boolean; private readonly initializationPromise: Promise; private signalInitialization: () => void = () => { /* Intentional no-op. */ }; - private workerTimerId?: ReturnType; + private stopToken = new AbortToken(); private readonly pollIntervalMs: number; + private readonly pollExpirationMs: number; readonly readyPromise: Promise; constructor(configFetcher: IConfigFetcher, options: AutoPollOptions) { @@ -20,6 +23,9 @@ export class AutoPollConfigService extends ConfigServiceBase im super(configFetcher, options); this.pollIntervalMs = options.pollIntervalSeconds * 1000; + // Due to the inaccuracy of the timer, some tolerance should be allowed when checking for + // cache expiration in the polling loop, otherwise some fetch operations may be missed. + this.pollExpirationMs = this.pollIntervalMs - POLL_EXPIRATION_TOLERANCE_MS; const initialCacheSyncUp = this.syncUpWithCache(); @@ -48,7 +54,7 @@ export class AutoPollConfigService extends ConfigServiceBase im }); if (!options.offline) { - this.startRefreshWorker(initialCacheSyncUp); + this.startRefreshWorker(initialCacheSyncUp, this.stopToken); } } @@ -58,12 +64,12 @@ export class AutoPollConfigService extends ConfigServiceBase im return true; } - const delayCleanup: { clearTimer?: () => void } = {}; + const abortToken = new AbortToken(); const success = await Promise.race([ initSignalPromise.then(() => true), - delay(this.options.maxInitWaitTimeSeconds * 1000, delayCleanup).then(() => false) + delay(this.options.maxInitWaitTimeSeconds * 1000, abortToken).then(() => false) ]); - delayCleanup.clearTimer!(); + abortToken.abort(); return success; } @@ -105,7 +111,7 @@ export class AutoPollConfigService extends ConfigServiceBase im dispose(): void { this.options.logger.debug("AutoPollConfigService.dispose() called."); super.dispose(); - if (this.workerTimerId) { + if (!this.stopToken.aborted) { this.stopRefreshWorker(); } } @@ -116,58 +122,65 @@ export class AutoPollConfigService extends ConfigServiceBase im } protected setOnlineCore(): void { - this.startRefreshWorker(); + this.startRefreshWorker(null, this.stopToken); } protected setOfflineCore(): void { this.stopRefreshWorker(); + this.stopToken = new AbortToken(); } - private async startRefreshWorker(initialCacheSyncUp?: ProjectConfig | Promise) { + private async startRefreshWorker(initialCacheSyncUp: ProjectConfig | Promise | null, stopToken: AbortToken) { this.options.logger.debug("AutoPollConfigService.startRefreshWorker() called."); - const delayMs = this.pollIntervalMs; + let isFirstIteration = true; + while (!stopToken.aborted) { + try { + const scheduledNextTimeMs = new Date().getTime() + this.pollIntervalMs; + try { + await this.refreshWorkerLogic(isFirstIteration, initialCacheSyncUp); + } + catch (err) { + this.options.logger.autoPollConfigServiceErrorDuringPolling(err); + } + + const realNextTimeMs = scheduledNextTimeMs - new Date().getTime(); + if (realNextTimeMs > 0) { + await delay(realNextTimeMs, stopToken); + } + } + catch (err) { + this.options.logger.autoPollConfigServiceErrorDuringPolling(err); + } + + isFirstIteration = false; + initialCacheSyncUp = null; // allow GC to collect the Promise and its result + } + } + + private stopRefreshWorker() { + this.options.logger.debug("AutoPollConfigService.stopRefreshWorker() called."); + this.stopToken.abort(); + } + + private async refreshWorkerLogic(isFirstIteration: boolean, initialCacheSyncUp: ProjectConfig | Promise | null) { + this.options.logger.debug("AutoPollConfigService.refreshWorkerLogic() - called."); const latestConfig = await (initialCacheSyncUp ?? this.options.cache.get(this.cacheKey)); - if (latestConfig.isExpired(this.pollIntervalMs)) { + if (latestConfig.isExpired(this.pollExpirationMs)) { // Even if the service gets disposed immediately, we allow the first refresh for backward compatibility, // i.e. to not break usage patterns like this: // ``` // client.getValueAsync("SOME_KEY", false).then(value => { /* ... */ }, user); // client.dispose(); // ``` - if (!this.isOfflineExactly) { + if (isFirstIteration ? !this.isOfflineExactly : !this.isOffline) { await this.refreshConfigCoreAsync(latestConfig); } } - else { + else if (isFirstIteration) { this.signalInitialization(); } - - this.options.logger.debug("AutoPollConfigService.startRefreshWorker() - calling refreshWorkerLogic()'s setTimeout."); - this.workerTimerId = setTimeout(d => this.refreshWorkerLogic(d), delayMs, delayMs); - } - - private stopRefreshWorker() { - this.options.logger.debug("AutoPollConfigService.stopRefreshWorker() - clearing setTimeout."); - clearTimeout(this.workerTimerId); - } - - private async refreshWorkerLogic(delayMs: number) { - if (this.disposed) { - this.options.logger.debug("AutoPollConfigService.refreshWorkerLogic() - called on a disposed client."); - return; - } - - this.options.logger.debug("AutoPollConfigService.refreshWorkerLogic() - called."); - - if (!this.isOffline) { - const latestConfig = await this.options.cache.get(this.cacheKey); - await this.refreshConfigCoreAsync(latestConfig); - } - - this.options.logger.debug("AutoPollConfigService.refreshWorkerLogic() - calling refreshWorkerLogic()'s setTimeout."); - this.workerTimerId = setTimeout(d => this.refreshWorkerLogic(d), delayMs, delayMs); } getCacheState(cachedConfig: ProjectConfig): ClientCacheState { diff --git a/src/ConfigCatLogger.ts b/src/ConfigCatLogger.ts index 089f348..cb47b3f 100644 --- a/src/ConfigCatLogger.ts +++ b/src/ConfigCatLogger.ts @@ -231,6 +231,14 @@ export class LoggerWrapper implements IConfigCatLogger { ); } + autoPollConfigServiceErrorDuringPolling(ex: any): LogMessage { + return this.log( + LogLevel.Error, 1200, + "Error occurred during auto polling.", + ex + ); + } + /* SDK-specific error messages (2000-2999) */ settingForVariationIdIsNotPresent(variationId: string): LogMessage { diff --git a/src/Utils.ts b/src/Utils.ts index fc1760d..2475680 100644 --- a/src/Utils.ts +++ b/src/Utils.ts @@ -1,10 +1,49 @@ -export function delay(delayMs: number, delayCleanup?: { clearTimer?: () => void } | null): Promise { - let timerId: ReturnType; - const promise = new Promise(resolve => timerId = setTimeout(resolve, delayMs)); - if (delayCleanup) { - delayCleanup.clearTimer = () => clearTimeout(timerId); +// NOTE: Normally, we'd just use AbortController/AbortSignal, however that may not be available on all platforms, +// and we don't want to include a complete polyfill. So we implement a simplified version that fits our use case. +export class AbortToken { + private callbacks: (() => void)[] | null = []; + get aborted(): boolean { return !this.callbacks; } + + abort(): void { + if (!this.aborted) { + const callbacks = this.callbacks!; + this.callbacks = null; + for (const callback of callbacks) { + callback(); + } + } } - return promise; + + registerCallback(callback: () => void): () => void { + if (this.aborted) { + callback(); + return () => { }; + } + + this.callbacks!.push(callback); + return () => { + const callbacks = this.callbacks; + let index: number; + if (callbacks && (index = callbacks.indexOf(callback)) >= 0) { + callbacks.splice(index, 1); + } + }; + } +} + +export function delay(delayMs: number, abortToken?: AbortToken | null): Promise { + let timerId: ReturnType; + return new Promise(resolve => { + const unregisterAbortCallback = abortToken?.registerCallback(() => { + clearTimeout(timerId); + resolve(false); + }); + + timerId = setTimeout(() => { + unregisterAbortCallback?.(); + resolve(true); + }, delayMs); + }); } export function errorToString(err: any, includeStackTrace = false): string { diff --git a/test/ConfigCatClientTests.ts b/test/ConfigCatClientTests.ts index c4d0a18..6581261 100644 --- a/test/ConfigCatClientTests.ts +++ b/test/ConfigCatClientTests.ts @@ -526,11 +526,13 @@ describe("ConfigCatClient", () => { setupHooks: hooks => hooks.on("configChanged", () => configChangedEventCount++) }; const options: AutoPollOptions = new AutoPollOptions("APIKEY", "common", "1.0.0", userOptions, null); - new ConfigCatClient(options, configCatKernel); - - await delay(2.5 * pollIntervalSeconds * 1000); + const client = new ConfigCatClient(options, configCatKernel); + try { + await delay(2.5 * pollIntervalSeconds * 1000); - assert.equal(configChangedEventCount, 3); + assert.equal(configChangedEventCount, 3); + } + finally { client.dispose(); } }); it("Initialization With AutoPollOptions - config doesn't change - should fire configChanged only once", async () => { @@ -544,11 +546,13 @@ describe("ConfigCatClient", () => { setupHooks: hooks => hooks.on("configChanged", () => configChangedEventCount++) }; const options: AutoPollOptions = new AutoPollOptions("APIKEY", "common", "1.0.0", userOptions, null); - new ConfigCatClient(options, configCatKernel); - - await delay(2.5 * pollIntervalSeconds * 1000); + const client = new ConfigCatClient(options, configCatKernel); + try { + await delay(2.5 * pollIntervalSeconds * 1000); - assert.equal(configChangedEventCount, 1); + assert.equal(configChangedEventCount, 1); + } + finally { client.dispose(); } }); it("Initialization With AutoPollOptions - with maxInitWaitTimeSeconds - getValueAsync should wait", async () => { diff --git a/test/ConfigServiceBaseTests.ts b/test/ConfigServiceBaseTests.ts index 59017bb..bc78118 100644 --- a/test/ConfigServiceBaseTests.ts +++ b/test/ConfigServiceBaseTests.ts @@ -2,7 +2,7 @@ import { assert } from "chai"; import "mocha"; import { EqualMatchingInjectorConfig, It, Mock, RejectedPromiseFactory, ResolvedPromiseFactory, Times } from "moq.ts"; import { MimicsRejectedAsyncPresetFactory, MimicsResolvedAsyncPresetFactory, Presets, ReturnsAsyncPresetFactory, RootMockProvider, ThrowsAsyncPresetFactory } from "moq.ts/internal"; -import { AutoPollConfigService } from "../src/AutoPollConfigService"; +import { AutoPollConfigService, POLL_EXPIRATION_TOLERANCE_MS } from "../src/AutoPollConfigService"; import { IConfigCache, InMemoryConfigCache } from "../src/ConfigCatCache"; import { AutoPollOptions, LazyLoadOptions, ManualPollOptions, OptionsBase } from "../src/ConfigCatClientOptions"; import { FetchResult, IConfigFetcher, IFetchResponse } from "../src/ConfigFetcher"; @@ -167,7 +167,7 @@ describe("ConfigServiceBaseTests", () => { const projectConfigNew: ProjectConfig = createConfigFromFetchResult(frNew); const time: number = new Date().getTime(); - const projectConfigOld: ProjectConfig = createConfigFromFetchResult(frOld).with(time - (1.5 * pollInterval * 1000)); + const projectConfigOld: ProjectConfig = createConfigFromFetchResult(frOld).with(time - (1.5 * pollInterval * 1000) + 0.5 * POLL_EXPIRATION_TOLERANCE_MS); const cache = new InMemoryConfigCache(); @@ -214,7 +214,7 @@ describe("ConfigServiceBaseTests", () => { const pollInterval = 10; const time: number = new Date().getTime(); - const projectConfigOld = createConfigFromFetchResult(frOld).with(time - (pollInterval * 1000) + 50); // 50ms for tolerance + const projectConfigOld = createConfigFromFetchResult(frOld).with(time - (pollInterval * 1000) + 0.5 * POLL_EXPIRATION_TOLERANCE_MS); const cache = new InMemoryConfigCache(); @@ -453,7 +453,7 @@ describe("ConfigServiceBaseTests", () => { const fr: FetchResult = createFetchResult(); let cachedPc: ProjectConfig = createConfigFromFetchResult(fr); - cachedPc = cachedPc.with(cachedPc.timestamp - 0.5 * pollIntervalSeconds * 1000); + cachedPc = cachedPc.with(cachedPc.timestamp - pollIntervalSeconds * 1000 + 1.5 * POLL_EXPIRATION_TOLERANCE_MS); const cache = new FakeCache(); cache.set("", cachedPc); @@ -474,6 +474,9 @@ describe("ConfigServiceBaseTests", () => { const service = new AutoPollConfigService(fetcherMock.object(), options); + // Give a bit of time to the polling loop to do the first iteration. + await delay(pollIntervalSeconds / 4 * 1000); + const actualPc = await service.getConfig(); // Assert @@ -491,17 +494,14 @@ describe("ConfigServiceBaseTests", () => { const fr: FetchResult = createFetchResult(); let cachedPc: ProjectConfig = createConfigFromFetchResult(fr); - cachedPc = cachedPc.with(cachedPc.timestamp - 1.5 * pollIntervalSeconds * 1000); + cachedPc = cachedPc.with(cachedPc.timestamp - pollIntervalSeconds * 1000 + 0.5 * POLL_EXPIRATION_TOLERANCE_MS); const cache = new FakeCache(); cache.set("", cachedPc); const fetcherMock = new Mock() .setup(m => m.fetchLogic(It.IsAny(), It.IsAny())) - .callback(async () => { - await delay(500); - return { statusCode: 200, reasonPhrase: "OK", eTag: fr.config.httpETag, body: fr.config.configJson }; - }); + .returnsAsync({ statusCode: 200, reasonPhrase: "OK", eTag: fr.config.httpETag, body: fr.config.configJson }); const options = new AutoPollOptions( "APIKEY", "common", "1.0.0", @@ -515,6 +515,9 @@ describe("ConfigServiceBaseTests", () => { const service = new AutoPollConfigService(fetcherMock.object(), options); + // Give a bit of time to the polling loop to do the first iteration. + await delay(pollIntervalSeconds / 4 * 1000); + const actualPc = await service.getConfig(); // Assert diff --git a/test/helpers/fakes.ts b/test/helpers/fakes.ts index 201da74..06c2220 100644 --- a/test/helpers/fakes.ts +++ b/test/helpers/fakes.ts @@ -185,8 +185,10 @@ export class FakeConfigFetcherWithAlwaysVariableEtag extends FakeConfigFetcher { return '{"f":{"debug":{"t":0,"v":{"b":true},"i":"abcdefgh"}}}'; } + private eTag = 0; + getEtag(): string { - return Math.random().toString(); + return `"${(this.eTag++).toString(16).padStart(8, "0")}"`; } }