Skip to content

feat(logger): pretty printing logs in local and non-prod environment #1141

New issue

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

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

Already on GitHub? Sign in to your account

Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions docs/core/logger.md
Original file line number Diff line number Diff line change
@@ -104,6 +104,9 @@ Your Logger will include the following keys to your structured logging (default
| **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 |

???+ info
When `POWERTOOLS_DEV` environment variable is present and set to `"true"` or `"1"`, Logger will pretty-print log messages for easier readability. We recommend to use this setting only when debugging on local environments.

### Capturing Lambda context info

You can enrich your structured logs with key Lambda context information in multiple ways.
1 change: 1 addition & 0 deletions docs/index.md
Original file line number Diff line number Diff line change
@@ -293,6 +293,7 @@ Core utilities such as Tracing, Logging, and Metrics will be available across al
| **POWERTOOLS_TRACER_CAPTURE_HTTPS_REQUESTS** | Captures HTTP(s) requests as segments. | [Tracer](./core/tracer) | `true` |
| **POWERTOOLS_LOGGER_LOG_EVENT** | Logs incoming event | [Logger](./core/logger) | `false` |
| **POWERTOOLS_LOGGER_SAMPLE_RATE** | Debug log sampling | [Logger](./core/logger) | `0` |
| **POWERTOOLS_DEV** | Increase JSON indentation to ease debugging when running functions locally or in a non-production environment | [Logger](./core/logger) | `false` |
| **LOG_LEVEL** | Sets logging level | [Logger](./core/logger) | `INFO` |

## Tenets
19 changes: 18 additions & 1 deletion packages/logger/src/Logger.ts
Original file line number Diff line number Diff line change
@@ -6,6 +6,7 @@ import { LogItem } from './log';
import cloneDeep from 'lodash.clonedeep';
import merge from 'lodash.merge';
import { ConfigServiceInterface, EnvironmentVariablesService } from './config';
import { LogJsonIndent } from './types';
import type {
ClassThatLogs,
Environment,
@@ -127,6 +128,8 @@ class Logger extends Utility implements ClassThatLogs {

private logFormatter?: LogFormatterInterface;

private logIndentation: number = LogJsonIndent.COMPACT;

private logLevel?: LogLevel;

private readonly logLevelThresholds: LogLevelThresholds = {
@@ -595,7 +598,7 @@ class Logger extends Utility implements ClassThatLogs {

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

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

/**
@@ -688,6 +691,19 @@ class Logger extends Utility implements ClassThatLogs {
this.logFormatter = logFormatter || new PowertoolLogFormatter();
}

/**
* If the `POWERTOOLS_DEV' env variable is set,
* it adds JSON indentation for pretty printing logs.
*
* @private
* @returns {void}
*/
private setLogIndentation(): void {
if (this.getEnvVarsService().getDevMode()) {
this.logIndentation = LogJsonIndent.PRETTY;
}
}

/**
* It sets the Logger's instance log level.
*
@@ -757,6 +773,7 @@ class Logger extends Utility implements ClassThatLogs {
this.setLogFormatter(logFormatter);
this.setPowertoolLogData(serviceName, environment);
this.setLogEvent();
this.setLogIndentation();

this.addPersistentLogAttributes(persistentLogAttributes);

15 changes: 15 additions & 0 deletions packages/logger/src/config/ConfigServiceInterface.ts
Original file line number Diff line number Diff line change
@@ -22,6 +22,13 @@ interface ConfigServiceInterface {
*/
getCurrentEnvironment(): string

/**
* It returns the value of the POWERTOOLS_DEV environment variable.
*
* @returns {boolean}
*/
getDevMode(): boolean

/**
* It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable.
*
@@ -50,6 +57,14 @@ interface ConfigServiceInterface {
*/
getServiceName(): string

/**
* It returns true if the string value represents a boolean true value.
*
* @param {string} value
* @returns boolean
*/
isValueTrue(value: string): boolean

}

export {
28 changes: 26 additions & 2 deletions packages/logger/src/config/EnvironmentVariablesService.ts
Original file line number Diff line number Diff line change
@@ -20,6 +20,7 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
// Reserved environment variables
private awsRegionVariable = 'AWS_REGION';
private currentEnvironmentVariable = 'ENVIRONMENT';
private devModeVariable = 'POWERTOOLS_DEV';
private functionNameVariable = 'AWS_LAMBDA_FUNCTION_NAME';
private functionVersionVariable = 'AWS_LAMBDA_FUNCTION_VERSION';
private logEventVariable = 'POWERTOOLS_LOGGER_LOG_EVENT';
@@ -45,6 +46,17 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
return this.get(this.currentEnvironmentVariable);
}

/**
* It returns the value of the POWERTOOLS_DEV environment variable.
*
* @returns {boolean}
*/
public getDevMode(): boolean {
const value = this.get(this.devModeVariable);

return this.isValueTrue(value);
}

/**
* It returns the value of the AWS_LAMBDA_FUNCTION_MEMORY_SIZE environment variable.
*
@@ -81,8 +93,8 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
*/
public getLogEvent(): boolean {
const value = this.get(this.logEventVariable);

return value.toLowerCase() === 'true' || value === '1';
return this.isValueTrue(value);
}

/**
@@ -105,6 +117,18 @@ class EnvironmentVariablesService extends CommonEnvironmentVariablesService impl
return (value && value.length > 0) ? Number(value) : undefined;
}

/**
* It returns true if the string value represents a boolean true value.
*
* @param {string} value
* @returns boolean
*/
public isValueTrue(value: string): boolean {
const truthyValues: string[] = [ '1', 'y', 'yes', 't', 'true', 'on' ];

return truthyValues.includes(value.toLowerCase());
}

}

export {
5 changes: 5 additions & 0 deletions packages/logger/src/types/Logger.ts
Original file line number Diff line number Diff line change
@@ -74,3 +74,8 @@ export {
ConstructorOptions,
HandlerOptions
};

export const enum LogJsonIndent {
PRETTY = 4,
COMPACT = 0,
}
52 changes: 51 additions & 1 deletion packages/logger/tests/unit/Logger.test.ts
Original file line number Diff line number Diff line change
@@ -11,7 +11,7 @@ import * as dummyEvent from '../../../../tests/resources/events/custom/hello-wor
import { createLogger, Logger } from '../../src';
import { EnvironmentVariablesService } from '../../src/config';
import { PowertoolLogFormatter } from '../../src/formatter';
import { ClassThatLogs } from '../../src/types';
import { ClassThatLogs, LogJsonIndent } from '../../src/types';
import { Context, Handler } from 'aws-lambda';
import { Console } from 'console';

@@ -573,6 +573,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
@@ -1271,6 +1272,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
@@ -1295,6 +1297,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
@@ -1321,6 +1324,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
@@ -1345,6 +1349,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'ERROR',
logLevelThresholds: {
@@ -1411,4 +1416,49 @@ describe('Class: Logger', () => {
});
});

describe('Feature: Pretty indentation for a local or non-production environment', () => {

test('when the `POWERTOOLS_DEV` env var is SET it makes log output has multiple lines', () => {

// Prepare
process.env.POWERTOOLS_DEV = 'true';
const INDENTATION = LogJsonIndent.PRETTY;
const logger = new Logger();
const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();

// Act
logger.info('Message with pretty identation');

// Assess
expect(consoleSpy).toBeCalledTimes(1);
expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({
level: 'INFO',
message: 'Message with pretty identation',
service: 'hello-world',
timestamp: '2016-06-20T12:08:10.000Z',
xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793',
}, null, INDENTATION));
});

test('when the `POWERTOOLS_DEV` env var is NOT SET it makes log output as one-liner', () => {

// Prepare
const logger = new Logger();
const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation();

// Act
logger.info('Message without pretty identation');

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

});
108 changes: 76 additions & 32 deletions packages/logger/tests/unit/config/EnvironmentVariablesService.test.ts
Original file line number Diff line number Diff line change
@@ -119,105 +119,149 @@ describe('Class: EnvironmentVariablesService', () => {
expect(value).toEqual(true);
});

test('It returns true if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "TRUE"', () => {
test('It returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "false"', () => {

// Prepare
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'TRUE';
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'false';
const service = new EnvironmentVariablesService();

// Act
const value = service.getLogEvent();

// Assess
expect(value).toEqual(true);
expect(value).toEqual(false);
});

test('It returns true if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "1"', () => {
test('It returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "somethingsilly"', () => {

// Prepare
process.env.POWERTOOLS_LOGGER_LOG_EVENT = '1';
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'somethingsilly';
const service = new EnvironmentVariablesService();

// Act
const value = service.getLogEvent();

// Assess
expect(value).toEqual(true);
expect(value).toEqual(false);
});

test('It returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "false"', () => {
});

describe('Method: getLogLevel', () => {

test('It returns the value of the environment variable LOG_LEVEL', () => {

// Prepare
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'false';
process.env.LOG_LEVEL = 'ERROR';
const service = new EnvironmentVariablesService();

// Act
const value = service.getLogEvent();
const value = service.getLogLevel();

// Assess
expect(value).toEqual(false);
expect(value).toEqual('ERROR');
});

test('It returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "0"', () => {
});

describe('Method: getSampleRateValue', () => {

test('It returns the value of the environment variable POWERTOOLS_LOGGER_SAMPLE_RATE', () => {

// Prepare
process.env.POWERTOOLS_LOGGER_LOG_EVENT = '0';
process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.01';
const service = new EnvironmentVariablesService();

// Act
const value = service.getLogEvent();
const value = service.getSampleRateValue();

// Assess
expect(value).toEqual(false);
expect(value).toEqual(0.01);
});

test('It returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "somethingsilly"', () => {
});

describe('Method: getDevMode', () => {

test('It returns true if the environment variable POWERTOOLS_DEV is "true"', () => {

// Prepare
process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'somethingsilly';
process.env.POWERTOOLS_DEV = 'true';
const service = new EnvironmentVariablesService();

// Act
const value = service.getLogEvent();
const value = service.getDevMode();

// Assess
expect(value).toEqual(false);
expect(value).toEqual(true);
});

});

describe('Method: getLogLevel', () => {

test('It returns the value of the environment variable LOG_LEVEL', () => {
test('It returns false if the environment variable POWERTOOLS_DEV is "false"', () => {

// Prepare
process.env.LOG_LEVEL = 'ERROR';
process.env.POWERTOOLS_DEV = 'false';
const service = new EnvironmentVariablesService();

// Act
const value = service.getLogLevel();
const value = service.getDevMode();

// Assess
expect(value).toEqual('ERROR');
expect(value).toEqual(false);
});

});
test('It returns false if the environment variable POWERTOOLS_DEV is NOT set', () => {

describe('Method: getSampleRateValue', () => {
// Prepare
process.env.POWERTOOLS_DEV = 'somethingsilly';
const service = new EnvironmentVariablesService();

test('It returns the value of the environment variable POWERTOOLS_LOGGER_SAMPLE_RATE', () => {
// Act
const value = service.getDevMode();

// Assess
expect(value).toEqual(false);
});

test('It returns false if the environment variable POWERTOOLS_DEV is "somethingsilly"', () => {

// Prepare
process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.01';
process.env.POWERTOOLS_DEV = 'somethingsilly';
const service = new EnvironmentVariablesService();

// Act
const value = service.getSampleRateValue();
const value = service.getDevMode();

// Assess
expect(value).toEqual(0.01);
expect(value).toEqual(false);
});

});

describe('Method: isValueTrue', () => {

const valuesToTest: Array<Array<string | boolean>> = [
[ '1', true ],
[ 'y', true ],
[ 'yes', true ],
[ 't', true ],
[ 'TRUE', true ],
[ 'on', true ],
[ '', false ],
[ 'false', false ],
[ 'fasle', false ],
[ 'somethingsilly', false ],
[ '0', false ]
];

test.each(valuesToTest)('It takes string "%s" and returns %s', (input, output) => {
Copy link
Contributor

Choose a reason for hiding this comment

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

Neat, I like it

// Prepare
const service = new EnvironmentVariablesService();
// Act
const value = service.isValueTrue(input as string);
// Assess
expect(value).toBe(output);
});

});

});
11 changes: 10 additions & 1 deletion packages/logger/tests/unit/helpers.test.ts
Original file line number Diff line number Diff line change
@@ -77,6 +77,7 @@ describe('Helper: createLogger function', () => {
customConfigService: expect.any(EnvironmentVariablesService),
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'WARN',
console: expect.any(Console),
@@ -117,6 +118,7 @@ describe('Helper: createLogger function', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'INFO',
console: expect.any(Console),
@@ -238,6 +240,7 @@ describe('Helper: createLogger function', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'INFO',
console: expect.any(Console),
@@ -307,7 +310,13 @@ describe('Helper: createLogger function', () => {
getServiceName(): string {
return 'my-backend-service';
},

getDevMode(): boolean {
return false;
},
isValueTrue(): boolean {
return true;
},

};
// Prepare
const loggerOptions:ConstructorOptions = {
7 changes: 6 additions & 1 deletion packages/logger/tests/unit/middleware/middy.test.ts
Original file line number Diff line number Diff line change
@@ -336,7 +336,12 @@ describe('Middy middleware', () => {
getServiceName(): string {
return 'my-backend-service';
},

getDevMode(): boolean {
return false;
},
isValueTrue(): boolean {
return true;
},
};

const logger = new Logger({