From 81a63f7cf1668d7cef3d41d5525da52369a92ff0 Mon Sep 17 00:00:00 2001 From: Rhys Date: Tue, 10 Jun 2025 10:35:27 -0400 Subject: [PATCH 1/2] chore(logs): add additional logging around auth updates COMPASS-9366 (#215) --- .github/workflows/nodejs.yml | 1 + src/log-hook.ts | 32 +++++++++++++++++ src/plugin.spec.ts | 40 +++++++++++++-------- src/plugin.ts | 50 +++++++++++++++++++++++++-- src/types.ts | 43 ++++++++++++++++++++--- test/log-hook-verification-helpers.ts | 8 +++++ test/oidc-test-provider.ts | 6 +++- 7 files changed, 157 insertions(+), 23 deletions(-) diff --git a/.github/workflows/nodejs.yml b/.github/workflows/nodejs.yml index 8b0a91a..ed6d790 100644 --- a/.github/workflows/nodejs.yml +++ b/.github/workflows/nodejs.yml @@ -11,6 +11,7 @@ name: CI jobs: test: name: Test + timeout-minutes: 10 strategy: fail-fast: false matrix: diff --git a/src/log-hook.ts b/src/log-hook.ts index ec53c78..e0558bc 100644 --- a/src/log-hook.ts +++ b/src/log-hook.ts @@ -242,6 +242,7 @@ export function hookLoggerToMongoLogWriter( emitter.on( 'mongodb-oidc-plugin:auth-succeeded', ({ + authStateId, tokenType, refreshToken, expiresAt, @@ -256,6 +257,7 @@ export function hookLoggerToMongoLogWriter( `${contextPrefix}-oidc`, 'Authentication succeeded', { + authStateId, tokenType, refreshToken, expiresAt, @@ -310,6 +312,36 @@ export function hookLoggerToMongoLogWriter( ); }); + emitter.on('mongodb-oidc-plugin:request-token-started', (ev) => { + log.info( + 'OIDC-PLUGIN', + mongoLogId(1_002_000_029), + `${contextPrefix}-oidc`, + 'Request token started', + { ...ev } + ); + }); + + emitter.on('mongodb-oidc-plugin:request-token-ended', (ev) => { + log.info( + 'OIDC-PLUGIN', + mongoLogId(1_002_000_030), + `${contextPrefix}-oidc`, + 'Request token finished', + { ...ev } + ); + }); + + emitter.on('mongodb-oidc-plugin:discarding-token-set', (ev) => { + log.info( + 'OIDC-PLUGIN', + mongoLogId(1_002_000_031), + `${contextPrefix}-oidc`, + 'Discarding token set', + { ...ev } + ); + }); + emitter.on('mongodb-oidc-plugin:destroyed', () => { log.info( 'OIDC-PLUGIN', diff --git a/src/plugin.spec.ts b/src/plugin.spec.ts index 9b6faf8..a35b260 100644 --- a/src/plugin.spec.ts +++ b/src/plugin.spec.ts @@ -25,7 +25,7 @@ import { import { MongoLogWriter } from 'mongodb-log-writer'; import { PassThrough } from 'stream'; import { verifySuccessfulAuthCodeFlowLog } from '../test/log-hook-verification-helpers'; -import { automaticRefreshTimeoutMS } from './plugin'; +import { automaticRefreshTimeoutMS, MongoDBOIDCPluginImpl } from './plugin'; import sinon from 'sinon'; import { publicPluginToInternalPluginMap_DoNotUseOutsideOfTests } from './api'; import type { Server as HTTPServer } from 'http'; @@ -104,6 +104,12 @@ describe('OIDC plugin (local OIDC provider)', function () { let defaultOpts: MongoDBOIDCPluginOptions; beforeEach(async function () { + let stateIdCounter = 0; + sinon.replace( + MongoDBOIDCPluginImpl, + 'createOIDCAuthStateId', + sinon.fake(() => `${stateIdCounter++}`) + ); provider = await OIDCTestProvider.create(); logger = new EventEmitter(); const logStream = new PassThrough(); @@ -136,6 +142,7 @@ describe('OIDC plugin (local OIDC provider)', function () { }); afterEach(async function () { + sinon.restore(); await provider.close(); if (originalElectronRunAsNode !== undefined) process.env.ELECTRON_RUN_AS_NODE = originalElectronRunAsNode; @@ -205,7 +212,7 @@ describe('OIDC plugin (local OIDC provider)', function () { ); expect(result1).to.deep.equal(result2); expect(await skipAuthAttemptEvent).to.deep.equal([ - { reason: 'not-expired' }, + { reason: 'not-expired', authStateId: '0' }, ]); }); @@ -249,7 +256,7 @@ describe('OIDC plugin (local OIDC provider)', function () { getJWTContents(result2.accessToken).sub ); expect(await skipAuthAttemptEvent).to.deep.equal([ - { reason: 'refresh-succeeded' }, + { authStateId: '0', reason: 'refresh-succeeded' }, ]); }); @@ -274,9 +281,9 @@ describe('OIDC plugin (local OIDC provider)', function () { expect(getJWTContents(result1.accessToken).sub).to.equal( getJWTContents(result2.accessToken).sub ); - expect(startedAuthAttempts).to.deep.equal([ - { flow: 'auth-code' }, - { flow: 'auth-code' }, + expect(startedAuthAttempts as { authStateId: string }[]).to.deep.equal([ + { authStateId: '0', flow: 'auth-code' }, + { authStateId: '0', flow: 'auth-code' }, ]); }); @@ -360,7 +367,9 @@ describe('OIDC plugin (local OIDC provider)', function () { getJWTContents(result2.accessToken).sub ); - expect(await skipEvent).to.deep.equal([{ reason: 'not-expired' }]); + expect(await skipEvent).to.deep.equal([ + { reason: 'not-expired', authStateId: '0' }, + ]); }); it('clears token refresh timers on destroy', async function () { @@ -393,6 +402,7 @@ describe('OIDC plugin (local OIDC provider)', function () { expect(Object.keys(serializedData.state[0][1]).sort()).to.deep.equal([ 'currentTokenSet', 'discardingTokenSets', + 'id', 'lastIdTokenClaims', 'serverOIDCMetadata', ]); @@ -428,7 +438,7 @@ describe('OIDC plugin (local OIDC provider)', function () { ); expect(result1).to.deep.equal(result2); expect(await skipAuthAttemptEvent).to.deep.equal([ - { reason: 'not-expired' }, + { reason: 'not-expired', authStateId: '0' }, ]); }); @@ -455,7 +465,7 @@ describe('OIDC plugin (local OIDC provider)', function () { getJWTContents(result2.accessToken).sub ); expect(await skipAuthAttemptEvent).to.deep.equal([ - { reason: 'refresh-succeeded' }, + { reason: 'refresh-succeeded', authStateId: '0' }, ]); }); @@ -519,7 +529,7 @@ describe('OIDC plugin (local OIDC provider)', function () { await requestToken(plugin, provider.getMongodbOIDCDBInfo()); await requestToken(plugin, provider.getMongodbOIDCDBInfo()); expect(await skipAuthAttemptEvent).to.deep.equal([ - { reason: 'refresh-succeeded' }, + { reason: 'refresh-succeeded', authStateId: '0' }, ]); expect(pluginOptions.allowedFlows).to.have.been.calledOnce; }); @@ -535,9 +545,9 @@ describe('OIDC plugin (local OIDC provider)', function () { await requestToken(plugin, provider.getMongodbOIDCDBInfo()); await delay(1000); await requestToken(plugin, provider.getMongodbOIDCDBInfo()); - expect(startedAuthAttempts).to.deep.equal([ - { flow: 'auth-code' }, - { flow: 'auth-code' }, + expect(startedAuthAttempts as { authStateId: string }[]).to.deep.equal([ + { flow: 'auth-code', authStateId: '0' }, + { flow: 'auth-code', authStateId: '0' }, ]); expect(pluginOptions.allowedFlows).to.have.been.calledTwice; }); @@ -682,14 +692,14 @@ describe('OIDC plugin (local OIDC provider)', function () { await requestToken(plugin, provider.getMongodbOIDCDBInfo()); expect(events).to.deep.include([ 'mongodb-oidc-plugin:auth-attempt-started', - { flow: 'auth-code' }, + { flow: 'auth-code', authStateId: '0' }, ]); expect(events.map((e) => e[0])).to.include( 'mongodb-oidc-plugin:auth-attempt-failed' ); expect(events).to.deep.include([ 'mongodb-oidc-plugin:auth-attempt-started', - { flow: 'device-auth' }, + { flow: 'device-auth', authStateId: '0' }, ]); expect(events.map((e) => e[0])).to.include( 'mongodb-oidc-plugin:auth-attempt-succeeded' diff --git a/src/plugin.ts b/src/plugin.ts index 5877543..3f43111 100644 --- a/src/plugin.ts +++ b/src/plugin.ts @@ -51,6 +51,9 @@ type LastIdTokenClaims = | { noIdToken: true }; interface UserOIDCAuthState { + // The ID for this state. This is useful for tracing in + // debugging and logs purposes. + id: string; // The information that the driver forwarded to us from the server // about the OIDC Identity Provider config. serverOIDCMetadata: IdPServerInfo & Pick; @@ -180,6 +183,7 @@ export function automaticRefreshTimeoutMS( const kEnableFallback = Symbol.for('@@mdb.oidcplugin.kEnableFallback'); let updateIdCounter = 0; +let authStateIdCounter = 0; function allowFallbackIfFailed(promise: Promise): Promise { return promise.catch((err) => { @@ -219,6 +223,13 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { } } + /** @internal Public for testing only. */ + public static createOIDCAuthStateId(): string { + // Use an ID for the OIDC auth state, so that we can distinguish + // between different auth states in logs. + return `${Date.now().toString(32)}-${authStateIdCounter++}`; + } + private _deserialize(serialized: string) { try { let original: ReturnType; @@ -244,6 +255,8 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { for (const [key, serializedState] of original.state) { const state: UserOIDCAuthState = { + id: + serializedState.id ?? MongoDBOIDCPluginImpl.createOIDCAuthStateId(), serverOIDCMetadata: { ...serializedState.serverOIDCMetadata }, currentAuthAttempt: null, currentTokenSet: null, @@ -279,6 +292,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { return [ key, { + id: state.id, serverOIDCMetadata: { ...state.serverOIDCMetadata }, currentTokenSet: { set: { ...state.currentTokenSet?.set }, @@ -344,6 +358,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { if (existing) return existing; const newState: UserOIDCAuthState = { serverOIDCMetadata: serverMetadata, + id: MongoDBOIDCPluginImpl.createOIDCAuthStateId(), currentAuthAttempt: null, currentTokenSet: null, }; @@ -866,12 +881,14 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { 5 * 60 ) { this.logger.emit('mongodb-oidc-plugin:skip-auth-attempt', { + authStateId: state.id, reason: 'not-expired', }); break get_tokens; } if (await state.currentTokenSet?.tryRefresh?.()) { this.logger.emit('mongodb-oidc-plugin:skip-auth-attempt', { + authStateId: state.id, reason: 'refresh-succeeded', }); break get_tokens; @@ -882,14 +899,18 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { if (currentAllowedFlowSet.includes('auth-code')) { try { this.logger.emit('mongodb-oidc-plugin:auth-attempt-started', { + authStateId: state.id, flow: 'auth-code', }); await this.authorizationCodeFlow(state, signal); - this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded'); + this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded', { + authStateId: state.id, + }); break get_tokens; } catch (err: unknown) { error = err; this.logger.emit('mongodb-oidc-plugin:auth-attempt-failed', { + authStateId: state.id, error: errorString(err), }); // eslint-disable-next-line @typescript-eslint/no-explicit-any @@ -899,13 +920,17 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { if (currentAllowedFlowSet.includes('device-auth')) { try { this.logger.emit('mongodb-oidc-plugin:auth-attempt-started', { + authStateId: state.id, flow: 'device-auth', }); await this.deviceAuthorizationFlow(state, signal); - this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded'); + this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded', { + authStateId: state.id, + }); break get_tokens; } catch (err: unknown) { this.logger.emit('mongodb-oidc-plugin:auth-attempt-failed', { + authStateId: state.id, error: errorString(err), }); throw err; @@ -921,6 +946,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { } } catch (err: unknown) { this.logger.emit('mongodb-oidc-plugin:auth-failed', { + authStateId: state.id, error: errorString(err), }); throw err; @@ -940,6 +966,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { !!state.discardingTokenSets?.includes(tokenSetId); this.logger.emit('mongodb-oidc-plugin:auth-succeeded', { + authStateId: state.id, tokenType: token_type ?? null, // DPoP or Bearer refreshToken: getRefreshTokenId(refresh_token), expiresAt: expires_at ? new Date(expires_at * 1000).toISOString() : null, @@ -1001,6 +1028,16 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { username: params.username, }); + this.logger.emit('mongodb-oidc-plugin:request-token-started', { + authStateId: state.id, + isCurrentAuthAttemptSet: !!state.currentAuthAttempt, + tokenSetId: params.refreshToken, + username: state.serverOIDCMetadata.username, + issuer: state.serverOIDCMetadata.issuer, + clientId: state.serverOIDCMetadata.clientId, + requestScopes: state.serverOIDCMetadata.requestScopes, + }); + // If the driver called us with a refresh token, that means that its corresponding // access token has become invalid and we should always return a new one. if (params.refreshToken) { @@ -1027,6 +1064,15 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin { state.currentAuthAttempt = null; } } finally { + this.logger.emit('mongodb-oidc-plugin:request-token-ended', { + authStateId: state.id, + isCurrentAuthAttemptSet: !!state.currentAuthAttempt, + tokenSetId: params.refreshToken, + username: state.serverOIDCMetadata.username, + issuer: state.serverOIDCMetadata.issuer, + clientId: state.serverOIDCMetadata.clientId, + requestScopes: state.serverOIDCMetadata.requestScopes, + }); if (params.refreshToken) { const index = state.discardingTokenSets?.indexOf(params.refreshToken) ?? -1; diff --git a/src/types.ts b/src/types.ts index 7ad6715..861241b 100644 --- a/src/types.ts +++ b/src/types.ts @@ -50,9 +50,17 @@ export interface MongoDBOIDCLogEventsMap { }) => void; 'mongodb-oidc-plugin:open-browser-complete': () => void; 'mongodb-oidc-plugin:notify-device-flow': () => void; - 'mongodb-oidc-plugin:auth-attempt-started': (event: { flow: string }) => void; - 'mongodb-oidc-plugin:auth-attempt-succeeded': () => void; - 'mongodb-oidc-plugin:auth-attempt-failed': (event: { error: string }) => void; + 'mongodb-oidc-plugin:auth-attempt-started': (event: { + authStateId: string; + flow: string; + }) => void; + 'mongodb-oidc-plugin:auth-attempt-succeeded': (event: { + authStateId: string; + }) => void; + 'mongodb-oidc-plugin:auth-attempt-failed': (event: { + authStateId: string; + error: string; + }) => void; 'mongodb-oidc-plugin:refresh-skipped': (event: { triggeringUpdateId: number; expectedRefreshToken: string | null; @@ -71,9 +79,16 @@ export interface MongoDBOIDCLogEventsMap { triggeringUpdateId: number; refreshToken: string | null; }) => void; - 'mongodb-oidc-plugin:skip-auth-attempt': (event: { reason: string }) => void; - 'mongodb-oidc-plugin:auth-failed': (event: { error: string }) => void; + 'mongodb-oidc-plugin:skip-auth-attempt': (event: { + authStateId: string; + reason: string; + }) => void; + 'mongodb-oidc-plugin:auth-failed': (event: { + authStateId: string; + error: string; + }) => void; 'mongodb-oidc-plugin:auth-succeeded': (event: { + authStateId: string; tokenType: string | null; refreshToken: string | null; expiresAt: string | null; @@ -87,6 +102,24 @@ export interface MongoDBOIDCLogEventsMap { willRetryWithForceRefreshOrReauth: boolean; tokenSetId: string; }) => void; + 'mongodb-oidc-plugin:request-token-started': (event: { + authStateId: string; + isCurrentAuthAttemptSet: boolean; + tokenSetId: string | undefined; + username: string | undefined; + issuer: string; + clientId: string; + requestScopes: string[] | undefined; + }) => void; + 'mongodb-oidc-plugin:request-token-ended': (event: { + authStateId: string; + isCurrentAuthAttemptSet: boolean; + tokenSetId: string | undefined; + username: string | undefined; + issuer: string; + clientId: string; + requestScopes: string[] | undefined; + }) => void; 'mongodb-oidc-plugin:discarding-token-set': (event: { tokenSetId: string; }) => void; diff --git a/test/log-hook-verification-helpers.ts b/test/log-hook-verification-helpers.ts index add2ece..10901ff 100644 --- a/test/log-hook-verification-helpers.ts +++ b/test/log-hook-verification-helpers.ts @@ -122,6 +122,14 @@ export function verifySuccessfulAuthCodeFlowLog(entries: any[]): void { if (typeof expectedAttr === 'function') { // eslint-disable-next-line @typescript-eslint/no-unsafe-argument expectedAttr(foundAttr); + } else if (foundAttr) { + const { + // Omit the authStateId from the expected attributes as its conditional. + // eslint-disable-next-line @typescript-eslint/no-unused-vars + authStateId, + ...foundAttrWithoutAuthStateId + } = foundAttr; + expect(foundAttrWithoutAuthStateId).to.deep.equal(expectedAttr); } else { expect(foundAttr).to.deep.equal(expectedAttr); } diff --git a/test/oidc-test-provider.ts b/test/oidc-test-provider.ts index 293f312..e421d94 100644 --- a/test/oidc-test-provider.ts +++ b/test/oidc-test-provider.ts @@ -227,7 +227,11 @@ async function spawnBrowser( ...options.capabilities, 'goog:chromeOptions': { binary: electronPath, - args: [`--app=${url}`, '--'], + args: [`--app=${url}`, '--disable-save-password-bubble', '--'], + prefs: { + 'profile.password_manager_enabled': false, + credentials_enable_service: false, + }, }, }, }); From 2d9074bd00287d8c5277835476031f8c5db56c82 Mon Sep 17 00:00:00 2001 From: "mongodb-devtools-bot[bot]" <189715634+mongodb-devtools-bot[bot]@users.noreply.github.com> Date: Mon, 16 Jun 2025 12:10:51 +0000 Subject: [PATCH 2/2] chore: bump version to v1.1.8 (#217) Co-authored-by: addaleax <899444+addaleax@users.noreply.github.com> --- package-lock.json | 4 ++-- package.json | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/package-lock.json b/package-lock.json index 8f4a7bf..62da3b8 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "@mongodb-js/oidc-plugin", - "version": "1.1.7", + "version": "1.1.8", "lockfileVersion": 2, "requires": true, "packages": { "": { "name": "@mongodb-js/oidc-plugin", - "version": "1.1.7", + "version": "1.1.8", "license": "Apache-2.0", "dependencies": { "express": "^4.18.2", diff --git a/package.json b/package.json index e099743..20ac61b 100644 --- a/package.json +++ b/package.json @@ -13,7 +13,7 @@ "email": "compass@mongodb.com" }, "homepage": "https://github.com/mongodb-js/oidc-plugin", - "version": "1.1.7", + "version": "1.1.8", "repository": { "type": "git", "url": "https://github.com/mongodb-js/oidc-plugin.git"