fix(logger): add xray_trace_id to every log (#776)

* fix: add xray_trace_id to logs

* chore: 100% test coverage is back

* chore: typo in comments

* Update docs/core/logger.md

Co-authored-by: ijemmy <[email protected]>

Co-authored-by: ijemmy <[email protected]>

Author: dreamorosi

Diff for: docs/core/logger.md

@@ -100,7 +100,7 @@ Key | Example | Note
 **sampling_rate**: `float` |  `0.1` | When enabled, it prints all the logs of a percentage of invocations, e.g. 10%
 **service**: `string` | `serverlessAirline` | A unique name identifier of the service this Lambda function belongs to, by default `service_undefined`
 **timestamp**: `string` | `2011-10-05T14:48:00.000Z` | Timestamp string in simplified extended ISO format (ISO 8601)
-**xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793` | When [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"}, it shows X-Ray Trace ID
+**xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793` | X-Ray Trace ID. This value is always presented in Lambda environment, whether [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"} or not. Logger will always log this value.
 **error**: `Object` | `{ name: "Error", location: "/my-project/handler.ts:18", message: "Unexpected error #1", stack: "[stacktrace]"}` | Optional - An object containing information about the Error passed to the logger
 
 ### Capturing Lambda context info

Diff for: packages/logger/src/Logger.ts

@@ -328,6 +328,7 @@ class Logger extends Utility implements ClassThatLogs {
       logLevel,
       timestamp: new Date(),
       message: typeof input === 'string' ? input : input.message,
+      xRayTraceId: this.getXrayTraceId(),
     }, this.getPowertoolLogData());
 
     const logItem = new LogItem({
@@ -428,6 +429,23 @@ class Logger extends Utility implements ClassThatLogs {
     return <number> this.powertoolLogData?.sampleRateValue;
   }
 
+  /**
+   * It returns the current X-Ray Trace ID parsing the content of the `_X_AMZN_TRACE_ID` env variable.
+   * 
+   * The X-Ray Trace data available in the environment variable has this format:
+   * `Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1`,
+   * 
+   * The actual Trace ID is: `1-5759e988-bd862e3fe1be46a994272793`.
+   *
+   * @private
+   * @returns {string}
+   */
+  private getXrayTraceId(): string {
+    const xRayTraceId = this.getEnvVarsService().getXrayTraceId();
+
+    return xRayTraceId.length > 0 ? xRayTraceId.split(';')[0].replace('Root=', '') : xRayTraceId;
+  }
+
   /**
    * It returns true if the provided log level is valid.
    *
@@ -629,7 +647,6 @@ class Logger extends Utility implements ClassThatLogs {
         sampleRateValue: this.getSampleRateValue(),
         serviceName:
           serviceName || this.getCustomConfigService()?.getServiceName() || this.getEnvVarsService().getServiceName() || Logger.defaultServiceName,
-        xRayTraceId: this.getEnvVarsService().getXrayTraceId(),
       },
       persistentLogAttributes,
     );

Diff for: packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts

@@ -18,15 +18,16 @@ const testFunction = async (event: APIGatewayProxyEvent, context: Context): Prom
   // Test feature 1: Log level filtering
   // Test feature 2: Context data
   // Test feature 3: Persistent additional log keys and value
+  // Test feature 4: X-Ray Trace ID injection
   logger.debug('##### This should not appear');
   logger.info('This is an INFO log with context and persistent key');
 
-  // Test feature 4: One-time additional log keys and values
+  // Test feature 5: One-time additional log keys and values
   logger.info('This is an one-time log with an additional key-value', {
     [SINGLE_LOG_ITEM_KEY]: SINGLE_LOG_ITEM_VALUE,
   });
 
-  // Test feature 5: Logging an error object
+  // Test feature 6: Logging an error object
   try {
     throw new Error(ERROR_MSG);
   } catch (e) {

Diff for: packages/logger/tests/e2e/basicFeatures.middy.test.ts

@@ -144,6 +144,16 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime}
     }, TEST_CASE_TIMEOUT);
   });
 
+  describe('X-Ray Trace ID injection', () => {
+    it('should inject & parse X-Ray Trace ID into every log', async () => {
+      const logMessages = invocationLogs[0].getFunctionLogs();
+
+      for (const message of logMessages) {
+        expect(message).toContain('xray_trace_id');
+      }
+    }, TEST_CASE_TIMEOUT);
+  });
+
   describe('One-time additional log keys and values', () => {
     it('should log additional keys and value only once', async () => {
       const logMessages = invocationLogs[0].getFunctionLogs()

Diff for: packages/logger/tests/helpers/populateEnvironmentVariables.ts

@@ -1,5 +1,5 @@
 // Reserved variables
-process.env._X_AMZN_TRACE_ID = 'abcdef123456abcdef123456abcdef123456';
+process.env._X_AMZN_TRACE_ID = 'Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1';
 process.env.AWS_LAMBDA_FUNCTION_NAME = 'my-lambda-function';
 process.env.AWS_LAMBDA_FUNCTION_MEMORY_SIZE = '128';
 process.env.AWS_REGION = 'eu-west-1';