diff --git a/core-libs/setup/ssr/engine-decorator/ng-express-engine-decorator.spec.ts b/core-libs/setup/ssr/engine-decorator/ng-express-engine-decorator.spec.ts index ac2cb1281a1..a89cac4dc0e 100644 --- a/core-libs/setup/ssr/engine-decorator/ng-express-engine-decorator.spec.ts +++ b/core-libs/setup/ssr/engine-decorator/ng-express-engine-decorator.spec.ts @@ -100,7 +100,7 @@ describe('decorateExpressEngine', () => { req: { protocol: 'https', originalUrl: '/electronics/en/USD/cart', - get: jest.fn(() => 'site.com'), + get: jest.fn(() => {}), app, connection: {}, res: >{ diff --git a/core-libs/setup/ssr/logger/loggers/default-express-server-logger.spec.ts b/core-libs/setup/ssr/logger/loggers/default-express-server-logger.spec.ts index 52f8ce642f7..2820daa60a1 100644 --- a/core-libs/setup/ssr/logger/loggers/default-express-server-logger.spec.ts +++ b/core-libs/setup/ssr/logger/loggers/default-express-server-logger.spec.ts @@ -7,7 +7,16 @@ const request = { res: { locals: { cx: { - request: { uuid: 'test', timeReceived: new Date('2023-05-26') }, + request: { + uuid: 'test', + timeReceived: new Date('2023-05-26'), + traceContext: { + version: '00', + traceId: 'd745f6735b44e81c0ae5410cb1fc8a0c', + parentId: '1b527c3828976b39', + traceFlags: '01', + }, + }, }, }, }, @@ -26,60 +35,6 @@ describe('DefaultExpressServerLogger', () => { expect(logger).toBeDefined(); }); - it('should log message', () => { - const logSpy = jest.spyOn(console, 'log').mockImplementation(() => {}); - - logger.log('test', { request: {} as Request }); - - expect(logSpy).toHaveBeenCalledWith( - logger['stringifyWithContext']('test', { request: {} as Request }) - ); - }); - - it('should warn message', () => { - const warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {}); - - logger.warn('test', { request: {} as Request }); - - expect(warnSpy).toHaveBeenCalledWith( - logger['stringifyWithContext']('test', { request: {} as Request }) - ); - }); - - it('should error message', () => { - const errorSpy = jest - .spyOn(console, 'error') - .mockImplementation(() => {}); - - logger.error('test', { request: {} as Request }); - - expect(errorSpy).toHaveBeenCalledWith( - logger['stringifyWithContext']('test', { request: {} as Request }) - ); - }); - - it('should info message', () => { - const infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {}); - - logger.info('test', { request: {} as Request }); - - expect(infoSpy).toHaveBeenCalledWith( - logger['stringifyWithContext']('test', { request: {} as Request }) - ); - }); - - it('should debug message', () => { - const debugSpy = jest - .spyOn(console, 'debug') - .mockImplementation(() => {}); - - logger.debug('test', { request: {} as Request }); - - expect(debugSpy).toHaveBeenCalledWith( - logger['stringifyWithContext']('test', { request: {} as Request }) - ); - }); - describe('is not dev mode', () => { beforeEach(() => { jest.spyOn(angularCore, 'isDevMode').mockReturnValue(false); @@ -94,7 +49,7 @@ describe('DefaultExpressServerLogger', () => { expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(` [ - "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z"}}}", + "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z","traceContext":{"version":"00","traceId":"d745f6735b44e81c0ae5410cb1fc8a0c","parentId":"1b527c3828976b39","traceFlags":"01"}}}}", ] `); }); @@ -108,7 +63,7 @@ describe('DefaultExpressServerLogger', () => { expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(` [ - "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z"}}}", + "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z","traceContext":{"version":"00","traceId":"d745f6735b44e81c0ae5410cb1fc8a0c","parentId":"1b527c3828976b39","traceFlags":"01"}}}}", ] `); }); @@ -122,23 +77,12 @@ describe('DefaultExpressServerLogger', () => { expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(` [ - "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z"}}}", + "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z","traceContext":{"version":"00","traceId":"d745f6735b44e81c0ae5410cb1fc8a0c","parentId":"1b527c3828976b39","traceFlags":"01"}}}}", ] `); }); it('should info proper shape of the JSON', () => { - const request = { - originalUrl: 'test', - res: { - locals: { - cx: { - request: { uuid: 'test', timeReceived: new Date() }, - }, - }, - }, - } as unknown as Request; - const debugSpy = jest .spyOn(console, 'info') .mockImplementation(() => {}); @@ -147,7 +91,7 @@ describe('DefaultExpressServerLogger', () => { expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(` [ - "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z"}}}", + "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z","traceContext":{"version":"00","traceId":"d745f6735b44e81c0ae5410cb1fc8a0c","parentId":"1b527c3828976b39","traceFlags":"01"}}}}", ] `); }); @@ -161,7 +105,7 @@ describe('DefaultExpressServerLogger', () => { expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(` [ - "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z"}}}", + "{"message":"test","context":{"timestamp":"2023-05-26T00:00:00.000Z","request":{"url":"test","uuid":"test","timeReceived":"2023-05-26T00:00:00.000Z","traceContext":{"version":"00","traceId":"d745f6735b44e81c0ae5410cb1fc8a0c","parentId":"1b527c3828976b39","traceFlags":"01"}}}}", ] `); }); @@ -188,7 +132,13 @@ describe('DefaultExpressServerLogger', () => { "request": { "url": "test", "uuid": "test", - "timeReceived": "2023-05-26T00:00:00.000Z" + "timeReceived": "2023-05-26T00:00:00.000Z", + "traceContext": { + "version": "00", + "traceId": "d745f6735b44e81c0ae5410cb1fc8a0c", + "parentId": "1b527c3828976b39", + "traceFlags": "01" + } } } }", @@ -212,7 +162,13 @@ describe('DefaultExpressServerLogger', () => { "request": { "url": "test", "uuid": "test", - "timeReceived": "2023-05-26T00:00:00.000Z" + "timeReceived": "2023-05-26T00:00:00.000Z", + "traceContext": { + "version": "00", + "traceId": "d745f6735b44e81c0ae5410cb1fc8a0c", + "parentId": "1b527c3828976b39", + "traceFlags": "01" + } } } }", @@ -236,7 +192,13 @@ describe('DefaultExpressServerLogger', () => { "request": { "url": "test", "uuid": "test", - "timeReceived": "2023-05-26T00:00:00.000Z" + "timeReceived": "2023-05-26T00:00:00.000Z", + "traceContext": { + "version": "00", + "traceId": "d745f6735b44e81c0ae5410cb1fc8a0c", + "parentId": "1b527c3828976b39", + "traceFlags": "01" + } } } }", @@ -260,7 +222,13 @@ describe('DefaultExpressServerLogger', () => { "request": { "url": "test", "uuid": "test", - "timeReceived": "2023-05-26T00:00:00.000Z" + "timeReceived": "2023-05-26T00:00:00.000Z", + "traceContext": { + "version": "00", + "traceId": "d745f6735b44e81c0ae5410cb1fc8a0c", + "parentId": "1b527c3828976b39", + "traceFlags": "01" + } } } }", @@ -284,7 +252,13 @@ describe('DefaultExpressServerLogger', () => { "request": { "url": "test", "uuid": "test", - "timeReceived": "2023-05-26T00:00:00.000Z" + "timeReceived": "2023-05-26T00:00:00.000Z", + "traceContext": { + "version": "00", + "traceId": "d745f6735b44e81c0ae5410cb1fc8a0c", + "parentId": "1b527c3828976b39", + "traceFlags": "01" + } } } }", @@ -303,7 +277,7 @@ describe('DefaultExpressServerLogger', () => { it('should return message with request', () => { const logMessage = logger['stringifyWithContext']('test', { - request: {} as Request, + request, }); expect(logMessage).toContain('request'); @@ -331,6 +305,12 @@ describe('DefaultExpressServerLogger', () => { { "request": { "timeReceived": 2023-05-26T00:00:00.000Z, + "traceContext": { + "parentId": "1b527c3828976b39", + "traceFlags": "01", + "traceId": "d745f6735b44e81c0ae5410cb1fc8a0c", + "version": "00", + }, "url": "test", "uuid": "test", }, @@ -342,23 +322,47 @@ describe('DefaultExpressServerLogger', () => { describe('map request', () => { it('should return mapped request', () => { - const request = { + const mappedRequest = logger['mapRequest'](request); + + expect(mappedRequest).toMatchInlineSnapshot(` + { + "timeReceived": 2023-05-26T00:00:00.000Z, + "traceContext": { + "parentId": "1b527c3828976b39", + "traceFlags": "01", + "traceId": "d745f6735b44e81c0ae5410cb1fc8a0c", + "version": "00", + }, + "url": "test", + "uuid": "test", + } + `); + }); + + it('should return mapped request without traceContext prop if traceparent is not available', () => { + const requestWithoutTraceContext = { originalUrl: 'test', res: { locals: { cx: { - request: { uuid: 'test', timeReceived: new Date() }, + request: { + uuid: 'test', + timeReceived: new Date('2023-05-26'), + }, }, }, }, - } as any; + } as unknown as Request; - const mappedRequest = logger['mapRequest'](request); + const mappedRequest = logger['mapRequest'](requestWithoutTraceContext); - expect(mappedRequest).toEqual({ - url: 'test', - ...request.res?.locals.cx.request, - }); + expect(mappedRequest).toMatchInlineSnapshot(` + { + "timeReceived": 2023-05-26T00:00:00.000Z, + "url": "test", + "uuid": "test", + } + `); }); }); }); diff --git a/core-libs/setup/ssr/logger/loggers/default-express-server-logger.ts b/core-libs/setup/ssr/logger/loggers/default-express-server-logger.ts index d6b7fc82b2f..db665130751 100644 --- a/core-libs/setup/ssr/logger/loggers/default-express-server-logger.ts +++ b/core-libs/setup/ssr/logger/loggers/default-express-server-logger.ts @@ -6,6 +6,7 @@ import { isDevMode } from '@angular/core'; import { Request } from 'express'; +import { getRequestContext } from '../../optimized-engine/request-context'; import { ExpressServerLogger, ExpressServerLoggerContext, @@ -16,6 +17,11 @@ import { * Default logger used in SSR (ExpressJS) to enhance logs visible e.g. in monitoring tools e.g. Kibana. * It outputs a JSON with properties "message" and "context", * which contains a "timestamp" and details of the "request" ("url", "uuid", "timeReceived") + * + * The output "context" JSON will contain also a property "traceContext" + * with "traceId", "parentId", "version" and "traceFlags", + * if only the given request has the special header "traceparent" (specifed in + * the "W3C TraceContext" document. See https://www.w3.org/TR/trace-context/#traceparent-header ). */ export class DefaultExpressServerLogger implements ExpressServerLogger { log(message: string, context: ExpressServerLoggerContext): void { @@ -90,7 +96,7 @@ export class DefaultExpressServerLogger implements ExpressServerLogger { protected mapRequest(request: Request): Record { return { url: request.originalUrl, - ...request.res?.locals.cx.request, + ...getRequestContext(request), }; } } diff --git a/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.spec.ts b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.spec.ts new file mode 100644 index 00000000000..438c1dca904 --- /dev/null +++ b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.spec.ts @@ -0,0 +1,8 @@ +import { InvalidTraceparentFormatError } from './invalid-traceparent-format-error'; + +describe('InvalidTraceparentFormatError', () => { + it('should be an instance of InstantiationError', () => { + const error = new InvalidTraceparentFormatError(); + expect(error).toBeInstanceOf(InvalidTraceparentFormatError); + }); +}); diff --git a/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.ts b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.ts new file mode 100644 index 00000000000..959a3213ffc --- /dev/null +++ b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.ts @@ -0,0 +1,14 @@ +/* + * SPDX-FileCopyrightText: 2023 SAP Spartacus team + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * Error thrown when the traceparent header has an invalid format. + */ +export class InvalidTraceparentFormatError extends Error { + constructor() { + super('Traceparent header has invalid format.'); + } +} diff --git a/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.spec.ts b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.spec.ts new file mode 100644 index 00000000000..c0b10ff396c --- /dev/null +++ b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.spec.ts @@ -0,0 +1,15 @@ +import { InvalidTraceparentLengthError } from './invalid-traceparent-length-error'; + +describe('InvalidTraceparentFormatError', () => { + it('should be an instance of InstantiationError', () => { + const error = new InvalidTraceparentLengthError(0); + expect(error).toBeInstanceOf(InvalidTraceparentLengthError); + }); + + it('should have the correct message', () => { + const error = new InvalidTraceparentLengthError(20); + expect(error.message).toBe( + `Traceparent header has invalid length: ${20}. Expected 55 characters.` + ); + }); +}); diff --git a/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.ts b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.ts new file mode 100644 index 00000000000..a90251c89d9 --- /dev/null +++ b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.ts @@ -0,0 +1,17 @@ +/* + * SPDX-FileCopyrightText: 2023 SAP Spartacus team + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * Error thrown when the traceparent header has an invalid length. + * @param traceparentLength The length of the traceparent header. + */ +export class InvalidTraceparentLengthError extends Error { + constructor(traceparentLength: number) { + super( + `Traceparent header has invalid length: ${traceparentLength}. Expected 55 characters.` + ); + } +} diff --git a/core-libs/setup/ssr/logger/loggers/w3c-trace-context/parse-traceparent.spec.ts b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/parse-traceparent.spec.ts new file mode 100644 index 00000000000..29602dd808c --- /dev/null +++ b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/parse-traceparent.spec.ts @@ -0,0 +1,60 @@ +import { InvalidTraceparentFormatError } from './errors/invalid-traceparent-format-error'; +import { InvalidTraceparentLengthError } from './errors/invalid-traceparent-length-error'; +import { parseTraceparent } from './parse-traceparent'; + +describe('parseTraceparent', () => { + it('should return null if traceparent is not a string', () => { + const result = parseTraceparent({} as string); + + expect(result).toBeUndefined(); + }); + + it('should throw an error if traceparent is not 55 characters long', () => { + const shorterString = '0'.repeat(54); + const longerString = '0'.repeat(56); + + expect(() => parseTraceparent(shorterString)).toThrow( + InvalidTraceparentLengthError + ); + expect(() => parseTraceparent(longerString)).toThrow( + InvalidTraceparentLengthError + ); + }); + + it('should throw an error if traceparent does not match the W3C pattern', () => { + const additionalChar = 'x'; + const unsupportedFormats: string[] = [ + `00${additionalChar}-af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01`, + `0-${additionalChar}0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01`, + `00-0af7651916cd43dd8448eb211c80319-${additionalChar}b7ad6b7169203331-01`, + `00-0af7651916cd43dd8448eb211c80319c-b7ad6b716920333-${additionalChar}01`, + `00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331${additionalChar}-1`, + `0010af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01`, + `00-0af7651916cd43dd8448eb211c80319c1b7ad6b7169203331-01`, + `00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331101`, + `0010af7651916cd43dd8448eb211c80319c1b7ad6b7169203331101`, + ]; + + unsupportedFormats.forEach((traceparent) => { + expect(() => parseTraceparent(traceparent)).toThrow( + InvalidTraceparentFormatError + ); + }); + }); + + it('should parse traceparent correctly', () => { + const traceparent = + '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01'; + + const result = parseTraceparent(traceparent); + + expect(result).toMatchInlineSnapshot(` + { + "parentId": "b7ad6b7169203331", + "traceFlags": "01", + "traceId": "0af7651916cd43dd8448eb211c80319c", + "version": "00", + } + `); + }); +}); diff --git a/core-libs/setup/ssr/logger/loggers/w3c-trace-context/parse-traceparent.ts b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/parse-traceparent.ts new file mode 100644 index 00000000000..77fbe7ca34f --- /dev/null +++ b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/parse-traceparent.ts @@ -0,0 +1,47 @@ +/* + * SPDX-FileCopyrightText: 2023 SAP Spartacus team + * + * SPDX-License-Identifier: Apache-2.0 + */ + +import { InvalidTraceparentFormatError } from './errors/invalid-traceparent-format-error'; +import { InvalidTraceparentLengthError } from './errors/invalid-traceparent-length-error'; +import { W3cTraceContext } from './w3c-trace-context.model'; + +const HEXDIGLC = '[0-9a-f]'; // https://www.w3.org/TR/trace-context/#traceparent-header-field-values +const VERSION = HEXDIGLC + '{2}'; // 2 HEXDIGLC +const TRACE_ID = HEXDIGLC + '{32}'; // 32 HEXDIGLC +const PARENT_ID = HEXDIGLC + '{16}'; // 16 HEXDIGLC +const TRACE_FLAGS = HEXDIGLC + '{2}'; // 2 HEXDIGLC +const TRACEPARENT = [VERSION, TRACE_ID, PARENT_ID, TRACE_FLAGS].join('-'); // separated by dashes +const traceparentPattern = new RegExp('^' + TRACEPARENT + '$'); + +/** + * Maps traceparent header to object with properties version, traceId, spanId and traceFlags. + * Since `traceparent` header may be not attached to the request, the function returns undefined if the header is not provided. + * If the header is provided but has invalid format or length, the function throws an error. + * + * @param traceparent + * @returns Params of the traceparent header. + * + * @see https://www.w3.org/TR/trace-context/#traceparent-header-field-values + */ +export function parseTraceparent( + traceparent: string | undefined | null +): W3cTraceContext | undefined { + if (typeof traceparent !== 'string') { + return undefined; + } + + if (traceparent.length !== 55) { + throw new InvalidTraceparentLengthError(traceparent.length); + } + + if (!traceparentPattern.test(traceparent)) { + throw new InvalidTraceparentFormatError(); + } + + const [version, traceId, parentId, traceFlags] = traceparent.split('-'); + + return { version, traceId, parentId, traceFlags }; +} diff --git a/core-libs/setup/ssr/logger/loggers/w3c-trace-context/w3c-trace-context.model.ts b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/w3c-trace-context.model.ts new file mode 100644 index 00000000000..03121ce4b9b --- /dev/null +++ b/core-libs/setup/ssr/logger/loggers/w3c-trace-context/w3c-trace-context.model.ts @@ -0,0 +1,23 @@ +/* + * SPDX-FileCopyrightText: 2023 SAP Spartacus team + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * W3cTraceContext is used for log message in server side rendering. + * It contains values of traceparent header. + * + * @property version - version of traceparent header + * @property traceId - traceId of traceparent header + * @property parentId - spanId of traceparent header + * @property traceFlags - traceFlags of traceparent header + * + * @see https://www.w3.org/TR/trace-context/#traceparent-header-field + */ +export interface W3cTraceContext { + version: string; + traceId: string; + parentId: string; + traceFlags: string; +} diff --git a/core-libs/setup/ssr/optimized-engine/index.ts b/core-libs/setup/ssr/optimized-engine/index.ts index b162debc6c5..6c71a29f6da 100644 --- a/core-libs/setup/ssr/optimized-engine/index.ts +++ b/core-libs/setup/ssr/optimized-engine/index.ts @@ -6,6 +6,7 @@ export * from './optimized-ssr-engine'; export * from './rendering-cache'; -export * from './ssr-optimization-options'; export * from './rendering-strategy-resolver'; export * from './rendering-strategy-resolver-options'; +export { RequestContext, getRequestContext } from './request-context'; +export * from './ssr-optimization-options'; diff --git a/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.spec.ts b/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.spec.ts index 02b175d50df..cced719ec68 100644 --- a/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.spec.ts +++ b/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.spec.ts @@ -1176,8 +1176,20 @@ describe('OptimizedSsrEngine', () => { }); describe('logger option', () => { + let dateSpy: jest.SpyInstance; + + beforeEach(() => { + const mockDate = new Date('2023-05-26'); + dateSpy = jest + .spyOn(global, 'Date') + .mockImplementationOnce(() => mockDate); + }); + + afterEach(() => { + dateSpy.mockReset(); + }); + it('should use ExpressServerLogger if logger is true', () => { - jest.useFakeTimers().setSystemTime(new Date('2023-05-26')); new TestEngineRunner({ logger: true, }); @@ -1202,6 +1214,7 @@ describe('OptimizedSsrEngine', () => { ] `); }); + it('should use the provided logger', () => { new TestEngineRunner({ logger: new MockExpressServerLogger() as ExpressServerLogger, @@ -1228,6 +1241,7 @@ describe('OptimizedSsrEngine', () => { ] `); }); + it('should use the legacy server logger, if logger option not specified', () => { new TestEngineRunner({}); expect(consoleLogSpy.mock.lastCall).toMatchInlineSnapshot(` diff --git a/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.ts b/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.ts index 8faa7c2f275..088443e77b6 100644 --- a/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.ts +++ b/core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.ts @@ -5,7 +5,6 @@ */ /* webpackIgnore: true */ -import { randomUUID } from 'crypto'; import { Request, Response } from 'express'; import * as fs from 'fs'; import { NgExpressEngineInstance } from '../engine-decorator/ng-express-engine-decorator'; @@ -19,6 +18,7 @@ import { } from '../logger'; import { getLoggableSsrOptimizationOptions } from './get-loggable-ssr-optimization-options'; import { RenderingCache } from './rendering-cache'; +import { preprocessRequestForLogger } from './request-context'; import { RenderingStrategy, SsrOptimizationOptions, @@ -254,11 +254,7 @@ export class OptimizedSsrEngine { options: any, callback: SsrCallbackFn ): void { - const requestContext = { - uuid: randomUUID(), - timeReceived: new Date().toISOString(), - }; - options.req.res.locals = { cx: { request: requestContext } }; + preprocessRequestForLogger(options.req, this.logger); const request: Request = options.req; const response: Response = options.req.res; diff --git a/core-libs/setup/ssr/optimized-engine/request-context.spec.ts b/core-libs/setup/ssr/optimized-engine/request-context.spec.ts new file mode 100644 index 00000000000..1fb767e1a5d --- /dev/null +++ b/core-libs/setup/ssr/optimized-engine/request-context.spec.ts @@ -0,0 +1,118 @@ +import crypto from 'crypto'; +import { Request } from 'express'; +import { IncomingHttpHeaders } from 'http'; +import { + DefaultExpressServerLogger, + ExpressServerLogger, + ExpressServerLoggerContext, +} from '../logger'; +import * as parser from '../logger/loggers/w3c-trace-context/parse-traceparent'; +import { preprocessRequestForLogger } from './request-context'; + +describe('RequestContext', () => { + let request: Request; + let headers: IncomingHttpHeaders; + let logger: ExpressServerLogger; + let dateSpy: jest.SpyInstance; + let randomUUIDSpy: jest.SpyInstance; + const mockDate = new Date('2023-09-07'); + + beforeEach(() => { + jest.spyOn(console, 'error').mockImplementation(); + dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate); + randomUUIDSpy = jest + .spyOn(crypto, 'randomUUID') + .mockReturnValue('ad90db04-a501-4dc5-9b4e-2cc2ab10d49c'); + + headers = {}; + request = { + res: { + locals: { + cx: { request: {} as ExpressServerLoggerContext }, + }, + }, + get: (header: string): string | string[] | undefined => { + return headers[header]; + }, + headers, + } as unknown as Request; + logger = new DefaultExpressServerLogger(); + }); + + afterEach(() => { + dateSpy.mockRestore(); + randomUUIDSpy.mockRestore(); + }); + + it('should add initial request context', () => { + preprocessRequestForLogger(request, logger); + expect(request.res?.locals.cx.request).toMatchInlineSnapshot(` + { + "timeReceived": "2023-09-07T00:00:00.000Z", + "traceContext": undefined, + "uuid": "ad90db04-a501-4dc5-9b4e-2cc2ab10d49c", + } + `); + }); + + it('should add trace context', () => { + request.headers.traceparent = + '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01'; + + preprocessRequestForLogger(request, logger); + expect(request.res?.locals.cx.request).toMatchInlineSnapshot(` + { + "timeReceived": "2023-09-07T00:00:00.000Z", + "traceContext": { + "parentId": "b7ad6b7169203331", + "traceFlags": "01", + "traceId": "0af7651916cd43dd8448eb211c80319c", + "version": "00", + }, + "uuid": "ad90db04-a501-4dc5-9b4e-2cc2ab10d49c", + } + `); + }); + + it('should add only initial context and log an error if traceparent is invalid', () => { + const invalidTraceparent = 'invalid'; + const loggerErrorSpy = jest.spyOn(logger, 'error'); + + request.headers.traceparent = invalidTraceparent; + preprocessRequestForLogger(request, logger); + expect(request.res?.locals.cx.request).toMatchInlineSnapshot(` + { + "timeReceived": "2023-09-07T00:00:00.000Z", + "traceContext": undefined, + "uuid": "ad90db04-a501-4dc5-9b4e-2cc2ab10d49c", + } + `); + expect(loggerErrorSpy).toHaveBeenCalledWith( + `Traceparent header has invalid length: ${invalidTraceparent.length}. Expected 55 characters.`, + { request } + ); + }); + + it('should add only initial context and log unexpected error if parsing failed for unknown reason', () => { + const invalidTraceparent = 'invalid'; + const loggerErrorSpy = jest.spyOn(logger, 'error'); + + jest.spyOn(parser, 'parseTraceparent').mockImplementationOnce(() => { + // eslint-disable-next-line no-throw-literal + throw { message: 'Unexpected error' }; + }); + request.headers.traceparent = invalidTraceparent; + preprocessRequestForLogger(request, logger); + expect(request.res?.locals.cx.request).toMatchInlineSnapshot(` + { + "timeReceived": "2023-09-07T00:00:00.000Z", + "traceContext": undefined, + "uuid": "ad90db04-a501-4dc5-9b4e-2cc2ab10d49c", + } + `); + expect(loggerErrorSpy).toHaveBeenCalledWith( + 'Unexpected error during parsing traceparent header', + { request } + ); + }); +}); diff --git a/core-libs/setup/ssr/optimized-engine/request-context.ts b/core-libs/setup/ssr/optimized-engine/request-context.ts new file mode 100644 index 00000000000..9a5d00eb6cc --- /dev/null +++ b/core-libs/setup/ssr/optimized-engine/request-context.ts @@ -0,0 +1,111 @@ +/* + * SPDX-FileCopyrightText: 2023 SAP Spartacus team + * + * SPDX-License-Identifier: Apache-2.0 + */ + +import { randomUUID } from 'crypto'; +import { Request } from 'express'; +import { ExpressServerLogger } from '../logger'; +import { parseTraceparent } from '../logger/loggers/w3c-trace-context/parse-traceparent'; +import { W3cTraceContext } from '../logger/loggers/w3c-trace-context/w3c-trace-context.model'; + +/** + * RequestContext is used for log message in server side rendering. + * It contains request's UUID, time of receiving the request and the W3C Trace Context if `traceparent` header is available and valid. + */ +export interface RequestContext { + uuid: string; + timeReceived: string; + traceContext?: W3cTraceContext; +} + +/** + * Returns the request context from the request object. + * @param request - the request object + * @returns the context of the request + */ +export const getRequestContext = (request: Request): RequestContext => { + return request.res?.locals?.cx?.request; +}; + +/** + * Prepares and updates a request with the context object, which is used to enrich the logs. + * It contains the random request's UUID, time of receiving the context and the W3C Trace Context (if available). + * The trace context is parsed from the `traceparent` header, which is specified in + * the "W3C TraceContext" document. See https://www.w3.org/TR/trace-context/#traceparent-header + * for more details. + * @param request - the request object + * @param logger - the ExpressServerLogger object. It is used to log the error if occurred during parsing traceparent header + * @returns the context of the request and error if occurred during parsing traceparent header + */ +export const preprocessRequestForLogger = ( + request: Request, + logger: ExpressServerLogger +) => { + const requestContext: RequestContext = { + ...createInitialRequestContext(), + traceContext: getTraceContext(request, logger), + }; + setRequestContext(request, requestContext); +}; + +/** + * Updates the request object with the request context. + * @param request - the request object + * @param context - the context of the request + */ +const setRequestContext = (request: Request, context: RequestContext) => { + if (request.res) { + request.res.locals = { + ...request.res.locals, + cx: { + ...request.res.locals.cx, + request: context, + }, + }; + } +}; + +/** + * Creates the initial request context to the request object. + * @param request - the request object + * @returns object with a randomly generated UUID and the current time + */ +const createInitialRequestContext = (): RequestContext => { + const requestContext: RequestContext = { + uuid: randomUUID(), + timeReceived: new Date().toISOString(), + }; + return requestContext; +}; + +/** + * Parses the `traceparent` header and returns an object with the W3C TraceContext. + * In case when the `traceparent` header is absent or invalid, `undefined` value is returned. + * @param request - the request object + * @param logger - the logger object + * + */ +const getTraceContext = ( + request: Request, + logger: ExpressServerLogger +): W3cTraceContext | undefined => { + try { + return parseTraceparent(request.get('traceparent')) ?? undefined; + } catch (e) { + const error = + e instanceof Error + ? e + : new Error('Unexpected error during parsing traceparent header'); + logger.error(error.message, { request }); + } +}; + +declare module 'express' { + export interface Locals { + cx: { + request: RequestContext; + }; + } +}