UBERF-5795: Improve logging capabilities (hcengineering#4813)

Signed-off-by: Andrey Sobolev <haiodo@gmail.com>
Signed-off-by: Tiago Cruz <tcruz@netic.io>

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<T>(
@@ -50,7 +60,7 @@ export class MeasureMetricsContext implements MeasureContext {
     op: (ctx: MeasureContext) => T | Promise<T>,
     fullParams?: ParamsType
   ): Promise<T> {
-    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<void> {
-    this.logger.error(message, args)
+  async withLog<T>(
+    name: string,
+    params: ParamsType,
+    op: (ctx: MeasureContext) => T | Promise<T>,
+    fullParams?: ParamsType
+  ): Promise<T> {
+    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<string, any>): Promise<void> {
+    this.logger.error(message, { ...this.params, ...args })
   }
 
-  async info (message: string, ...args: any[]): Promise<void> {
-    this.logger.info(message, args)
+  async info (message: string, args?: Record<string, any>): Promise<void> {
+    this.logger.info(message, { ...this.params, ...args })
   }
 
   end (): void {

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)
   }
 }
 

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<string, any>) => void
+  error: (message: string, obj?: Record<string, any>) => void
+
+  logOperation: (operation: string, time: number, params: ParamsType) => void
+
+  childLogger?: (name: string, params: Record<string, any>) => MeasureLogger
+
+  close: () => Promise<void>
 }
 /**
  * @public
@@ -54,13 +60,20 @@ export interface MeasureContext {
     fullParams?: FullParamsType
   ) => Promise<T>
 
+  withLog: <T>(
+    name: string,
+    params: ParamsType,
+    op: (ctx: MeasureContext) => T | Promise<T>,
+    fullParams?: FullParamsType
+  ) => Promise<T>
+
   logger: MeasureLogger
 
   measure: (name: string, value: number) => void
 
   // Capture error
-  error: (message: string, ...args: any[]) => Promise<void>
-  info: (message: string, ...args: any[]) => Promise<void>
+  error: (message: string, obj?: Record<string, any>) => Promise<void>
+  info: (message: string, obj?: Record<string, any>) => Promise<void>
 
   // Mark current context as complete
   // If no value is passed, time difference will be used.

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<T>(
     name: string,
-    params: Record<string, ParamType>,
-    op: (ctx: MeasureContext) => T | Promise<T>
+    params: ParamsType,
+    op: (ctx: MeasureContext) => T | Promise<T>,
+    fullParams?: ParamsType
   ): Promise<T> {
     const c = this.newChild(name, params)
     try {
@@ -80,6 +83,18 @@ export class APMMeasureContext implements MeasureContext {
     }
   }
 
+  async withLog<T>(
+    name: string,
+    params: ParamsType,
+    op: (ctx: MeasureContext) => T | Promise<T>,
+    fullParams?: ParamsType
+  ): Promise<T> {
+    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<void> {
     this.logger.error(message, args)