Skip to content

Commit 81a63f7

Browse files
AnemyAnemy
authored
chore(logs): add additional logging around auth updates COMPASS-9366 (#215)
1 parent 2dafeb4 commit 81a63f7

File tree

7 files changed

+157
-23
lines changed

7 files changed

+157
-23
lines changed

‎.github/workflows/nodejs.yml‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ name: CI
1111
jobs:
1212
test:
1313
name: Test
14+
timeout-minutes: 10
1415
strategy:
1516
fail-fast: false
1617
matrix:

‎src/log-hook.ts‎

Lines changed: 32 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -242,6 +242,7 @@ export function hookLoggerToMongoLogWriter(
242242
emitter.on(
243243
'mongodb-oidc-plugin:auth-succeeded',
244244
({
245+
authStateId,
245246
tokenType,
246247
refreshToken,
247248
expiresAt,
@@ -256,6 +257,7 @@ export function hookLoggerToMongoLogWriter(
256257
`${contextPrefix}-oidc`,
257258
'Authentication succeeded',
258259
{
260+
authStateId,
259261
tokenType,
260262
refreshToken,
261263
expiresAt,
@@ -310,6 +312,36 @@ export function hookLoggerToMongoLogWriter(
310312
);
311313
});
312314

315+
emitter.on('mongodb-oidc-plugin:request-token-started', (ev) => {
316+
log.info(
317+
'OIDC-PLUGIN',
318+
mongoLogId(1_002_000_029),
319+
`${contextPrefix}-oidc`,
320+
'Request token started',
321+
{ ...ev }
322+
);
323+
});
324+
325+
emitter.on('mongodb-oidc-plugin:request-token-ended', (ev) => {
326+
log.info(
327+
'OIDC-PLUGIN',
328+
mongoLogId(1_002_000_030),
329+
`${contextPrefix}-oidc`,
330+
'Request token finished',
331+
{ ...ev }
332+
);
333+
});
334+
335+
emitter.on('mongodb-oidc-plugin:discarding-token-set', (ev) => {
336+
log.info(
337+
'OIDC-PLUGIN',
338+
mongoLogId(1_002_000_031),
339+
`${contextPrefix}-oidc`,
340+
'Discarding token set',
341+
{ ...ev }
342+
);
343+
});
344+
313345
emitter.on('mongodb-oidc-plugin:destroyed', () => {
314346
log.info(
315347
'OIDC-PLUGIN',

‎src/plugin.spec.ts‎

Lines changed: 25 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@ import {
2525
import { MongoLogWriter } from 'mongodb-log-writer';
2626
import { PassThrough } from 'stream';
2727
import { verifySuccessfulAuthCodeFlowLog } from '../test/log-hook-verification-helpers';
28-
import { automaticRefreshTimeoutMS } from './plugin';
28+
import { automaticRefreshTimeoutMS, MongoDBOIDCPluginImpl } from './plugin';
2929
import sinon from 'sinon';
3030
import { publicPluginToInternalPluginMap_DoNotUseOutsideOfTests } from './api';
3131
import type { Server as HTTPServer } from 'http';
@@ -104,6 +104,12 @@ describe('OIDC plugin (local OIDC provider)', function () {
104104
let defaultOpts: MongoDBOIDCPluginOptions;
105105

106106
beforeEach(async function () {
107+
let stateIdCounter = 0;
108+
sinon.replace(
109+
MongoDBOIDCPluginImpl,
110+
'createOIDCAuthStateId',
111+
sinon.fake(() => `${stateIdCounter++}`)
112+
);
107113
provider = await OIDCTestProvider.create();
108114
logger = new EventEmitter();
109115
const logStream = new PassThrough();
@@ -136,6 +142,7 @@ describe('OIDC plugin (local OIDC provider)', function () {
136142
});
137143

138144
afterEach(async function () {
145+
sinon.restore();
139146
await provider.close();
140147
if (originalElectronRunAsNode !== undefined)
141148
process.env.ELECTRON_RUN_AS_NODE = originalElectronRunAsNode;
@@ -205,7 +212,7 @@ describe('OIDC plugin (local OIDC provider)', function () {
205212
);
206213
expect(result1).to.deep.equal(result2);
207214
expect(await skipAuthAttemptEvent).to.deep.equal([
208-
{ reason: 'not-expired' },
215+
{ reason: 'not-expired', authStateId: '0' },
209216
]);
210217
});
211218

@@ -249,7 +256,7 @@ describe('OIDC plugin (local OIDC provider)', function () {
249256
getJWTContents(result2.accessToken).sub
250257
);
251258
expect(await skipAuthAttemptEvent).to.deep.equal([
252-
{ reason: 'refresh-succeeded' },
259+
{ authStateId: '0', reason: 'refresh-succeeded' },
253260
]);
254261
});
255262

@@ -274,9 +281,9 @@ describe('OIDC plugin (local OIDC provider)', function () {
274281
expect(getJWTContents(result1.accessToken).sub).to.equal(
275282
getJWTContents(result2.accessToken).sub
276283
);
277-
expect(startedAuthAttempts).to.deep.equal([
278-
{ flow: 'auth-code' },
279-
{ flow: 'auth-code' },
284+
expect(startedAuthAttempts as { authStateId: string }[]).to.deep.equal([
285+
{ authStateId: '0', flow: 'auth-code' },
286+
{ authStateId: '0', flow: 'auth-code' },
280287
]);
281288
});
282289

@@ -360,7 +367,9 @@ describe('OIDC plugin (local OIDC provider)', function () {
360367
getJWTContents(result2.accessToken).sub
361368
);
362369

363-
expect(await skipEvent).to.deep.equal([{ reason: 'not-expired' }]);
370+
expect(await skipEvent).to.deep.equal([
371+
{ reason: 'not-expired', authStateId: '0' },
372+
]);
364373
});
365374

366375
it('clears token refresh timers on destroy', async function () {
@@ -393,6 +402,7 @@ describe('OIDC plugin (local OIDC provider)', function () {
393402
expect(Object.keys(serializedData.state[0][1]).sort()).to.deep.equal([
394403
'currentTokenSet',
395404
'discardingTokenSets',
405+
'id',
396406
'lastIdTokenClaims',
397407
'serverOIDCMetadata',
398408
]);
@@ -428,7 +438,7 @@ describe('OIDC plugin (local OIDC provider)', function () {
428438
);
429439
expect(result1).to.deep.equal(result2);
430440
expect(await skipAuthAttemptEvent).to.deep.equal([
431-
{ reason: 'not-expired' },
441+
{ reason: 'not-expired', authStateId: '0' },
432442
]);
433443
});
434444

@@ -455,7 +465,7 @@ describe('OIDC plugin (local OIDC provider)', function () {
455465
getJWTContents(result2.accessToken).sub
456466
);
457467
expect(await skipAuthAttemptEvent).to.deep.equal([
458-
{ reason: 'refresh-succeeded' },
468+
{ reason: 'refresh-succeeded', authStateId: '0' },
459469
]);
460470
});
461471

@@ -519,7 +529,7 @@ describe('OIDC plugin (local OIDC provider)', function () {
519529
await requestToken(plugin, provider.getMongodbOIDCDBInfo());
520530
await requestToken(plugin, provider.getMongodbOIDCDBInfo());
521531
expect(await skipAuthAttemptEvent).to.deep.equal([
522-
{ reason: 'refresh-succeeded' },
532+
{ reason: 'refresh-succeeded', authStateId: '0' },
523533
]);
524534
expect(pluginOptions.allowedFlows).to.have.been.calledOnce;
525535
});
@@ -535,9 +545,9 @@ describe('OIDC plugin (local OIDC provider)', function () {
535545
await requestToken(plugin, provider.getMongodbOIDCDBInfo());
536546
await delay(1000);
537547
await requestToken(plugin, provider.getMongodbOIDCDBInfo());
538-
expect(startedAuthAttempts).to.deep.equal([
539-
{ flow: 'auth-code' },
540-
{ flow: 'auth-code' },
548+
expect(startedAuthAttempts as { authStateId: string }[]).to.deep.equal([
549+
{ flow: 'auth-code', authStateId: '0' },
550+
{ flow: 'auth-code', authStateId: '0' },
541551
]);
542552
expect(pluginOptions.allowedFlows).to.have.been.calledTwice;
543553
});
@@ -682,14 +692,14 @@ describe('OIDC plugin (local OIDC provider)', function () {
682692
await requestToken(plugin, provider.getMongodbOIDCDBInfo());
683693
expect(events).to.deep.include([
684694
'mongodb-oidc-plugin:auth-attempt-started',
685-
{ flow: 'auth-code' },
695+
{ flow: 'auth-code', authStateId: '0' },
686696
]);
687697
expect(events.map((e) => e[0])).to.include(
688698
'mongodb-oidc-plugin:auth-attempt-failed'
689699
);
690700
expect(events).to.deep.include([
691701
'mongodb-oidc-plugin:auth-attempt-started',
692-
{ flow: 'device-auth' },
702+
{ flow: 'device-auth', authStateId: '0' },
693703
]);
694704
expect(events.map((e) => e[0])).to.include(
695705
'mongodb-oidc-plugin:auth-attempt-succeeded'

‎src/plugin.ts‎

Lines changed: 48 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,9 @@ type LastIdTokenClaims =
5151
| { noIdToken: true };
5252

5353
interface UserOIDCAuthState {
54+
// The ID for this state. This is useful for tracing in
55+
// debugging and logs purposes.
56+
id: string;
5457
// The information that the driver forwarded to us from the server
5558
// about the OIDC Identity Provider config.
5659
serverOIDCMetadata: IdPServerInfo & Pick<OIDCCallbackParams, 'username'>;
@@ -180,6 +183,7 @@ export function automaticRefreshTimeoutMS(
180183

181184
const kEnableFallback = Symbol.for('@@mdb.oidcplugin.kEnableFallback');
182185
let updateIdCounter = 0;
186+
let authStateIdCounter = 0;
183187

184188
function allowFallbackIfFailed<T>(promise: Promise<T>): Promise<T> {
185189
return promise.catch((err) => {
@@ -219,6 +223,13 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
219223
}
220224
}
221225

226+
/** @internal Public for testing only. */
227+
public static createOIDCAuthStateId(): string {
228+
// Use an ID for the OIDC auth state, so that we can distinguish
229+
// between different auth states in logs.
230+
return `${Date.now().toString(32)}-${authStateIdCounter++}`;
231+
}
232+
222233
private _deserialize(serialized: string) {
223234
try {
224235
let original: ReturnType<typeof this._serialize>;
@@ -244,6 +255,8 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
244255

245256
for (const [key, serializedState] of original.state) {
246257
const state: UserOIDCAuthState = {
258+
id:
259+
serializedState.id ?? MongoDBOIDCPluginImpl.createOIDCAuthStateId(),
247260
serverOIDCMetadata: { ...serializedState.serverOIDCMetadata },
248261
currentAuthAttempt: null,
249262
currentTokenSet: null,
@@ -279,6 +292,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
279292
return [
280293
key,
281294
{
295+
id: state.id,
282296
serverOIDCMetadata: { ...state.serverOIDCMetadata },
283297
currentTokenSet: {
284298
set: { ...state.currentTokenSet?.set },
@@ -344,6 +358,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
344358
if (existing) return existing;
345359
const newState: UserOIDCAuthState = {
346360
serverOIDCMetadata: serverMetadata,
361+
id: MongoDBOIDCPluginImpl.createOIDCAuthStateId(),
347362
currentAuthAttempt: null,
348363
currentTokenSet: null,
349364
};
@@ -866,12 +881,14 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
866881
5 * 60
867882
) {
868883
this.logger.emit('mongodb-oidc-plugin:skip-auth-attempt', {
884+
authStateId: state.id,
869885
reason: 'not-expired',
870886
});
871887
break get_tokens;
872888
}
873889
if (await state.currentTokenSet?.tryRefresh?.()) {
874890
this.logger.emit('mongodb-oidc-plugin:skip-auth-attempt', {
891+
authStateId: state.id,
875892
reason: 'refresh-succeeded',
876893
});
877894
break get_tokens;
@@ -882,14 +899,18 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
882899
if (currentAllowedFlowSet.includes('auth-code')) {
883900
try {
884901
this.logger.emit('mongodb-oidc-plugin:auth-attempt-started', {
902+
authStateId: state.id,
885903
flow: 'auth-code',
886904
});
887905
await this.authorizationCodeFlow(state, signal);
888-
this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded');
906+
this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded', {
907+
authStateId: state.id,
908+
});
889909
break get_tokens;
890910
} catch (err: unknown) {
891911
error = err;
892912
this.logger.emit('mongodb-oidc-plugin:auth-attempt-failed', {
913+
authStateId: state.id,
893914
error: errorString(err),
894915
});
895916
// eslint-disable-next-line @typescript-eslint/no-explicit-any
@@ -899,13 +920,17 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
899920
if (currentAllowedFlowSet.includes('device-auth')) {
900921
try {
901922
this.logger.emit('mongodb-oidc-plugin:auth-attempt-started', {
923+
authStateId: state.id,
902924
flow: 'device-auth',
903925
});
904926
await this.deviceAuthorizationFlow(state, signal);
905-
this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded');
927+
this.logger.emit('mongodb-oidc-plugin:auth-attempt-succeeded', {
928+
authStateId: state.id,
929+
});
906930
break get_tokens;
907931
} catch (err: unknown) {
908932
this.logger.emit('mongodb-oidc-plugin:auth-attempt-failed', {
933+
authStateId: state.id,
909934
error: errorString(err),
910935
});
911936
throw err;
@@ -921,6 +946,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
921946
}
922947
} catch (err: unknown) {
923948
this.logger.emit('mongodb-oidc-plugin:auth-failed', {
949+
authStateId: state.id,
924950
error: errorString(err),
925951
});
926952
throw err;
@@ -940,6 +966,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
940966
!!state.discardingTokenSets?.includes(tokenSetId);
941967

942968
this.logger.emit('mongodb-oidc-plugin:auth-succeeded', {
969+
authStateId: state.id,
943970
tokenType: token_type ?? null, // DPoP or Bearer
944971
refreshToken: getRefreshTokenId(refresh_token),
945972
expiresAt: expires_at ? new Date(expires_at * 1000).toISOString() : null,
@@ -1001,6 +1028,16 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
10011028
username: params.username,
10021029
});
10031030

1031+
this.logger.emit('mongodb-oidc-plugin:request-token-started', {
1032+
authStateId: state.id,
1033+
isCurrentAuthAttemptSet: !!state.currentAuthAttempt,
1034+
tokenSetId: params.refreshToken,
1035+
username: state.serverOIDCMetadata.username,
1036+
issuer: state.serverOIDCMetadata.issuer,
1037+
clientId: state.serverOIDCMetadata.clientId,
1038+
requestScopes: state.serverOIDCMetadata.requestScopes,
1039+
});
1040+
10041041
// If the driver called us with a refresh token, that means that its corresponding
10051042
// access token has become invalid and we should always return a new one.
10061043
if (params.refreshToken) {
@@ -1027,6 +1064,15 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
10271064
state.currentAuthAttempt = null;
10281065
}
10291066
} finally {
1067+
this.logger.emit('mongodb-oidc-plugin:request-token-ended', {
1068+
authStateId: state.id,
1069+
isCurrentAuthAttemptSet: !!state.currentAuthAttempt,
1070+
tokenSetId: params.refreshToken,
1071+
username: state.serverOIDCMetadata.username,
1072+
issuer: state.serverOIDCMetadata.issuer,
1073+
clientId: state.serverOIDCMetadata.clientId,
1074+
requestScopes: state.serverOIDCMetadata.requestScopes,
1075+
});
10301076
if (params.refreshToken) {
10311077
const index =
10321078
state.discardingTokenSets?.indexOf(params.refreshToken) ?? -1;

0 commit comments

Comments
 (0)