fix(logger): prevent overwriting standard keys

Author: dreamorosi

packages/logger/src/Logger.ts

@@ -9,7 +9,7 @@ import type {
 import type { Context, Handler } from 'aws-lambda';
 import merge from 'lodash.merge';
 import { EnvironmentVariablesService } from './config/EnvironmentVariablesService.js';
-import { LogJsonIndent, LogLevelThreshold } from './constants.js';
+import { LogJsonIndent, LogLevelThreshold, ReservedKeys } from './constants.js';
 import type { LogFormatter } from './formatter/LogFormatter.js';
 import type { LogItem } from './formatter/LogItem.js';
 import { PowertoolsLogFormatter } from './formatter/PowertoolsLogFormatter.js';
@@ -221,10 +221,7 @@ class Logger extends Utility implements LoggerInterface {
    * @param attributes - The attributes to add to all log items.
    */
   public appendKeys(attributes: LogAttributes): void {
-    for (const attributeKey of Object.keys(attributes)) {
-      this.#keys.set(attributeKey, 'temp');
-    }
-    merge(this.temporaryLogAttributes, attributes);
+    this.#appendAnyKeys(attributes, 'temp');
   }
 
   /**
@@ -233,10 +230,7 @@ class Logger extends Utility implements LoggerInterface {
    * @param attributes - The attributes to add to all log items.
    */
   public appendPersistentKeys(attributes: LogAttributes): void {
-    for (const attributeKey of Object.keys(attributes)) {
-      this.#keys.set(attributeKey, 'persistent');
-    }
-    merge(this.persistentLogAttributes, attributes);
+    this.#appendAnyKeys(attributes, 'persistent');
   }
 
   /**
@@ -293,6 +287,13 @@ class Logger extends Utility implements LoggerInterface {
    * @param extraInput - The extra input to log.
    */
   public debug(input: LogItemMessage, ...extraInput: LogItemExtraInput): void {
+    for (const extra of extraInput) {
+      if (!(extra instanceof Error) && !(typeof extra === 'string')) {
+        for (const key of Object.keys(extra)) {
+          this.#checkReservedKeyAndWarn(key);
+        }
+      }
+    }
     this.processLogItem(LogLevelThreshold.DEBUG, input, extraInput);
   }
 
@@ -666,6 +667,25 @@ class Logger extends Utility implements LoggerInterface {
     merge(this.powertoolsLogData, attributes);
   }
 
+  /**
+   * Shared logic for adding keys to the logger instance.
+   *
+   * @param attributes - The attributes to add to the log item.
+   * @param type - The type of the attributes to add.
+   */
+  #appendAnyKeys(attributes: LogAttributes, type: 'temp' | 'persistent'): void {
+    for (const attributeKey of Object.keys(attributes)) {
+      if (this.#checkReservedKeyAndWarn(attributeKey) === false) {
+        this.#keys.set(attributeKey, 'temp');
+      }
+    }
+    if (type === 'temp') {
+      merge(this.temporaryLogAttributes, attributes);
+    } else {
+      merge(this.persistentLogAttributes, attributes);
+    }
+  }
+
   private awsLogLevelShortCircuit(selectedLogLevel?: string): boolean {
     const awsLogLevel = this.getEnvVarsService().getAwsLogLevel();
     if (this.isValidLogLevel(awsLogLevel)) {
@@ -754,6 +774,19 @@ class Logger extends Utility implements LoggerInterface {
     );
   }
 
+  /**
+   * Check if a given key is reserved and warn the user if it is.
+   *
+   * @param key - The key to check
+   */
+  #checkReservedKeyAndWarn(key: string): boolean {
+    if (ReservedKeys.includes(key)) {
+      this.warn(`The key "${key}" is a reserved key and will be dropped.`);
+      return true;
+    }
+    return false;
+  }
+
   /**
    * Get the custom config service, an abstraction used to fetch environment variables.
    */

packages/logger/src/constants.ts

@@ -37,4 +37,18 @@ const LogLevelThreshold = {
   SILENT: 28,
 } as const;
 
-export { LogJsonIndent, LogLevel, LogLevelThreshold };
+/**
+ * Reserved keys that are included in every log item when using the default log formatter.
+ *
+ * These keys are reserved and cannot be overwritten by custom log attributes.
+ */
+const ReservedKeys = [
+  'level',
+  'message',
+  'sampling_rate',
+  'service',
+  'timestamp',
+  'xray_trace_id',
+];
+
+export { LogJsonIndent, LogLevel, LogLevelThreshold, ReservedKeys };

packages/logger/src/formatter/LogItem.ts

@@ -23,7 +23,7 @@ class LogItem {
    * @param params - The parameters for the LogItem.
    */
   public constructor(params: { attributes: LogAttributes }) {
-    this.addAttributes(params.attributes);
+    this.attributes = params.attributes;
   }
 
   /**
@@ -32,7 +32,7 @@ class LogItem {
    * @param attributes - The attributes to add to the log item.
    */
   public addAttributes(attributes: LogAttributes): this {
-    merge(this.attributes, attributes);
+    merge(attributes, this.attributes);
 
     return this;
   }
@@ -50,7 +50,7 @@ class LogItem {
    * This operation removes empty keys from the log item, see {@link removeEmptyKeys | removeEmptyKeys()} for more information.
    */
   public prepareForPrint(): void {
-    this.setAttributes(this.removeEmptyKeys(this.getAttributes()));
+    this.attributes = this.removeEmptyKeys(this.getAttributes());
   }
 
   /**

packages/logger/tests/unit/repro.test.ts

@@ -0,0 +1,119 @@
+import { expect, it, vi } from 'vitest';
+import { Logger } from '../../src/Logger.js';
+
+vi.hoisted(() => {
+  process.env.POWERTOOLS_DEV = 'true';
+});
+
+it('does not overwrite via appendKeys', () => {
+  const logger = new Logger({
+    logLevel: 'DEBUG',
+  });
+  const debugSpy = vi.spyOn(console, 'debug');
+  const warnSpy = vi.spyOn(console, 'warn');
+
+  logger.appendKeys({
+    level: 'Hello, World!',
+  });
+
+  logger.debug('stuff');
+
+  const log = JSON.parse(debugSpy.mock.calls[0][0]);
+  expect(log).toStrictEqual(
+    expect.objectContaining({
+      level: 'DEBUG',
+    })
+  );
+  expect(warnSpy).toHaveBeenCalledTimes(1);
+  const warn = JSON.parse(warnSpy.mock.calls[0][0]);
+  expect(warn).toStrictEqual(
+    expect.objectContaining({
+      message: 'The key "level" is a reserved key and will be dropped.',
+    })
+  );
+});
+
+it('does not overwrite via appendPersistentKeys', () => {
+  const logger = new Logger({
+    logLevel: 'DEBUG',
+  });
+  const debugSpy = vi.spyOn(console, 'debug');
+  const warnSpy = vi.spyOn(console, 'warn');
+
+  logger.appendPersistentKeys({
+    level: 'Hello, World!',
+  });
+
+  logger.debug('stuff');
+
+  const log = JSON.parse(debugSpy.mock.calls[0][0]);
+  expect(log).toStrictEqual(
+    expect.objectContaining({
+      level: 'DEBUG',
+    })
+  );
+  expect(warnSpy).toHaveBeenCalledTimes(1);
+  const warn = JSON.parse(warnSpy.mock.calls[0][0]);
+  expect(warn).toStrictEqual(
+    expect.objectContaining({
+      message: 'The key "level" is a reserved key and will be dropped.',
+    })
+  );
+});
+
+it('does not overwrite via constructor keys', () => {
+  const debugSpy = vi.spyOn(console, 'debug');
+  const warnSpy = vi.spyOn(console, 'warn');
+  const logger = new Logger({
+    logLevel: 'DEBUG',
+    persistentKeys: {
+      level: 'Hello, World!',
+    },
+  });
+
+  logger.debug('stuff');
+
+  const log = JSON.parse(debugSpy.mock.calls[0][0]);
+  expect(log).toStrictEqual(
+    expect.objectContaining({
+      level: 'DEBUG',
+    })
+  );
+  expect(warnSpy).toHaveBeenCalledTimes(1);
+  const warn = JSON.parse(warnSpy.mock.calls[0][0]);
+  expect(warn).toStrictEqual(
+    expect.objectContaining({
+      message: 'The key "level" is a reserved key and will be dropped.',
+    })
+  );
+});
+
+it('does not overwrite via extra keys', () => {
+  const debugSpy = vi.spyOn(console, 'debug');
+  const warnSpy = vi.spyOn(console, 'warn');
+  const logger = new Logger({
+    logLevel: 'DEBUG',
+  });
+
+  logger.debug('stuff', {
+    level: 'Hello, World!',
+    timestamp: 'foo',
+    message: 'bar',
+  });
+
+  const log = JSON.parse(debugSpy.mock.calls[0][0]);
+  expect(log).toStrictEqual(
+    expect.objectContaining({
+      level: 'DEBUG',
+      timestamp: expect.not.stringMatching('foo'),
+      message: 'stuff',
+    })
+  );
+  expect(warnSpy).toHaveBeenCalledTimes(3);
+  const warn = JSON.parse(warnSpy.mock.calls[0][0]);
+  expect(warn).toStrictEqual(
+    expect.objectContaining({
+      message: 'The key "level" is a reserved key and will be dropped.',
+    })
+  );
+});