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
Show file tree
Hide file tree
Changes from 8 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
Expand Up @@ -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"`, 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.
Expand Down
1 change: 1 addition & 0 deletions docs/index.md
Original file line number Diff line number Diff line change
Expand Up @@ -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) | `0` |
| **LOG_LEVEL** | Sets logging level | [Logger](./core/logger) | `INFO` |

## Tenets
Expand Down
19 changes: 18 additions & 1 deletion packages/logger/src/Logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -124,6 +125,8 @@ class Logger extends Utility implements ClassThatLogs {

private logFormatter?: LogFormatterInterface;

private logIndentation: number = LogJsonIndent.COMPACT;

private logLevel?: LogLevel;

private readonly logLevelThresholds: LogLevelThresholds = {
Expand Down Expand Up @@ -569,7 +572,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));
}

/**
Expand Down Expand Up @@ -662,6 +665,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.
*
Expand Down Expand Up @@ -731,6 +747,7 @@ class Logger extends Utility implements ClassThatLogs {
this.setLogFormatter(logFormatter);
this.setPowertoolLogData(serviceName, environment);
this.setLogEvent();
this.setLogIndentation();

this.addPersistentLogAttributes(persistentLogAttributes);

Expand Down
7 changes: 7 additions & 0 deletions packages/logger/src/config/ConfigServiceInterface.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand Down
12 changes: 12 additions & 0 deletions packages/logger/src/config/EnvironmentVariablesService.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand All @@ -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 value.toLowerCase() === 'true' || value === '1';
}

/**
* It returns the value of the AWS_LAMBDA_FUNCTION_MEMORY_SIZE environment variable.
*
Expand Down
5 changes: 5 additions & 0 deletions packages/logger/src/types/Logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Up @@ -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';

Expand Down Expand Up @@ -573,6 +573,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
Expand Down Expand Up @@ -1271,6 +1272,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
Expand All @@ -1295,6 +1297,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
Expand All @@ -1321,6 +1324,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'DEBUG',
logLevelThresholds: {
Expand All @@ -1345,6 +1349,7 @@ describe('Class: Logger', () => {
customConfigService: undefined,
envVarsService: expect.any(EnvironmentVariablesService),
logEvent: false,
logIndentation: 0,
logFormatter: expect.any(PowertoolLogFormatter),
logLevel: 'ERROR',
logLevelThresholds: {
Expand Down Expand Up @@ -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: 108 additions & 0 deletions packages/logger/tests/unit/config/EnvironmentVariablesService.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -220,4 +220,112 @@ describe('Class: EnvironmentVariablesService', () => {

});

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

// Prepare
process.env.POWERTOOLS_DEV = 'FALSE';
const service = new EnvironmentVariablesService();

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

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

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

// Prepare
process.env.POWERTOOLS_DEV = '0';
const service = new EnvironmentVariablesService();

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

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

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

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

// 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_DEV = 'somethingsilly';
const service = new EnvironmentVariablesService();

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

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

});

});
8 changes: 7 additions & 1 deletion packages/logger/tests/unit/helpers.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand Down Expand Up @@ -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),
Expand Down Expand Up @@ -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),
Expand Down Expand Up @@ -307,7 +310,10 @@ describe('Helper: createLogger function', () => {
getServiceName(): string {
return 'my-backend-service';
},

getDevMode(): boolean {
return false;
},

};
// Prepare
const loggerOptions:ConstructorOptions = {
Expand Down
3 changes: 3 additions & 0 deletions packages/logger/tests/unit/middleware/middy.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -336,6 +336,9 @@ describe('Middy middleware', () => {
getServiceName(): string {
return 'my-backend-service';
},
getDevMode(): boolean {
return false;
},

};

Expand Down