Skip to content

chore(logs): add additional logging around auth updates COMPASS-9366 #215

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 8 commits into from
Jun 10, 2025
Merged

chore(logs): add additional logging around auth updates COMPASS-9366 #215

Show file tree
Hide file tree
Changes from 7 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
ed7bf9b
chore(logs): add additional logging around auth updates
Anemy Jun 3, 2025
d812d72
fixup: remove unrelated change
Anemy Jun 3, 2025
7c9a93e
fixup: update comments and tests
Anemy Jun 4, 2025
4422a6c
fixup: integration test ids
Anemy Jun 4, 2025
07a74ef
fixup: use the actual variable name
Anemy Jun 4, 2025
aafe5bc
fixup: add method to class for stubbing in tests
Anemy Jun 5, 2025
9d6f9e2
fixup: tests
Anemy Jun 5, 2025
af57ffb
fixup: add fields of serverOIDCMetadata to the request token logs
Anemy Jun 9, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions .github/workflows/nodejs.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ name: CI
jobs:
test:
name: Test
timeout-minutes: 10
strategy:
fail-fast: false
matrix:
Expand Down
32 changes: 32 additions & 0 deletions src/log-hook.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -242,6 +242,7 @@ export function hookLoggerToMongoLogWriter(
emitter.on(
'mongodb-oidc-plugin:auth-succeeded',
({
authStateId,
tokenType,
refreshToken,
expiresAt,
Expand All @@ -256,6 +257,7 @@ export function hookLoggerToMongoLogWriter(
`${contextPrefix}-oidc`,
'Authentication succeeded',
{
authStateId,
tokenType,
refreshToken,
expiresAt,
Expand Down Expand Up @@ -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',
Expand Down
40 changes: 25 additions & 15 deletions src/plugin.spec.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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' },
]);
});

Expand Down Expand Up @@ -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' },
]);
});

Expand All @@ -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' },
]);
});

Expand Down Expand Up @@ -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 () {
Expand Down Expand Up @@ -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',
]);
Expand Down Expand Up @@ -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' },
]);
});

Expand All @@ -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' },
]);
});

Expand Down Expand Up @@ -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;
});
Expand All @@ -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;
});
Expand Down Expand Up @@ -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'
Expand Down
42 changes: 40 additions & 2 deletions src/plugin.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<OIDCCallbackParams, 'username'>;
Expand Down Expand Up @@ -180,6 +183,7 @@ export function automaticRefreshTimeoutMS(

const kEnableFallback = Symbol.for('@@mdb.oidcplugin.kEnableFallback');
let updateIdCounter = 0;
let authStateIdCounter = 0;

function allowFallbackIfFailed<T>(promise: Promise<T>): Promise<T> {
return promise.catch((err) => {
Expand Down Expand Up @@ -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<typeof this._serialize>;
Expand All @@ -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,
Expand Down Expand Up @@ -279,6 +292,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
return [
key,
{
id: state.id,
serverOIDCMetadata: { ...state.serverOIDCMetadata },
currentTokenSet: {
set: { ...state.currentTokenSet?.set },
Expand Down Expand Up @@ -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,
};
Expand Down Expand Up @@ -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;
Expand All @@ -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
Expand All @@ -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;
Expand All @@ -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;
Expand All @@ -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,
Expand Down Expand Up @@ -1001,6 +1028,12 @@ 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,
});
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fwiw I still think this would be useful:

Log when we enter/leave requestToken(), and in particular log whether state.currentAuthAttempt is set or not. Include the UserOIDCAuthState id as well, and the values of the known fields of serverOIDCMetadata.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pushed a commit adding the values of the serverOIDCMetadata fields to this started and ended log.


// 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) {
Expand All @@ -1027,6 +1060,11 @@ 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,
});
if (params.refreshToken) {
const index =
state.discardingTokenSets?.indexOf(params.refreshToken) ?? -1;
Expand Down
Loading
Loading