Fix cookie redaction in logs (#17914)

* removed incorrect redaction logic

* updated paths that werent working

* Added new redaction function

* Reverting unintentional change

* don't force lowercase provider names

* extracted cookieNames

* set cookie based on driver settings suggested by ian

* add unit test

* redact the entire cookie header

* updated the tests

* move redact text to constants

---------

Co-authored-by: Azri Kahar <42867097+azrikahar@users.noreply.github.com>
Co-authored-by: Rijk van Zanten <rijkvanzanten@me.com>

api/src/constants.ts

@@ -62,3 +62,5 @@ export const COOKIE_OPTIONS: CookieOptions = {
 };
 
 export const OAS_REQUIRED_SCHEMAS = ['Diff', 'Schema', 'Query', 'x-metadata'];
+
+export const REDACT_TEXT = '--redact--';

api/src/logger.test.ts

@@ -0,0 +1,140 @@
+import { afterEach, beforeEach, describe, expect, test, vi } from 'vitest';
+
+const REFRESH_TOKEN_COOKIE_NAME = 'directus_refresh_token';
+
+vi.mock('./env', async () => {
+	const MOCK_ENV = {
+		AUTH_PROVIDERS: 'ranger,monospace',
+		AUTH_RANGER_DRIVER: 'oauth2',
+		AUTH_MONOSPACE_DRIVER: 'openid',
+		REFRESH_TOKEN_COOKIE_NAME,
+		LOG_LEVEL: 'info',
+		LOG_STYLE: 'raw',
+	};
+	return {
+		default: MOCK_ENV,
+		getEnv: () => MOCK_ENV,
+	};
+});
+
+import { Writable } from 'node:stream';
+import pino from 'pino';
+import { REDACT_TEXT } from './constants';
+import { httpLoggerOptions } from './logger';
+
+const logOutput = vi.fn();
+
+let stream: Writable;
+
+beforeEach(() => {
+	stream = new Writable({
+		write(chunk) {
+			logOutput(JSON.parse(chunk.toString()));
+		},
+	});
+});
+
+afterEach(() => {
+	vi.clearAllMocks();
+});
+
+describe('req.headers.authorization', () => {
+	test('Should redact bearer token in Authorization header', () => {
+		const instance = pino(httpLoggerOptions, stream);
+		instance.info({
+			req: {
+				headers: {
+					authorization: `Bearer test-access-token-value`,
+				},
+			},
+		});
+		expect(logOutput.mock.calls[0][0]).toMatchObject({
+			req: {
+				headers: {
+					authorization: REDACT_TEXT,
+				},
+			},
+		});
+	});
+});
+
+describe('req.headers.cookie', () => {
+	test('Should redact refresh token when there is only one entry', () => {
+		const instance = pino(httpLoggerOptions, stream);
+		instance.info({
+			req: {
+				headers: {
+					cookie: `${REFRESH_TOKEN_COOKIE_NAME}=test-refresh-token-value`,
+				},
+			},
+		});
+		expect(logOutput.mock.calls[0][0]).toMatchObject({
+			req: {
+				headers: {
+					cookie: REDACT_TEXT,
+				},
+			},
+		});
+	});
+
+	test('Should redact refresh token with multiple entries', () => {
+		const instance = pino(httpLoggerOptions, stream);
+		instance.info({
+			req: {
+				headers: {
+					cookie: `custom_test_cookie=custom_test_value; access_token=test-access-token-value; oauth2.ranger=test-oauth2-value; openid.monospace=test-openid-value; ${REFRESH_TOKEN_COOKIE_NAME}=test-refresh-token-value`,
+				},
+			},
+		});
+		expect(logOutput.mock.calls[0][0]).toMatchObject({
+			req: {
+				headers: {
+					cookie: REDACT_TEXT,
+				},
+			},
+		});
+	});
+});
+
+describe('res.headers', () => {
+	test('Should redact refresh token when there is only one entry', () => {
+		const instance = pino(httpLoggerOptions, stream);
+		instance.info({
+			res: {
+				headers: {
+					'set-cookie': `${REFRESH_TOKEN_COOKIE_NAME}=test-refresh-token-value; Max-Age=604800; Path=/; Expires=Tue, 14 Feb 2023 12:00:00 GMT; HttpOnly; SameSite=Lax`,
+				},
+			},
+		});
+		expect(logOutput.mock.calls[0][0]).toMatchObject({
+			res: {
+				headers: {
+					'set-cookie': REDACT_TEXT,
+				},
+			},
+		});
+	});
+
+	test('Should redact refresh token with multiple entries', () => {
+		const instance = pino(httpLoggerOptions, stream);
+		instance.info({
+			res: {
+				headers: {
+					'set-cookie': [
+						`access_token=test-access-token-value; Max-Age=604800; Path=/; Expires=Tue, 14 Feb 2023 12:00:00 GMT; HttpOnly; SameSite=Lax`,
+						`oauth2.ranger=test-oauth2-value; Max-Age=604800; Path=/; Expires=Tue, 14 Feb 2023 12:00:00 GMT; HttpOnly; SameSite=Lax`,
+						`openid.monospace=test-openid-value; Max-Age=604800; Path=/; Expires=Tue, 14 Feb 2023 12:00:00 GMT; HttpOnly; SameSite=Lax`,
+						`${REFRESH_TOKEN_COOKIE_NAME}=test-refresh-token-value; Max-Age=604800; Path=/; Expires=Tue, 14 Feb 2023 12:00:00 GMT; HttpOnly; SameSite=Lax`,
+					],
+				},
+			},
+		});
+		expect(logOutput.mock.calls[0][0]).toMatchObject({
+			res: {
+				headers: {
+					'set-cookie': REDACT_TEXT,
+				},
+			},
+		});
+	});
+});

api/src/logger.ts

@@ -1,25 +1,25 @@
 import { toArray } from '@directus/shared/utils';
 import { merge } from 'lodash';
-import pino, { LoggerOptions, SerializedResponse } from 'pino';
+import pino, { LoggerOptions } from 'pino';
 import type { Request, RequestHandler } from 'express';
 import pinoHTTP, { stdSerializers } from 'pino-http';
 import { URL } from 'url';
 import env from './env';
+import { REDACT_TEXT } from './constants';
 import { getConfigFromEnv } from './utils/get-config-from-env';
-import { redactHeaderCookie } from './utils/redact-header-cookies';
 
 const pinoOptions: LoggerOptions = {
 	level: env['LOG_LEVEL'] || 'info',
 	redact: {
-		paths: ['req.headers.authorization', `req.cookies.${env['REFRESH_TOKEN_COOKIE_NAME']}`],
-		censor: '--redact--',
+		paths: ['req.headers.authorization', 'req.headers.cookie'],
+		censor: REDACT_TEXT,
 	},
 };
-const httpLoggerOptions: LoggerOptions = {
+export const httpLoggerOptions: LoggerOptions = {
 	level: env['LOG_LEVEL'] || 'info',
 	redact: {
-		paths: ['req.headers.authorization', `req.cookies.${env['REFRESH_TOKEN_COOKIE_NAME']}`],
-		censor: '--redact--',
+		paths: ['req.headers.authorization', 'req.headers.cookie'],
+		censor: REDACT_TEXT,
 	},
 };
 
@@ -44,6 +44,21 @@ if (env['LOG_STYLE'] !== 'raw') {
 		},
 	};
 }
