Skip to content

Commit bbeed5d

Browse files
addaleaxaddaleax
authored
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
1 parent 4b1f081 commit bbeed5d

File tree

7 files changed

+188
-43
lines changed

7 files changed

+188
-43
lines changed

‎src/api.ts‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -191,6 +191,12 @@ export interface MongoDBOIDCPluginOptions {
191191
customHttpOptions?:
192192
| HttpOptions
193193
| ((url: string, options: Readonly<HttpOptions>) => HttpOptions);
194+
195+
/**
196+
* Pass ID tokens in place of access tokens. For debugging/working around
197+
* broken identity providers.
198+
*/
199+
passIdTokenAsAccessToken?: boolean;
194200
}
195201

196202
/** @public */

‎src/log-hook.ts‎

Lines changed: 47 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -140,6 +140,15 @@ export function hookLoggerToMongoLogWriter(
140140
);
141141
});
142142

143+
emitter.on('mongodb-oidc-plugin:open-browser-complete', () => {
144+
log.info(
145+
'OIDC-PLUGIN',
146+
mongoLogId(1_002_000_025),
147+
`${contextPrefix}-oidc`,
148+
'Successfully opened browser'
149+
);
150+
});
151+
143152
emitter.on('mongodb-oidc-plugin:notify-device-flow', () => {
144153
log.info(
145154
'OIDC-PLUGIN',
@@ -218,33 +227,51 @@ export function hookLoggerToMongoLogWriter(
218227
);
219228
});
220229

221-
emitter.on('mongodb-oidc-plugin:auth-succeeded', (ev) => {
230+
emitter.on(
231+
'mongodb-oidc-plugin:auth-succeeded',
232+
({ tokenType, refreshToken, expiresAt, passIdTokenAsAccessToken }) => {
233+
log.info(
234+
'OIDC-PLUGIN',
235+
mongoLogId(1_002_000_017),
236+
`${contextPrefix}-oidc`,
237+
'Authentication succeeded',
238+
{
239+
tokenType,
240+
refreshToken,
241+
expiresAt,
242+
passIdTokenAsAccessToken,
243+
}
244+
);
245+
}
246+
);
247+
248+
emitter.on('mongodb-oidc-plugin:refresh-skipped', (ev) => {
222249
log.info(
223250
'OIDC-PLUGIN',
224-
mongoLogId(1_002_000_017),
251+
mongoLogId(1_002_000_026),
225252
`${contextPrefix}-oidc`,
226-
'Authentication succeeded',
227-
{
228-
...ev,
229-
}
253+
'Token refresh attempt skipped',
254+
{ ...ev }
230255
);
231256
});
232257

233-
emitter.on('mongodb-oidc-plugin:refresh-started', () => {
258+
emitter.on('mongodb-oidc-plugin:refresh-started', (ev) => {
234259
log.info(
235260
'OIDC-PLUGIN',
236261
mongoLogId(1_002_000_018),
237262
`${contextPrefix}-oidc`,
238-
'Token refresh attempt started'
263+
'Token refresh attempt started',
264+
{ ...ev }
239265
);
240266
});
241267

242-
emitter.on('mongodb-oidc-plugin:refresh-succeeded', () => {
268+
emitter.on('mongodb-oidc-plugin:refresh-succeeded', (ev) => {
243269
log.info(
244270
'OIDC-PLUGIN',
245271
mongoLogId(1_002_000_019),
246272
`${contextPrefix}-oidc`,
247-
'Token refresh attempt succeeded'
273+
'Token refresh attempt succeeded',
274+
{ ...ev }
248275
);
249276
});
250277

@@ -297,6 +324,16 @@ export function hookLoggerToMongoLogWriter(
297324
{ url: redactUrl(ev.url) }
298325
);
299326
});
327+
328+
emitter.on('mongodb-oidc-plugin:state-updated', (ev) => {
329+
log.info(
330+
'OIDC-PLUGIN',
331+
mongoLogId(1_002_000_027),
332+
`${contextPrefix}-oidc`,
333+
'Updated internal token store state',
334+
{ ...ev }
335+
);
336+
});
300337
}
301338

302339
function redactUrl(url: string): string {

‎src/plugin.spec.ts‎

Lines changed: 35 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -168,6 +168,27 @@ describe('OIDC plugin (local OIDC provider)', function () {
168168
]);
169169
});
170170

171+
it('can optionally use id tokens instead of access tokens', async function () {
172+
pluginOptions = {
173+
...defaultOpts,
174+
allowedFlows: ['auth-code'],
175+
openBrowser: functioningAuthCodeBrowserFlow,
176+
passIdTokenAsAccessToken: true,
177+
};
178+
plugin = createMongoDBOIDCPlugin(pluginOptions);
179+
const result = await requestToken(
180+
plugin,
181+
provider.getMongodbOIDCDBInfo()
182+
);
183+
const accessTokenContents = getJWTContents(result.accessToken);
184+
expect(accessTokenContents.sub).to.equal('testuser');
185+
expect(accessTokenContents.aud).to.equal(
186+
provider.getMongodbOIDCDBInfo().clientId
187+
);
188+
expect(accessTokenContents.client_id).to.equal(undefined);
189+
verifySuccessfulAuthCodeFlowLog(await readLog());
190+
});
191+
171192
it('will refresh tokens if they are expiring', async function () {
172193
const skipAuthAttemptEvent = once(
173194
logger,
@@ -266,18 +287,22 @@ describe('OIDC plugin (local OIDC provider)', function () {
266287
provider.getMongodbOIDCDBInfo()
267288
);
268289

269-
expect(timeouts).to.have.lengthOf(1);
290+
expect(timeouts).to.have.lengthOf(2);
291+
// 0 -> browser timeout, 1 -> refresh timeout
270292
expect(timeouts[0].refed).to.equal(false);
271293
expect(timeouts[0].cleared).to.equal(false);
294+
expect(timeouts[0].timeout).to.equal(60_000);
295+
expect(timeouts[1].refed).to.equal(false);
296+
expect(timeouts[1].cleared).to.equal(false);
272297
// openid-client bases expiration time on the actual current time, so
273298
// allow for a small margin of error
274-
expect(timeouts[0].timeout).to.be.greaterThanOrEqual(9_600_000);
275-
expect(timeouts[0].timeout).to.be.lessThanOrEqual(9_800_000);
299+
expect(timeouts[1].timeout).to.be.greaterThanOrEqual(9_600_000);
300+
expect(timeouts[1].timeout).to.be.lessThanOrEqual(9_800_000);
276301
const refreshStartedEvent = once(
277302
plugin.logger,
278303
'mongodb-oidc-plugin:refresh-started'
279304
);
280-
timeouts[0].fn();
305+
timeouts[1].fn();
281306
await refreshStartedEvent;
282307
await once(plugin.logger, 'mongodb-oidc-plugin:refresh-succeeded');
283308

@@ -302,14 +327,14 @@ describe('OIDC plugin (local OIDC provider)', function () {
302327
provider.accessTokenTTLSeconds = 10000;
303328
await requestToken(plugin, provider.getMongodbOIDCDBInfo());
304329

305-
expect(timeouts).to.have.lengthOf(1);
306-
expect(timeouts[0].refed).to.equal(false);
307-
expect(timeouts[0].cleared).to.equal(false);
330+
expect(timeouts).to.have.lengthOf(2);
331+
expect(timeouts[1].refed).to.equal(false);
332+
expect(timeouts[1].cleared).to.equal(false);
308333
await plugin.destroy();
309334

310-
expect(timeouts).to.have.lengthOf(1);
311-
expect(timeouts[0].refed).to.equal(false);
312-
expect(timeouts[0].cleared).to.equal(true);
335+
expect(timeouts).to.have.lengthOf(2);
336+
expect(timeouts[1].refed).to.equal(false);
337+
expect(timeouts[1].cleared).to.equal(true);
313338
});
314339
});
315340

‎src/plugin.ts‎

Lines changed: 56 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import type {
99
import { MongoDBOIDCError } from './types';
1010
import {
1111
errorString,
12+
getRefreshTokenId,
1213
messageFromError,
1314
normalizeObject,
1415
throwIfAborted,
@@ -147,6 +148,7 @@ export function automaticRefreshTimeoutMS(
147148
}
148149

149150
const kEnableFallback = Symbol.for('@@mdb.oidcplugin.kEnableFallback');
151+
let updateIdCounter = 0;
150152

151153
function allowFallbackIfFailed<T>(promise: Promise<T>): Promise<T> {
152154
return promise.catch((err) => {
@@ -558,6 +560,9 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
558560
this.logger.emit('mongodb-oidc-plugin:missing-id-token');
559561
}
560562

563+
const refreshTokenId = getRefreshTokenId(tokenSet.refresh_token);
564+
const updateId = updateIdCounter++;
565+
561566
const timerDuration = automaticRefreshTimeoutMS(tokenSet);
562567
// Use `.call()` because in browsers, `setTimeout()` requires that it is called
563568
// without a `this` value. `.unref()` is not available in browsers either.
@@ -577,21 +582,38 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
577582
}
578583
// Only refresh this token set if it is the one currently
579584
// being used.
580-
if (state.currentTokenSet?.set !== tokenSet) return false;
585+
if (state.currentTokenSet?.set !== tokenSet) {
586+
this.logger.emit('mongodb-oidc-plugin:refresh-skipped', {
587+
triggeringUpdateId: updateId,
588+
expectedRefreshToken: refreshTokenId,
589+
actualRefreshToken: getRefreshTokenId(
590+
state.currentTokenSet?.set?.refresh_token
591+
),
592+
});
593+
return false;
594+
}
581595
try {
582-
this.logger.emit('mongodb-oidc-plugin:refresh-started');
596+
this.logger.emit('mongodb-oidc-plugin:refresh-started', {
597+
triggeringUpdateId: updateId,
598+
refreshToken: refreshTokenId,
599+
});
583600

584601
const { client } = await this.getOIDCClient(state);
585602
const refreshedTokens = await client.refresh(tokenSet);
586603
// Check again to avoid race conditions.
587604
if (state.currentTokenSet?.set === tokenSet) {
588-
this.logger.emit('mongodb-oidc-plugin:refresh-succeeded');
605+
this.logger.emit('mongodb-oidc-plugin:refresh-succeeded', {
606+
triggeringUpdateId: updateId,
607+
refreshToken: refreshTokenId,
608+
});
589609
this.updateStateWithTokenSet(state, refreshedTokens);
590610
return true;
591611
}
592612
} catch (err: unknown) {
593613
this.logger.emit('mongodb-oidc-plugin:refresh-failed', {
594614
error: errorString(err),
615+
triggeringUpdateId: updateId,
616+
refreshToken: refreshTokenId,
595617
});
596618
}
597619
return false;
@@ -602,7 +624,10 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
602624
tryRefresh,
603625
};
604626

605-
this.logger.emit('mongodb-oidc-plugin:state-updated');
627+
this.logger.emit('mongodb-oidc-plugin:state-updated', {
628+
updateId,
629+
timerDuration,
630+
});
606631
}
607632

608633
static readonly defaultRedirectURI = 'http://localhost:27097/redirect';
@@ -667,6 +692,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
667692
new Promise<never>((resolve, reject) => {
668693
this.openBrowser({ url: localUrl, signal })
669694
.then((browserHandle) => {
695+
this.logger.emit('mongodb-oidc-plugin:open-browser-complete');
670696
const extraErrorInfo = () =>
671697
browserHandle?.spawnargs
672698
? ` (${JSON.stringify(browserHandle.spawnargs)})`
@@ -697,11 +723,14 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
697723
const timeout: Promise<never> = allowFallbackIfFailed(
698724
new Promise((resolve, reject) => {
699725
if (this.options.openBrowserTimeout !== 0) {
700-
setTimeout(
701-
reject,
702-
this.options.openBrowserTimeout ?? kDefaultOpenBrowserTimeout,
703-
new MongoDBOIDCError('Opening browser timed out')
704-
).unref();
726+
this.timers.setTimeout
727+
.call(
728+
null,
729+
() =>
730+
reject(new MongoDBOIDCError('Opening browser timed out')),
731+
this.options.openBrowserTimeout ?? kDefaultOpenBrowserTimeout
732+
)
733+
?.unref?.();
705734
}
706735
})
707736
);
@@ -777,6 +806,7 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
777806
};
778807
this.options.signal?.addEventListener('abort', optionsAbortCb);
779808
driverAbortSignal?.addEventListener('abort', driverAbortCb);
809+
const { passIdTokenAsAccessToken } = this.options;
780810
const signal = combinedAbortController.signal;
781811

782812
try {
@@ -831,7 +861,9 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
831861
if (error) throw error;
832862
}
833863

834-
if (!state.currentTokenSet?.set?.access_token) {
864+
if (passIdTokenAsAccessToken && !state.currentTokenSet?.set?.id_token) {
865+
throw new MongoDBOIDCError('Could not retrieve valid ID token');
866+
} else if (!state.currentTokenSet?.set?.access_token) {
835867
throw new MongoDBOIDCError('Could not retrieve valid access token');
836868
}
837869
} catch (err: unknown) {
@@ -844,17 +876,24 @@ export class MongoDBOIDCPluginImpl implements MongoDBOIDCPlugin {
844876
driverAbortSignal?.removeEventListener('abort', driverAbortCb);
845877
}
846878

879+
const { token_type, expires_at, access_token, id_token, refresh_token } =
880+
state.currentTokenSet.set;
881+
847882
this.logger.emit('mongodb-oidc-plugin:auth-succeeded', {
848-
tokenType: state.currentTokenSet.set.token_type ?? null, // DPoP or Bearer
849-
hasRefreshToken: !!state.currentTokenSet.set.refresh_token,
850-
expiresAt: state.currentTokenSet.set.expires_at
851-
? new Date(state.currentTokenSet.set.expires_at * 1000).toISOString()
852-
: null,
883+
tokenType: token_type ?? null, // DPoP or Bearer
884+
refreshToken: getRefreshTokenId(refresh_token),
885+
expiresAt: expires_at ? new Date(expires_at * 1000).toISOString() : null,
886+
passIdTokenAsAccessToken: !!passIdTokenAsAccessToken,
887+
tokens: {
888+
accessToken: access_token,
889+
idToken: id_token,
890+
refreshToken: refresh_token,
891+
},
853892
});
854893

855894
return {
856-
accessToken: state.currentTokenSet.set.access_token,
857-
refreshToken: state.currentTokenSet.set.refresh_token,
895+
accessToken: passIdTokenAsAccessToken ? id_token || '' : access_token,
896+
refreshToken: refresh_token,
858897
// Passing `expiresInSeconds: 0` results in the driver not caching the token.
859898
// We perform our own caching here inside the plugin, so interactions with the
860899
// cache of the driver are not really required or necessarily helpful.

0 commit comments

Comments
 (0)