diff --git a/README.md b/README.md index 017497d..18269c1 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,6 @@ # logger component -Simple stdout & stderr logger component. Prints JSON when `NODE_ENV=production` +Simple stdout & stderr logger component. ## Config @@ -13,13 +13,58 @@ Using the LOG_LEVEL value provided by the IConfigComponent, the following scale Eg: ```typescript -const config: IConfigComponent = - createConfigComponent({ ...process.env, LOG_LEVEL: "INFO" }) +const config: IConfigComponent = createConfigComponent({ ...process.env, LOG_LEVEL: 'INFO' }) const loggerComponent = createLogComponent({ config }) -const logger = getLogger("Test") +const logger = getLogger('Test') -logger.info("log some info") // This will be logged -logger.warn("log some warn") // This will be logged -logger.debug("log some debug") // This will NOT be logged +logger.info('log some info') // This will be logged +logger.warn('log some warn') // This will be logged +logger.debug('log some debug') // This will NOT be logged +``` + +## Logger enhancers can be configured + +```ts +// Datadog enhancer +const tracer = require('dd-trace') +const formats = require('dd-trace/ext/formats') + +// enhances the "extra" field of each log to add new data. in this case +// dd.trace_id and dd.span_id will be added +function enhancer(extra) { + var enhancedObject = extra || {} + const time = new Date().toISOString() + + const span = tracer.scope().active() + if (span) { + tracer.inject(span.context(), formats.LOG, enhancedObject) + } + return enhancedObject +} + +// in initComponents(), pass the enhancer +const logs = createJsonLogComponent({}, enhancer) +``` + +## The loggers generate metrics, use them like this: + +```ts +// metrics.ts +import { validateMetricsDeclaration } from '@well-known-components/metrics' +import { metricDeclarations as logsMetricsDeclarations } from '@well-known-components/logger' + +export const metricDeclarations = { + // ...otherMetrics, + ...logsMetricsDeclarations +} + +// type assertions +validateMetricsDeclaration(metricDeclarations) +``` + +```ts +// in initComponents(), pass the metrics component to the component + +const logs = createJsonLogComponent({ metrics }) ``` diff --git a/etc/logger.api.md b/etc/logger.api.md index 59ef0a2..7a533fc 100644 --- a/etc/logger.api.md +++ b/etc/logger.api.md @@ -10,15 +10,19 @@ import { IMetricsComponent } from '@well-known-components/interfaces'; import { ITracerComponent } from '@well-known-components/interfaces'; // Warning: (ae-forgotten-export) The symbol "LoggerComponents" needs to be exported by the entry point index.d.ts +// Warning: (ae-forgotten-export) The symbol "EnricherFunction" needs to be exported by the entry point index.d.ts // // @public -export function createConsoleLogComponent(components: LoggerComponents): Promise; +export function createConsoleLogComponent(components: LoggerComponents, enricher?: EnricherFunction): Promise; // @public -export function createJsonLogComponent(components: LoggerComponents): Promise; +export function createJsonLogComponent(components: LoggerComponents, enricher?: EnricherFunction): Promise; // @public -export function createLogComponent(components: LoggerComponents): Promise; +export function createLogComponent(components: LoggerComponents, enricher?: EnricherFunction): Promise; + +// @public +export function createLogfmtLogComponent(components: LoggerComponents, enricher?: EnricherFunction): Promise; // @public export const metricDeclarations: IMetricsComponent.MetricsRecordDefinition<"wkc_logger_logs_total">; diff --git a/package.json b/package.json index fbcd17a..ac8a615 100644 --- a/package.json +++ b/package.json @@ -35,5 +35,6 @@ }, "files": [ "dist" - ] + ], + "dependencies": {} } diff --git a/src/helpers.ts b/src/helpers.ts index 4991350..7612229 100644 --- a/src/helpers.ts +++ b/src/helpers.ts @@ -2,9 +2,9 @@ import { ILoggerComponent, IMetricsComponent, IConfigComponent, - ITracerComponent, -} from "@well-known-components/interfaces" -import { metricDeclarations } from "./metrics" + ITracerComponent +} from '@well-known-components/interfaces' +import { metricDeclarations } from './metrics' /** * @public @@ -36,7 +36,18 @@ export type ILoggerConfigComponent = { /** * @public */ -export type LogLevel = "ALL" | "LOG" | "DEBUG" | "INFO" | "WARN" | "ERROR" | "OFF" +export type LogLevel = 'ALL' | 'LOG' | 'DEBUG' | 'INFO' | 'WARN' | 'ERROR' | 'OFF' + +/** + * This function may be provided to enrich the "extra" properties of a log. + * The funcitonality is useful for scenarios in which the structured log requires + * some special fields for traceability reasons. + * + * The enricher function must return a new "extra" object. + * + * @public + */ +export type EnricherFunction = (extra: any) => any /** * Creates a scoped logger component using a LogLineFunction function. @@ -44,11 +55,12 @@ export type LogLevel = "ALL" | "LOG" | "DEBUG" | "INFO" | "WARN" | "ERROR" | "OF */ export async function createGenericLogComponent( components: LoggerComponents, - print: LogLineFunction + print: LogLineFunction, + enricher?: EnricherFunction ): Promise { const levelsEnum = { ALL: 0, LOG: 1, DEBUG: 2, INFO: 4, WARN: 8, ERROR: 16, OFF: 1 | 2 | 4 | 8 | 16 } - let minLogLevel: LogLevel = "ALL" + let minLogLevel: LogLevel = 'ALL' let numericMinLevel = levelsEnum[minLogLevel] || 0 function setLogLevel(level: LogLevel) { @@ -58,16 +70,18 @@ export async function createGenericLogComponent( } } + const enrichExtra = enricher ?? ((a) => a) + // set ALL log level by default - setLogLevel("ALL") + setLogLevel('ALL') if (components.config) { try { // if a config component is provided, we try to get the LOG_LEVEL config - const newLevel = await components.config.getString("LOG_LEVEL") + const newLevel = await components.config.getString('LOG_LEVEL') if (newLevel) setLogLevel(newLevel as LogLevel) } catch (error: any) { - print(components, "ERROR", "LOG_LEVEL", error.toString(), error) + print(components, 'ERROR', 'LOG_LEVEL', error.toString(), error) } } @@ -81,51 +95,51 @@ export async function createGenericLogComponent( getLogger(loggerName: string) { return { log(message: string, extra?: Record) { - if (shouldPrint("LOG")) { - print(components, "LOG", loggerName, message, extra) + if (shouldPrint('LOG')) { + print(components, 'LOG', loggerName, message, enrichExtra(extra)) } }, warn(message: string, extra?: Record) { - if (shouldPrint("WARN")) { - print(components, "WARNING", loggerName, message, extra) + if (shouldPrint('WARN')) { + print(components, 'WARNING', loggerName, message, enrichExtra(extra)) } }, info(message: string, extra?: Record) { - if (shouldPrint("INFO")) { - print(components, "INFO", loggerName, message, extra) + if (shouldPrint('INFO')) { + print(components, 'INFO', loggerName, message, enrichExtra(extra)) } }, debug(message: string, extra?: Record) { - if (shouldPrint("DEBUG")) { - print(components, "DEBUG", loggerName, message, extra) + if (shouldPrint('DEBUG')) { + print(components, 'DEBUG', loggerName, message, enrichExtra(extra)) } }, error(error: string | Error, extra?: Record) { - if (shouldPrint("ERROR")) { + if (shouldPrint('ERROR')) { let message = `${error}` let printTrace = true - if (error instanceof Error && "stack" in error && typeof error.stack == "string") { + if (error instanceof Error && 'stack' in error && typeof error.stack == 'string') { if (error.stack!.includes(error.message)) { message = error.stack printTrace = false } } - print(components, "ERROR", loggerName, message, extra || error) + print(components, 'ERROR', loggerName, message, enrichExtra(extra) || error) if (printTrace) { console.trace() } } - }, + } } - }, + } } } // @internal export function incrementMetric(components: LoggerComponents, loggerName: string, level: string) { if (components.metrics) { - components.metrics.increment("wkc_logger_logs_total", { logger: loggerName, level }) + components.metrics.increment('wkc_logger_logs_total', { logger: loggerName, level }) } } diff --git a/src/index.ts b/src/index.ts index 3f79a2d..ab291b6 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,8 +1,9 @@ -import { ILoggerComponent } from "@well-known-components/interfaces" -import { printCloudwatch } from "./cloudwatch-printer" -import { printConsole } from "./console-printer" -import { createGenericLogComponent, LoggerComponents } from "./helpers" -import { metricDeclarations } from "./metrics" +import { ILoggerComponent } from '@well-known-components/interfaces' +import { printJson } from './json-printer' +import { printConsole } from './console-printer' +import { createGenericLogComponent, EnricherFunction, LoggerComponents } from './helpers' +import { metricDeclarations } from './metrics' +import { printLogfmt } from './logfmt-printer' export { metricDeclarations } @@ -11,16 +12,23 @@ export { metricDeclarations } * and json logger for NODE_ENV=production * @public */ -export async function createLogComponent(components: LoggerComponents): Promise { - return createConsoleLogComponent(components) +export async function createLogComponent( + components: LoggerComponents, + enricher?: EnricherFunction +): Promise { + return createConsoleLogComponent(components, enricher) } /** * Creates a scoped logger component to print a readable output to the stderr + * * @public */ -export async function createConsoleLogComponent(components: LoggerComponents): Promise { - return createGenericLogComponent(components, printConsole) +export async function createConsoleLogComponent( + components: LoggerComponents, + enricher?: EnricherFunction +): Promise { + return createGenericLogComponent(components, printConsole, enricher) } /** @@ -28,6 +36,21 @@ export async function createConsoleLogComponent(components: LoggerComponents): P * Useful for cloudwatch and other logging services. * @public */ -export async function createJsonLogComponent(components: LoggerComponents): Promise { - return createGenericLogComponent(components, printCloudwatch) +export async function createJsonLogComponent( + components: LoggerComponents, + enricher?: EnricherFunction +): Promise { + return createGenericLogComponent(components, printJson, enricher) +} + +/** + * Creates a scoped logger component to print logfmt to the stderr. + * Useful for cloudwatch and other logging services. + * @public + */ +export async function createLogfmtLogComponent( + components: LoggerComponents, + enricher?: EnricherFunction +): Promise { + return createGenericLogComponent(components, printLogfmt, enricher) } diff --git a/src/cloudwatch-printer.ts b/src/json-printer.ts similarity index 62% rename from src/cloudwatch-printer.ts rename to src/json-printer.ts index dd22cf4..8661689 100644 --- a/src/cloudwatch-printer.ts +++ b/src/json-printer.ts @@ -1,9 +1,9 @@ -import { incrementMetric, LoggerComponents, LogLineFunction } from "./helpers" +import { incrementMetric, LoggerComponents, LogLineFunction } from './helpers' /** * @internal */ -export const printCloudwatch: LogLineFunction = ( +export const printJson: LogLineFunction = ( components: LoggerComponents, kind: string, loggerName: string, @@ -14,15 +14,15 @@ export const printCloudwatch: LogLineFunction = ( const logline = { timestamp: new Date().toISOString(), - kind, - system: loggerName, + level: kind, + logger: loggerName, message, - extra, - traceId: trace?.traceId, - parentId: trace?.parentId, + traceId: trace?.traceId || undefined, + parentId: trace?.parentId || undefined, + ...extra } incrementMetric(components, loggerName, kind) - return process.stderr.write(JSON.stringify(logline) + "\n") + return process.stderr.write(JSON.stringify(logline) + '\n') } diff --git a/src/logfmt-printer.ts b/src/logfmt-printer.ts new file mode 100644 index 0000000..4c5bb13 --- /dev/null +++ b/src/logfmt-printer.ts @@ -0,0 +1,54 @@ +import { incrementMetric, LoggerComponents, LogLineFunction } from './helpers' + +/** + * https://brandur.org/logfmt + * @internal + */ +export const printLogfmt: LogLineFunction = ( + components: LoggerComponents, + kind: string, + loggerName: string, + message: string, + extra: any +) => { + incrementMetric(components, loggerName, kind) + + const structuredLog = { + date: new Date().toISOString(), + level: kind, + logger: loggerName, + msg: message, + ...extra + } + + return process.stderr.write(logfmt(structuredLog)) +} + +function logfmt(data: Record) { + var line = '' + + for (var key in data) { + var value = data[key] + var is_null = false + if (value == null) { + is_null = true + value = '' + } else if (typeof value == 'object') { + value = JSON.stringify(value) + } else { + value = value.toString() + + var needs_quoting = value.indexOf(' ') > -1 || value.indexOf('=') > -1 + var needs_escaping = value.indexOf('"') > -1 || value.indexOf('\\') > -1 + + if (needs_escaping) value = value.replace(/["\\]/g, '\\$&') + if (needs_quoting || needs_escaping) value = '"' + value + '"' + if (value === '' && !is_null) value = '""' + } + + line += key + '=' + value + ' ' + } + + //trim traling space + return line.substring(0, line.length - 1) +} diff --git a/test/cloudwatch-printer.spec.ts b/test/json-printer.spec.ts similarity index 60% rename from test/cloudwatch-printer.spec.ts rename to test/json-printer.spec.ts index e76c44c..2ce66ba 100644 --- a/test/cloudwatch-printer.spec.ts +++ b/test/json-printer.spec.ts @@ -1,13 +1,13 @@ -import type { ITracerComponent } from "@well-known-components/interfaces" -import { printCloudwatch } from "../src/cloudwatch-printer" +import type { ITracerComponent } from '@well-known-components/interfaces' +import { printJson } from '../src/json-printer' let tracerComponentMock: ITracerComponent let isInsideOfTraceSpanMock: jest.Mock let getTraceMock: jest.Mock -const writeSpy = jest.spyOn(process.stderr, "write") +const writeSpy = jest.spyOn(process.stderr, 'write') -describe("when printing a cloudwatch log", () => { +describe('when printing a cloudwatch log', () => { beforeEach(() => { isInsideOfTraceSpanMock = jest.fn() getTraceMock = jest.fn() @@ -17,33 +17,33 @@ describe("when printing a cloudwatch log", () => { beforeEach(() => { tracerComponentMock = { isInsideOfTraceSpan: isInsideOfTraceSpanMock, - getTrace: getTraceMock, + getTrace: getTraceMock } as unknown as ITracerComponent }) - describe("and the logging is performed inside of a trace span", () => { + describe('and the logging is performed inside of a trace span', () => { beforeEach(() => { isInsideOfTraceSpanMock.mockReturnValue(true) getTraceMock.mockReturnValue({ - traceId: "aTraceString", - parentId: "aParentId", + traceId: 'aTraceString', + parentId: 'aParentId' }) }) - it("should print the trace", () => { - printCloudwatch({ tracer: tracerComponentMock }, "INFO", "test", "a test message") + it('should print the trace', () => { + printJson({ tracer: tracerComponentMock }, 'INFO', 'test', 'a test message') expect(writeSpy).toHaveBeenCalledWith(expect.stringContaining('"traceId":"aTraceString"')) expect(writeSpy).toHaveBeenCalledWith(expect.stringContaining('"parentId":"aParentId"')) }) }) - describe("and the logging is not performed inside of a trace span", () => { + describe('and the logging is not performed inside of a trace span', () => { beforeEach(() => { isInsideOfTraceSpanMock.mockReturnValue(false) }) - it("should not print anything related to the trace", () => { - printCloudwatch({ tracer: tracerComponentMock }, "INFO", "test", "a test message") + it('should not print anything related to the trace', () => { + printJson({ tracer: tracerComponentMock }, 'INFO', 'test', 'a test message') expect(writeSpy).toHaveBeenCalledWith(expect.not.stringContaining('"traceId":"aTraceString"')) expect(writeSpy).toHaveBeenCalledWith(expect.not.stringContaining('"parentId":"aParentId"')) }) @@ -55,8 +55,8 @@ describe("when printing a cloudwatch log", () => { tracerComponentMock = undefined }) - it("should not print anything related to the trace", () => { - printCloudwatch({ tracer: tracerComponentMock }, "INFO", "test", "a test message") + it('should not print anything related to the trace', () => { + printJson({ tracer: tracerComponentMock }, 'INFO', 'test', 'a test message') expect(writeSpy).toHaveBeenCalledWith(expect.not.stringContaining('"traceId":"aTraceString"')) expect(writeSpy).toHaveBeenCalledWith(expect.not.stringContaining('"parentId":"aParentId"')) }) diff --git a/test/logfmt-printer.spec.ts b/test/logfmt-printer.spec.ts new file mode 100644 index 0000000..9c3295c --- /dev/null +++ b/test/logfmt-printer.spec.ts @@ -0,0 +1,77 @@ +import type { ITracerComponent } from '@well-known-components/interfaces' +import { printLogfmt } from '../src/logfmt-printer' + +let tracerComponentMock: ITracerComponent +let isInsideOfTraceSpanMock: jest.Mock +let getTraceStringMock: jest.Mock +const startsWithTrace = /^\[.+\].+/ + +const writeSpy = jest.spyOn(process.stderr, 'write') + +describe('when printing a logfmt', () => { + beforeEach(() => { + isInsideOfTraceSpanMock = jest.fn() + getTraceStringMock = jest.fn() + }) + + describe("and there's a tracer component available", () => { + beforeEach(() => { + tracerComponentMock = { + isInsideOfTraceSpan: isInsideOfTraceSpanMock, + getTraceString: getTraceStringMock + } as unknown as ITracerComponent + }) + + describe.skip('and the logging is performed inside of a trace span', () => { + beforeEach(() => { + isInsideOfTraceSpanMock.mockReturnValue(true) + getTraceStringMock.mockReturnValue('aTraceString') + printLogfmt({ tracer: tracerComponentMock }, 'INFO', 'test', 'a test message') + }) + + it('should print the trace', () => { + expect(writeSpy).toHaveBeenCalledWith(expect.stringContaining('traceId=aTraceString')) + }) + + it('should print other information of the logger', () => { + expect(writeSpy).toHaveBeenCalledWith(expect.stringContaining('[INFO]')) + expect(writeSpy).toHaveBeenCalledWith(expect.stringContaining('(test)')) + expect(writeSpy).toHaveBeenCalledWith(expect.stringContaining('a test message')) + }) + }) + + describe('and the logging is not performed inside of a trace span', () => { + beforeEach(() => { + isInsideOfTraceSpanMock.mockReturnValue(false) + }) + + it('should not print anything related to the trace', () => { + printLogfmt({ tracer: tracerComponentMock }, 'INFO', 'test', 'a test message') + expect(writeSpy).toHaveBeenCalledWith(expect.not.stringMatching(startsWithTrace)) + }) + }) + }) + + describe("and there's no tracer component available", () => { + beforeEach(() => { + tracerComponentMock = undefined + }) + + it('should not print anything related to the trace', () => { + printLogfmt({ tracer: tracerComponentMock }, 'INFO', 'test', 'a test message') + expect(writeSpy).toHaveBeenCalledWith(expect.not.stringMatching(startsWithTrace)) + }) + }) + describe('test extra', () => { + beforeEach(() => { + tracerComponentMock = undefined + }) + + it('should not print anything related to the trace', () => { + printLogfmt({ tracer: tracerComponentMock }, 'INFO', 'test', 'a test message', { a: 1, b: { c: 3 } }) + expect(writeSpy).toHaveBeenCalledWith( + expect.stringContaining('level=INFO logger=test msg="a test message" a=1 b={\"c\":3}') + ) + }) + }) +})