Merge pull request #550 from vtex/metrics/requestDetailsTrace

Add disk cache steps and retry count to tracing

Author: filafb

CHANGELOG.md

@@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 
 ## [Unreleased]
 
+## [6.46.0] - 2023-10-25
+### Added
+- Add disk cache steps and retry count to tracing
+
 ### Changed
 - Stop updating client cache when revalidated and still expired
 

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@vtex/api",
-  "version": "6.45.24",
+  "version": "6.46.0",
   "description": "VTEX I/O API client",
   "main": "lib/index.js",
   "typings": "lib/index.d.ts",

src/HttpClient/middlewares/cache.ts

@@ -1,7 +1,10 @@
 import { AxiosRequestConfig, AxiosResponse } from 'axios'
+import { Span } from 'opentracing'
 
 import { CacheLayer } from '../../caches/CacheLayer'
 import { LOCALE_HEADER, SEGMENT_HEADER, SESSION_HEADER } from '../../constants'
+import { IOContext } from '../../service/worker/runtime/typings'
+import { ErrorReport } from '../../tracing'
 import { HttpLogEvents } from '../../tracing/LogEvents'
 import { HttpCacheLogFields } from '../../tracing/LogFields'
 import { CustomHttpTags } from '../../tracing/Tags'
@@ -90,7 +93,7 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => {
       return await next()
     }
 
-    const span = ctx.tracing?.rootSpan
+    const { rootSpan: span, tracer, logger } = ctx.tracing ?? {}
 
     const key = cacheKey(ctx.config)
     const segmentToken = ctx.config.headers[SEGMENT_HEADER]
@@ -103,8 +106,18 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => {
       [HttpCacheLogFields.KEY_WITH_SEGMENT]: keyWithSegment,
     })
 
-    const cacheHasWithSegment = await storage.has(keyWithSegment)
-    const cached = cacheHasWithSegment ? await storage.get(keyWithSegment) : await storage.get(key)
+
+    const cacheReadSpan = createCacheSpan(cacheType, 'read', tracer, span)
+    let cached: void | Cached
+    try {
+      const cacheHasWithSegment = await storage.has(keyWithSegment)
+      cached = cacheHasWithSegment ? await storage.get(keyWithSegment) : await storage.get(key)
+    } catch (error) {
+      ErrorReport.create({ originalError: error }).injectOnSpan(cacheReadSpan)
+      logger?.warn({ message: 'Error reading from the HttpClient cache', error })
+    } finally {
+      cacheReadSpan?.finish()
+    }
 
     if (cached && cached.response) {
       const {etag: cachedEtag, response, expiration, responseType, responseEncoding} = cached as Cached
@@ -208,24 +221,32 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => {
         return
       }
 
-      await storage.set(setKey, {
-        etag,
-        expiration,
-        response: {data: cacheableData, headers, status},
-        responseEncoding,
-        responseType,
-      })
-
-      span?.log({
-        event: HttpLogEvents.LOCAL_CACHE_SAVED,
-        [HttpCacheLogFields.CACHE_TYPE]: cacheType,
-        [HttpCacheLogFields.KEY_SET]: setKey,
-        [HttpCacheLogFields.AGE]: currentAge,
-        [HttpCacheLogFields.ETAG]: etag,
-        [HttpCacheLogFields.EXPIRATION_TIME]: (expiration - Date.now())/1000,
-        [HttpCacheLogFields.RESPONSE_ENCONDING]: responseEncoding,
-        [HttpCacheLogFields.RESPONSE_TYPE]: responseType,
-      })
+      const cacheWriteSpan = createCacheSpan(cacheType, 'write', tracer, span)
+      try {
+        await storage.set(setKey, {
+          etag,
+          expiration,
+          response: {data: cacheableData, headers, status},
+          responseEncoding,
+          responseType,
+        })
+
+        span?.log({
+          event: HttpLogEvents.LOCAL_CACHE_SAVED,
+          [HttpCacheLogFields.CACHE_TYPE]: cacheType,
+          [HttpCacheLogFields.KEY_SET]: setKey,
+          [HttpCacheLogFields.AGE]: currentAge,
+          [HttpCacheLogFields.ETAG]: etag,
+          [HttpCacheLogFields.EXPIRATION_TIME]: (expiration - Date.now())/1000,
+          [HttpCacheLogFields.RESPONSE_ENCONDING]: responseEncoding,
+          [HttpCacheLogFields.RESPONSE_TYPE]: responseType,
+        })
+      } catch (error) {
+        ErrorReport.create({ originalError: error }).injectOnSpan(cacheWriteSpan)
+        logger?.warn({ message: 'Error writing to the HttpClient cache', error })
+      } finally {
+        cacheWriteSpan?.finish()
+      }
 
       return
     }
@@ -234,6 +255,12 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => {
   }
 }
 
+const createCacheSpan = (cacheType: string, operation: 'read' | 'write', tracer?: IOContext['tracer'], parentSpan?: Span) => {
+  if (tracer && tracer.isTraceSampled && cacheType === 'disk') {
+    return tracer.startSpan(`${operation}-disk-cache`, { childOf: parentSpan })
+  }
+}
+
 export interface Cached {
   etag: string
   expiration: number

src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts

@@ -1,9 +1,9 @@
 import { AxiosInstance } from 'axios'
 import { HttpLogEvents } from '../../../../../tracing/LogEvents'
 import { HttpRetryLogFields } from '../../../../../tracing/LogFields'
+import { CustomHttpTags } from '../../../../../tracing/Tags'
 import { isAbortedOrNetworkErrorOrRouterTimeout } from '../../../../../utils/retry'
 import { RequestConfig } from '../../../../typings'
-import { TraceableRequestConfig } from '../../../tracing'
 
 function fixConfig(axiosInstance: AxiosInstance, config: RequestConfig) {
   if (axiosInstance.defaults.httpAgent === config.httpAgent) {
@@ -66,6 +66,10 @@ const onResponseError = (http: AxiosInstance) => (error: any) => {
     config.transformRequest = [data => data]
 
     config.tracing?.rootSpan?.log({ event: HttpLogEvents.SETUP_REQUEST_RETRY, [HttpRetryLogFields.RETRY_NUMBER]: config.retryCount, [HttpRetryLogFields.RETRY_IN]: delay })
+    config.tracing?.rootSpan?.addTags({
+      [CustomHttpTags.HTTP_RETRY_COUNT]: config.retryCount,
+      [CustomHttpTags.HTTP_RETRY_ERROR_CODE]: error.code,
+    })
 
     return new Promise(resolve => setTimeout(() => resolve(http(config)), delay))
   }

src/tracing/Tags.ts

@@ -69,6 +69,9 @@ export const enum CustomHttpTags {
   HTTP_MEMOIZATION_CACHE_RESULT = 'http.cache.memoization',
   HTTP_DISK_CACHE_RESULT = 'http.cache.disk',
   HTTP_ROUTER_CACHE_RESULT = 'http.cache.router',
+
+  HTTP_RETRY_ERROR_CODE = 'http.retry.error.code',
+  HTTP_RETRY_COUNT = 'http.retry.count',
 }
 
 export const UserlandTags = {