Improve auth failure diagnostics (#295)

* Expand on key details.

* Improve JWKS timeout handling.

* Add changeset.

* Always log JWKS errors.

Author: rkistner

.changeset/wild-llamas-melt.md

@@ -0,0 +1,5 @@
+---
+'@powersync/service-core': patch
+---
+
+Improve diagnostics in logs for JWKS timeouts.

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)];

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;

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<Collector extends KeyCollector = KeyCollector> {
         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
         }
       );

packages/service-core/src/auth/RemoteJWKSCollector.ts

@@ -49,9 +49,10 @@ export class RemoteJWKSCollector implements KeyCollector {
 
   private async getJwksData(): Promise<any> {
     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);