Skip to content

Commit

Permalink
feat: add ability to attach extra data to log lines (#50)
Browse files Browse the repository at this point in the history
* feat: new logging system with extra data and more strict error format

* fix error override

* allow override logger extra data

* small fixes

* Update src/lib/context.ts

Co-authored-by: Andrey Melikhov <[email protected]>

* fix review notes

* add logging tests

* fix review notes

---------

Co-authored-by: Andrey Melikhov <[email protected]>
  • Loading branch information
goshander and melikhov-dev authored Oct 10, 2024
1 parent 79cd488 commit 76eb406
Show file tree
Hide file tree
Showing 2 changed files with 172 additions and 18 deletions.
58 changes: 40 additions & 18 deletions src/lib/context.ts
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ interface ContextInitialParams {
utils: NodeKit['utils'];
dynamicConfig?: AppDynamicConfig;
loggerPostfix?: string;
loggerExtra?: Dict;
tags?: Dict;
}

Expand All @@ -32,7 +33,10 @@ export interface AppTelemetrySendStats {
}

interface ContextParentParams
extends Pick<ContextInitialParams, 'parentSpanContext' | 'loggerPostfix' | 'tags'> {
extends Pick<
ContextInitialParams,
'parentSpanContext' | 'loggerPostfix' | 'loggerExtra' | 'tags'
> {
parentContext: AppContext;
}

Expand All @@ -58,6 +62,7 @@ export class AppContext {
private endTime?: number;
private loggerPrefix: string;
private loggerPostfix: string;
private loggerExtra?: Dict;

constructor(name: string, params: ContextParams) {
this.name = name;
Expand All @@ -72,12 +77,18 @@ export class AppContext {
this.appParams = Object.assign({}, params.parentContext?.appParams);
this.loggerPrefix = `${params.parentContext.loggerPrefix} [${this.name}]`.trim();
this.loggerPostfix = params.loggerPostfix || params.parentContext.loggerPostfix;
this.loggerExtra = this.mergeExtra(
params.parentContext.loggerExtra,
params.loggerExtra,
);

this.span = this.tracer.startSpan(this.name, {
tags: this.utils.redactSensitiveKeys(params.tags || {}),
childOf: params.parentSpanContext || params.parentContext?.span,
});
this.stats = params.parentContext.stats;

this.parentContext = params.parentContext;
} else if (params.config && params.logger && params.tracer && params.utils) {
this.appParams = {};
this.config = params.config;
Expand All @@ -87,6 +98,7 @@ export class AppContext {
this.dynamicConfig = {};
this.loggerPrefix = '';
this.loggerPostfix = params.loggerPostfix || '';
this.loggerExtra = params.loggerExtra;
this.stats = params.stats;
} else {
throw new Error(
Expand All @@ -95,34 +107,29 @@ export class AppContext {
}
}

log(message: string, extra: Dict = {}) {
this.logger.info(this.prepareExtra(extra), this.prepareLogMessage(message));
this.span?.log(Object.assign({}, this.utils.redactSensitiveKeys(extra), {event: message}));
log(message: string, extra?: Dict) {
const preparedExtra = this.prepareExtra(extra);

this.logger.info(preparedExtra, this.prepareLogMessage(message));
this.span?.log(Object.assign({}, preparedExtra, {event: message}));
}

logError(message: string, error?: AppError | Error | unknown, extra: Dict = {}) {
logError(message: string, error?: AppError | Error | unknown, extra?: Dict) {
if (error) {
this.logger.error(
Object.assign({}, extractErrorInfo(error), {
extra: this.utils.redactSensitiveKeys(extra),
}),
Object.assign({}, this.prepareExtra(extra), extractErrorInfo(error)),
this.prepareLogMessage(message),
);
} else if (extra) {
this.logger.error(
{
extra: this.utils.redactSensitiveKeys(extra),
},
this.prepareLogMessage(message),
);
this.logger.error(this.prepareExtra(extra), this.prepareLogMessage(message));
} else {
this.logger.error(this.prepareLogMessage(message));
this.logger.error(this.loggerExtra, this.prepareLogMessage(message));
}

this.span?.setTag(Tags.SAMPLING_PRIORITY, 1);
this.span?.setTag(Tags.ERROR, true);
this.span?.log(
Object.assign({}, this.utils.redactSensitiveKeys(extra), {
Object.assign({}, this.prepareExtra(extra), {
event: message,
stack: error instanceof Error && error?.stack,
}),
Expand Down Expand Up @@ -230,12 +237,27 @@ export class AppContext {
return this.span?._spanContext?.toTraceId();
}

// allow add extra logger data, after ctx already initialized (ex. to add traceId from ctx)
addLoggerExtra(key: string, value: unknown) {
this.loggerExtra = this.mergeExtra(this.loggerExtra, {[key]: value});
}

clearLoggerExtra() {
this.loggerExtra = Object.assign({}, this.parentContext?.loggerExtra);
}

private prepareLogMessage(message: string) {
return `${this.loggerPrefix} ${message} ${this.loggerPostfix}`.trim();
}

private prepareExtra(extra: Dict) {
const preparedExtra = this.utils.redactSensitiveKeys(extra);
private prepareExtra(extra: Dict | undefined) {
const mergedExtra = this.mergeExtra(this.loggerExtra, extra);

const preparedExtra = this.utils.redactSensitiveKeys(mergedExtra);
return Object.keys(preparedExtra).length ? preparedExtra : undefined;
}

private mergeExtra(extraParent: Dict | undefined, extraCurrent: Dict | undefined) {
return Object.assign({}, extraParent, extraCurrent);
}
}
132 changes: 132 additions & 0 deletions src/tests/logging.test.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,132 @@
import {NodeKit} from '..';

const logger = {
write: jest.fn(),
};

test('check base logging system', () => {
const nodeKit = new NodeKit({config: {appLoggingDestination: logger}});

// log function
nodeKit.ctx.log('log info');
let log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({
msg: 'log info',
level: 30,
});

// logError function
nodeKit.ctx.logError('log error');
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({
msg: 'log error',
level: 50,
});

// logError function with error object
const err = new Error('error object');

nodeKit.ctx.logError('log error with error object', err);
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({
msg: 'log error with error object',
level: 50,
err: {
message: 'error object',
type: 'Object',
stack: expect.stringContaining('Error: error object'),
},
});
});

test('check logging with extra data', () => {
const nodeKit = new NodeKit({config: {appLoggingDestination: logger}});

const extra = Math.random().toString();

// log function with extra param
nodeKit.ctx.log('log info', {extra});
let log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({extra});

// add extra data to ctx
const traceId = Math.random().toString();
nodeKit.ctx.addLoggerExtra('traceId', traceId);

// log function with extra ctx data
nodeKit.ctx.log('log info');
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({traceId});

// log function with extra param and extra ctx data
nodeKit.ctx.log('log info', {extra});
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({traceId, extra});

// logError function with extra param and extra ctx data
nodeKit.ctx.logError('log error', new Error('err'), {extra});
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({
extra,
traceId,
level: 50,
});
});

test('check logging from nested ctx', () => {
const nodeKit = new NodeKit({config: {appLoggingDestination: logger}});

const traceId = Math.random().toString();
nodeKit.ctx.addLoggerExtra('traceId', traceId);

// log function from parent ctx
nodeKit.ctx.log('log info');
let log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({traceId});

const ctxName = Math.random().toString();
const logPostfix = Math.random().toString();
const newCtx = nodeKit.ctx.create(ctxName, {loggerPostfix: logPostfix});

// log function from nested ctx
newCtx.log('log info');
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({traceId, msg: `[${ctxName}] log info ${logPostfix}`});

// log function from nested ctx with override data
const anotherTraceId = Math.random().toString();
newCtx.addLoggerExtra('traceId', anotherTraceId);

newCtx.log('log info');
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({traceId: anotherTraceId});

// log function from nested ctx with new data
newCtx.clearLoggerExtra();
newCtx.addLoggerExtra('anotherTraceId', anotherTraceId);

newCtx.log('log info');
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({traceId, anotherTraceId});

// logError function from nested ctx with new data
newCtx.logError('log error');
log = JSON.parse(logger.write.mock.lastCall?.pop() || '{}');

expect(log).toMatchObject({
traceId,
anotherTraceId,
msg: `[${ctxName}] log error ${logPostfix}`,
});
});

0 comments on commit 76eb406

Please sign in to comment.