Skip to content

fix(logger): logger throws TypeError when log item has BigInt value #1201

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 2 additions & 3 deletions packages/logger/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -46,8 +46,7 @@
},
"dependencies": {
"@aws-lambda-powertools/commons": "^1.5.0",
"lodash.merge": "^4.6.2",
"lodash.pickby": "^4.6.0"
"lodash.merge": "^4.6.2"
},
"keywords": [
"aws",
Expand All @@ -58,4 +57,4 @@
"serverless",
"nodejs"
]
}
}
60 changes: 32 additions & 28 deletions packages/logger/src/Logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -568,6 +568,37 @@ class Logger extends Utility implements ClassThatLogs {
return this.powertoolLogData;
}

/**
* When the data added in the log item contains object references or BigInt values,
* `JSON.stringify()` can't handle them and instead throws errors:
* `TypeError: cyclic object value` or `TypeError: Do not know how to serialize a BigInt`.
* To mitigate these issues, this method will find and remove all cyclic references and convert BigInt values to strings.
*
* @see https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/JSON/stringify#exceptions
* @private
*/
private getReplacer(): (key: string, value: LogAttributes | Error | bigint) => void {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the new name, thanks for making the change

const references = new WeakSet();

return (key, value) => {
let item = value;
if (item instanceof Error) {
item = this.getLogFormatter().formatError(item);
}
if (typeof item === 'bigint') {
return item.toString();
}
if (typeof item === 'object' && value !== null) {
if (references.has(item)) {
return;
}
references.add(item);
}

return item;
};
}

/**
* It returns the numeric sample rate value.
*
Expand Down Expand Up @@ -605,7 +636,7 @@ class Logger extends Utility implements ClassThatLogs {

const consoleMethod = logLevel.toLowerCase() as keyof ClassThatLogs;

this.console[consoleMethod](JSON.stringify(log.getAttributes(), this.removeCircularDependencies(), this.logIndentation));
this.console[consoleMethod](JSON.stringify(log.getAttributes(), this.getReplacer(), this.logIndentation));
}

/**
Expand All @@ -622,33 +653,6 @@ class Logger extends Utility implements ClassThatLogs {
this.printLog(logLevel, this.createAndPopulateLogItem(logLevel, input, extraInput));
}

/**
* When the data added in the log item contains object references,
* JSON.stringify() doesn't try to solve them and instead throws an error: TypeError: cyclic object value.
* To mitigate this issue, this method will find and remove all cyclic references.
*
* @see https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Errors/Cyclic_object_value
* @private
*/
private removeCircularDependencies(): (key: string, value: LogAttributes | Error) => void {
const references = new WeakSet();

return (key, value) => {
let item = value;
if (item instanceof Error) {
item = this.getLogFormatter().formatError(item);
}
if (typeof item === 'object' && value !== null) {
if (references.has(item)) {
return;
}
references.add(item);
}

return item;
};
}

