feat: CXSPA-2067 SSR Logging - Trace Context (#17597)

Introducing the Trace Context extension, a significant advancement in server-side rendering (SSR) logging. This feature elevates contextual logging by seamlessly incorporating Trace Context parameters into SSR logs. For detailed information on Trace Context, please refer to the official documentation at https://www.w3.org/TR/trace-context/#overview. With this pull request, we are now bridging the power of Trace Context to your SSR logs. Our utilities seamlessly map headers to trace context parameters, enabling you to effortlessly expand the context of your SSR logs. This enhancement opens up new possibilities, allowing you to effortlessly connect logs from popular monitoring tools like Kibana to distributed trace presentation tools like Dynatrace. Closes CXSPA-2067
SAP · Oct 5, 2023 · 68705ca · 68705ca
1 parent 6a8349d
commit 68705ca
Show file tree

Hide file tree

Showing 15 changed files with 529 additions and 95 deletions.
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
@@ -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>>{

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
@@ -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
@@ -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),
     };
   }
 }
diff --git a/...etup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.spec.ts b/...etup/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/...ibs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-format-error.ts b/...ibs/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.');
+  }
+}
diff --git a/...etup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.spec.ts b/...etup/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/...ibs/setup/ssr/logger/loggers/w3c-trace-context/errors/invalid-traceparent-length-error.ts b/...ibs/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.`
+    );
+  }
+}