diff --git a/.changeset/wild-llamas-melt.md b/.changeset/wild-llamas-melt.md new file mode 100644 index 000000000..1cf607fd1 --- /dev/null +++ b/.changeset/wild-llamas-melt.md @@ -0,0 +1,5 @@ +--- +'@powersync/service-core': patch +--- + +Improve diagnostics in logs for JWKS timeouts. diff --git a/packages/service-core/src/auth/CachedKeyCollector.ts b/packages/service-core/src/auth/CachedKeyCollector.ts index 6ef0a67dc..fd45889a0 100644 --- a/packages/service-core/src/auth/CachedKeyCollector.ts +++ b/packages/service-core/src/auth/CachedKeyCollector.ts @@ -3,7 +3,7 @@ import timers from 'timers/promises'; import { KeySpec } from './KeySpec.js'; import { LeakyBucket } from './LeakyBucket.js'; import { KeyCollector, KeyResult } from './KeyCollector.js'; -import { AuthorizationError } from '@powersync/lib-services-framework'; +import { AuthorizationError, ErrorCode, logger } from '@powersync/lib-services-framework'; import { mapAuthConfigError } from './utils.js'; /** @@ -70,8 +70,21 @@ export class CachedKeyCollector implements KeyCollector { // e.g. in the case of waiting for error retries. // In the case of very slow requests, we don't wait for it to complete, but the // request can still complete in the background. - const timeout = timers.setTimeout(3000); - await Promise.race([this.refreshPromise, timeout]); + const WAIT_TIMEOUT_SECONDS = 3; + const timeout = timers.setTimeout(WAIT_TIMEOUT_SECONDS * 1000).then(() => { + throw new AuthorizationError(ErrorCode.PSYNC_S2204, `JWKS request failed`, { + cause: { message: `Key request timed out in ${WAIT_TIMEOUT_SECONDS}s`, name: 'AbortError' } + }); + }); + try { + await Promise.race([this.refreshPromise, timeout]); + } catch (e) { + if (e instanceof AuthorizationError) { + return { keys: this.currentKeys, errors: [...this.currentErrors, e] }; + } else { + throw e; + } + } } return { keys: this.currentKeys, errors: this.currentErrors }; @@ -102,7 +115,16 @@ export class CachedKeyCollector implements KeyCollector { this.currentErrors = errors; this.keyTimestamp = Date.now(); this.error = false; + + // Due to caching and background refresh behavior, errors are not always propagated to the request handler, + // so we log them here. + for (let error of errors) { + logger.error(`Soft key refresh error`, error); + } } catch (e) { + // Due to caching and background refresh behavior, errors are not always propagated to the request handler, + // so we log them here. + logger.error(`Hard key refresh error`, e); this.error = true; // No result - keep previous keys this.currentErrors = [mapAuthConfigError(e)]; diff --git a/packages/service-core/src/auth/KeySpec.ts b/packages/service-core/src/auth/KeySpec.ts index d6941b877..84ce6ee10 100644 --- a/packages/service-core/src/auth/KeySpec.ts +++ b/packages/service-core/src/auth/KeySpec.ts @@ -40,6 +40,20 @@ export class KeySpec { return this.source.kid; } + get description(): string { + let details: string[] = []; + details.push(`kid: ${this.kid ?? '*'}`); + details.push(`kty: ${this.source.kty}`); + if (this.source.alg != null) { + details.push(`alg: ${this.source.alg}`); + } + if (this.options.requiresAudience != null) { + details.push(`aud: ${this.options.requiresAudience.join(', ')}`); + } + + return `<${details.filter((x) => x != null).join(', ')}>`; + } + matchesAlgorithm(jwtAlg: string): boolean { if (this.source.alg) { return jwtAlg === this.source.alg; diff --git a/packages/service-core/src/auth/KeyStore.ts b/packages/service-core/src/auth/KeyStore.ts index aed06e799..6e48159c5 100644 --- a/packages/service-core/src/auth/KeyStore.ts +++ b/packages/service-core/src/auth/KeyStore.ts @@ -1,4 +1,4 @@ -import { logger, errors, AuthorizationError, ErrorCode } from '@powersync/lib-services-framework'; +import { AuthorizationError, ErrorCode, logger } from '@powersync/lib-services-framework'; import * as jose from 'jose'; import secs from '../util/secs.js'; import { JwtPayload } from './JwtPayload.js'; @@ -169,7 +169,7 @@ export class KeyStore { ErrorCode.PSYNC_S2101, 'Could not find an appropriate key in the keystore. The key is missing or no key matched the token KID', { - configurationDetails: `Known kid values: ${keys.map((key) => key.kid ?? '*').join(', ')}` + configurationDetails: `Known keys: ${keys.map((key) => key.description).join(', ')}` // tokenDetails automatically populated later } ); diff --git a/packages/service-core/src/auth/RemoteJWKSCollector.ts b/packages/service-core/src/auth/RemoteJWKSCollector.ts index 9a1d0fd8e..34984c8f2 100644 --- a/packages/service-core/src/auth/RemoteJWKSCollector.ts +++ b/packages/service-core/src/auth/RemoteJWKSCollector.ts @@ -49,9 +49,10 @@ export class RemoteJWKSCollector implements KeyCollector { private async getJwksData(): Promise { const abortController = new AbortController(); + const REQUEST_TIMEOUT_SECONDS = 30; const timeout = setTimeout(() => { abortController.abort(); - }, 30_000); + }, REQUEST_TIMEOUT_SECONDS * 1000); try { const res = await fetch(this.url, { @@ -71,11 +72,14 @@ export class RemoteJWKSCollector implements KeyCollector { return (await res.json()) as any; } catch (e) { + if (e instanceof Error && e.name === 'AbortError') { + e = { message: `Request timed out in ${REQUEST_TIMEOUT_SECONDS}s`, name: 'AbortError' }; + } throw new AuthorizationError(ErrorCode.PSYNC_S2204, `JWKS request failed`, { configurationDetails: `JWKS URL: ${this.url}`, // This covers most cases of FetchError // `cause: e` could lose the error message - cause: { message: e.message, code: e.code } + cause: { message: e.message, code: e.code, name: e.name } }); } finally { clearTimeout(timeout);