From 053496c7c2381b9549d57aefdb86f57faeda1741 Mon Sep 17 00:00:00 2001 From: Andrey Sobolev Date: Thu, 29 Feb 2024 14:01:17 +0700 Subject: [PATCH] UBERF-5795: Improve logging capabilities (#4813) Signed-off-by: Andrey Sobolev --- packages/core/src/measurements/context.ts | 44 +++++++++++++++++------ packages/core/src/measurements/metrics.ts | 8 ++++- packages/core/src/measurements/types.ts | 21 ++++++++--- server/server/src/apm.ts | 27 ++++++++++---- 4 files changed, 78 insertions(+), 22 deletions(-) diff --git a/packages/core/src/measurements/context.ts b/packages/core/src/measurements/context.ts index 0f4d4062859..57a862ce9d8 100644 --- a/packages/core/src/measurements/context.ts +++ b/packages/core/src/measurements/context.ts @@ -23,25 +23,35 @@ export class MeasureMetricsContext implements MeasureContext { this.name = name this.params = params this.metrics = metrics - this.done = measure(metrics, params, fullParams) + this.done = measure(metrics, params, fullParams, (spend) => { + this.logger.logOperation(this.name, spend, { ...params, ...fullParams }) + }) this.logger = logger ?? { info: (msg, args) => { - console.info(msg, ...args) + console.info(msg, ...Object.entries(args ?? {}).map((it) => `${it[0]}=${JSON.stringify(it[1])}`)) }, error: (msg, args) => { - console.error(msg, ...args) - } + console.error(msg, ...Object.entries(args ?? {}).map((it) => `${it[0]}=${JSON.stringify(it[1])}`)) + }, + close: async () => {}, + logOperation: (operation, time, params) => {} } } measure (name: string, value: number): void { - const c = new MeasureMetricsContext('#' + name, {}, {}, childMetrics(this.metrics, ['#' + name])) + const c = new MeasureMetricsContext('#' + name, {}, {}, childMetrics(this.metrics, ['#' + name]), this.logger) c.done(value) } newChild (name: string, params: ParamsType, fullParams?: FullParamsType, logger?: MeasureLogger): MeasureContext { - return new MeasureMetricsContext(name, params, fullParams ?? {}, childMetrics(this.metrics, [name]), logger) + return new MeasureMetricsContext( + name, + params, + fullParams ?? {}, + childMetrics(this.metrics, [name]), + logger ?? this.logger + ) } async with( @@ -50,7 +60,7 @@ export class MeasureMetricsContext implements MeasureContext { op: (ctx: MeasureContext) => T | Promise, fullParams?: ParamsType ): Promise { - const c = this.newChild(name, params, fullParams) + const c = this.newChild(name, params, fullParams, this.logger) try { let value = op(c) if (value instanceof Promise) { @@ -64,12 +74,24 @@ export class MeasureMetricsContext implements MeasureContext { } } - async error (message: string, ...args: any[]): Promise { - this.logger.error(message, args) + async withLog( + name: string, + params: ParamsType, + op: (ctx: MeasureContext) => T | Promise, + fullParams?: ParamsType + ): Promise { + const st = Date.now() + const r = await this.with(name, params, op, fullParams) + this.logger.logOperation(name, Date.now() - st, { ...params, ...fullParams }) + return r + } + + async error (message: string, args?: Record): Promise { + this.logger.error(message, { ...this.params, ...args }) } - async info (message: string, ...args: any[]): Promise { - this.logger.info(message, args) + async info (message: string, args?: Record): Promise { + this.logger.info(message, { ...this.params, ...args }) } end (): void { diff --git a/packages/core/src/measurements/metrics.ts b/packages/core/src/measurements/metrics.ts index 047a0837979..1d8f8c7882f 100644 --- a/packages/core/src/measurements/metrics.ts +++ b/packages/core/src/measurements/metrics.ts @@ -45,7 +45,12 @@ function getUpdatedTopResult ( * Measure with tree expansion. Operation counter will be added only to leaf's. * @public */ -export function measure (metrics: Metrics, params: ParamsType, fullParams: FullParamsType = {}): () => void { +export function measure ( + metrics: Metrics, + params: ParamsType, + fullParams: FullParamsType = {}, + endOp?: (spend: number) => void +): () => void { const st = Date.now() return (value?: number) => { const ed = Date.now() @@ -75,6 +80,7 @@ export function measure (metrics: Metrics, params: ParamsType, fullParams: FullP metrics.operations++ metrics.topResult = getUpdatedTopResult(metrics.topResult, ed - st, fullParams) + endOp?.(ed - st) } } diff --git a/packages/core/src/measurements/types.ts b/packages/core/src/measurements/types.ts index 2052948d7f7..29757705eb7 100644 --- a/packages/core/src/measurements/types.ts +++ b/packages/core/src/measurements/types.ts @@ -37,8 +37,14 @@ export interface Metrics extends MetricsData { * @public */ export interface MeasureLogger { - info: (message: string, ...args: any[]) => void - error: (message: string, ...args: any[]) => void + info: (message: string, obj?: Record) => void + error: (message: string, obj?: Record) => void + + logOperation: (operation: string, time: number, params: ParamsType) => void + + childLogger?: (name: string, params: Record) => MeasureLogger + + close: () => Promise } /** * @public @@ -54,13 +60,20 @@ export interface MeasureContext { fullParams?: FullParamsType ) => Promise + withLog: ( + name: string, + params: ParamsType, + op: (ctx: MeasureContext) => T | Promise, + fullParams?: FullParamsType + ) => Promise + logger: MeasureLogger measure: (name: string, value: number) => void // Capture error - error: (message: string, ...args: any[]) => Promise - info: (message: string, ...args: any[]) => Promise + error: (message: string, obj?: Record) => Promise + info: (message: string, obj?: Record) => Promise // Mark current context as complete // If no value is passed, time difference will be used. diff --git a/server/server/src/apm.ts b/server/server/src/apm.ts index b232e19fab4..754a19b035e 100644 --- a/server/server/src/apm.ts +++ b/server/server/src/apm.ts @@ -1,4 +1,4 @@ -import { MeasureContext, MeasureLogger, ParamType } from '@hcengineering/core' +import { MeasureContext, MeasureLogger, ParamType, ParamsType } from '@hcengineering/core' import apm, { Agent, Span, Transaction } from 'elastic-apm-node' /** @@ -37,11 +37,13 @@ export class APMMeasureContext implements MeasureContext { this.parent = parent this.logger = { info: (msg, args) => { - agent.logger.info(msg, args) + agent.logger.info({ message: msg, ...args }) }, error: (msg, args) => { - agent.logger.error(msg, args) - } + agent.logger.error({ message: msg, ...args }) + }, + logOperation (operation, time, params) {}, + close: async () => {} } if (!(noTransaction ?? false)) { if (this.parent === undefined) { @@ -63,8 +65,9 @@ export class APMMeasureContext implements MeasureContext { async with( name: string, - params: Record, - op: (ctx: MeasureContext) => T | Promise + params: ParamsType, + op: (ctx: MeasureContext) => T | Promise, + fullParams?: ParamsType ): Promise { const c = this.newChild(name, params) try { @@ -80,6 +83,18 @@ export class APMMeasureContext implements MeasureContext { } } + async withLog( + name: string, + params: ParamsType, + op: (ctx: MeasureContext) => T | Promise, + fullParams?: ParamsType + ): Promise { + const st = Date.now() + const r = await this.with(name, params, op, fullParams) + this.logger.logOperation(name, Date.now() - st, { ...params, ...fullParams }) + return r + } + async error (message: string, ...args: any[]): Promise { this.logger.error(message, args)