+if (env['LOG_STYLE'] === 'raw') {
+	httpLoggerOptions.redact = {
+		paths: ['req.headers.authorization', 'req.headers.cookie', 'res.headers'],
+		censor: (value, pathParts) => {
+			const path = pathParts.join('.');
+			if (path === 'res.headers') {
+				if ('set-cookie' in value) {
+					value['set-cookie'] = REDACT_TEXT;
+				}
+				return value;
+			}
+			return REDACT_TEXT;
+		},
+	};
+}
 
 const loggerEnvConfig = getConfigFromEnv('LOGGER_', 'LOGGER_HTTP');
 
@@ -87,23 +102,8 @@ export const expressLogger = pinoHTTP({
 		req(request: Request) {
 			const output = stdSerializers.req(request);
 			output.url = redactQuery(output.url);
-			if (output.headers?.['cookie']) {
-				output.headers['cookie'] = redactHeaderCookie(output.headers['cookie'], [
-					'access_token',
-					`${env['REFRESH_TOKEN_COOKIE_NAME']}`,
-				]);
-			}
 			return output;
 		},
-		res(response: SerializedResponse) {
-			if (response.headers?.['set-cookie']) {
-				response.headers['set-cookie'] = redactHeaderCookie(response.headers['set-cookie'], [
-					'access_token',
-					`${env['REFRESH_TOKEN_COOKIE_NAME']}`,
-				]);
-			}
-			return response;
-		},
 	},
 }) as RequestHandler;
 
