From f071baad6112b23da0510479e7a68e9667623936 Mon Sep 17 00:00:00 2001 From: Sara Gerion Date: Tue, 23 Mar 2021 21:18:49 +0100 Subject: [PATCH 1/2] chore(logger): merge with main --- .eslintrc.js | 1 + packages/logger/README.md | 3 - .../logger/examples/custom-logger-options.ts | 3 +- .../logger/examples/ephemeral-attributes.ts | 38 ++ packages/logger/examples/errors.ts | 36 ++ .../examples/formatters/CustomLogFormatter.ts | 8 +- ...orld-with-context.ts => inject-context.ts} | 1 - .../logger/examples/persistent-attributes.ts | 40 ++ packages/logger/examples/sample-rate.ts | 3 + packages/logger/package.json | 8 +- packages/logger/src/Logger.ts | 374 ++++++++---------- packages/logger/src/LoggerInterface.ts | 10 +- packages/logger/src/config/ConfigService.ts | 3 - .../src/config/ConfigServiceInterface.ts | 2 - .../src/config/EnvironmentVariablesService.ts | 4 - packages/logger/src/formatter/LogFormatter.ts | 27 +- .../src/formatter/LogFormatterInterface.ts | 4 +- .../src/formatter/PowertoolLogFormatter.ts | 8 +- packages/logger/src/log/LogItem.ts | 23 +- packages/logger/src/log/LogItemInterface.ts | 2 - packages/logger/types/Logger.ts | 23 +- 21 files changed, 361 insertions(+), 260 deletions(-) create mode 100644 packages/logger/examples/ephemeral-attributes.ts create mode 100644 packages/logger/examples/errors.ts rename packages/logger/examples/{hello-world-with-context.ts => inject-context.ts} (94%) create mode 100644 packages/logger/examples/persistent-attributes.ts diff --git a/.eslintrc.js b/.eslintrc.js index 6ffb8193a4..e649c90fd4 100644 --- a/.eslintrc.js +++ b/.eslintrc.js @@ -48,6 +48,7 @@ module.exports = { 'no-console': 0, 'no-multi-spaces': [ 'error', { 'ignoreEOLComments': false } ], 'no-multiple-empty-lines': [ 'error', { 'max': 1, 'maxBOF': 0 } ], + 'no-throw-literal': 'error', 'object-curly-spacing': [ 'error', 'always' ], 'prefer-arrow-callback': 'error', 'quotes': [ 'error', 'single', { 'allowTemplateLiterals': true } ], diff --git a/packages/logger/README.md b/packages/logger/README.md index 2fe5a328f8..fab7a82fac 100644 --- a/packages/logger/README.md +++ b/packages/logger/README.md @@ -56,7 +56,6 @@ Without decorators: // Environment variables set for the Lambda process.env.LOG_LEVEL = 'WARN'; process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; -process.env.POWERTOOLS_CONTEXT_ENABLED = 'TRUE'; const logger = new Logger(); @@ -333,9 +332,7 @@ const lambdaHandler: Handler = async () => { ## Custom logger options: log level, service name, sample rate value, log attributes, variables source, log format ```typescript - process.env.CUSTOM_ENV = 'prod'; -process.env.POWERTOOLS_CONTEXT_ENABLED = 'TRUE'; // Custom configuration service for variables, and custom formatter to comply to different log JSON schema import { CustomConfigService } from './config/CustomConfigService'; diff --git a/packages/logger/examples/custom-logger-options.ts b/packages/logger/examples/custom-logger-options.ts index a861bae120..21e43a1d81 100644 --- a/packages/logger/examples/custom-logger-options.ts +++ b/packages/logger/examples/custom-logger-options.ts @@ -4,7 +4,6 @@ import { populateEnvironmentVariables } from '../tests/helpers'; populateEnvironmentVariables(); // Additional runtime variables process.env.CUSTOM_ENV = 'prod'; -process.env.POWERTOOLS_CONTEXT_ENABLED = 'TRUE'; import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; import * as powertool from '../../../package.json'; @@ -18,7 +17,7 @@ const logger = new Logger({ logLevel: 'INFO', // Override options serviceName: 'foo-bar', sampleRateValue: 0.00001, - customAttributes: { // Custom attributes that will be added in every log + persistentLogAttributes: { // Custom attributes that will be added in every log awsAccountId: '123456789012', logger: { name: powertool.name, diff --git a/packages/logger/examples/ephemeral-attributes.ts b/packages/logger/examples/ephemeral-attributes.ts new file mode 100644 index 0000000000..722c4d6ba7 --- /dev/null +++ b/packages/logger/examples/ephemeral-attributes.ts @@ -0,0 +1,38 @@ +import { populateEnvironmentVariables } from '../tests/helpers'; + +// Populate runtime +populateEnvironmentVariables(); +// Additional runtime variables +process.env.LOG_LEVEL = 'WARN'; +process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; + +import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; +import { context as dummyContext } from '../../../tests/resources/contexts/hello-world'; +import { Handler } from 'aws-lambda'; +import { Logger } from '../src'; + +const logger = new Logger(); + +const lambdaHandler: Handler = async () => { + + // Example of use case: + // Log an error with a message (informative string) and + // some extra ephemeral custom attributes to help debugging (like a correlation ID) + + // Logs below will result in the same JSON output + + const error = new Error('Something bad happened!'); + + // You can add ephemeral extra custom attributes like this: + logger.error('This is an ERROR log', error, { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }); + + // Or you can also add them like this (same log output): + logger.error({ message: 'This is an ERROR log', correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }, error); + + return { + foo: 'bar' + }; + +}; + +lambdaHandler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); \ No newline at end of file diff --git a/packages/logger/examples/errors.ts b/packages/logger/examples/errors.ts new file mode 100644 index 0000000000..bee4eb23a6 --- /dev/null +++ b/packages/logger/examples/errors.ts @@ -0,0 +1,36 @@ +import { populateEnvironmentVariables } from '../tests/helpers'; + +// Populate runtime +populateEnvironmentVariables(); +// Additional runtime variables +process.env.LOG_LEVEL = 'WARN'; +process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; + +import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; +import { context as dummyContext } from '../../../tests/resources/contexts/hello-world'; +import { Handler } from 'aws-lambda'; +import { Logger } from '../src'; + +const logger = new Logger(); + +const lambdaHandler: Handler = async () => { + + try { + throw new Error('Unexpected error #1'); + } catch (error) { + logger.error('This is an ERROR log', error); + } + + try { + throw new Error('Unexpected error #2'); + } catch (error) { + logger.error('This is an ERROR log', { myCustomErrorKey: error } ); + } + + return { + foo: 'bar' + }; + +}; + +lambdaHandler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); \ No newline at end of file diff --git a/packages/logger/examples/formatters/CustomLogFormatter.ts b/packages/logger/examples/formatters/CustomLogFormatter.ts index 8bb0872e3c..702b2a7939 100644 --- a/packages/logger/examples/formatters/CustomLogFormatter.ts +++ b/packages/logger/examples/formatters/CustomLogFormatter.ts @@ -5,7 +5,7 @@ type MyCompanyLog = LogAttributes; class CustomLogFormatter extends LogFormatter { - public format(attributes: UnformattedAttributes): MyCompanyLog { + public formatAttributes(attributes: UnformattedAttributes): MyCompanyLog { return { message: attributes.message, service: attributes.serviceName, @@ -16,10 +16,10 @@ class CustomLogFormatter extends LogFormatter { xRayTraceId: attributes.xRayTraceId }, lambdaFunction: { - name: attributes.lambdaContext?.name, - arn: attributes.lambdaContext?.arn, + name: attributes.lambdaContext?.functionName, + arn: attributes.lambdaContext?.invokedFunctionArn, memoryLimitInMB: attributes.lambdaContext?.memoryLimitInMB, - version: attributes.lambdaContext?.version, + version: attributes.lambdaContext?.functionVersion, coldStart: attributes.lambdaContext?.coldStart, }, logLevel: attributes.logLevel, diff --git a/packages/logger/examples/hello-world-with-context.ts b/packages/logger/examples/inject-context.ts similarity index 94% rename from packages/logger/examples/hello-world-with-context.ts rename to packages/logger/examples/inject-context.ts index 806cbd9433..7ee0711965 100644 --- a/packages/logger/examples/hello-world-with-context.ts +++ b/packages/logger/examples/inject-context.ts @@ -5,7 +5,6 @@ populateEnvironmentVariables(); // Additional runtime variables process.env.LOG_LEVEL = 'WARN'; process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; -process.env.POWERTOOLS_CONTEXT_ENABLED = 'TRUE'; import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; import { context as dummyContext } from '../../../tests/resources/contexts/hello-world'; diff --git a/packages/logger/examples/persistent-attributes.ts b/packages/logger/examples/persistent-attributes.ts new file mode 100644 index 0000000000..a348ddf9d2 --- /dev/null +++ b/packages/logger/examples/persistent-attributes.ts @@ -0,0 +1,40 @@ +import { populateEnvironmentVariables } from '../tests/helpers'; + +// Populate runtime +populateEnvironmentVariables(); +// Additional runtime variables +process.env.LOG_LEVEL = 'INFO'; +process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; + +import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; +import * as powertool from '../../../package.json'; +import { context as dummyContext } from '../../../tests/resources/contexts/hello-world'; +import { Handler } from 'aws-lambda'; +import { Logger } from '../src'; + +// You can add persistent extra custom attributes directly in the constructor of the logger: +const logger = new Logger(); + +const lambdaHandler: Handler = async () => { + + // Or you can choose to add persistent log keys to an existing Logger instance: + logger.appendKeys({ + aws_account_id: '123456789012', + aws_region: 'eu-central-1', + logger: { + name: powertool.name, + version: powertool.version, + } + }); + + // This info log will print all extra custom attributes added above + // Extra attributes: logger object with name and version of this library, awsAccountId, awsRegion + logger.info('This is an INFO log'); + + return { + foo: 'bar' + }; + +}; + +lambdaHandler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); \ No newline at end of file diff --git a/packages/logger/examples/sample-rate.ts b/packages/logger/examples/sample-rate.ts index 72937304e3..6f0402b568 100644 --- a/packages/logger/examples/sample-rate.ts +++ b/packages/logger/examples/sample-rate.ts @@ -21,6 +21,9 @@ const lambdaHandler: Handler = async () => { logger.info('This is INFO log #3'); logger.info('This is INFO log #4'); + // Refresh sample rate calculation on runtime + logger.refreshSampleRateCalculation(); + return { foo: 'bar' }; diff --git a/packages/logger/package.json b/packages/logger/package.json index 1669113d63..b062e02b67 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -19,12 +19,14 @@ "version": "npm run format && git add -A src", "postversion": "git push && git push --tags", "example:hello-world": "ts-node examples/hello-world.ts", - "example:hello-world-with-context": "ts-node examples/hello-world-with-context.ts", - "example:hello-world-with-context-decorators": "ts-node examples/hello-world-with-context-decorators.ts", + "example:hello-world-with-context": "ts-node examples/inject-context.ts", + "example:hello-world-errors": "ts-node examples/errors.ts", "example:custom-logger-options": "ts-node examples/custom-logger-options.ts", "example:child-logger": "ts-node examples/child-logger.ts", "example:additional-keys": "ts-node examples/additional-keys.ts", - "example:sample-rate": "ts-node examples/sample-rate.ts" + "example:sample-rate": "ts-node examples/sample-rate.ts", + "example:persistent-attributes": "ts-node examples/persistent-attributes.ts", + "example:ephemeral-attributes": "ts-node examples/ephemeral-attributes.ts" }, "homepage": "https://github.com/awslabs/aws-lambda-powertools-typescript/tree/master/packages/logging#readme", "license": "MIT", diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index e93267e9b2..e7eb1dc19e 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -6,36 +6,31 @@ import { cloneDeep, merge } from 'lodash/fp'; import { ConfigServiceInterface, EnvironmentVariablesService } from './config'; import { LogFormatterInterface, PowertoolLogFormatter } from './formatter'; import { - PowertoolLogAttributes, + Environment, + PowertoolLogData, LogAttributes, LoggerOptions, LogLevel, LogLevelThresholds, LambdaFunctionContext, - LoggerInput, - LoggerExtraInput, + LogItemMessage, + LogItemExtraInput, HandlerMethodDecorator } from '../types'; class Logger implements LoggerInterface { - private customAttributes: LogAttributes; + private static coldStart: boolean = true; private customConfigService?: ConfigServiceInterface; - private static readonly defaultIsContextEnabled: boolean = false; + private static readonly defaultLogLevel: LogLevel = 'INFO'; - private static readonly defaultLogLevelThreshold: LogLevel = 'INFO'; + private envVarsService?: EnvironmentVariablesService; - private readonly envVarsService: EnvironmentVariablesService; + private logFormatter?: LogFormatterInterface; - private static isColdStart: boolean = true; - - private isContextEnabled: boolean; - - private logFormatter: LogFormatterInterface; - - private logLevelThreshold: LogLevel; + private logLevel?: LogLevel; private readonly logLevelThresholds: LogLevelThresholds = { 'DEBUG' : 8, @@ -44,79 +39,67 @@ class Logger implements LoggerInterface { 'ERROR': 20 }; - private powertoolLogAttributes: PowertoolLogAttributes = {}; + private logsSampled: boolean = false; - private sampleRateValue?: number; + private persistentLogAttributes?: LogAttributes = {}; - public constructor(options: LoggerOptions = {}) { - const { - logLevel, - serviceName, - sampleRateValue, - logFormatter, - customConfigService, - customAttributes, - environment, - isContextEnabled - } = options; + private powertoolLogData: PowertoolLogData = {}; - this.customAttributes = this.pickValueWithDefault({}, customAttributes); - this.customConfigService = customConfigService; - this.envVarsService = new EnvironmentVariablesService(); - this.isContextEnabled = this.pickValueWithDefault( - Logger.defaultIsContextEnabled, - isContextEnabled, - this.getCustomConfigService()?.getIsContextEnabled(), - this.getEnvVarsService().getIsContextEnabled() - ); - this.logFormatter = this.pickValueWithDefault(new PowertoolLogFormatter(),logFormatter); - this.logLevelThreshold = this.pickValueWithDefault( - Logger.defaultLogLevelThreshold,logLevel, - this.getCustomConfigService()?.getLogLevel(), - this.getEnvVarsService().getLogLevel() - ); - this.sampleRateValue = this.pickValue( - sampleRateValue, - this.getCustomConfigService()?.getSampleRateValue(), - this.getEnvVarsService()?.getSampleRateValue() - ); - this.populatePowertoolLogAttributes(serviceName, environment); + public constructor(options: LoggerOptions = {}) { + this.setOptions(options); } public addContext(context: Context): void { - if (!this.getIsContextEnabled()) { - return; - } - const lambdaContext: Partial = { - arn: context.invokedFunctionArn, + invokedFunctionArn: context.invokedFunctionArn, + coldStart: Logger.isColdStart(), awsRequestId: context.awsRequestId, memoryLimitInMB: Number(context.memoryLimitInMB), - name: context.functionName, - version: context.functionVersion, + functionName: context.functionName, + functionVersion: context.functionVersion, }; - this.addToPowertoolLogAttributes({ + this.addToPowertoolLogData({ lambdaContext }); + } + + public addPersistentLogAttributes(attributes?: LogAttributes): void { + this.persistentLogAttributes = merge(this.getPersistentLogAttributes(), attributes); + } + public appendKeys(attributes?: LogAttributes): void { + this.addPersistentLogAttributes(attributes); } public createChild(options: LoggerOptions = {}): Logger { - return cloneDeep(this).applyOptions(options); + return cloneDeep(this).setOptions(options); + } + + public debug(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { + if (!this.shouldPrint('DEBUG')) { + return; + } + this.printLog(this.createAndPopulateLogItem('DEBUG', input, extraInput)); } - public debug(input: LoggerInput, ...extraInput: LoggerExtraInput): void { - this.processLogInputData('DEBUG', input, extraInput); + public error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { + if (!this.shouldPrint('ERROR')) { + return; + } + this.printLog(this.createAndPopulateLogItem('ERROR', input, extraInput)); } - public error(input: LoggerInput, ...extraInput: LoggerExtraInput): void { - this.processLogInputData('ERROR', input, extraInput); + public info(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { + if (!this.shouldPrint('INFO')) { + return; + } + this.printLog(this.createAndPopulateLogItem('INFO', input, extraInput)); } - public static getIsColdStart(): boolean { - if (Logger.isColdStart === true) { - Logger.isColdStart = false; + public static isColdStart(): boolean { + if (Logger.coldStart === true) { + Logger.coldStart = false; return true; } @@ -124,220 +107,191 @@ class Logger implements LoggerInterface { return false; } - public info(input: LoggerInput, ...extraInput: LoggerExtraInput): void { - this.processLogInputData('INFO', input, extraInput); + public refreshSampleRateCalculation(): void { + this.setLogsSampled(); } - public injectLambdaContext(enableContext: boolean = true): HandlerMethodDecorator { - return (target, propertyKey, descriptor ) => { - const originalMethod = descriptor.value; - - descriptor.value = (event, context, callback) => { - this.setIsContextEnabled(enableContext); - this.addContext(context); - const result = originalMethod?.apply(this, [ event, context, callback ]); - - return result; - }; - }; + public setSampleRateValue(sampleRateValue?: number): void { + this.powertoolLogData.sampleRateValue = sampleRateValue || this.getCustomConfigService()?.getSampleRateValue() + || this.getEnvVarsService().getSampleRateValue(); } - public warn(input: LoggerInput, ...extraInput: LoggerExtraInput): void { - this.processLogInputData('WARN', input, extraInput); + public warn(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { + if (!this.shouldPrint('WARN')) { + return; + } + this.printLog(this.createAndPopulateLogItem('WARN', input, extraInput)); } - private addToPowertoolLogAttributes(...attributesArray: Array>): void { - attributesArray.forEach((attributes: Partial) => { - this.powertoolLogAttributes = merge(this.getPowertoolLogAttributes(), attributes); + private addToPowertoolLogData(...attributesArray: Array>): void { + attributesArray.forEach((attributes: Partial) => { + this.powertoolLogData = merge(this.getPowertoolLogData(), attributes); }); } - private applyOptions(options: LoggerOptions): Logger { - const { - logLevel, - serviceName, - sampleRateValue, - logFormatter, - customConfigService, - customAttributes, - environment, - isContextEnabled - } = options; - - if (customAttributes) { - this.setCustomAttributes(customAttributes); - } - if (customConfigService) { - this.setCustomConfigService(customConfigService); - } - if (isContextEnabled){ - this.setIsContextEnabled(isContextEnabled); - } - if (logFormatter) { - this.setLogFormatter(logFormatter); - } - if (logLevel) { - this.setLogLevelThreshold(logLevel); - } - if (sampleRateValue) { - this.setSampleRateValue(sampleRateValue); - } - if (serviceName || environment || isContextEnabled || customConfigService || logFormatter) { - this.populatePowertoolLogAttributes(serviceName, environment); - } - - return this; - } + private createAndPopulateLogItem(logLevel: LogLevel, input: LogItemMessage, extraInput: LogItemExtraInput): LogItem { - private createLogItem(logLevel: LogLevel, input: LoggerInput, extraInput: LoggerExtraInput): LogItem { + const unformattedBaseAttributes = merge( + this.getPowertoolLogData(), + { + logLevel, + timestamp: new Date(), + message: (typeof input === 'string') ? input : input.message + }); - const logItem = new LogItem().addAttributes( - this.getLogFormatter().format( - merge({ - logLevel, - timestamp: new Date(), - message: (typeof input === 'string') ? input : input.message - }, - this.getPowertoolLogAttributes()) - ) - ).addAttributes(this.getCustomAttributes()); + const logItem = new LogItem({ + baseAttributes: this.getLogFormatter().formatAttributes(unformattedBaseAttributes), + persistentAttributes: this.getPersistentLogAttributes() + }); + // Add ephemeral attributes if (typeof input !== 'string') { logItem.addAttributes(input); } - extraInput.forEach((item: Error | LogAttributes) => { - const attributes = (item instanceof Error) ? { - error: { - name: item.name, - message: item.message, - stack: item.stack, - } - } : item; + const attributes = (item instanceof Error) ? { error: item } : item; logItem.addAttributes(attributes); }); return logItem; } - private getCustomAttributes(): LogAttributes { - return this.customAttributes; - } - private getCustomConfigService(): ConfigServiceInterface | undefined { return this.customConfigService; } private getEnvVarsService(): EnvironmentVariablesService { - return this.envVarsService; - } + if (!this.envVarsService) { + this.setEnvVarsService(); + } - private getIsContextEnabled(): boolean { - return this.isContextEnabled; + return this.envVarsService; } private getLogFormatter(): LogFormatterInterface { - return this.logFormatter; - } + if (!this.logFormatter) { + this.setLogFormatter(); + } - private getLogLevelThreshold(): LogLevel { - return this.logLevelThreshold; + return this.logFormatter; } - private getPowertoolLogAttributes(): PowertoolLogAttributes { - return this.powertoolLogAttributes; + private getLogLevel(): LogLevel { + if (this.powertoolLogData?.logLevel) { + this.setLogLevel(); + } + + return this.logLevel; } - private getSampleRateValue(): number | undefined { - return this.sampleRateValue; + private getLogsSampled(): boolean { + return this.logsSampled; } - private pickValue(...values: Array): ValueType | undefined { - for (const entry of values) { - if (entry) { - return entry; - } - } + private getPersistentLogAttributes(): LogAttributes { + return this.persistentLogAttributes || {}; + } - return undefined; + private getPowertoolLogData(): PowertoolLogData { + return this.powertoolLogData || {}; } - private pickValueWithDefault(defaultValue: ValueType, ...values: Array): ValueType { - return this.pickValue(...values) || defaultValue; + private getSampleRateValue(): number { + if (!this.powertoolLogData?.sampleRateValue) { + this.setSampleRateValue(); + } + + return this.powertoolLogData?.sampleRateValue; } - private populatePowertoolLogAttributes(serviceName?: string, environment?: string): void { + private printLog(log: LogItem): void { + log.prepareForPrint(); - this.addToPowertoolLogAttributes({ - awsRegion: this.getEnvVarsService().getAwsRegion(), - environment: this.pickValue(environment, this.getCustomConfigService()?.getCurrentEnvironment(), this.getEnvVarsService().getCurrentEnvironment()), - sampleRateValue: this.getSampleRateValue(), - serviceName: this.pickValue(serviceName,this.getCustomConfigService()?.getServiceName(), this.getEnvVarsService().getServiceName()), - xRayTraceId: this.getEnvVarsService().getXrayTraceId(), - }); + const references = new WeakSet(); - if (this.getIsContextEnabled()) { - this.addToPowertoolLogAttributes({ - lambdaContext: { - coldStart: Logger.getIsColdStart(), - memoryLimitInMB: this.getEnvVarsService().getFunctionMemory(), - name: this.getEnvVarsService().getFunctionName(), - version: this.getEnvVarsService().getFunctionVersion(), + try { + console.log(JSON.parse(JSON.stringify(log.getAttributes(), (key: string, value: LogAttributes) => { + 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; + }))); + } catch (err) { + console.log('Unexpected error occurred trying to print the log', err); } } - private printLog(log: LogAttributes): void { - // TODO: revisit this - Object.keys(log).forEach(key => (log[key] === undefined || log[key] === '' || log[key] === null) && delete log[key]); - - console.log(log); + private setCustomConfigService(customConfigService?: ConfigServiceInterface): void { + this.customConfigService = customConfigService? customConfigService : undefined; } - private processLogInputData(logLevel: LogLevel, input: LoggerInput, extraInput: LoggerExtraInput): void { - if (!this.shouldPrint(logLevel)) { - return; - } - this.printLog(this.createLogItem(logLevel, input, extraInput).getAttributes()); + private setEnvVarsService(): void { + this.envVarsService = new EnvironmentVariablesService(); } - private setCustomAttributes(attributes: LogAttributes): void { - this.customAttributes = attributes; + private setLogFormatter(logFormatter?: LogFormatterInterface): void { + this.logFormatter = logFormatter || new PowertoolLogFormatter(); } - private setCustomConfigService(customConfigService?: ConfigServiceInterface): void { - this.customConfigService = customConfigService; + private setLogLevel(logLevel?: LogLevel): void { + this.logLevel = (logLevel || this.getCustomConfigService()?.getLogLevel() || this.getEnvVarsService().getLogLevel() + || Logger.defaultLogLevel) as LogLevel; } - private setIsContextEnabled(value: boolean = true): void { - this.isContextEnabled = value; + private setLogsSampled(): void { + const sampleRateValue = this.getSampleRateValue(); + // TODO: revisit Math.random() as it's not a real randomization + this.logsSampled = sampleRateValue !== undefined && (sampleRateValue === 1 || Math.random() < sampleRateValue); } - private setLogFormatter(value: LogFormatterInterface): void { - this.logFormatter = value; - } + private setOptions(options: LoggerOptions = {}): Logger { + const { + logLevel, + serviceName, + sampleRateValue, + logFormatter, + customConfigService, + persistentLogAttributes, + environment + } = options; + + this.setEnvVarsService(); + this.setCustomConfigService(customConfigService); + this.setLogLevel(logLevel); + this.setSampleRateValue(sampleRateValue); + this.setLogsSampled(); + this.setLogFormatter(logFormatter); + this.setPowertoolLogData(serviceName, environment); + + this.addPersistentLogAttributes(persistentLogAttributes); - private setLogLevelThreshold(value: LogLevel): void { - this.logLevelThreshold = value; + return this; } - private setSampleRateValue(value?: number): void { - this.sampleRateValue = value; + private setPowertoolLogData(serviceName?: string, environment?: Environment, persistentLogAttributes: LogAttributes = {}): void { + this.addToPowertoolLogData({ + awsRegion: this.getEnvVarsService().getAwsRegion(), + environment: environment || this.getCustomConfigService()?.getCurrentEnvironment() || this.getEnvVarsService().getCurrentEnvironment(), + sampleRateValue: this.getSampleRateValue(), + serviceName: serviceName || this.getCustomConfigService()?.getServiceName() || this.getEnvVarsService().getServiceName(), + xRayTraceId: this.getEnvVarsService().getXrayTraceId(), + }, persistentLogAttributes ); } private shouldPrint(logLevel: LogLevel): boolean { - if (this.logLevelThresholds[logLevel] >= this.logLevelThresholds[this.getLogLevelThreshold()]) { - return true; - } - - // TODO: refactor this logic (Math.random() does not provide cryptographically secure random numbers) - const sampleRateValue = this.getSampleRateValue(); - if (sampleRateValue && (sampleRateValue === 1 || Math.random() < sampleRateValue)) { + if (this.logLevelThresholds[logLevel] >= this.logLevelThresholds[this.getLogLevel()]) { return true; } - return false; + return this.getLogsSampled(); } } diff --git a/packages/logger/src/LoggerInterface.ts b/packages/logger/src/LoggerInterface.ts index 1b0a98919c..39b78f8fc5 100644 --- a/packages/logger/src/LoggerInterface.ts +++ b/packages/logger/src/LoggerInterface.ts @@ -1,14 +1,14 @@ -import { LoggerExtraInput, LoggerInput } from '../types'; +import { LogItemExtraInput, LogItemMessage } from '../types'; interface LoggerInterface { - debug(input: LoggerInput, ...extraInput: LoggerExtraInput): void + debug(input: LogItemMessage, ...extraInput: LogItemExtraInput): void - error(input: LoggerInput, ...extraInput: LoggerExtraInput): void + error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void - info(input: LoggerInput, ...extraInput: LoggerExtraInput): void + info(input: LogItemMessage, ...extraInput: LogItemExtraInput): void - warn(input: LoggerInput, ...extraInput: LoggerExtraInput): void + warn(input: LogItemMessage, ...extraInput: LogItemExtraInput): void } diff --git a/packages/logger/src/config/ConfigService.ts b/packages/logger/src/config/ConfigService.ts index 526f7cb892..1f2797b4d1 100644 --- a/packages/logger/src/config/ConfigService.ts +++ b/packages/logger/src/config/ConfigService.ts @@ -3,7 +3,6 @@ import { ConfigServiceInterface } from '.'; abstract class ConfigService implements ConfigServiceInterface { // Custom environment variables - protected contextEnabledVariable = 'POWERTOOLS_CONTEXT_ENABLED'; protected currentEnvironmentVariable = 'ENVIRONMENT'; protected logLevelVariable = 'LOG_LEVEL'; protected sampleRateValueVariable = 'POWERTOOLS_LOGGER_SAMPLE_RATE'; @@ -13,8 +12,6 @@ abstract class ConfigService implements ConfigServiceInterface { abstract getCurrentEnvironment(): string; - abstract getIsContextEnabled(): boolean; - abstract getLogLevel(): string; abstract getSampleRateValue(): number | undefined; diff --git a/packages/logger/src/config/ConfigServiceInterface.ts b/packages/logger/src/config/ConfigServiceInterface.ts index b04f4866e9..a1db5bd465 100644 --- a/packages/logger/src/config/ConfigServiceInterface.ts +++ b/packages/logger/src/config/ConfigServiceInterface.ts @@ -4,8 +4,6 @@ interface ConfigServiceInterface { getCurrentEnvironment(): string - getIsContextEnabled(): boolean - getLogLevel(): string getSampleRateValue(): number | undefined diff --git a/packages/logger/src/config/EnvironmentVariablesService.ts b/packages/logger/src/config/EnvironmentVariablesService.ts index bc61f23fb7..fec5fdae88 100644 --- a/packages/logger/src/config/EnvironmentVariablesService.ts +++ b/packages/logger/src/config/EnvironmentVariablesService.ts @@ -35,10 +35,6 @@ class EnvironmentVariablesService extends ConfigService { return this.get(this.functionVersionVariable); } - public getIsContextEnabled(): boolean { - return [ '1', 'TRUE', 'ON' ].includes(this.get(this.contextEnabledVariable).toUpperCase()); - } - public getLogLevel(): string { return this.get(this.logLevelVariable); } diff --git a/packages/logger/src/formatter/LogFormatter.ts b/packages/logger/src/formatter/LogFormatter.ts index fe062191dd..862f2d1d73 100644 --- a/packages/logger/src/formatter/LogFormatter.ts +++ b/packages/logger/src/formatter/LogFormatter.ts @@ -3,11 +3,36 @@ import { LogAttributes, UnformattedAttributes } from '../../types'; abstract class LogFormatter implements LogFormatterInterface { - abstract format(attributes: UnformattedAttributes): LogAttributes; + abstract formatAttributes(attributes: UnformattedAttributes): LogAttributes; + + public formatError(error: Error): LogAttributes { + return { + name: error.name, + location: this.getCodeLocation(error.stack), + message: error.message, + stack: error.stack, + + }; + } public formatTimestamp(now: Date): string { return now.toISOString(); } + + public getCodeLocation(stack?: string): string { + if (!stack) { + return ''; + } + + const regex = /\((.*):(\d+):(\d+)\)$/; + const match = regex.exec(stack.split('\n')[1]); + + if (!Array.isArray(match)) { + return ''; + } + + return `${match[1]}:${Number(match[2])}`; + } } export { diff --git a/packages/logger/src/formatter/LogFormatterInterface.ts b/packages/logger/src/formatter/LogFormatterInterface.ts index 82492fe36c..7d415cbf40 100644 --- a/packages/logger/src/formatter/LogFormatterInterface.ts +++ b/packages/logger/src/formatter/LogFormatterInterface.ts @@ -2,7 +2,9 @@ import { LogAttributes, UnformattedAttributes } from '../../types'; interface LogFormatterInterface { - format(attributes: UnformattedAttributes): LogAttributes + formatAttributes(attributes: UnformattedAttributes): LogAttributes + + formatError(error: Error): LogAttributes } diff --git a/packages/logger/src/formatter/PowertoolLogFormatter.ts b/packages/logger/src/formatter/PowertoolLogFormatter.ts index da747dfd20..b5d25cded1 100644 --- a/packages/logger/src/formatter/PowertoolLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolLogFormatter.ts @@ -4,19 +4,19 @@ import { UnformattedAttributes } from '../../types'; class PowertoolLogFormatter extends LogFormatter { - public format(attributes: UnformattedAttributes): PowertoolLog { + public formatAttributes(attributes: UnformattedAttributes): PowertoolLog { return { aws_request_id: attributes.lambdaContext?.awsRequestId, cold_start: attributes.lambdaContext?.coldStart, - lambda_function_arn: attributes.lambdaContext?.arn, + lambda_function_arn: attributes.lambdaContext?.invokedFunctionArn, lambda_function_memory_size: attributes.lambdaContext?.memoryLimitInMB, - lambda_function_name: attributes.lambdaContext?.name, + lambda_function_name: attributes.lambdaContext?.functionName, level: attributes.logLevel, message: attributes.message, sampling_rate: attributes.sampleRateValue, service: attributes.serviceName, timestamp: this.formatTimestamp(attributes.timestamp), - xray_trace_id: attributes.xRayTraceId, + xray_trace_id: attributes.xRayTraceId }; } diff --git a/packages/logger/src/log/LogItem.ts b/packages/logger/src/log/LogItem.ts index 7c94cceaef..33af6c67ff 100644 --- a/packages/logger/src/log/LogItem.ts +++ b/packages/logger/src/log/LogItem.ts @@ -1,11 +1,20 @@ import { LogAttributes } from '../../types'; import { LogItemInterface } from '.'; -import { merge } from 'lodash/fp'; +import { pickBy, merge } from 'lodash'; class LogItem implements LogItemInterface { private attributes: LogAttributes = {}; + public constructor(params: { baseAttributes: LogAttributes; persistentAttributes: LogAttributes }) { + // Add attributes in the log item in this order: + // - Base attributes supported by the Powertool by default + // - Persistent attributes provided by developer, not formatted + // - Ephemeral attributes provided as parameters for a single log item (done later) + this.addAttributes(params.baseAttributes); + this.addAttributes(params.persistentAttributes); + } + public addAttributes(attributes: LogAttributes): LogItem { this.attributes = merge(this.attributes, attributes); @@ -16,8 +25,16 @@ class LogItem implements LogItemInterface { return this.attributes; } - public toJSON(): string { - return JSON.stringify(this.getAttributes()); + public prepareForPrint(): void { + this.setAttributes(this.removeEmptyKeys(this.getAttributes())); + } + + public removeEmptyKeys(attributes: LogAttributes): LogAttributes { + return pickBy(attributes, (value) => value !== undefined && value !== '' && value !== null); + } + + public setAttributes(attributes: LogAttributes): void { + this.attributes = attributes; } } diff --git a/packages/logger/src/log/LogItemInterface.ts b/packages/logger/src/log/LogItemInterface.ts index 13aad006a8..5ffa23da16 100644 --- a/packages/logger/src/log/LogItemInterface.ts +++ b/packages/logger/src/log/LogItemInterface.ts @@ -6,8 +6,6 @@ interface LogItemInterface { getAttributes(): LogAttributes - toJSON(): string - } export { diff --git a/packages/logger/types/Logger.ts b/packages/logger/types/Logger.ts index cea33eada8..016a10bf3e 100644 --- a/packages/logger/types/Logger.ts +++ b/packages/logger/types/Logger.ts @@ -10,21 +10,20 @@ type LoggerOptions = { sampleRateValue?: number logFormatter?: LogFormatterInterface customConfigService?: ConfigServiceInterface - customAttributes?: LogAttributes + persistentLogAttributes?: LogAttributes environment?: Environment - isContextEnabled?: boolean }; type LambdaFunctionContext = { - name: string + functionName: string memoryLimitInMB: number - version: string + functionVersion: string coldStart: boolean - arn: string + invokedFunctionArn: string awsRequestId: string }; -type PowertoolLogAttributes = LogAttributes & { +type PowertoolLogData = LogAttributes & { environment?: Environment serviceName: string sampleRateValue?: number @@ -33,7 +32,7 @@ type PowertoolLogAttributes = LogAttributes & { awsRegion: string }; -type UnformattedAttributes = PowertoolLogAttributes & { +type UnformattedAttributes = { environment?: Environment error?: Error serviceName: string @@ -46,17 +45,17 @@ type UnformattedAttributes = PowertoolLogAttributes & { message: string }; -type LoggerInput = string | LogAttributesWithMessage; -type LoggerExtraInput = Array; +type LogItemMessage = string | LogAttributesWithMessage; +type LogItemExtraInput = Array; type HandlerMethodDecorator = (target: LambdaInterface, propertyKey: string | symbol, descriptor: TypedPropertyDescriptor) => TypedPropertyDescriptor | void; export { + LogItemMessage, + LogItemExtraInput, HandlerMethodDecorator, - LoggerInput, - LoggerExtraInput, LambdaFunctionContext, UnformattedAttributes, - PowertoolLogAttributes, + PowertoolLogData, LoggerOptions }; \ No newline at end of file From 9354f7b156cb1170410e963fcdfff198778d7610 Mon Sep 17 00:00:00 2001 From: Sara Gerion Date: Thu, 25 Mar 2021 16:54:07 +0100 Subject: [PATCH 2/2] docs(logger): update examples folder and temp readme --- packages/logger/README.md | 286 +++++++++++++----- .../examples/config/CustomConfigService.ts | 16 - ...itional-keys.ts => constructor-options.ts} | 24 +- ...ger-options.ts => custom-log-formatter.ts} | 18 +- .../logger/examples/ephemeral-attributes.ts | 26 +- packages/logger/examples/errors.ts | 4 +- ...gFormatter.ts => MyCompanyLogFormatter.ts} | 4 +- ...orators.ts => inject-context-decorator.ts} | 0 packages/logger/examples/inject-context.ts | 10 +- .../logger/examples/persistent-attributes.ts | 4 +- packages/logger/package.json | 8 +- packages/logger/src/Logger.ts | 17 +- .../src/formatter/PowertoolLogFormatter.ts | 8 +- packages/logger/tests/unit/Logger.test.ts | 24 +- 14 files changed, 297 insertions(+), 152 deletions(-) delete mode 100644 packages/logger/examples/config/CustomConfigService.ts rename packages/logger/examples/{additional-keys.ts => constructor-options.ts} (51%) rename packages/logger/examples/{custom-logger-options.ts => custom-log-formatter.ts} (61%) rename packages/logger/examples/formatters/{CustomLogFormatter.ts => MyCompanyLogFormatter.ts} (93%) rename packages/logger/examples/{hello-world-with-context-decorators.ts => inject-context-decorator.ts} (100%) diff --git a/packages/logger/README.md b/packages/logger/README.md index fab7a82fac..d7204a1466 100644 --- a/packages/logger/README.md +++ b/packages/logger/README.md @@ -1,7 +1,27 @@ # `logger` + ## Usage +```bash + +npm run test + +npm run example:hello-world +npm run example:inject-context +npm run example:inject-context-decorator +npm run example:errors +npm run example:constructor-options +npm run example:custom-log-formatter +npm run example:child-logger +npm run example:additional-keys +npm run example:sample-rate +npm run example:persistent-attributes +npm run example:ephemeral-attributes + +``` + + ### Getting started ```typescript @@ -54,18 +74,16 @@ Without decorators: ```typescript // Environment variables set for the Lambda -process.env.LOG_LEVEL = 'WARN'; +process.env.LOG_LEVEL = 'INFO'; process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; const logger = new Logger(); -const lambdaHandler: Handler = async (event, context) => { - logger.addContext(context); // This should be in a custom Middy middleware https://github.com/middyjs/middy +const lambdaHandler: Handler = async () => { + + logger.addContext(context); - logger.debug('This is a DEBUG log'); logger.info('This is an INFO log'); - logger.warn('This is a WARN log'); - logger.error('This is an ERROR log'); return { foo: 'bar' @@ -140,13 +158,14 @@ new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked { aws_request_id: 'c6af9ac6-7b61-11e6-9a41-93e8deadbeef', + cold_start: true, lambda_function_arn: 'arn:aws:lambda:eu-central-1:123456789012:function:Example', lambda_function_memory_size: 128, lambda_function_name: 'foo-bar-function', level: 'INFO', message: 'This is an INFO log with some context', service: 'hello-world', - timestamp: '2021-03-17T08:25:41.198Z', + timestamp: '2021-03-25T11:00:01.400Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456' } @@ -154,23 +173,35 @@ new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked -### Appending additional keys +### Appending additional ephemeral keys ```typescript // Environment variables set for the Lambda -process.env.LOG_LEVEL = 'WARN'; +process.env.LOG_LEVEL = 'INFO'; process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; const logger = new Logger(); const lambdaHandler: Handler = async () => { - // Pass a custom correlation ID - logger.warn('This is a WARN log', { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }); + const myImportantVariable = { + foo: 'bar' + }; - // Pass an error that occurred - logger.error('This is an ERROR log', new Error('Something bad happened!')); + // Pass a variable + logger.info('This is a log with an extra variable', { data: { myImportantVariable } }); + + // Pass a variable + const myOtherImportantVariable = { + biz: 'baz' + }; + + // Pass multiple variables + logger.info('This is a log with 2 extra variables', { + data: { myOtherImportantVariable }, + correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } + }); return { foo: 'bar' @@ -178,6 +209,7 @@ const lambdaHandler: Handler = async () => { }; + ```
@@ -186,38 +218,115 @@ const lambdaHandler: Handler = async () => { ```bash { - level: 'WARN', - message: 'This is a WARN log', + level: 'INFO', + message: 'This is a log with an extra variable', + service: 'hello-world', + timestamp: '2021-03-25T09:30:55.097Z', + xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + data: { myImportantVariable: { foo: 'bar' } } +} +{ + level: 'INFO', + message: 'This is a log with 2 extra variables', service: 'hello-world', - timestamp: '2021-03-13T20:21:28.423Z', + timestamp: '2021-03-25T09:30:55.102Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + data: { myOtherImportantVariable: { biz: 'baz' } }, correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } } + +``` +
+ + +### Log errors + +```typescript + +// Environment variables set for the Lambda +process.env.LOG_LEVEL = 'WARN'; +process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; + +const logger = new Logger(); + +const lambdaHandler: Handler = async () => { + + try { + throw new Error('Unexpected error #1'); + } catch (error) { + logger.error('This is an ERROR log #1', error); + } + + try { + throw new Error('Unexpected error #2'); + } catch (error) { + logger.error('This is an ERROR log #2', { myCustomErrorKey: error } ); + } + + return { + foo: 'bar' + }; + +}; + +``` + +
+ Click to expand and see the logs outputs + +```bash + { level: 'ERROR', - message: 'This is an ERROR log', + message: 'This is an ERROR log #1', service: 'hello-world', - timestamp: '2021-03-13T20:21:28.426Z', + timestamp: '2021-03-25T10:55:46.590Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456', error: { name: 'Error', - message: 'Something bad happened!', - stack: 'Error: Something bad happened!\n' + - ' at lambdaHandler (/Users/username/Workspace/projects/aws-lambda-powertools-typescript/packages/logger/examples/additional-keys.ts:22:40)\n' + - ' at Object. (/Users/username/Workspace/projects/aws-lambda-powertools-typescript/packages/logger/examples/additional-keys.ts:30:1)\n' + + location: '/projects/aws-lambda-powertools-typescript/packages/logger/examples/errors.ts:19', + message: 'Unexpected error #1', + stack: 'Error: Unexpected error #1\n' + + ' at lambdaHandler (/projects/aws-lambda-powertools-typescript/packages/logger/examples/errors.ts:19:11)\n' + + ' at Object. (/projects/aws-lambda-powertools-typescript/packages/logger/examples/errors.ts:36:1)\n' + ' at Module._compile (node:internal/modules/cjs/loader:1108:14)\n' + - ' at Module.m._compile (/Users/username/Workspace/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/index.ts:1056:23)\n' + + ' at Module.m._compile (/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/index.ts:1056:23)\n' + ' at Module._extensions..js (node:internal/modules/cjs/loader:1137:10)\n' + - ' at Object.require.extensions. [as .ts] (/Users/username/Workspace/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/index.ts:1059:12)\n' + + ' at Object.require.extensions. [as .ts] (/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/index.ts:1059:12)\n' + ' at Module.load (node:internal/modules/cjs/loader:973:32)\n' + ' at Function.Module._load (node:internal/modules/cjs/loader:813:14)\n' + ' at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:76:12)\n' + - ' at main (/Users/username/Workspace/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/bin.ts:198:14)' + ' at main (/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/bin.ts:198:14)' } } +{ + level: 'ERROR', + message: 'This is an ERROR log #2', + service: 'hello-world', + timestamp: '2021-03-25T10:55:46.624Z', + xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + myCustomErrorKey: { + name: 'Error', + location: '/projects/aws-lambda-powertools-typescript/packages/logger/examples/errors.ts:25', + message: 'Unexpected error #2', + stack: 'Error: Unexpected error #2\n' + + ' at lambdaHandler (/projects/aws-lambda-powertools-typescript/packages/logger/examples/errors.ts:25:11)\n' + + ' at Object. (/projects/aws-lambda-powertools-typescript/packages/logger/examples/errors.ts:36:1)\n' + + ' at Module._compile (node:internal/modules/cjs/loader:1108:14)\n' + + ' at Module.m._compile (/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/index.ts:1056:23)\n' + + ' at Module._extensions..js (node:internal/modules/cjs/loader:1137:10)\n' + + ' at Object.require.extensions. [as .ts] (/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/index.ts:1059:12)\n' + + ' at Module.load (node:internal/modules/cjs/loader:973:32)\n' + + ' at Function.Module._load (node:internal/modules/cjs/loader:813:14)\n' + + ' at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:76:12)\n' + + ' at main (/projects/aws-lambda-powertools-typescript/packages/logger/node_modules/ts-node/src/bin.ts:198:14)' + } +} + ```
+ ### Reusing Logger across your code ```typescript @@ -255,21 +364,21 @@ const lambdaHandler: Handler = async () => { level: 'INFO', message: 'This is an INFO log, from the parent logger', service: 'hello-world', - timestamp: '2021-03-13T20:33:41.128Z', + timestamp: '2021-03-25T09:34:06.652Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456' } { level: 'ERROR', message: 'This is an ERROR log, from the parent logger', service: 'hello-world', - timestamp: '2021-03-13T20:33:41.130Z', + timestamp: '2021-03-25T09:34:06.656Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456' } { level: 'ERROR', message: 'This is an ERROR log, from the child logger', service: 'hello-world', - timestamp: '2021-03-13T20:33:41.131Z', + timestamp: '2021-03-25T09:34:06.656Z', xray_trace_id: 'abcdef123456abcdef123456abcdef123456' } @@ -284,6 +393,7 @@ const lambdaHandler: Handler = async () => { // Environment variables set for the Lambda process.env.LOG_LEVEL = 'WARN'; process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; +process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.5'; const logger = new Logger(); @@ -301,6 +411,35 @@ const lambdaHandler: Handler = async () => { }; +``` + + +## Constructor options + +```typescript + +const logger = new Logger({ + logLevel: 'DEBUG', + serviceName: 'hello-world', + sampleRateValue: 0.5, + persistentLogAttributes: { // Custom attributes that will be added in every log item + awsAccountId: process.env.AWS_ACCOUNT_ID || '123456789012', + logger: { + name: powertool.name, + version: powertool.version, + } + }, +}); + +const lambdaHandler: Handler = async () => { + + logger.info('This is an INFO log', { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }); + + return { + foo: 'bar' + }; +}; + ```
@@ -310,47 +449,69 @@ const lambdaHandler: Handler = async () => { { level: 'INFO', - message: 'This is INFO log #2', - sampling_rate: 0.5, - service: 'hello-world', - timestamp: '2021-03-13T20:45:06.093Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456' -} -{ - level: 'INFO', - message: 'This is INFO log #4', + message: 'This is an INFO log', sampling_rate: 0.5, service: 'hello-world', - timestamp: '2021-03-13T20:45:06.096Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456' + timestamp: '2021-03-25T09:59:31.252Z', + xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + awsAccountId: '123456789012', + logger: { name: 'aws-lambda-powertools-typescript', version: '0.0.1' }, + correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } } ```
-## Custom logger options: log level, service name, sample rate value, log attributes, variables source, log format +## Custom log formatter ```typescript -process.env.CUSTOM_ENV = 'prod'; -// Custom configuration service for variables, and custom formatter to comply to different log JSON schema -import { CustomConfigService } from './config/CustomConfigService'; -import { CustomLogFormatter } from './formatters/CustomLogFormatter'; +class MyCompanyLogFormatter extends LogFormatter { + + public formatAttributes(attributes: UnformattedAttributes): MyCompanyLog { + return { + message: attributes.message, + service: attributes.serviceName, + environment: attributes.environment, + awsRegion: attributes.awsRegion, + correlationIds: { + awsRequestId: attributes.lambdaContext?.awsRequestId, + xRayTraceId: attributes.xRayTraceId + }, + lambdaFunction: { + name: attributes.lambdaContext?.functionName, + arn: attributes.lambdaContext?.invokedFunctionArn, + memoryLimitInMB: attributes.lambdaContext?.memoryLimitInMB, + version: attributes.lambdaContext?.functionVersion, + coldStart: attributes.lambdaContext?.coldStart, + }, + logLevel: attributes.logLevel, + timestamp: this.formatTimestamp(attributes.timestamp), + logger: { + sampleRateValue: attributes.sampleRateValue, + }, + }; + } + +} + +``` + +```typescript const logger = new Logger({ - logLevel: 'INFO', // Override options - serviceName: 'foo-bar', - sampleRateValue: 0.00001, - customAttributes: { // Custom attributes that will be added in every log - awsAccountId: '123456789012', + logFormatter: new MyCompanyLogFormatter(), // Custom log formatter to print the log in a custom structure + logLevel: 'DEBUG', + serviceName: 'hello-world', + sampleRateValue: 0.5, + persistentLogAttributes: { // Custom attributes that will be added in every log item + awsAccountId: process.env.AWS_ACCOUNT_ID || '123456789012', logger: { name: powertool.name, version: powertool.version, } }, - logFormatter: new CustomLogFormatter(), // Custom log formatter to print the log in a custom format (JSON schema) - customConfigService: new CustomConfigService() // Custom config service, that could be used for AppConfig for example }); const lambdaHandler: Handler = async (event, context) => { @@ -363,7 +524,6 @@ const lambdaHandler: Handler = async (event, context) => { }; }; - ```
@@ -373,8 +533,7 @@ const lambdaHandler: Handler = async (event, context) => { { message: 'This is an INFO log', - service: 'foo-bar', - environment: 'prod', + service: 'hello-world', awsRegion: 'eu-central-1', correlationIds: { awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e8deadbeef', @@ -389,9 +548,9 @@ const lambdaHandler: Handler = async (event, context) => { coldStart: true }, logLevel: 'INFO', - timestamp: '2021-03-13T21:43:47.759Z', + timestamp: '2021-03-25T10:00:37.194Z', logger: { - sampleRateValue: 0.00001, + sampleRateValue: 0.5, name: 'aws-lambda-powertools-typescript', version: '0.0.1' }, @@ -400,17 +559,4 @@ const lambdaHandler: Handler = async (event, context) => { ``` -
- -## Test locally - -```bash - -npm run test - -npm run example:hello-world -npm run example:hello-world-with-context -npm run example:custom-logger-options -npm run example:child-logger - -``` + \ No newline at end of file diff --git a/packages/logger/examples/config/CustomConfigService.ts b/packages/logger/examples/config/CustomConfigService.ts deleted file mode 100644 index e66203c502..0000000000 --- a/packages/logger/examples/config/CustomConfigService.ts +++ /dev/null @@ -1,16 +0,0 @@ -import { EnvironmentVariablesService } from '../../src/config'; - -class CustomConfigService extends EnvironmentVariablesService { - - // Custom environment variables - protected customEnvironmentVariable = 'CUSTOM_ENV'; - - public getCurrentEnvironment(): string { - return this.get(this.customEnvironmentVariable); - } - -} - -export { - CustomConfigService -}; \ No newline at end of file diff --git a/packages/logger/examples/additional-keys.ts b/packages/logger/examples/constructor-options.ts similarity index 51% rename from packages/logger/examples/additional-keys.ts rename to packages/logger/examples/constructor-options.ts index 6d5c918052..120cdf6142 100644 --- a/packages/logger/examples/additional-keys.ts +++ b/packages/logger/examples/constructor-options.ts @@ -2,29 +2,33 @@ import { populateEnvironmentVariables } from '../tests/helpers'; // Populate runtime populateEnvironmentVariables(); -// Additional runtime variables -process.env.LOG_LEVEL = 'WARN'; -process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; +import * as powertool from '../../../package.json'; import { context as dummyContext } from '../../../tests/resources/contexts/hello-world'; import { Handler } from 'aws-lambda'; import { Logger } from '../src'; -const logger = new Logger(); +const logger = new Logger({ + logLevel: 'DEBUG', + serviceName: 'hello-world', + sampleRateValue: 0.5, + persistentLogAttributes: { // Custom attributes that will be added in every log item + awsAccountId: process.env.AWS_ACCOUNT_ID || '123456789012', + logger: { + name: powertool.name, + version: powertool.version, + } + }, +}); const lambdaHandler: Handler = async () => { - // Pass a custom correlation ID - logger.warn('This is a WARN log', { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }); - - // Pass an error that occurred - logger.error('This is an ERROR log', new Error('Something bad happened!')); + logger.info('This is an INFO log', { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }); return { foo: 'bar' }; - }; lambdaHandler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); \ No newline at end of file diff --git a/packages/logger/examples/custom-logger-options.ts b/packages/logger/examples/custom-log-formatter.ts similarity index 61% rename from packages/logger/examples/custom-logger-options.ts rename to packages/logger/examples/custom-log-formatter.ts index 21e43a1d81..5ea02e0a69 100644 --- a/packages/logger/examples/custom-logger-options.ts +++ b/packages/logger/examples/custom-log-formatter.ts @@ -2,30 +2,26 @@ import { populateEnvironmentVariables } from '../tests/helpers'; // Populate runtime populateEnvironmentVariables(); -// Additional runtime variables -process.env.CUSTOM_ENV = 'prod'; import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; import * as powertool from '../../../package.json'; -import { CustomConfigService } from './config/CustomConfigService'; -import { CustomLogFormatter } from './formatters/CustomLogFormatter'; +import { MyCompanyLogFormatter } from './formatters/MyCompanyLogFormatter'; import { context as dummyContext } from '../../../tests/resources/contexts/hello-world'; import { Handler } from 'aws-lambda'; import { Logger } from '../src'; const logger = new Logger({ - logLevel: 'INFO', // Override options - serviceName: 'foo-bar', - sampleRateValue: 0.00001, - persistentLogAttributes: { // Custom attributes that will be added in every log - awsAccountId: '123456789012', + logFormatter: new MyCompanyLogFormatter(), // Custom log formatter to print the log in a custom structure + logLevel: 'DEBUG', + serviceName: 'hello-world', + sampleRateValue: 0.5, + persistentLogAttributes: { // Custom attributes that will be added in every log item + awsAccountId: process.env.AWS_ACCOUNT_ID || '123456789012', logger: { name: powertool.name, version: powertool.version, } }, - logFormatter: new CustomLogFormatter(), // Custom log formatter to print the log in custom structure - customConfigService: new CustomConfigService() // Custom config service, that could be used for AppConfig for example }); const lambdaHandler: Handler = async (event, context) => { diff --git a/packages/logger/examples/ephemeral-attributes.ts b/packages/logger/examples/ephemeral-attributes.ts index 722c4d6ba7..1cf2304dc6 100644 --- a/packages/logger/examples/ephemeral-attributes.ts +++ b/packages/logger/examples/ephemeral-attributes.ts @@ -3,7 +3,7 @@ import { populateEnvironmentVariables } from '../tests/helpers'; // Populate runtime populateEnvironmentVariables(); // Additional runtime variables -process.env.LOG_LEVEL = 'WARN'; +process.env.LOG_LEVEL = 'INFO'; process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; @@ -15,19 +15,23 @@ const logger = new Logger(); const lambdaHandler: Handler = async () => { - // Example of use case: - // Log an error with a message (informative string) and - // some extra ephemeral custom attributes to help debugging (like a correlation ID) - - // Logs below will result in the same JSON output + const myImportantVariable = { + foo: 'bar' + }; - const error = new Error('Something bad happened!'); + // Pass a variable + logger.info('This is a log with an extra variable', { data: { myImportantVariable } }); - // You can add ephemeral extra custom attributes like this: - logger.error('This is an ERROR log', error, { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }); + // Pass a variable + const myOtherImportantVariable = { + biz: 'baz' + }; - // Or you can also add them like this (same log output): - logger.error({ message: 'This is an ERROR log', correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }, error); + // Pass multiple variables + logger.info('This is a log with 2 extra variables', { + data: { myOtherImportantVariable }, + correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } + }); return { foo: 'bar' diff --git a/packages/logger/examples/errors.ts b/packages/logger/examples/errors.ts index bee4eb23a6..957440b73c 100644 --- a/packages/logger/examples/errors.ts +++ b/packages/logger/examples/errors.ts @@ -18,13 +18,13 @@ const lambdaHandler: Handler = async () => { try { throw new Error('Unexpected error #1'); } catch (error) { - logger.error('This is an ERROR log', error); + logger.error('This is an ERROR log #1', error); } try { throw new Error('Unexpected error #2'); } catch (error) { - logger.error('This is an ERROR log', { myCustomErrorKey: error } ); + logger.error('This is an ERROR log #2', { myCustomErrorKey: error } ); } return { diff --git a/packages/logger/examples/formatters/CustomLogFormatter.ts b/packages/logger/examples/formatters/MyCompanyLogFormatter.ts similarity index 93% rename from packages/logger/examples/formatters/CustomLogFormatter.ts rename to packages/logger/examples/formatters/MyCompanyLogFormatter.ts index 702b2a7939..76a56e6774 100644 --- a/packages/logger/examples/formatters/CustomLogFormatter.ts +++ b/packages/logger/examples/formatters/MyCompanyLogFormatter.ts @@ -3,7 +3,7 @@ import { LogAttributes, UnformattedAttributes } from '../../types'; type MyCompanyLog = LogAttributes; -class CustomLogFormatter extends LogFormatter { +class MyCompanyLogFormatter extends LogFormatter { public formatAttributes(attributes: UnformattedAttributes): MyCompanyLog { return { @@ -33,5 +33,5 @@ class CustomLogFormatter extends LogFormatter { } export { - CustomLogFormatter + MyCompanyLogFormatter }; \ No newline at end of file diff --git a/packages/logger/examples/hello-world-with-context-decorators.ts b/packages/logger/examples/inject-context-decorator.ts similarity index 100% rename from packages/logger/examples/hello-world-with-context-decorators.ts rename to packages/logger/examples/inject-context-decorator.ts diff --git a/packages/logger/examples/inject-context.ts b/packages/logger/examples/inject-context.ts index 7ee0711965..95945fc550 100644 --- a/packages/logger/examples/inject-context.ts +++ b/packages/logger/examples/inject-context.ts @@ -3,23 +3,21 @@ import { populateEnvironmentVariables } from '../tests/helpers'; // Populate runtime populateEnvironmentVariables(); // Additional runtime variables -process.env.LOG_LEVEL = 'WARN'; +process.env.LOG_LEVEL = 'INFO'; process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; import * as dummyEvent from '../../../tests/resources/events/custom/hello-world.json'; -import { context as dummyContext } from '../../../tests/resources/contexts/hello-world'; import { Handler } from 'aws-lambda'; import { Logger } from '../src'; +import { context, context as dummyContext } from '../../../tests/resources/contexts/hello-world'; const logger = new Logger(); -const lambdaHandler: Handler = async (event, context) => { +const lambdaHandler: Handler = async () => { + logger.addContext(context); - logger.debug('This is a DEBUG log'); logger.info('This is an INFO log'); - logger.warn('This is a WARN log'); - logger.error('This is an ERROR log'); return { foo: 'bar' diff --git a/packages/logger/examples/persistent-attributes.ts b/packages/logger/examples/persistent-attributes.ts index a348ddf9d2..a7096af5aa 100644 --- a/packages/logger/examples/persistent-attributes.ts +++ b/packages/logger/examples/persistent-attributes.ts @@ -12,12 +12,11 @@ import { context as dummyContext } from '../../../tests/resources/contexts/hello import { Handler } from 'aws-lambda'; import { Logger } from '../src'; -// You can add persistent extra custom attributes directly in the constructor of the logger: const logger = new Logger(); const lambdaHandler: Handler = async () => { - // Or you can choose to add persistent log keys to an existing Logger instance: + // Add persistent log keys to an existing Logger instance: logger.appendKeys({ aws_account_id: '123456789012', aws_region: 'eu-central-1', @@ -30,6 +29,7 @@ const lambdaHandler: Handler = async () => { // This info log will print all extra custom attributes added above // Extra attributes: logger object with name and version of this library, awsAccountId, awsRegion logger.info('This is an INFO log'); + logger.info('This is another INFO log'); return { foo: 'bar' diff --git a/packages/logger/package.json b/packages/logger/package.json index b062e02b67..6356242e68 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -19,9 +19,11 @@ "version": "npm run format && git add -A src", "postversion": "git push && git push --tags", "example:hello-world": "ts-node examples/hello-world.ts", - "example:hello-world-with-context": "ts-node examples/inject-context.ts", - "example:hello-world-errors": "ts-node examples/errors.ts", - "example:custom-logger-options": "ts-node examples/custom-logger-options.ts", + "example:inject-context": "ts-node examples/inject-context.ts", + "example:inject-context-decorator": "ts-node examples/inject-context-decorator.ts", + "example:errors": "ts-node examples/errors.ts", + "example:constructor-options": "ts-node examples/constructor-options.ts", + "example:custom-log-formatter": "ts-node examples/custom-log-formatter.ts", "example:child-logger": "ts-node examples/child-logger.ts", "example:additional-keys": "ts-node examples/additional-keys.ts", "example:sample-rate": "ts-node examples/sample-rate.ts", diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index e7eb1dc19e..4e6114fc53 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -4,9 +4,9 @@ import { LogItem } from './log'; import { cloneDeep, merge } from 'lodash/fp'; import { ConfigServiceInterface, EnvironmentVariablesService } from './config'; -import { LogFormatterInterface, PowertoolLogFormatter } from './formatter'; import { Environment, + HandlerMethodDecorator, PowertoolLogData, LogAttributes, LoggerOptions, @@ -15,8 +15,8 @@ import { LambdaFunctionContext, LogItemMessage, LogItemExtraInput, - HandlerMethodDecorator } from '../types'; +import { LogFormatterInterface, PowertoolLogFormatter } from './formatter'; class Logger implements LoggerInterface { @@ -97,6 +97,19 @@ class Logger implements LoggerInterface { this.printLog(this.createAndPopulateLogItem('INFO', input, extraInput)); } + public injectLambdaContext(): HandlerMethodDecorator { + return (target, propertyKey, descriptor ) => { + const originalMethod = descriptor.value; + + descriptor.value = (event, context, callback) => { + this.addContext(context); + const result = originalMethod?.apply(this, [ event, context, callback ]); + + return result; + }; + }; + } + public static isColdStart(): boolean { if (Logger.coldStart === true) { Logger.coldStart = false; diff --git a/packages/logger/src/formatter/PowertoolLogFormatter.ts b/packages/logger/src/formatter/PowertoolLogFormatter.ts index b5d25cded1..da70123703 100644 --- a/packages/logger/src/formatter/PowertoolLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolLogFormatter.ts @@ -6,11 +6,11 @@ class PowertoolLogFormatter extends LogFormatter { public formatAttributes(attributes: UnformattedAttributes): PowertoolLog { return { - aws_request_id: attributes.lambdaContext?.awsRequestId, cold_start: attributes.lambdaContext?.coldStart, - lambda_function_arn: attributes.lambdaContext?.invokedFunctionArn, - lambda_function_memory_size: attributes.lambdaContext?.memoryLimitInMB, - lambda_function_name: attributes.lambdaContext?.functionName, + function_arn: attributes.lambdaContext?.invokedFunctionArn, + function_memory_size: attributes.lambdaContext?.memoryLimitInMB, + function_request_id: attributes.lambdaContext?.awsRequestId, + function_name: attributes.lambdaContext?.functionName, level: attributes.logLevel, message: attributes.message, sampling_rate: attributes.sampleRateValue, diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 2ced521b64..69aeafe53a 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -59,7 +59,6 @@ describe('Logger', () => { logger.error({ bar: 'baz', message: 'foo' }); const error = new Error('Something happened!'); - error.stack = 'A custom stack trace'; logger.error('foo', { bar: 'baz' }, error); expect(console.log).toBeCalledTimes(4); @@ -89,9 +88,10 @@ describe('Logger', () => { expect(console.log).toHaveBeenNthCalledWith(4, { bar: 'baz', error: { + location: expect.stringMatching(/Logger.test.ts:[1-9]+$/), message: 'Something happened!', name: 'Error', - stack: 'A custom stack trace', + stack: expect.stringMatching(/Logger.test.ts:[1-9]+:[1-9]+/), }, message: 'foo', service: 'hello-world', @@ -154,9 +154,7 @@ describe('Logger', () => { test('should return a valid INFO log with context enabled', () => { - const logger = new Logger({ - isContextEnabled: true - }); + const logger = new Logger(); logger.addContext(dummyContext); logger.info('foo'); @@ -164,11 +162,11 @@ describe('Logger', () => { expect(console.log).toBeCalledTimes(2); expect(console.log).toHaveBeenNthCalledWith(1, { - 'aws_request_id': 'c6af9ac6-7b61-11e6-9a41-93e8deadbeef', 'cold_start': true, - 'lambda_function_arn': 'arn:aws:lambda:eu-central-1:123456789012:function:Example', - 'lambda_function_memory_size': 128, - 'lambda_function_name': 'foo-bar-function', + 'function_arn': 'arn:aws:lambda:eu-central-1:123456789012:function:Example', + 'function_memory_size': 128, + 'function_name': 'foo-bar-function', + 'function_request_id': 'c6af9ac6-7b61-11e6-9a41-93e8deadbeef', 'level': 'INFO', 'message': 'foo', 'service': 'hello-world', @@ -176,12 +174,12 @@ describe('Logger', () => { 'xray_trace_id': 'abcdef123456abcdef123456abcdef123456' }); expect(console.log).toHaveBeenNthCalledWith(2, { - 'aws_request_id': 'c6af9ac6-7b61-11e6-9a41-93e8deadbeef', 'bar': 'baz', 'cold_start': true, - 'lambda_function_arn': 'arn:aws:lambda:eu-central-1:123456789012:function:Example', - 'lambda_function_memory_size': 128, - 'lambda_function_name': 'foo-bar-function', + 'function_arn': 'arn:aws:lambda:eu-central-1:123456789012:function:Example', + 'function_memory_size': 128, + 'function_name': 'foo-bar-function', + 'function_request_id': 'c6af9ac6-7b61-11e6-9a41-93e8deadbeef', 'level': 'INFO', 'message': 'foo', 'service': 'hello-world',