feat: improve logging and testing, allow using id tokens instead of access tokens (#193)

* feat: improve logging and testing

Miscellaneous improvements around logging inside the plugin, plus a few preparations
for downstream diagnostics improvements:
- Emit an event when the browser has successfully been opened (COMPASS-8121)
- Improve logging around token refreshing (MONGOSH-1795)
- Emit acquired tokens in an event (MONGOSH-1845)
- Use `.timers` for also testing the browser timer

* feat: allow using id tokens instead of access tokens MONGOSH-1843

Author: addaleax

src/api.ts

@@ -191,6 +191,12 @@ export interface MongoDBOIDCPluginOptions {
   customHttpOptions?:
     | HttpOptions
     | ((url: string, options: Readonly<HttpOptions>) => HttpOptions);
+
+  /**
+   * Pass ID tokens in place of access tokens. For debugging/working around
+   * broken identity providers.
+   */
+  passIdTokenAsAccessToken?: boolean;
 }
 
 /** @public */

src/log-hook.ts

@@ -140,6 +140,15 @@ export function hookLoggerToMongoLogWriter(
     );
   });
 
+  emitter.on('mongodb-oidc-plugin:open-browser-complete', () => {
+    log.info(
+      'OIDC-PLUGIN',
+      mongoLogId(1_002_000_025),
+      `${contextPrefix}-oidc`,
+      'Successfully opened browser'
+    );
+  });
+
   emitter.on('mongodb-oidc-plugin:notify-device-flow', () => {
     log.info(
       'OIDC-PLUGIN',
@@ -218,33 +227,51 @@ export function hookLoggerToMongoLogWriter(
     );
   });
 
-  emitter.on('mongodb-oidc-plugin:auth-succeeded', (ev) => {
+  emitter.on(
+    'mongodb-oidc-plugin:auth-succeeded',
+    ({ tokenType, refreshToken, expiresAt, passIdTokenAsAccessToken }) => {
+      log.info(
+        'OIDC-PLUGIN',
+        mongoLogId(1_002_000_017),
+        `${contextPrefix}-oidc`,
+        'Authentication succeeded',
+        {
+          tokenType,
+          refreshToken,
+          expiresAt,
+          passIdTokenAsAccessToken,
+        }
+      );
+    }
+  );
+
+  emitter.on('mongodb-oidc-plugin:refresh-skipped', (ev) => {
     log.info(
       'OIDC-PLUGIN',
-      mongoLogId(1_002_000_017),
+      mongoLogId(1_002_000_026),
       `${contextPrefix}-oidc`,
-      'Authentication succeeded',
-      {
-        ...ev,
-      }
+      'Token refresh attempt skipped',
+      { ...ev }
     );
   });
 
-  emitter.on('mongodb-oidc-plugin:refresh-started', () => {
+  emitter.on('mongodb-oidc-plugin:refresh-started', (ev) => {
     log.info(
       'OIDC-PLUGIN',
       mongoLogId(1_002_000_018),
       `${contextPrefix}-oidc`,
-      'Token refresh attempt started'
+      'Token refresh attempt started',
+      { ...ev }
     );
   });
 
-  emitter.on('mongodb-oidc-plugin:refresh-succeeded', () => {
+  emitter.on('mongodb-oidc-plugin:refresh-succeeded', (ev) => {
     log.info(
       'OIDC-PLUGIN',
       mongoLogId(1_002_000_019),
       `${contextPrefix}-oidc`,
-      'Token refresh attempt succeeded'
+      'Token refresh attempt succeeded',
+      { ...ev }
     );
   });
 
@@ -297,6 +324,16 @@ export function hookLoggerToMongoLogWriter(
       { url: redactUrl(ev.url) }
     );
   });
+
+  emitter.on('mongodb-oidc-plugin:state-updated', (ev) => {
+    log.info(
+      'OIDC-PLUGIN',
+      mongoLogId(1_002_000_027),
+      `${contextPrefix}-oidc`,
+      'Updated internal token store state',
+      { ...ev }
+    );
+  });
 }
 
 function redactUrl(url: string): string {

src/plugin.spec.ts

@@ -168,6 +168,27 @@ describe('OIDC plugin (local OIDC provider)', function () {
       ]);
     });
 
+    it('can optionally use id tokens instead of access tokens', async function () {
+      pluginOptions = {
+        ...defaultOpts,
+        allowedFlows: ['auth-code'],
+        openBrowser: functioningAuthCodeBrowserFlow,
+        passIdTokenAsAccessToken: true,
+      };
+      plugin = createMongoDBOIDCPlugin(pluginOptions);
+      const result = await requestToken(
+        plugin,
+        provider.getMongodbOIDCDBInfo()
+      );
+      const accessTokenContents = getJWTContents(result.accessToken);
+      expect(accessTokenContents.sub).to.equal('testuser');
+      expect(accessTokenContents.aud).to.equal(
+        provider.getMongodbOIDCDBInfo().clientId
+      );
+      expect(accessTokenContents.client_id).to.equal(undefined);
+      verifySuccessfulAuthCodeFlowLog(await readLog());
+    });
+
     it('will refresh tokens if they are expiring', async function () {
       const skipAuthAttemptEvent = once(
         logger,
@@ -266,18 +287,22 @@ describe('OIDC plugin (local OIDC provider)', function () {
           provider.getMongodbOIDCDBInfo()
         );
 
-        expect(timeouts).to.have.lengthOf(1);
+        expect(timeouts).to.have.lengthOf(2);
+        // 0 -> browser timeout, 1 -> refresh timeout
         expect(timeouts[0].refed).to.equal(false);
         expect(timeouts[0].cleared).to.equal(false);
+        expect(timeouts[0].timeout).to.equal(60_000);
+        expect(timeouts[1].refed).to.equal(false);
+        expect(timeouts[1].cleared).to.equal(false);
         // openid-client bases expiration time on the actual current time, so
         // allow for a small margin of error
-        expect(timeouts[0].timeout).to.be.greaterThanOrEqual(9_600_000);
-        expect(timeouts[0].timeout).to.be.lessThanOrEqual(9_800_000);
+        expect(timeouts[1].timeout).to.be.greaterThanOrEqual(9_600_000);
+        expect(timeouts[1].timeout).to.be.lessThanOrEqual(9_800_000);
         const refreshStartedEvent = once(
           plugin.logger,
           'mongodb-oidc-plugin:refresh-started'
         );
-        timeouts[0].fn();
+        timeouts[1].fn();
         await refreshStartedEvent;
         await once(plugin.logger, 'mongodb-oidc-plugin:refresh-succeeded');
 
@@ -302,14 +327,14 @@ describe('OIDC plugin (local OIDC provider)', function () {
         provider.accessTokenTTLSeconds = 10000;
         await requestToken(plugin, provider.getMongodbOIDCDBInfo());
 
-        expect(timeouts).to.have.lengthOf(1);
-        expect(timeouts[0].refed).to.equal(false);
-        expect(timeouts[0].cleared).to.equal(false);
+        expect(timeouts).to.have.lengthOf(2);
+        expect(timeouts[1].refed).to.equal(false);
+        expect(timeouts[1].cleared).to.equal(false);
         await plugin.destroy();
 
-        expect(timeouts).to.have.lengthOf(1);
-        expect(timeouts[0].refed).to.equal(false);
-        expect(timeouts[0].cleared).to.equal(true);
+        expect(timeouts).to.have.lengthOf(2);
+        expect(timeouts[1].refed).to.equal(false);
+        expect(timeouts[1].cleared).to.equal(true);
       });
     });
 

src/plugin.ts

@@ -9,6 +9,7 @@ import type {
 import { MongoDBOIDCError } from './types';
 import {
   errorString,
+  getRefreshTokenId,
   messageFromError,
   normalizeObject,
   throwIfAborted,
@@ -147,6 +148,7 @@ export function automaticRefreshTimeoutMS(
 }
 
 const kEnableFallback = Symbol.for('@@mdb.oidcplugin.kEnableFallback');
+let updateIdCounter = 0;
 
 function allowFallbackIfFailed<T>(promise: Promise<T>): Promise<T> {
   return promise.catch((err) => {
@@ -558,6 +560,9 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
       this.logger.emit('mongodb-oidc-plugin:missing-id-token');
     }
 
+    const refreshTokenId = getRefreshTokenId(tokenSet.refresh_token);
+    const updateId = updateIdCounter++;
+
     const timerDuration = automaticRefreshTimeoutMS(tokenSet);
     // Use `.call()` because in browsers, `setTimeout()` requires that it is called
     // without a `this` value. `.unref()` is not available in browsers either.
@@ -577,21 +582,38 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
       }
       // Only refresh this token set if it is the one currently
       // being used.
-      if (state.currentTokenSet?.set !== tokenSet) return false;
+      if (state.currentTokenSet?.set !== tokenSet) {
+        this.logger.emit('mongodb-oidc-plugin:refresh-skipped', {
+          triggeringUpdateId: updateId,
+          expectedRefreshToken: refreshTokenId,
+          actualRefreshToken: getRefreshTokenId(
+            state.currentTokenSet?.set?.refresh_token
+          ),
+        });
+        return false;
+      }
       try {
-        this.logger.emit('mongodb-oidc-plugin:refresh-started');
+        this.logger.emit('mongodb-oidc-plugin:refresh-started', {
+          triggeringUpdateId: updateId,
+          refreshToken: refreshTokenId,
+        });
 
         const { client } = await this.getOIDCClient(state);
         const refreshedTokens = await client.refresh(tokenSet);
         // Check again to avoid race conditions.
         if (state.currentTokenSet?.set === tokenSet) {
-          this.logger.emit('mongodb-oidc-plugin:refresh-succeeded');
+          this.logger.emit('mongodb-oidc-plugin:refresh-succeeded', {
+            triggeringUpdateId: updateId,
+            refreshToken: refreshTokenId,
+          });
           this.updateStateWithTokenSet(state, refreshedTokens);
           return true;
         }
       } catch (err: unknown) {
         this.logger.emit('mongodb-oidc-plugin:refresh-failed', {
           error: errorString(err),
+          triggeringUpdateId: updateId,
+          refreshToken: refreshTokenId,
         });
       }
       return false;
@@ -602,7 +624,10 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
       tryRefresh,
     };
 
-    this.logger.emit('mongodb-oidc-plugin:state-updated');
+    this.logger.emit('mongodb-oidc-plugin:state-updated', {
+      updateId,
+      timerDuration,
+    });
   }
 
   static readonly defaultRedirectURI = 'http://localhost:27097/redirect';
@@ -667,6 +692,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
           new Promise<never>((resolve, reject) => {
             this.openBrowser({ url: localUrl, signal })
               .then((browserHandle) => {
+                this.logger.emit('mongodb-oidc-plugin:open-browser-complete');
                 const extraErrorInfo = () =>
                   browserHandle?.spawnargs
                     ? ` (${JSON.stringify(browserHandle.spawnargs)})`
@@ -697,11 +723,14 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
         const timeout: Promise<never> = allowFallbackIfFailed(
           new Promise((resolve, reject) => {
             if (this.options.openBrowserTimeout !== 0) {
-              setTimeout(
-                reject,
-                this.options.openBrowserTimeout ?? kDefaultOpenBrowserTimeout,
-                new MongoDBOIDCError('Opening browser timed out')
-              ).unref();
+              this.timers.setTimeout
+                .call(
+                  null,
+                  () =>
+                    reject(new MongoDBOIDCError('Opening browser timed out')),
+                  this.options.openBrowserTimeout ?? kDefaultOpenBrowserTimeout
+                )
+                ?.unref?.();
             }
           })
         );
@@ -777,6 +806,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
     };
     this.options.signal?.addEventListener('abort', optionsAbortCb);
     driverAbortSignal?.addEventListener('abort', driverAbortCb);
+    const { passIdTokenAsAccessToken } = this.options;
     const signal = combinedAbortController.signal;
 
     try {
@@ -831,7 +861,9 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
         if (error) throw error;
       }
 
-      if (!state.currentTokenSet?.set?.access_token) {
+      if (passIdTokenAsAccessToken && !state.currentTokenSet?.set?.id_token) {
+        throw new MongoDBOIDCError('Could not retrieve valid ID token');
+      } else if (!state.currentTokenSet?.set?.access_token) {
         throw new MongoDBOIDCError('Could not retrieve valid access token');
       }
     } catch (err: unknown) {
@@ -844,17 +876,24 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
       driverAbortSignal?.removeEventListener('abort', driverAbortCb);
     }
 
+    const { token_type, expires_at, access_token, id_token, refresh_token } =
+      state.currentTokenSet.set;
+
     this.logger.emit('mongodb-oidc-plugin:auth-succeeded', {
-      tokenType: state.currentTokenSet.set.token_type ?? null, // DPoP or Bearer
-      hasRefreshToken: !!state.currentTokenSet.set.refresh_token,
-      expiresAt: state.currentTokenSet.set.expires_at
-        ? new Date(state.currentTokenSet.set.expires_at * 1000).toISOString()
-        : null,
+      tokenType: token_type ?? null, // DPoP or Bearer
+      refreshToken: getRefreshTokenId(refresh_token),
+      expiresAt: expires_at ? new Date(expires_at * 1000).toISOString() : null,
+      passIdTokenAsAccessToken: !!passIdTokenAsAccessToken,
+      tokens: {
+        accessToken: access_token,
+        idToken: id_token,
+        refreshToken: refresh_token,
+      },
     });
 
     return {
-      accessToken: state.currentTokenSet.set.access_token,
-      refreshToken: state.currentTokenSet.set.refresh_token,
+      accessToken: passIdTokenAsAccessToken ? id_token || '' : access_token,
+      refreshToken: refresh_token,
       // Passing `expiresInSeconds: 0` results in the driver not caching the token.
       // We perform our own caching here inside the plugin, so interactions with the
       // cache of the driver are not really required or necessarily helpful.