@@ -113,7 +113,7 @@ function redactQuery(originalPath: string) {
 	const url = new URL(originalPath, 'http://example.com/');
 
 	if (url.searchParams.has('access_token')) {
-		url.searchParams.set('access_token', '--redacted--');
+		url.searchParams.set('access_token', REDACT_TEXT);
 	}
 
 	return url.pathname + url.search;

api/src/utils/redact-header-cookies.test.ts

@@ -1,42 +0,0 @@
-import { describe, expect, test } from 'vitest';
-import env from '../env';
-import { redactHeaderCookie } from './redact-header-cookies';
-
-describe('redactHeaderCookie', () => {
-	describe('Given auth cookies', () => {
-		test('When it finds a refresh_token, it should redact the value', () => {
-			const tokenKey = env['REFRESH_TOKEN_COOKIE_NAME'];
-			const cookieHeader = `${tokenKey}=shh;`;
-			const cookieNames = [`${tokenKey}`];
-
-			const redactedCookie = redactHeaderCookie(cookieHeader, cookieNames);
-			expect(redactedCookie).toBe(`${tokenKey}=--redacted--;`);
-		});
-		test('When it finds an access_token, it should redact the value', () => {
-			const tokenKey = 'access_token';
-			const cookieHeader = `${tokenKey}=secret;`;
-			const cookieNames = [`${tokenKey}`];
-
-			const redactedCookie = redactHeaderCookie(cookieHeader, cookieNames);
-			expect(redactedCookie).toBe(`${tokenKey}=--redacted--;`);
-		});
-		test('When it finds both an access_token and refresh_token, it should redact both values', () => {
-			const cookieHeader = `access_token=secret; ${env['REFRESH_TOKEN_COOKIE_NAME']}=shhhhhhh; randomCookie=Erdtree;`;
-			const cookieNames = ['access_token', `${env['REFRESH_TOKEN_COOKIE_NAME']}`];
-
-			const redactedCookie = redactHeaderCookie(cookieHeader, cookieNames);
-			expect(redactedCookie).toBe(
-				`access_token=--redacted--; ${env['REFRESH_TOKEN_COOKIE_NAME']}=--redacted--; randomCookie=Erdtree;`
-			);
-		});
-	});
-	describe('Given negligible cookies', () => {
-		test('It should return the orignal value', () => {
-			const originalCookie = `Crown=Swords; Hail=Sithis;`;
-			const cookieNames = [env['REFRESH_TOKEN_COOKIE_NAME'], 'access_token'];
-
-			const redactedCookie = redactHeaderCookie(originalCookie, cookieNames);
-			expect(redactedCookie).toBe(originalCookie);
-		});
-	});
-});

api/src/utils/redact-header-cookies.ts

@@ -1,7 +0,0 @@
-export function redactHeaderCookie(cookieHeader: string, cookieNames: string[]) {
-	for (const cookieName of cookieNames) {
-		const re = new RegExp(`(${cookieName}=)([^;]+)`);
-		cookieHeader = cookieHeader.replace(re, `$1--redacted--`);
-	}
-	return cookieHeader;
-}