Add logs to track data store execution time

apps/armory/src/managed-data-store/core/service/entity-data-store.service.ts

@@ -1,8 +1,8 @@
+import { LoggerService } from '@narval/nestjs-shared'
 import { EntityStore } from '@narval/policy-engine-shared'
 import { HttpStatus, Injectable, NotFoundException } from '@nestjs/common'
 import { ClientService } from '../../../client/core/service/client.service'
 import { ClusterService } from '../../../policy-engine/core/service/cluster.service'
-import { SetEntityStoreResponse } from '../../http/rest/dto/set-entity-store.dto'
 import { EntityDataStoreRepository } from '../../persistence/repository/entity-data-store.repository'
 import { SignatureService } from './signature.service'
 
@@ -11,19 +11,36 @@ export class EntityDataStoreService extends SignatureService {
   constructor(
     private entityDataStoreRepository: EntityDataStoreRepository,
     private clientService: ClientService,
-    private clusterService: ClusterService
+    private clusterService: ClusterService,
+    loggerService: LoggerService
   ) {
-    super()
+    super(loggerService)
   }
 
   async getEntities(clientId: string): Promise<EntityStore | null> {
-    const entityStore = await this.entityDataStoreRepository.getLatestDataStore(clientId)
+    const entityStore = await this.withExecutionTimeLog({
+      clientId,
+      id: 'entityDataStoreRepository.getLatestDataStore',
+      thunk: () => this.entityDataStoreRepository.getLatestDataStore(clientId)
+    })
+
+    if (entityStore) {
+      return this.withExecutionTimeLog({
+        clientId,
+        id: 'EntityStore.parse',
+        thunk: () => EntityStore.parse(entityStore.data)
+      })
+    }
 
-    return entityStore ? EntityStore.parse(entityStore.data) : null
+    return null
   }
 
   async setEntities(clientId: string, payload: EntityStore) {
-    const client = await this.clientService.findById(clientId)
+    const client = await this.withExecutionTimeLog({
+      clientId,
+      id: 'clientService.findById',
+      thunk: () => this.clientService.findById(clientId)
+    })
 
     if (!client) {
       throw new NotFoundException({
@@ -32,25 +49,49 @@ export class EntityDataStoreService extends SignatureService {
       })
     }
 
-    const latestDataStore = await this.entityDataStoreRepository.getLatestDataStore(clientId)
+    const latestDataStore = await this.withExecutionTimeLog({
+      clientId,
+      id: 'entityDataStoreRepository.getLatestDataStore',
+      thunk: () => this.entityDataStoreRepository.getLatestDataStore(clientId)
+    })
 
-    await this.verifySignature({
-      payload,
-      keys: client.dataStore.entityPublicKeys,
-      date: latestDataStore?.createdAt
+    await this.withExecutionTimeLog({
+      clientId,
+      id: 'verifySignature(entity)',
+      thunk: () =>
+        this.verifySignature({
+          payload,
+          keys: client.dataStore.entityPublicKeys,
+          date: latestDataStore?.createdAt
+        })
     })
 
-    const { data, version } = await this.entityDataStoreRepository.setDataStore(clientId, {
-      version: latestDataStore?.version ? latestDataStore.version + 1 : 1,
-      data: EntityStore.parse(payload)
+    const { data, version } = await this.withExecutionTimeLog({
+      clientId,
+      id: 'entityDataStoreRepository.setDataStore',
+      thunk: () =>
+        this.entityDataStoreRepository.setDataStore(clientId, {
+          version: latestDataStore?.version ? latestDataStore.version + 1 : 1,
+          data: EntityStore.parse(payload)
+        })
     })
 
-    const success = await this.clusterService.sync(clientId)
+    const success = await this.withExecutionTimeLog({
+      clientId,
+      id: 'clusterService.sync(entity)',
+      thunk: () => this.clusterService.sync(clientId)
+    })
+
+    const entity = this.withExecutionTimeLog({
+      clientId,
+      id: 'EntityStore.parse',
+      thunk: () => EntityStore.parse(data)
+    })
 
-    return SetEntityStoreResponse.parse({
+    return {
       latestSync: { success },
-      entity: EntityStore.parse(data),
+      entity,
       version
-    })
+    }
   }
 }

apps/armory/src/managed-data-store/core/service/policy-data-store.service.ts

@@ -1,3 +1,4 @@
+import { LoggerService } from '@narval/nestjs-shared'
 import { PolicyStore } from '@narval/policy-engine-shared'
 import { HttpStatus, Injectable, NotFoundException } from '@nestjs/common'
 import { ClientService } from '../../../client/core/service/client.service'
@@ -10,19 +11,36 @@ export class PolicyDataStoreService extends SignatureService {
   constructor(
     private policyDataStoreRepository: PolicyDataStoreRepository,
     private clientService: ClientService,
-    private clusterService: ClusterService
+    private clusterService: ClusterService,
+    loggerService: LoggerService
   ) {
-    super()
+    super(loggerService)
   }
 
   async getPolicies(clientId: string): Promise<PolicyStore | null> {
-    const policyStore = await this.policyDataStoreRepository.getLatestDataStore(clientId)
+    const policyStore = await this.withExecutionTimeLog({
+      clientId,
+      id: 'policyDataStoreRepository.getLatestDataStore',
+      thunk: () => this.policyDataStoreRepository.getLatestDataStore(clientId)
+    })
 
-    return policyStore ? PolicyStore.parse(policyStore.data) : null
+    if (policyStore) {
+      return this.withExecutionTimeLog({
+        clientId,
+        id: 'PolicyStore.parse',
+        thunk: () => PolicyStore.parse(policyStore.data)
+      })
+    }
+
+    return null
   }
 
   async setPolicies(clientId: string, payload: PolicyStore) {
-    const client = await this.clientService.findById(clientId)
+    const client = await this.withExecutionTimeLog({
+      clientId,
+      id: 'clientService.findById',
+      thunk: async () => this.clientService.findById(clientId)
+    })
 
     if (!client) {
       throw new NotFoundException({
@@ -31,24 +49,48 @@ export class PolicyDataStoreService extends SignatureService {
       })
     }
 
-    const latestDataStore = await this.policyDataStoreRepository.getLatestDataStore(clientId)
+    const latestDataStore = await this.withExecutionTimeLog({
+      clientId,
+      id: 'policyDataStoreRepository.getLatestDataStore',
+      thunk: () => this.policyDataStoreRepository.getLatestDataStore(clientId)
+    })
+
+    await this.withExecutionTimeLog({
+      clientId,
+      id: 'verifySignature(policy)',
+      thunk: () =>
+        this.verifySignature({
+          payload,
+          keys: client.dataStore.policyPublicKeys,
+          date: latestDataStore?.createdAt
+        })
+    })
 
-    await this.verifySignature({
-      payload,
-      keys: client.dataStore.policyPublicKeys,
-      date: latestDataStore?.createdAt
+    const { data, version } = await this.withExecutionTimeLog({
+      clientId,
+      id: 'policyDataStoreRepository.setDataStore',
+      thunk: () =>
+        this.policyDataStoreRepository.setDataStore(clientId, {
+          version: latestDataStore?.version ? latestDataStore.version + 1 : 1,
+          data: PolicyStore.parse(payload)
+        })
     })
 
-    const { data, version } = await this.policyDataStoreRepository.setDataStore(clientId, {
-      version: latestDataStore?.version ? latestDataStore.version + 1 : 1,
-      data: PolicyStore.parse(payload)
+    const success = await this.withExecutionTimeLog({
+      clientId,
+      thunk: () => this.clusterService.sync(clientId),
+      id: 'clusterService.sync(policy)'
     })
 
-    const success = await this.clusterService.sync(clientId)
+    const policy = await this.withExecutionTimeLog({
+      clientId,
+      id: 'PolicyStore.parse',
+      thunk: () => PolicyStore.parse(data)
+    })
 
     return {
       latestSync: { success },
-      policy: PolicyStore.parse(data),
+      policy,
       version
     }
   }

apps/armory/src/managed-data-store/core/service/signature.service.ts

@@ -1,9 +1,15 @@
+import { LoggerService, log } from '@narval/nestjs-shared'
 import { Jwk, Jwt, decodeJwt, hash, verifyJwt } from '@narval/signature'
-import { HttpStatus, Injectable } from '@nestjs/common'
+import { HttpStatus } from '@nestjs/common'
 import { ApplicationException } from '../../../shared/exception/application.exception'
 
-@Injectable()
-export class SignatureService {
+export abstract class SignatureService {
+  protected loggerService: LoggerService
+
+  constructor(loggerService: LoggerService) {
+    this.loggerService = loggerService
+  }
+
   async verifySignature(params: {
     keys: Jwk[]
     payload: { signature: string; data: unknown }
@@ -62,4 +68,21 @@ export class SignatureService {
 
     return true
   }
+
+  protected withExecutionTimeLog<T>({
+    id,
+    thunk,
+    clientId
+  }: {
+    id: string
+    thunk: () => T | Promise<T>
+    clientId: string
+  }): T | Promise<T> {
+    return log.withExecutionTime({
+      thunk,
+      startContext: { clientId },
+      logger: this.loggerService,
+      id: `${this.constructor.name}.${id}`
+    })
+  }
 }

packages/nestjs-shared/src/lib/util/index.ts

@@ -1,4 +1,5 @@
 export * as coerce from './coerce.util'
+export * as log from './log.util'
 export * as secret from './secret.util'
 
 export * from './with-api-version.util'

packages/nestjs-shared/src/lib/util/log.util.ts

@@ -0,0 +1,58 @@
+import { LoggerService } from '../module/logger/service/logger.service'
+
+export const startExecutionTimer = (logger: LoggerService, id: string, startContext?: Record<string, unknown>) => {
+  const startTime = new Date().getTime()
+
+  logger.log(`Execution time of ${id} - Start`, {
+    ...(startContext ? { ...startContext } : {}),
+    startTime
+  })
+
+  return {
+    stop: (stopContext?: Record<string, unknown>) => {
+      const stopTime = new Date().getTime()
+      const duration = stopTime - startTime
+
+      logger.log(`Execution time of ${id} - Stop`, {
+        ...(startContext ? { ...startContext } : {}),
+        ...(stopContext ? { ...stopContext } : {}),
+        startTime,
+        stopTime,
+        duration
+      })
+    }
+  }
+}
+
+export const withExecutionTime = <T>({
+  logger,
+  id,
+  startContext,
+  thunk
+}: {
+  logger: LoggerService
+  id: string
+  thunk: () => T | Promise<T>
+  startContext?: Record<string, unknown>
+}): T | Promise<T> => {
+  const timer = startExecutionTimer(logger, id, startContext)
+  const result = thunk()
+
+  if (result instanceof Promise) {
+    return result.then(
+      (value) => {
+        timer.stop()
+
+        return value
+      },
+      (error) => {
+        timer.stop()
+        throw error
+      }
+    )
+  }
+
+  timer.stop()
+
+  return result
+}