feat(logger): time zone aware timestamp in Logger (#2710)

arnabrahman · dreamorosi · web-flow · commit 9fe4c754960a · 2024-07-03T10:15:24.000+02:00
Co-authored-by: Andrea Amorosi &lt;dreamorosi@gmail.com&gt;
diff --git a/docs/core/logger.md b/docs/core/logger.md
@@ -519,6 +519,26 @@ We prioritise log level settings in this order:
 
 In the event you have set a log level in Powertools to a level that is lower than the ACL setting, we will output a warning log message informing you that your messages will be discarded by Lambda.
 
+### Setting timestamp to custom Timezone
+
+By default, Logger emits records with the default Lambda timestamp in **UTC**, i.e. `2016-06-20T12:08:10.000Z`
+
+If you prefer to log in a specific timezone, you can configure it by setting the `TZ` environment variable. You can do this either as an environment variable or directly within your Lambda function settings.
+
+[Click here](https://docs.aws.amazon.com/lambda/latest/dg/configuration-envvars.html#configuration-envvars-runtime){target="_blank"} for a comprehensive list of available Lambda environment variables.
+
+=== "customTimezone.ts"
+
+    ```typescript hl_lines="8"
+    --8<-- "examples/snippets/logger/customTimezone.ts"
+    ```
+
+=== "customTimezoneOutput.json"
+
+    ```json hl_lines="7 15"
+    --8<-- "examples/snippets/logger/customTimezoneOutput.json"
+    ```
+
 ### Using multiple Logger instances across your code
 
 The `createChild` method allows you to create a child instance of the Logger, which inherits all of the attributes from its parent. You have the option to override any of the settings and attributes from the parent logger, including [its settings](#utility-settings), any [extra keys](#appending-additional-keys), and [the log formatter](#custom-log-formatter-bring-your-own-formatter).
diff --git a/examples/snippets/logger/customTimezone.ts b/examples/snippets/logger/customTimezone.ts
@@ -0,0 +1,13 @@
+import { Logger } from '@aws-lambda-powertools/logger';
+
+const logger = new Logger({ serviceName: 'serverlessAirline' });
+
+export const handler = async (): Promise<void> => {
+  logger.info('Hello, World!');
+
+  process.env.TZ = 'Europe/Rome';
+
+  const childLogger = logger.createChild();
+
+  childLogger.info('Ciao, Mondo!');
+};
diff --git a/examples/snippets/logger/customTimezoneOutput.json b/examples/snippets/logger/customTimezoneOutput.json
@@ -0,0 +1,18 @@
+[
+  {
+    "level": "INFO",
+    "message": "Hello, World!",
+    "sampling_rate": 0,
+    "service": "serverlessAirline",
+    "timestamp": "2024-07-01T11:00:37.886Z",
+    "xray_trace_id": "1-66828c55-2bb635c65eb609c820ebe7bc"
+  },
+  {
+    "level": "INFO",
+    "message": "Ciao, Mondo!",
+    "sampling_rate": 0,
+    "service": "serverlessAirline",
+    "timestamp": "2024-07-01T13:00:37.934+02:00",
+    "xray_trace_id": "1-66828c55-2bb635c65eb609c820ebe7bc"
+  }
+]
diff --git a/packages/logger/src/formatter/LogFormatter.ts b/packages/logger/src/formatter/LogFormatter.ts
@@ -57,12 +57,24 @@ abstract class LogFormatter implements LogFormatterInterface {
   }
 
   /**
-   * It formats a date into a string in simplified extended ISO format (ISO 8601).
+   * Formats a given date into an ISO 8601 string, considering the configured timezone.
+   * If `envVarsService` is set and the configured timezone differs from 'UTC',
+   * the date is formatted to that timezone. Otherwise, it defaults to 'UTC'.
    *
    * @param {Date} now
    * @returns {string}
    */
   public formatTimestamp(now: Date): string {
+    const defaultTimezone = 'UTC';
+
+    /**
+     * If a specific timezone is configured and it's not the default `UTC`,
+     * format the timestamp with the appropriate timezone offset.
+     **/
+    const configuredTimezone = this.envVarsService?.getTimezone();
+    if (configuredTimezone && !configuredTimezone.includes(defaultTimezone))
+      return this.#generateISOTimestampWithOffset(now, configuredTimezone);
+
     return now.toISOString();
   }
 
@@ -91,6 +103,61 @@ abstract class LogFormatter implements LogFormatterInterface {
 
     return '';
   }
+
+  /**
+   * Generates a new Intl.DateTimeFormat object configured with the specified time zone
+   * and formatting options. The time is displayed in 24-hour format (hour12: false).
+   *
+   * @param {string} timeZone - the IANA time zone identifier (e.g., "Asia/Dhaka").
+   */
+  #getDateFormatter = (timeZone: string): Intl.DateTimeFormat => {
+    const twoDigitFormatOption = '2-digit';
+
+    return new Intl.DateTimeFormat('en', {
+      year: 'numeric',
+      month: twoDigitFormatOption,
+      day: twoDigitFormatOption,
+      hour: twoDigitFormatOption,
+      minute: twoDigitFormatOption,
+      second: twoDigitFormatOption,
+      hour12: false,
+      timeZone,
+    });
+  };
+
+  /**
+   * Generates an ISO 8601 timestamp string with the specified time zone and the local time zone offset.
+   *
+   * @param {Date} date - the date to format
+   * @param {string} timeZone - the IANA time zone identifier (e.g., "Asia/Dhaka").
+   */
+  #generateISOTimestampWithOffset(date: Date, timeZone: string): string {
+    const { year, month, day, hour, minute, second } = this.#getDateFormatter(
+      timeZone
+    )
+      .formatToParts(date)
+      .reduce(
+        (acc, item) => {
+          acc[item.type] = item.value;
+
+          return acc;
+        },
+        {} as Record<Intl.DateTimeFormatPartTypes, string>
+      );
+    const datePart = `${year}-${month}-${day}T${hour}:${minute}:${second}`;
+    const offset = -date.getTimezoneOffset();
+    const offsetSign = offset >= 0 ? '+' : '-';
+    const offsetHours = Math.abs(Math.floor(offset / 60))
+      .toString()
+      .padStart(2, '0');
+    const offsetMinutes = Math.abs(offset % 60)
+      .toString()
+      .padStart(2, '0');
+    const millisecondPart = date.getMilliseconds().toString().padStart(3, '0');
+    const offsetPart = `${offsetSign}${offsetHours}:${offsetMinutes}`;
+
+    return `${datePart}.${millisecondPart}${offsetPart}`;
+  }
 }
 
 export { LogFormatter };
