Skip to content

Commit

Permalink
fix: moved to stdout, unit tests wip
Browse files Browse the repository at this point in the history
  • Loading branch information
@dreamorosi
dreamorosi committed Apr 8, 2022
1 parent d64dc9b commit 409dc32
Show file tree
Hide file tree
Showing 4 changed files with 56 additions and 43 deletions.
5 changes: 4 additions & 1 deletion packages/logger/src/Logger.ts
View file
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import { Console } from 'console';
import type { Context } from 'aws-lambda';
import { Utility } from '@aws-lambda-powertools/commons';
import { LogFormatterInterface, PowertoolLogFormatter } from './formatter';
Expand Down Expand Up @@ -107,6 +108,8 @@ import type {
*/
class Logger extends Utility implements ClassThatLogs {

private console = new Console({ stdout: process.stdout, stderr: process.stderr });

private customConfigService?: ConfigServiceInterface;

private static readonly defaultLogLevel: LogLevel = 'INFO';
Expand Down Expand Up @@ -448,7 +451,7 @@ class Logger extends Utility implements ClassThatLogs {

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

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

/**
Expand Down
77 changes: 38 additions & 39 deletions packages/logger/tests/unit/Logger.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,24 +14,16 @@ import { EnvironmentVariablesService } from '../../src/config';
import { PowertoolLogFormatter } from '../../src/formatter';
import { ClassThatLogs } from '../../src/types';
import { Context } from 'aws-lambda';
import { Console } from 'console';

const mockDate = new Date(1466424490000);
const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate as unknown as string);

const consoleSpy = {
'debug': jest.spyOn(console, 'debug').mockImplementation(),
'info': jest.spyOn(console, 'info').mockImplementation(),
'warn': jest.spyOn(console, 'warn').mockImplementation(),
'error': jest.spyOn(console, 'error').mockImplementation(),
};
const stdoutSpy = jest.spyOn(process.stdout, 'write').mockImplementation(() => true);

describe('Class: Logger', () => {

beforeEach(() => {
consoleSpy['debug'].mockClear();
consoleSpy['info'].mockClear();
consoleSpy['warn'].mockClear();
consoleSpy['error'].mockClear();
stdoutSpy.mockClear();
dateSpy.mockClear();
});

Expand Down Expand Up @@ -70,9 +62,9 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(debugPrints ? 1 : 0);
expect(stdoutSpy).toBeCalledTimes(debugPrints ? 1 : 0);
if (debugPrints) {
expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: methodOfLogger.toUpperCase(),
message: 'foo',
service: 'hello-world',
Expand All @@ -96,9 +88,9 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(infoPrints ? 1 : 0);
expect(stdoutSpy).toBeCalledTimes(infoPrints ? 1 : 0);
if (infoPrints) {
expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: methodOfLogger.toUpperCase(),
message: 'foo',
service: 'hello-world',
Expand All @@ -122,9 +114,9 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(warnPrints ? 1 : 0);
expect(stdoutSpy).toBeCalledTimes(warnPrints ? 1 : 0);
if (warnPrints) {
expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: methodOfLogger.toUpperCase(),
message: 'foo',
service: 'hello-world',
Expand All @@ -148,9 +140,9 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(errorPrints ? 1 : 0);
expect(stdoutSpy).toBeCalledTimes(errorPrints ? 1 : 0);
if (errorPrints) {
expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: methodOfLogger.toUpperCase(),
message: 'foo',
service: 'hello-world',
Expand Down Expand Up @@ -181,7 +173,7 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(method === 'error' ? 1 : 0);
expect(stdoutSpy).toBeCalledTimes(method === 'error' ? 1 : 0);
});

test('when the Logger\'s log level is higher and the current Lambda invocation IS sampled for logging, it DOES print to stdout', () => {
Expand All @@ -198,8 +190,8 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(1);
expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toBeCalledTimes(1);
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: method.toUpperCase(),
message: 'foo',
sampling_rate: 1,
Expand All @@ -226,8 +218,8 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(1);
expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toBeCalledTimes(1);
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: method.toUpperCase(),
message: 'foo',
service: 'hello-world',
Expand All @@ -250,8 +242,8 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfLogger]).toBeCalledTimes(1);
expect(console[methodOfLogger]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toBeCalledTimes(1);
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
cold_start: true,
function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
function_memory_size: 128,
Expand Down Expand Up @@ -292,22 +284,22 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfConsole]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: method.toUpperCase(),
message: 'A log item without extra parameters',
service: 'hello-world',
timestamp: '2016-06-20T12:08:10.000Z',
xray_trace_id: 'abcdef123456abcdef123456abcdef123456',
}));
expect(console[methodOfConsole]).toHaveBeenNthCalledWith(2, JSON.stringify({
expect(stdoutSpy).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',
extra: 'parameter',
}));
expect(console[methodOfConsole]).toHaveBeenNthCalledWith(3, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(3, JSON.stringify({
level: method.toUpperCase(),
message: 'A log item with a string as first parameter, and objects as other parameters',
service: 'hello-world',
Expand All @@ -316,15 +308,15 @@ describe('Class: Logger', () => {
parameterOne: 'foo',
parameterTwo: 'bar',
}));
expect(console[methodOfConsole]).toHaveBeenNthCalledWith(4, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(4, JSON.stringify({
level: method.toUpperCase(),
message: 'A log item with an object as first parameters',
service: 'hello-world',
timestamp: '2016-06-20T12:08:10.000Z',
xray_trace_id: 'abcdef123456abcdef123456abcdef123456',
extra: 'parameter',
}));
const parameterCallNumber5 = JSON.parse(consoleSpy[methodOfConsole].mock.calls[4][0]);
const parameterCallNumber5 = JSON.parse(stdoutSpy.mock.calls[4][0] as string);
expect(parameterCallNumber5).toEqual(expect.objectContaining( {
level: method.toUpperCase(),
message: 'A log item with a string as first parameter, and an error as second parameter',
Expand All @@ -338,7 +330,7 @@ describe('Class: Logger', () => {
stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/),
},
}));
const parameterCallNumber6 = JSON.parse(consoleSpy[methodOfConsole].mock.calls[5][0]);
const parameterCallNumber6 = JSON.parse(stdoutSpy.mock.calls[5][0] as string);
expect(parameterCallNumber6).toEqual(expect.objectContaining({
level: method.toUpperCase(),
message: 'A log item with a string as first parameter, and an error with custom key as second parameter',
Expand All @@ -352,7 +344,7 @@ describe('Class: Logger', () => {
stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/),
},
}));
expect(console[methodOfConsole]).toHaveBeenNthCalledWith(7, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(7, JSON.stringify({
level: method.toUpperCase(),
message: 'A log item with a string as first parameter, and a string as second parameter',
service: 'hello-world',
Expand Down Expand Up @@ -385,8 +377,8 @@ describe('Class: Logger', () => {
}

// Assess
expect(console[methodOfConsole]).toBeCalledTimes(1);
expect(console[methodOfConsole]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toBeCalledTimes(1);
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: method.toUpperCase(),
message: 'foo',
service: 'hello-world',
Expand Down Expand Up @@ -428,7 +420,7 @@ describe('Class: Logger', () => {

// Assess
expect(result).toBe('All good!');
expect(console[methodOfConsole]).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: method.toUpperCase(),
message: 'A log with a circular reference',
service: 'hello-world',
Expand Down Expand Up @@ -471,6 +463,7 @@ describe('Class: Logger', () => {

// Assess
expect(logger).toEqual({
console: expect.any(Console),
coldStart: false, // This is now false because the `coldStart` attribute has been already accessed once by the `addContext` method
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
Expand Down Expand Up @@ -723,15 +716,17 @@ describe('Class: Logger', () => {
// Assess

expect(actualResult).toEqual(expectedReturnValue);
expect(console['info']).toBeCalledTimes(2);
expect(console['info']).toHaveBeenNthCalledWith(1, JSON.stringify({
expect(stdoutSpy).toBeCalledTimes(2);
const actualCall1 = stdoutSpy.mock.calls[0][0];
expect(actualCall1).toEqual(JSON.stringify({
level: 'INFO',
message: 'An INFO log without context!',
service: 'hello-world',
timestamp: '2016-06-20T12:08:10.000Z',
xray_trace_id: 'abcdef123456abcdef123456abcdef123456',
}));
expect(console['info']).toHaveBeenNthCalledWith(2, JSON.stringify({
const actualCall2 = stdoutSpy.mock.calls[0][1];
expect(actualCall2).toEqual(JSON.stringify({
cold_start: true,
function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function',
function_memory_size: 128,
Expand Down Expand Up @@ -804,6 +799,7 @@ describe('Class: Logger', () => {
expect(parentLogger === childLoggerWithErrorLogLevel).toBe(false);

expect(parentLogger).toEqual({
console: expect.any(Console),
coldStart: true,
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
Expand All @@ -827,6 +823,7 @@ describe('Class: Logger', () => {
});

expect(childLoggerWithPermanentAttributes).toEqual({
console: expect.any(Console),
coldStart: true,
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
Expand All @@ -852,6 +849,7 @@ describe('Class: Logger', () => {
});

expect(childLoggerWithSampleRateEnabled).toEqual({
console: expect.any(Console),
coldStart: true,
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
Expand All @@ -875,6 +873,7 @@ describe('Class: Logger', () => {
});

expect(childLoggerWithErrorLogLevel).toEqual({
console: expect.any(Console),
coldStart: true,
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
Expand Down
4 changes: 4 additions & 0 deletions packages/logger/tests/unit/helpers.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@
* @group unit/logger/all
*/

import { Console } from 'console';
import { ConfigServiceInterface, EnvironmentVariablesService } from '../../src/config';
import { LogFormatter, PowertoolLogFormatter } from '../../src/formatter';
import { LoggerOptions } from '../../src/types';
Expand Down Expand Up @@ -78,6 +79,7 @@ describe('Helper: createLogger function', () => {
envVarsService: expect.any(EnvironmentVariablesService),
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'WARN',
console: expect.any(Console),
logLevelThresholds: {
DEBUG: 8,
ERROR: 20,
Expand Down Expand Up @@ -117,6 +119,7 @@ describe('Helper: createLogger function', () => {
envVarsService: expect.any(EnvironmentVariablesService),
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'INFO',
console: expect.any(Console),
logLevelThresholds: {
DEBUG: 8,
ERROR: 20,
Expand Down Expand Up @@ -240,6 +243,7 @@ describe('Helper: createLogger function', () => {
envVarsService: expect.any(EnvironmentVariablesService),
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'INFO',
console: expect.any(Console),
logLevelThresholds: {
DEBUG: 8,
ERROR: 20,
Expand Down
13 changes: 10 additions & 3 deletions packages/logger/tests/unit/middleware/middy.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,15 +9,15 @@ import { injectLambdaContext } from '../../../src/middleware/middy';
import { Logger } from './../../../src';
import middy from '@middy/core';
import { PowertoolLogFormatter } from '../../../src/formatter';
import { Console } from 'console';

describe('Middy middleware', () => {

const ENVIRONMENT_VARIABLES = process.env;

beforeEach(() => {
jest.resetModules();
// eslint-disable-next-line @typescript-eslint/no-empty-function
jest.spyOn(console, 'log').mockImplementation(() => {});
jest.spyOn(process.stdout, 'write').mockImplementation(() => null as unknown as boolean);
process.env = { ...ENVIRONMENT_VARIABLES };
});

Expand Down Expand Up @@ -120,6 +120,8 @@ describe('Middy middleware', () => {

// Assess
const expectation = expect.objectContaining({
logsSampled: false,
persistentLogAttributes: {},
powertoolLogData: {
sampleRateValue: undefined,
awsRegion: 'eu-west-1',
Expand All @@ -135,8 +137,13 @@ describe('Middy middleware', () => {
serviceName: 'hello-world',
xRayTraceId: 'abcdef123456abcdef123456abcdef123456',
},
envVarsService: expect.any(EnvironmentVariablesService),
customConfigService: undefined,
logLevel: 'DEBUG',
logFormatter: expect.any(PowertoolLogFormatter),
console: expect.any(Console),
});
expect(logger).toEqual(anotherLogger);
expect(logger).toEqual(expectation);
expect(anotherLogger).toEqual(expectation);

});
Expand Down

0 comments on commit 409dc32

Please sign in to comment.