feat: CXSPA-4370 PoC with alternative way of providing Trace Context (and other transformations in the future)

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/index.ts

@@ -6,3 +6,4 @@
 
 export * from './loggers/index';
 export * from './services/index';
+export * from './transformers/index';

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

@@ -10,33 +10,57 @@ import {
   ExpressServerLogger,
   ExpressServerLoggerContext,
 } from './express-server-logger';
-
 /**
  *
  * 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 {
+export class DefaultExpressServerLogger extends ExpressServerLogger {
   log(message: string, context: ExpressServerLoggerContext): void {
     /* eslint-disable-next-line no-console */
-    console.log(this.stringifyWithContext(message, context));
+    console.log(
+      this.stringifyWithContext(
+        ...this.transform(message, context, this._transformers, this)
+      )
+    );
   }
   warn(message: string, context: ExpressServerLoggerContext): void {
     /* eslint-disable-next-line no-console */
-    console.warn(this.stringifyWithContext(message, context));
+    console.warn(
+      this.stringifyWithContext(
+        ...this.transform(message, context, this._transformers, this)
+      )
+    );
   }
   error(message: string, context: ExpressServerLoggerContext): void {
     /* eslint-disable-next-line no-console */
-    console.error(this.stringifyWithContext(message, context));
+    console.error(
+      this.stringifyWithContext(
+        ...this.transform(message, context, this._transformers, this)
+      )
+    );
   }
   info(message: string, context: ExpressServerLoggerContext): void {
     /* eslint-disable-next-line no-console */
-    console.info(this.stringifyWithContext(message, context));
+    console.info(
+      this.stringifyWithContext(
+        ...this.transform(message, context, this._transformers, this)
+      )
+    );
   }
   debug(message: string, context: ExpressServerLoggerContext): void {
     /* eslint-disable-next-line no-console */
-    console.debug(this.stringifyWithContext(message, context));
+    console.debug(
+      this.stringifyWithContext(
+        ...this.transform(message, context, this._transformers, this)
+      )
+    );
   }
 
   /**