diff --git a/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts b/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts
@@ -8,13 +8,20 @@ import { PowertoolsLogFormatter } from '../../../src/formatter/PowertoolsLogForm
 import { LogItem } from '../../../src/index.js';
 import type { UnformattedAttributes } from '../../../src/types/Logger.js';
 import type { LogAttributes } from '../../../src/types/Log.js';
+import { EnvironmentVariablesService } from '../../../src/config/EnvironmentVariablesService.js';
 
 describe('Class: PowertoolsLogFormatter', () => {
-  const mockDate = new Date(1466424490000);
-  const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate);
+  const ENVIRONMENT_VARIABLES = process.env;
 
   beforeEach(() => {
-    dateSpy.mockClear();
+    const mockDate = new Date(1466424490000);
+    jest.useFakeTimers().setSystemTime(mockDate);
+    process.env = { ...ENVIRONMENT_VARIABLES };
+  });
+
+  afterAll(() => {
+    process.env = ENVIRONMENT_VARIABLES;
+    jest.useRealTimers();
   });
 
   describe('Method: formatAttributes', () => {
@@ -309,6 +316,161 @@ describe('Class: PowertoolsLogFormatter', () => {
       // Assess
       expect(timestamp).toEqual('2016-06-20T12:08:10.000Z');
     });
+
+    test('it formats the timestamp to ISO 8601, accounting for the `America/New_York` timezone offset', () => {
+      // Prepare
+      process.env.TZ = 'America/New_York';
+      /* 
+        Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes.
+        The positive value indicates that `America/New_York` is behind UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240);
+      const formatter = new PowertoolsLogFormatter({
+        envVarsService: new EnvironmentVariablesService(),
+      });
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-20T08:08:10.000-04:00');
+    });
+
+    test('it formats the timestamp to ISO 8601 with correct milliseconds for `America/New_York` timezone', () => {
+      // Prepare
+      process.env.TZ = 'America/New_York';
+      const mockDate = new Date('2016-06-20T12:08:10.910Z');
+      jest.useFakeTimers().setSystemTime(mockDate);
+      /* 
+        Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes.
+        The positive value indicates that `America/New_York` is behind UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240);
+      const formatter = new PowertoolsLogFormatter({
+        envVarsService: new EnvironmentVariablesService(),
+      });
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-20T08:08:10.910-04:00');
+    });
+
+    test('it formats the timestamp to ISO 8601, adjusting for `America/New_York` timezone, preserving milliseconds and accounting for date change', () => {
+      // Prepare
+      process.env.TZ = 'America/New_York';
+      const mockDate = new Date('2016-06-20T00:08:10.910Z');
+      jest.useFakeTimers().setSystemTime(mockDate);
+      /* 
+        Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes.
+        The positive value indicates that `America/New_York` is behind UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240);
+      const formatter = new PowertoolsLogFormatter({
+        envVarsService: new EnvironmentVariablesService(),
+      });
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-19T20:08:10.910-04:00');
+    });
+
+    test('if `envVarsService` is not set, ensures timestamp is formatted to `UTC` even with `America/New_York` timezone', () => {
+      // Prepare
+      process.env.TZ = 'America/New_York';
+      /* 
+        Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes.
+        The positive value indicates that `America/New_York` is behind UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240);
+      const formatter = new PowertoolsLogFormatter();
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-20T12:08:10.000Z');
+    });
+
+    test('it formats the timestamp to ISO 8601, accounting for the `Asia/Dhaka` timezone offset', () => {
+      // Prepare
+      process.env.TZ = 'Asia/Dhaka';
+      /*
+        Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes.
+        The negative value indicates that `Asia/Dhaka` is ahead of UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360);
+      const formatter = new PowertoolsLogFormatter({
+        envVarsService: new EnvironmentVariablesService(),
+      });
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-20T18:08:10.000+06:00');
+    });
+
+    test('it formats the timestamp to ISO 8601 with correct milliseconds for `Asia/Dhaka` timezone', () => {
+      // Prepare
+      process.env.TZ = 'Asia/Dhaka';
+      jest.useFakeTimers().setSystemTime(new Date('2016-06-20T12:08:10.910Z'));
+      /*
+        Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes.
+        The negative value indicates that `Asia/Dhaka` is ahead of UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360);
+      const formatter = new PowertoolsLogFormatter({
+        envVarsService: new EnvironmentVariablesService(),
+      });
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-20T18:08:10.910+06:00');
+    });
+
+    test('it formats the timestamp to ISO 8601, adjusting for `Asia/Dhaka` timezone, preserving milliseconds and accounting for date change', () => {
+      // Prepare
+      process.env.TZ = 'Asia/Dhaka';
+      const mockDate = new Date('2016-06-20T20:08:10.910Z');
+      jest.useFakeTimers().setSystemTime(mockDate);
+      /*
+        Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes.
+        The negative value indicates that `Asia/Dhaka` is ahead of UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360);
+      const formatter = new PowertoolsLogFormatter({
+        envVarsService: new EnvironmentVariablesService(),
+      });
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-21T02:08:10.910+06:00');
+    });
+
+    test('if `envVarsService` is not set, ensures timestamp is formatted to `UTC` even with `Asia/Dhaka` timezone', () => {
+      // Prepare
+      process.env.TZ = 'Asia/Dhaka';
+      /*
+        Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes.
+        The negative value indicates that `Asia/Dhaka` is ahead of UTC.
+      */
+      jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360);
+      const formatter = new PowertoolsLogFormatter();
+
+      // Act
+      const timestamp = formatter.formatTimestamp(new Date());
+
+      // Assess
+      expect(timestamp).toEqual('2016-06-20T12:08:10.000Z');
+    });
   });
 
   describe('Method: getCodeLocation', () => {
