chore: Logs peer & graph API response times

src/AssetPack/AssetPack.router.ts

@@ -7,6 +7,7 @@ import { ILoggerComponent } from '@well-known-components/interfaces'
 import { Router } from '../common/Router'
 import { HTTPError, STATUS_CODES } from '../common/HTTPError'
 import { getValidator } from '../utils/validator'
+import { logExecutionTime } from '../utils/logging'
 import {
   withModelExists,
   withModelAuthorization,
@@ -120,8 +121,9 @@ export class AssetPackRouter extends Router {
     if (owner === 'default') {
       return this.sendDefaultAssetPacksRaw(res, tracer)
     } else if (ethAddress && owner === ethAddress) {
-      const usersAssetPacks = await this.logExecutionTime(
+      const usersAssetPacks = await logExecutionTime(
         () => AssetPack.findByEthAddressWithAssets(ethAddress),
+        this.logger,
         `Get the user\'s (${ethAddress}) asset packs`,
         tracer
       )
@@ -138,8 +140,9 @@ export class AssetPackRouter extends Router {
 
     // Get user asset packs
     if (ethAddress) {
-      assetPacks = await this.logExecutionTime(
+      assetPacks = await logExecutionTime(
         () => AssetPack.findByEthAddressWithAssets(ethAddress),
+        this.logger,
         `Get the user\'s (${ethAddress}) asset packs`,
         tracer
       )
@@ -151,8 +154,9 @@ export class AssetPackRouter extends Router {
 
     // Get default asset packs
     if (ethAddress !== DEFAULT_ETH_ADDRESS) {
-      const [defaultAssetPacks] = await this.logExecutionTime(
+      const [defaultAssetPacks] = await logExecutionTime(
         this.getDefaultAssetPacks,
+        this.logger,
         'Get the default asset packs',
         tracer
       )
@@ -177,8 +181,9 @@ export class AssetPackRouter extends Router {
       `Starting request to get the asset pack with id ${id} and the address ${eth_address} with tracer ${tracer}`
     )
 
-    const isVisible = await this.logExecutionTime(
+    const isVisible = await logExecutionTime(
       () => AssetPack.isVisible(id, [eth_address, DEFAULT_ETH_ADDRESS]),
+      this.logger,
       'Get if asset pack is visible',
       tracer
     )
@@ -195,8 +200,9 @@ export class AssetPackRouter extends Router {
       `[${tracer}] Assets pack with id ${id} is visible to ${eth_address}`
     )
 
-    const assetPack = await this.logExecutionTime(
+    const assetPack = await logExecutionTime(
       () => AssetPack.findOneWithAssets(id),
+      this.logger,
       'Find one with assets',
       tracer
     )
@@ -308,8 +314,9 @@ export class AssetPackRouter extends Router {
     res: express.Response,
     tracer: string
   ) => {
-    const [, defaultAssetPacksRaw] = await this.logExecutionTime(
+    const [, defaultAssetPacksRaw] = await logExecutionTime(
       this.getDefaultAssetPacks,
+      this.logger,
       'Get default asset packs for default owner',
       tracer
     )
@@ -347,20 +354,6 @@ export class AssetPackRouter extends Router {
     return [this.defaultAssetPacks, this.defaultAssetPacksCachedResponse]
   }
 
-  private logExecutionTime = async <T>(
-    functionToMeasure: () => T | Promise<T>,
-    name: string,
-    tracer: string
-  ): Promise<T> => {
-    const start = process.hrtime.bigint()
-    const result = await functionToMeasure()
-    const end = process.hrtime.bigint()
-    this.logger.info(
-      `[${tracer}] ${name} took ${(end - start) / BigInt(1000000)} ms to run`
-    )
-    return result
-  }
-
   private sanitize(assetPacks: FullAssetPackAttributes[]) {
     return utils.mapOmit<FullAssetPackAttributes>(
       assetPacks,

src/ethereum/api/collection.ts

@@ -1,5 +1,7 @@
 import gql from 'graphql-tag'
 import { env } from 'decentraland-commons'
+import { createConsoleLogComponent } from '@well-known-components/logger'
+import { ILoggerComponent } from '@well-known-components/interfaces'
 import {
   collectionFragment,
   itemFragment,
@@ -16,6 +18,7 @@ import {
   PAGINATION_VARIABLES,
   PAGINATION_ARGUMENTS,
 } from './BaseGraphAPI'
+import { logExecutionTime } from '../../utils/logging'
 
 const getCollectionByIdQuery = () => gql`
   query getCollectionById($id: String) {
@@ -132,6 +135,13 @@ const getRaritiesQuery = () => gql`
 export const COLLECTIONS_URL = env.get('COLLECTIONS_GRAPH_URL', '')
 
 export class CollectionAPI extends BaseGraphAPI {
+  logger: ILoggerComponent.ILogger
+
+  constructor(url: string) {
+    super(url)
+    this.logger = createConsoleLogComponent().getLogger('GraphAPI')
+  }
+
   fetchCollection = async (contractAddress: string) => {
     const {
       data: { collections = [] },
@@ -153,17 +163,26 @@ export class CollectionAPI extends BaseGraphAPI {
   fetchCollectionsByAuthorizedUser = async (
     userAddress: string
   ): Promise<CollectionFragment[]> => {
-    return this.paginate(['creator', 'manager', 'minter'], {
-      query: getCollectionsByAuthorizedUserQuery(),
-      variables: {
-        user: userAddress.toLowerCase(),
-        users: [userAddress.toLowerCase()],
-      },
-    })
+    return logExecutionTime(
+      () =>
+        this.paginate(['creator', 'manager', 'minter'], {
+          query: getCollectionsByAuthorizedUserQuery(),
+          variables: {
+            user: userAddress.toLowerCase(),
+            users: [userAddress.toLowerCase()],
+          },
+        }),
+      this.logger,
+      'Collections by authorized user'
+    )
   }
 
   fetchItems = async (): Promise<ItemFragment[]> => {
-    return this.paginate(['items'], { query: getItemsQuery() })
+    return logExecutionTime(
+      () => this.paginate(['items'], { query: getItemsQuery() }),
+      this.logger,
+      'Items fetch'
+    )
   }
 
   fetchItem = async (contractAddress: string, tokenId: string) => {
@@ -182,26 +201,33 @@ export class CollectionAPI extends BaseGraphAPI {
   ): Promise<ItemFragment[]> => {
     const {
       data: { items = [] },
-    } = await this.query<{ items: ItemFragment[] }>({
-      query: getItemsByCollectionIdQuery(),
-      variables: { collectionId: contractAddress.toLowerCase() },
-    })
+    } = await logExecutionTime(
+      () =>
+        this.query<{ items: ItemFragment[] }>({
+          query: getItemsByCollectionIdQuery(),
+          variables: { collectionId: contractAddress.toLowerCase() },
+        }),
+      this.logger,
+      'Items by contract fetch'
+    )
 
     return items
   }
 
   fetchItemsByAuthorizedUser = async (
     userAddress: string
   ): Promise<ItemFragment[]> => {
-    const result: { items: ItemFragment[] }[] = await this.paginate(
-      ['creator', 'manager', 'minter'],
-      {
-        query: getItemsByAuthorizedUserQuery(),
-        variables: {
-          user: userAddress.toLowerCase(),
-          users: [userAddress.toLowerCase()],
-        },
-      }
+    const result: { items: ItemFragment[] }[] = await logExecutionTime(
+      () =>
+        this.paginate(['creator', 'manager', 'minter'], {
+          query: getItemsByAuthorizedUserQuery(),
+          variables: {
+            user: userAddress.toLowerCase(),
+            users: [userAddress.toLowerCase()],
+          },
+        }),
+      this.logger,
+      'Items by author fetch'
     )
 
     return result.reduce(
@@ -234,7 +260,11 @@ export class CollectionAPI extends BaseGraphAPI {
   }
 
   fetchCommittee = async (): Promise<AccountFragment[]> => {
-    return this.paginate(['accounts'], { query: getCommitteeQuery() })
+    return logExecutionTime(
+      () => this.paginate(['accounts'], { query: getCommitteeQuery() }),
+      this.logger,
+      'Committee fetch'
+    )
   }
 
   fetchRarities = async () => {

src/ethereum/api/peer.ts

@@ -1,10 +1,13 @@
 import fetch from 'isomorphic-fetch'
+import { ILoggerComponent } from '@well-known-components/interfaces'
+import { createConsoleLogComponent } from '@well-known-components/logger'
 import { env } from 'decentraland-commons'
 import { LambdasClient } from 'dcl-catalyst-client'
 import { AuthLink } from 'dcl-crypto'
 import { WearableData, WearableRepresentation } from '../../Item/wearable/types'
 import { ItemRarity } from '../../Item'
 import { MetricsAttributes } from '../../Metrics'
+import { logExecutionTime } from '../../utils/logging'
 
 export const THUMBNAIL_PATH = 'thumbnail.png'
 
@@ -48,36 +51,45 @@ export const PEER_URL = env.get('PEER_URL', '')
 
 export class PeerAPI {
   lambdasClient: LambdasClient
+  logger: ILoggerComponent.ILogger
 
   constructor() {
     this.lambdasClient = new LambdasClient(`${PEER_URL}/lambdas`)
+    this.logger = createConsoleLogComponent().getLogger('PeerAPI')
   }
 
   async validateSignature(
     body: SignatureBody
   ): Promise<ValidateSignatureResponse> {
-    const response = await fetch(
-      `${PEER_URL}/lambdas/crypto/validate-signature`,
-      {
-        method: 'post',
-        headers: {
-          'Content-Type': 'application/json',
-        },
-        body: JSON.stringify(body, null, 2),
-      }
+    const response = await logExecutionTime(
+      () =>
+        fetch(`${PEER_URL}/lambdas/crypto/validate-signature`, {
+          method: 'post',
+          headers: {
+            'Content-Type': 'application/json',
+          },
+          body: JSON.stringify(body, null, 2),
+        }),
+      this.logger,
+      'Validate Signature Fetch'
     )
     const result = (await response.json()) as ValidateSignatureResponse
     if (!result.valid) {
+      this.logger.error('Logging request unsuccessful')
       throw new Error(result.error)
     }
     return result
   }
 
   async fetchWearables(urns: string[]): Promise<Wearable[]> {
-    const wearables: PeerWearable[] =
-      urns.length > 0
-        ? await this.lambdasClient.fetchWearables({ wearableIds: urns })
-        : []
+    const wearables: PeerWearable[] = await logExecutionTime(
+      () =>
+        urns.length > 0
+          ? this.lambdasClient.fetchWearables({ wearableIds: urns })
+          : [],
+      this.logger,
+      'Wearables Fetch'
+    )
     return wearables.map((wearable) => this.toWearable(wearable))
   }
 

src/utils/logging.ts

@@ -0,0 +1,20 @@
+import { ILoggerComponent } from '@well-known-components/interfaces'
+import { v4 as uuidv4 } from 'uuid'
+
+export const logExecutionTime = async <T>(
+  functionToMeasure: () => T | Promise<T>,
+  logger: ILoggerComponent.ILogger,
+  name: string,
+  tracer: string = uuidv4()
+): Promise<T> => {
+  const start = process.hrtime.bigint()
+  logger.info(`[${tracer}] Performing ${name}`)
+  const result = await functionToMeasure()
+  const end = process.hrtime.bigint()
+  logger.info(
+    `[${tracer ?? 'no-tracer'}] ${name} took ${
+      (end - start) / BigInt(1000000)
+    } ms to run`
+  )
+  return result
+}