/**
* It initializes console property as an instance of the internal version of Console() class (PR #748)
* or as the global node console if the `POWERTOOLS_DEV' env variable is set and has truthy value.
Expand Down
10 changes: 8 additions & 2 deletions packages/logger/src/log/LogItem.ts
Original file line number Diff line number Diff line change
@@ -1,4 +1,3 @@
import pickBy from 'lodash.pickby';
import merge from 'lodash.merge';
import { LogItemInterface } from '.';
import { LogAttributes } from '../types';
Expand Down Expand Up @@ -31,7 +30,14 @@ class LogItem implements LogItemInterface {
}

public removeEmptyKeys(attributes: LogAttributes): LogAttributes {
return pickBy(attributes, (value) => value !== undefined && value !== '' && value !== null);
const newAttributes: LogAttributes = {};
for (const key in attributes) {
if (attributes[key] !== undefined && attributes[key] !== '' && attributes[key] !== null) {
newAttributes[key] = attributes[key];
}
}

return newAttributes;
}
Comment on lines 32 to 41
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Firstly, I wrote a declarative one-liner:

public removeEmptyKeys(attributes: LogAttributes): LogAttributes {
    return Object.fromEntries(Object.entries(attributes).filter(([, value]) => value !== undefined && value !== '' && value !== null));
}

But for the sake of readability, I stick to the verbose version.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't know if nested objects could be in the logItem, but it wasn't and isn't supported by this function.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you give an example of what do you mean by nested objects?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

logger.info("my message", { value: 42, nested: { value: "nested value", emptyValue: '', undefinedValue: undefined, nullValue: null } });

Copy link
Contributor

@dreamorosi dreamorosi Dec 28, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we need to support nested objects though.

Here's an example of logs emitted by Logger v1.5.0 (latest):
Screenshot 2022-12-28 at 14 40 48

from this code:

import { Logger, injectLambdaContext } from "@aws-lambda-powertools/logger";
import middy from "@middy/core";

const logger = new Logger({});

export const handler = middy(async () => {
  logger.info("my message", {
    value: 42,
    nested: {
      value: "nested value",
      emptyValue: "",
      undefinedValue: undefined,
      nullValue: null,
    },
  });
}).use(injectLambdaContext(logger, { logEvent: true }));

this was the event payload passed:

{
  "key1": "value1",
  "key2": "value2",
  "key3": "value3",
  "nested": {
      "some": "key",
      "other": 1
  }
}

We need to support nested objects both for the logEvent functionality (also present in the unit tests) and arbitrary objects

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh after re-reading I realize I might have misunderstood your comment.

Were you referring to supporting the removal of undefined, null, etc. from nested objects?

yes, it's just go through the first level

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see, apologies for the misunderstanding!

I think that at the moment we should strive for maintaining the same exact functionality level as the current version without breaking changes. Which based on the test I did above, seems to at least remove undefined values.

Then later on, if there's demand we can explore extending the behavior to empty strings and/or null.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

undefined values are filtered somewhere else 🙃

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great then!

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And I definitely support/agree with the choice of using a more verbose version for the sake of readability.


public setAttributes(attributes: LogAttributes): void {
Expand Down
107 changes: 84 additions & 23 deletions packages/logger/tests/unit/Logger.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -533,6 +533,68 @@ describe('Class: Logger', () => {

});

test('when a logged item has BigInt value, it doen\'t throw TypeError', () => {

// Prepare
const logger = new Logger();
jest.spyOn(logger['console'], methodOfLogger).mockImplementation();
const message = `This is an ${methodOfLogger} log with BigInt value`;
const logItem = { value: BigInt(42) };
const errorMessage = 'Do not know how to serialize a BigInt';

// Act & Assess
expect(() => { logger[methodOfLogger](message, logItem); }).not.toThrow(errorMessage);

});

test('when a logged item has a BigInt value, it prints the log with value as a string', () => {

// Prepare
const logger = new Logger();
const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation();
const message = `This is an ${methodOfLogger} log with BigInt value`;
const logItem = { value: BigInt(42) };

// Act
logger[methodOfLogger](message, logItem);

// Assess
expect(consoleSpy).toBeCalledTimes(1);
expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: methodOfLogger.toUpperCase(),
message: message,
service: 'hello-world',
timestamp: '2016-06-20T12:08:10.000Z',
xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
value: '42',
}));

});

test('when a logged item has empty string, null, or undefined values, it removes it', () => {

// Prepare
const logger = new Logger();
const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation();
const message = `This is an ${methodOfLogger} log with empty, null, and undefined values`;
const logItem = { value: 42, emptyValue: '', undefinedValue: undefined, nullValue: null };

// Act
logger[methodOfLogger](message, logItem);

// Assess
expect(consoleSpy).toBeCalledTimes(1);
expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: methodOfLogger.toUpperCase(),
message: message,
service: 'hello-world',
timestamp: '2016-06-20T12:08:10.000Z',
xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
value: 42,
}));

});

});
});

Expand Down Expand Up @@ -765,34 +827,33 @@ describe('Class: Logger', () => {
}));
});

});

test('when called multiple times with the same keys, the outcome is the same', () => {

// Prepare
const logger = new Logger();
logger.appendKeys({
aws_account_id: '123456789012',
aws_region: 'eu-west-1',
logger: {
name: 'aws-lambda-powertool-typescript',
version: '0.2.4',
},
});

// Act
logger.removeKeys([ 'aws_account_id', 'aws_region' ]);
logger.removeKeys([ 'aws_account_id', 'aws_region' ]);
test('when called multiple times with the same keys, the outcome is the same', () => {

// Assess
expect(logger).toEqual(expect.objectContaining({
persistentLogAttributes: {
// Prepare
const logger = new Logger();
logger.appendKeys({
aws_account_id: '123456789012',
aws_region: 'eu-west-1',
logger: {
name: 'aws-lambda-powertool-typescript',
version: '0.2.4',
},
},
}));
});

// Act
logger.removeKeys([ 'aws_account_id', 'aws_region' ]);
logger.removeKeys([ 'aws_account_id', 'aws_region' ]);

// Assess
expect(logger).toEqual(expect.objectContaining({
persistentLogAttributes: {
logger: {
name: 'aws-lambda-powertool-typescript',
version: '0.2.4',
},
},
}));
});

});

Expand Down