feat: CXSPA-2067 SSR Logging - Trace Context

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: <Partial<Response>>{

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",
+        }
+      `);
     });
   });
 });

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<string, any> {
     return {
       url: request.originalUrl,
-      ...request.res?.locals.cx.request,
+      ...getRequestContext(request),
     };
   }
 }

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);
+  });
+});

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 <[email protected]>
+ *
+ * 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.');
+  }
+}

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.`
+    );
+  });
+});

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 <[email protected]>
+ *
+ * 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.`
+    );
+  }
+}