From 28635d2b4ab9fe160d2e23a93f0e6f1298af65ef Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Fri, 15 Apr 2022 20:16:58 +0200 Subject: [PATCH 1/4] fix: add xray_trace_id to logs --- docs/core/logger.md | 2 +- packages/logger/src/Logger.ts | 19 ++++++++++++++++++- .../basicFeatures.middy.test.FunctionCode.ts | 5 +++-- .../tests/e2e/basicFeatures.middy.test.ts | 10 ++++++++++ packages/logger/tests/unit/Logger.test.ts | 5 ----- packages/logger/tests/unit/helpers.test.ts | 11 ----------- .../tests/unit/middleware/middy.test.ts | 2 -- 7 files changed, 32 insertions(+), 22 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index be6dc09963..ec32297346 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -100,7 +100,7 @@ Key | Example | Note **sampling_rate**: `float` | `0.1` | When enabled, it prints all the logs of a percentage of invocations, e.g. 10% **service**: `string` | `serverlessAirline` | A unique name identifier of the service this Lambda function belongs to, by default `service_undefined` **timestamp**: `string` | `2011-10-05T14:48:00.000Z` | Timestamp string in simplified extended ISO format (ISO 8601) -**xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793` | When [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"}, it shows X-Ray Trace ID +**xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793` | X-Ray Trace ID, when [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"} it's used to send data to X-Ray **error**: `Object` | `{ name: "Error", location: "/my-project/handler.ts:18", message: "Unexpected error #1", stack: "[stacktrace]"}` | Optional - An object containing information about the Error passed to the logger ### Capturing Lambda context info diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 523bed85a4..36f37255cc 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -328,6 +328,7 @@ class Logger extends Utility implements ClassThatLogs { logLevel, timestamp: new Date(), message: typeof input === 'string' ? input : input.message, + xRayTraceId: this.getXrayTraceId(), }, this.getPowertoolLogData()); const logItem = new LogItem({ @@ -428,6 +429,23 @@ class Logger extends Utility implements ClassThatLogs { return this.powertoolLogData?.sampleRateValue; } + /** + * It returns the current X-Ray Trace ID when Active Tracing is enabled. + * + * The X-Ray Trace data available in the environment variable has this format: + * `Root=1-6259a84e-26aa1820731c069002527c4e;Parent=557abcec3ee5a047;Sampled=1`, + * + * The actual Trace ID is: `1-5759e988-bd862e3fe1be46a994272793`. + * + * @private + * @returns {string} + */ + private getXrayTraceId(): string { + const xRayTraceId = this.getEnvVarsService().getXrayTraceId(); + + return xRayTraceId.length > 0 ? xRayTraceId.split(';')[0].replace('Root=', '') : xRayTraceId; + } + /** * It returns true if the provided log level is valid. * @@ -629,7 +647,6 @@ class Logger extends Utility implements ClassThatLogs { sampleRateValue: this.getSampleRateValue(), serviceName: serviceName || this.getCustomConfigService()?.getServiceName() || this.getEnvVarsService().getServiceName() || Logger.defaultServiceName, - xRayTraceId: this.getEnvVarsService().getXrayTraceId(), }, persistentLogAttributes, ); diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts index 4cec4de0ce..e78811c4c6 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts @@ -18,15 +18,16 @@ const testFunction = async (event: APIGatewayProxyEvent, context: Context): Prom // Test feature 1: Log level filtering // Test feature 2: Context data // Test feature 3: Persistent additional log keys and value + // Test feature 5: X-Ray Trace ID injection logger.debug('##### This should not appear'); logger.info('This is an INFO log with context and persistent key'); - // Test feature 4: One-time additional log keys and values + // Test feature 5: One-time additional log keys and values logger.info('This is an one-time log with an additional key-value', { [SINGLE_LOG_ITEM_KEY]: SINGLE_LOG_ITEM_VALUE, }); - // Test feature 5: Logging an error object + // Test feature 6: Logging an error object try { throw new Error(ERROR_MSG); } catch (e) { diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.ts index 140f08eef9..c2e1b73a92 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.ts @@ -144,6 +144,16 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} }, TEST_CASE_TIMEOUT); }); + describe('X-Ray Trace ID injection', () => { + it('should inject & parse X-Ray Trace ID into every log', async () => { + const logMessages = invocationLogs[0].getFunctionLogs(); + + for (const message of logMessages) { + expect(message).toContain('xray_trace_id'); + } + }, TEST_CASE_TIMEOUT); + }); + describe('One-time additional log keys and values', () => { it('should log additional keys and value only once', async () => { const logMessages = invocationLogs[0].getFunctionLogs() diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index a6d5b034ac..f6046d1bf5 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -496,7 +496,6 @@ describe('Class: Logger', () => { }, sampleRateValue: undefined, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); }); @@ -825,7 +824,6 @@ describe('Class: Logger', () => { environment: '', sampleRateValue: undefined, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); @@ -851,7 +849,6 @@ describe('Class: Logger', () => { environment: '', sampleRateValue: undefined, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); @@ -875,7 +872,6 @@ describe('Class: Logger', () => { environment: '', sampleRateValue: 1, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); @@ -899,7 +895,6 @@ describe('Class: Logger', () => { environment: '', sampleRateValue: undefined, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); diff --git a/packages/logger/tests/unit/helpers.test.ts b/packages/logger/tests/unit/helpers.test.ts index eea86b4c0c..b90882df38 100644 --- a/packages/logger/tests/unit/helpers.test.ts +++ b/packages/logger/tests/unit/helpers.test.ts @@ -43,7 +43,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, @@ -95,7 +94,6 @@ describe('Helper: createLogger function', () => { environment: 'prod', sampleRateValue: 1, serviceName: 'my-lambda-service', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); @@ -133,7 +131,6 @@ describe('Helper: createLogger function', () => { environment: '', sampleRateValue: undefined, serviceName: 'service_undefined', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); @@ -159,7 +156,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, @@ -188,7 +184,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: '', serviceName: 'my-backend-service', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, @@ -217,7 +212,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, @@ -257,7 +251,6 @@ describe('Helper: createLogger function', () => { environment: '', sampleRateValue: undefined, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, }); }); @@ -282,7 +275,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, @@ -329,7 +321,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: 'dev', serviceName: 'my-backend-service', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: configService, @@ -372,7 +363,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, @@ -401,7 +391,6 @@ describe('Helper: createLogger function', () => { awsRegion: 'eu-west-1', environment: 'dev', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 979a5a5462..6a25f8f713 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -74,7 +74,6 @@ describe('Middy middleware', () => { memoryLimitInMB: 128, }, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, @@ -135,7 +134,6 @@ describe('Middy middleware', () => { memoryLimitInMB: 128, }, serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, From dcee9b54a0f400055760751b306735703909703b Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Fri, 15 Apr 2022 20:51:54 +0200 Subject: [PATCH 2/4] chore: 100% test coverage is back --- packages/logger/src/Logger.ts | 4 +- .../helpers/populateEnvironmentVariables.ts | 2 +- packages/logger/tests/unit/Logger.test.ts | 100 ++++++++++++++---- .../formatter/PowertoolLogFormatter.test.ts | 22 +--- 4 files changed, 85 insertions(+), 43 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 36f37255cc..8d6a936645 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -430,10 +430,10 @@ class Logger extends Utility implements ClassThatLogs { } /** - * It returns the current X-Ray Trace ID when Active Tracing is enabled. + * It returns the current X-Ray Trace ID parsing the content of the `_X_AMZN_TRACE_ID` env variable. * * The X-Ray Trace data available in the environment variable has this format: - * `Root=1-6259a84e-26aa1820731c069002527c4e;Parent=557abcec3ee5a047;Sampled=1`, + * `Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1`, * * The actual Trace ID is: `1-5759e988-bd862e3fe1be46a994272793`. * diff --git a/packages/logger/tests/helpers/populateEnvironmentVariables.ts b/packages/logger/tests/helpers/populateEnvironmentVariables.ts index 8355fb5711..e808ac84b9 100644 --- a/packages/logger/tests/helpers/populateEnvironmentVariables.ts +++ b/packages/logger/tests/helpers/populateEnvironmentVariables.ts @@ -1,5 +1,5 @@ // Reserved variables -process.env._X_AMZN_TRACE_ID = 'abcdef123456abcdef123456abcdef123456'; +process.env._X_AMZN_TRACE_ID = 'Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1'; process.env.AWS_LAMBDA_FUNCTION_NAME = 'my-lambda-function'; process.env.AWS_LAMBDA_FUNCTION_MEMORY_SIZE = '128'; process.env.AWS_REGION = 'eu-west-1'; diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index f6046d1bf5..b22afda18d 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -20,9 +20,11 @@ const mockDate = new Date(1466424490000); const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate as unknown as string); describe('Class: Logger', () => { + const ENVIRONMENT_VARIABLES = process.env; beforeEach(() => { dateSpy.mockClear(); + process.env = { ...ENVIRONMENT_VARIABLES }; }); describe.each([ @@ -68,7 +70,7 @@ describe('Class: Logger', () => { message: 'foo', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); } @@ -95,7 +97,7 @@ describe('Class: Logger', () => { message: 'foo', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); } @@ -122,7 +124,7 @@ describe('Class: Logger', () => { message: 'foo', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); } @@ -149,7 +151,7 @@ describe('Class: Logger', () => { message: 'foo', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); } @@ -201,7 +203,7 @@ describe('Class: Logger', () => { sampling_rate: 1, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); }); @@ -229,7 +231,7 @@ describe('Class: Logger', () => { message: 'foo', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); }); @@ -259,7 +261,7 @@ describe('Class: Logger', () => { message: 'foo', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); }); @@ -295,14 +297,14 @@ describe('Class: Logger', () => { message: 'A log item without extra parameters', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); expect(consoleSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an object as second parameter', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', extra: 'parameter', })); expect(consoleSpy).toHaveBeenNthCalledWith(3, JSON.stringify({ @@ -310,7 +312,7 @@ describe('Class: Logger', () => { message: 'A log item with a string as first parameter, and objects as other parameters', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', parameterOne: 'foo', parameterTwo: 'bar', })); @@ -319,7 +321,7 @@ describe('Class: Logger', () => { message: 'A log item with an object as first parameters', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', extra: 'parameter', })); const parameterCallNumber5 = JSON.parse(consoleSpy.mock.calls[4][0]); @@ -328,7 +330,7 @@ describe('Class: Logger', () => { message: 'A log item with a string as first parameter, and an error as second parameter', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', error: { location: expect.stringMatching(/Logger.test.ts:[0-9]+$/), message: 'Something happened!', @@ -342,7 +344,7 @@ describe('Class: Logger', () => { message: 'A log item with a string as first parameter, and an error with custom key as second parameter', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', myCustomErrorKey: { location: expect.stringMatching(/Logger.test.ts:[0-9]+$/), message: 'Something happened!', @@ -355,7 +357,7 @@ describe('Class: Logger', () => { message: 'A log item with a string as first parameter, and a string as second parameter', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', extra: 'parameter', })); }); @@ -389,7 +391,7 @@ describe('Class: Logger', () => { message: 'foo', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', aws_account_id: '123456789012', aws_region: 'eu-west-1', })); @@ -397,6 +399,60 @@ describe('Class: Logger', () => { }); + describe('Feature: X-Ray Trace ID injection', () => { + + const methodOfLogger = method as keyof ClassThatLogs; + + test('when the `_X_AMZN_TRACE_ID` environment variable is set it parses it correctly and adds the Trace ID to the log', () => { + + // Prepare + const logger: Logger = createLogger({ + logLevel: 'DEBUG', + }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); + + // Act + if (logger[methodOfLogger]) { + logger[methodOfLogger]('foo'); + } + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + level: method.toUpperCase(), + message: 'foo', + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + })); + }); + + test('when the `_X_AMZN_TRACE_ID` environment variable is NOT set it parses it correctly and adds the Trace ID to the log', () => { + + // Prepare + delete process.env._X_AMZN_TRACE_ID; + const logger: Logger = createLogger({ + logLevel: 'DEBUG', + }); + const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); + + // Act + if (logger[methodOfLogger]) { + logger[methodOfLogger]('foo'); + } + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + level: method.toUpperCase(), + message: 'foo', + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + })); + }); + + }); + describe('Feature: handle safely unexpected errors', () => { const methodOfLogger = method as keyof ClassThatLogs; @@ -431,7 +487,7 @@ describe('Class: Logger', () => { message: 'A log with a circular reference', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', details: { foo: 'bar', }, @@ -450,7 +506,7 @@ describe('Class: Logger', () => { functionName: 'foo-bar-function-with-cold-start', memoryLimitInMB: '128', logGroupName: '/aws/lambda/foo-bar-function-with-cold-start', - logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456', + logStreamName: '2021/03/09/[$LATEST]1-5759e988-bd862e3fe1be46a994272793', invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function-with-cold-start', awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e812345678', getRemainingTimeInMillis: () => 1234, @@ -650,7 +706,7 @@ describe('Class: Logger', () => { message: 'This is an INFO log with some context', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); }); @@ -682,7 +738,7 @@ describe('Class: Logger', () => { message: 'An INFO log without context!', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); expect(consoleSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ cold_start: true, @@ -694,7 +750,7 @@ describe('Class: Logger', () => { message: 'This is an INFO log with some context', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); }); @@ -730,7 +786,7 @@ describe('Class: Logger', () => { message: 'An INFO log without context!', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); expect(consoleSpy).toHaveBeenNthCalledWith(2, JSON.stringify({ cold_start: true, @@ -742,7 +798,7 @@ describe('Class: Logger', () => { message: 'This is an INFO log with some context', service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', })); }); diff --git a/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts b/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts index 798ac5bb8c..253f7e30ca 100644 --- a/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts +++ b/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts @@ -28,7 +28,7 @@ describe('Class: PowertoolLogFormatter', () => { awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', + xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', logLevel: 'WARN', timestamp: new Date(), message: 'This is a WARN log', @@ -49,7 +49,7 @@ describe('Class: PowertoolLogFormatter', () => { sampling_rate: undefined, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }); }); @@ -62,7 +62,7 @@ describe('Class: PowertoolLogFormatter', () => { awsRegion: 'eu-west-1', environment: 'prod', serviceName: 'hello-world', - xRayTraceId: 'abcdef123456abcdef123456abcdef123456', + xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', logLevel: 'WARN', timestamp: new Date(), message: 'This is a WARN log', @@ -92,7 +92,7 @@ describe('Class: PowertoolLogFormatter', () => { sampling_rate: 0.25, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: 'abcdef123456abcdef123456abcdef123456', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }); }); @@ -363,18 +363,4 @@ describe('Class: PowertoolLogFormatter', () => { }); -// 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])}`; -// } }); \ No newline at end of file From 6929b23d6b06870d801df92002f8f14484054f9a Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Fri, 15 Apr 2022 21:04:11 +0200 Subject: [PATCH 3/4] chore: typo in comments --- .../logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts index e78811c4c6..385c8a7d7e 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts @@ -18,7 +18,7 @@ const testFunction = async (event: APIGatewayProxyEvent, context: Context): Prom // Test feature 1: Log level filtering // Test feature 2: Context data // Test feature 3: Persistent additional log keys and value - // Test feature 5: X-Ray Trace ID injection + // Test feature 4: X-Ray Trace ID injection logger.debug('##### This should not appear'); logger.info('This is an INFO log with context and persistent key'); From 596b03f8b7ea8baa1c00d5d2f5c5275854331acb Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 20 Apr 2022 15:26:26 +0200 Subject: [PATCH 4/4] Update docs/core/logger.md Co-authored-by: ijemmy --- docs/core/logger.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index ec32297346..d554d0e1e0 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -100,7 +100,7 @@ Key | Example | Note **sampling_rate**: `float` | `0.1` | When enabled, it prints all the logs of a percentage of invocations, e.g. 10% **service**: `string` | `serverlessAirline` | A unique name identifier of the service this Lambda function belongs to, by default `service_undefined` **timestamp**: `string` | `2011-10-05T14:48:00.000Z` | Timestamp string in simplified extended ISO format (ISO 8601) -**xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793` | X-Ray Trace ID, when [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"} it's used to send data to X-Ray +**xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793` | X-Ray Trace ID. This value is always presented in Lambda environment, whether [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"} or not. Logger will always log this value. **error**: `Object` | `{ name: "Error", location: "/my-project/handler.ts:18", message: "Unexpected error #1", stack: "[stacktrace]"}` | Optional - An object containing information about the Error passed to the logger ### Capturing Lambda context info