From 5088409c4d7db9fa3977c40e34fc6a6dd6e58e03 Mon Sep 17 00:00:00 2001 From: Simon Hornby Date: Fri, 10 Mar 2023 10:03:32 +0200 Subject: [PATCH] fix: polling in proxy repository now stops correctly (#3268) ### What This patches two very subtle bugs in the proxy repository that cause it to never actually stop polling the db in the background ## Details - Issue 1 We've recently started to get the following output when running `yarn test`: ` Attempted to log "Error: Unable to acquire a connection at Object.queryBuilder (/home/simon/dev/unleash/node_modules/knex/lib/knex-builder/make-knex.js:111:26)` This seems to occur for every test suite after running the proxy tests and the full stack trace doesn't point to anything related to the running tests that produce this output. Running a `git bisect` points to this commit: https://github.com/Unleash/unleash/commit/6e44a65c58d8e28668f0d3459b62c0ce0b84849a being the culprit but I believe that this may have surfaced the bug rather than causing it. Layering in a few console logs and running Unleash, seems to point to the proxy repository setting up data polling but never actually terminating it when `stop` was called, which is inline with the output here - effectively the tests were continuing to run the polling in the background after the suite had exited and jest freaks out that an async task is running when it shouldn't be. This is easy to reproduce once the console logs are in place in the `dataPolling` function, by running Unleash - creating and deleting a front end token never terminates the poll cycle. I believe the cause here is some subtlety around using async functions with timers - stop was being called, which results in the timer being cleared but a scheduled async call was already on the stack, causing the recursive call to resolve after stop, resurrecting the timer and reinitializing the poll cycle. I've moved the terminating code into the async callback. Which seems to solve the problem here. ## Details - Issue 2 Related to the first issue, when the proxy service stops the underlying Unleash Client, it never actually calls destroy on the client, it only removes it from its internal map. That in turn means that the Client never calls stop on the injected repository, it only removes it from memory. However, the scheduled task is `async` and `unref`, meaning it continues to spin in the background until every other process also exits. This is patched by simply calling destroy on the client when cleaning up ## The Ugly This is really hard to test effectively, mostly because this is an issue caused by internals within NodeJS and async. I've added a test that reads the output from the debug log (and also placed a debug log in the termination code). This also requires the test code to wait until the async task completes. This is horribly fragile so if someone has a better idea on how to prove this I would be a very happy human. The second ugly part is that this is a subtle issue in complex code that really, really needs to work correctly. I'm nervous about making changes here without lots of eyes on this --- src/lib/proxy/proxy-repository.ts | 15 ++++++- src/lib/services/proxy-service.ts | 9 ++-- src/test/e2e/api/proxy/proxy.e2e.test.ts | 55 ++++++++++++++++++++++-- 3 files changed, 70 insertions(+), 9 deletions(-) diff --git a/src/lib/proxy/proxy-repository.ts b/src/lib/proxy/proxy-repository.ts index 141374ddd9..a3c185c5e1 100644 --- a/src/lib/proxy/proxy-repository.ts +++ b/src/lib/proxy/proxy-repository.ts @@ -42,7 +42,9 @@ export class ProxyRepository private interval: number; - private timer: NodeJS.Timer; + private timer: NodeJS.Timer | null; + + private running: boolean; constructor( config: Config, @@ -73,6 +75,7 @@ export class ProxyRepository } async start(): Promise { + this.running = true; await this.dataPolling(); // Reload cached token data whenever something relevant has changed. @@ -85,11 +88,19 @@ export class ProxyRepository stop(): void { this.stores.eventStore.off(ANY_EVENT, this.onAnyEvent); - clearTimeout(this.timer); + this.running = false; } private async dataPolling() { this.timer = setTimeout(async () => { + if (!this.running) { + clearTimeout(this.timer!); + this.timer = null; + this.logger.debug( + 'Shutting down data polling for proxy repository', + ); + return; + } await this.dataPolling(); }, this.randomizeDelay(this.interval, this.interval * 2)).unref(); diff --git a/src/lib/services/proxy-service.ts b/src/lib/services/proxy-service.ts index ad1314395b..cc9526db93 100644 --- a/src/lib/services/proxy-service.ts +++ b/src/lib/services/proxy-service.ts @@ -46,7 +46,7 @@ export class ProxyService { private cachedFrontendSettings?: FrontendSettings; - private timer: NodeJS.Timeout; + private timer: NodeJS.Timeout | null; constructor(config: Config, stores: Stores, services: Services) { this.config = config; @@ -150,6 +150,7 @@ export class ProxyService { } deleteClientForProxyToken(secret: string): void { + this.clients.get(secret)?.destroy(); this.clients.delete(secret); } @@ -200,7 +201,9 @@ export class ProxyService { } destroy(): void { - clearInterval(this.timer); - this.timer = null; + if (this.timer) { + clearInterval(this.timer); + this.timer = null; + } } } diff --git a/src/test/e2e/api/proxy/proxy.e2e.test.ts b/src/test/e2e/api/proxy/proxy.e2e.test.ts index 3dd7ff93a2..e32dffff82 100644 --- a/src/test/e2e/api/proxy/proxy.e2e.test.ts +++ b/src/test/e2e/api/proxy/proxy.e2e.test.ts @@ -14,6 +14,7 @@ import { IStrategyConfig, } from '../../../../lib/types'; import { ProxyRepository } from '../../../../lib/proxy'; +import { Logger } from '../../../../lib/logger'; let app: IUnleashTest; let db: ITestDb; @@ -27,6 +28,7 @@ beforeAll(async () => { afterEach(() => { app.services.proxyService.stopAll(); + jest.clearAllMocks(); }); afterAll(async () => { @@ -853,6 +855,7 @@ test('Should sync proxy for keys on an interval', async () => { ProxyRepository.prototype as any, 'featuresForToken', ); + expect(user).not.toBeNull(); const proxyRepository = new ProxyRepository( { getLogger, @@ -860,7 +863,7 @@ test('Should sync proxy for keys on an interval', async () => { }, db.stores, app.services, - user, + user!, ); await proxyRepository.start(); @@ -891,7 +894,7 @@ test('Should change fetch interval', async () => { }, db.stores, app.services, - user, + user!, ); await proxyRepository.start(); @@ -919,7 +922,7 @@ test('Should not recursively set off timers on events', async () => { }, db.stores, app.services, - user, + user!, ); await proxyRepository.start(); @@ -934,7 +937,7 @@ test('Should not recursively set off timers on events', async () => { }); test('should return all features when specified', async () => { - app.config.experimental.flags.proxyReturnAllToggles = true; + app.config.experimental!.flags.proxyReturnAllToggles = true; const frontendToken = await createApiToken(ApiTokenType.FRONTEND); await createFeatureToggle({ name: 'enabledFeature1', @@ -991,3 +994,47 @@ test('should return maxAge header on options call', async () => { expect(res.headers['access-control-max-age']).toBe('86400'); }); }); + +test('should terminate data polling when stop is called', async () => { + const frontendToken = await createApiToken(ApiTokenType.FRONTEND); + const user = await app.services.apiTokenService.getUserForToken( + frontendToken.secret, + ); + + const logTrap = []; + const getDebugLogger = (): Logger => { + return { + /* eslint-disable-next-line */ + debug: (message: any, ...args: any[]) => { + logTrap.push(message); + }, + /* eslint-disable-next-line */ + info: (...args: any[]) => {}, + /* eslint-disable-next-line */ + warn: (...args: any[]) => {}, + /* eslint-disable-next-line */ + error: (...args: any[]) => {}, + /* eslint-disable-next-line */ + fatal: (...args: any[]) => {}, + }; + }; + + /* eslint-disable-next-line */ + const proxyRepository = new ProxyRepository( + { + getLogger: getDebugLogger, + frontendApi: { refreshIntervalInMs: 1 }, + }, + db.stores, + app.services, + user, + ); + + await proxyRepository.start(); + proxyRepository.stop(); + // Polling here is an async recursive call, so we gotta give it a bit of time + await new Promise((r) => setTimeout(r, 10)); + expect(logTrap).toContain( + 'Shutting down data polling for proxy repository', + ); +});