From 8d3c0aa7aa089e6194c5700cdeb74f4e3c7a26ce Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mai=CC=81ra=20Bello?= Date: Mon, 9 Oct 2023 15:26:34 -0300 Subject: [PATCH 1/8] Create new spans for the operations of reading/writing to cache --- src/HttpClient/HttpClient.ts | 4 ++-- src/HttpClient/middlewares/cache.ts | 17 ++++++++++++++++- 2 files changed, 18 insertions(+), 3 deletions(-) diff --git a/src/HttpClient/HttpClient.ts b/src/HttpClient/HttpClient.ts index 5b3e4ab2..471eafdb 100644 --- a/src/HttpClient/HttpClient.ts +++ b/src/HttpClient/HttpClient.ts @@ -114,8 +114,8 @@ export class HttpClient { cancellationToken(cancellation), singleFlightMiddleware, acceptNotFoundMiddleware, - ...memoryCache ? [cacheMiddleware({ type: CacheType.Memory, storage: memoryCache })] : [], - ...diskCache ? [cacheMiddleware({ type: CacheType.Disk, storage: diskCache })] : [], + ...memoryCache ? [cacheMiddleware({ type: CacheType.Memory, storage: memoryCache, tracer })] : [], + ...diskCache ? [cacheMiddleware({ type: CacheType.Disk, storage: diskCache, tracer })] : [], notFoundFallbackMiddleware, routerCacheMiddleware, requestMiddleware(limit), diff --git a/src/HttpClient/middlewares/cache.ts b/src/HttpClient/middlewares/cache.ts index 2d36e40c..004e4f5c 100644 --- a/src/HttpClient/middlewares/cache.ts +++ b/src/HttpClient/middlewares/cache.ts @@ -1,7 +1,9 @@ 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 { HttpLogEvents } from '../../tracing/LogEvents' import { HttpCacheLogFields } from '../../tracing/LogFields' import { CustomHttpTags } from '../../tracing/Tags' @@ -79,9 +81,10 @@ const CacheTypeNames = { interface CacheOptions { type: CacheType storage: CacheLayer + tracer: IOContext['tracer'] } -export const cacheMiddleware = ({ type, storage }: CacheOptions) => { +export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { const CACHE_RESULT_TAG = type === CacheType.Disk ? CustomHttpTags.HTTP_DISK_CACHE_RESULT : CustomHttpTags.HTTP_MEMORY_CACHE_RESULT const cacheType = CacheTypeNames[type] @@ -103,8 +106,11 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => { [HttpCacheLogFields.KEY_WITH_SEGMENT]: keyWithSegment, }) + + const cacheReadSpan = createCacheSpan(tracer, cacheType, 'read', span) const cacheHasWithSegment = await storage.has(keyWithSegment) const cached = cacheHasWithSegment ? await storage.get(keyWithSegment) : await storage.get(key) + cacheReadSpan?.finish() if (cached && cached.response) { const {etag: cachedEtag, response, expiration, responseType, responseEncoding} = cached as Cached @@ -199,6 +205,8 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => { : data const expiration = Date.now() + (maxAge - currentAge) * 1000 + + const cacheWriteSpan = createCacheSpan(tracer, cacheType, 'write', span) await storage.set(setKey, { etag, expiration, @@ -206,6 +214,7 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => { responseEncoding, responseType, }) + cacheWriteSpan?.finish() span?.log({ event: HttpLogEvents.LOCAL_CACHE_SAVED, @@ -225,6 +234,12 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => { } } +const createCacheSpan = (tracer: IOContext['tracer'], cacheType: string, operation: 'read' | 'write', parentSpan?: Span) => { + if (tracer.isTraceSampled && cacheType === 'disk') { + return tracer.startSpan(`${operation}-disk-cache`, { childOf: parentSpan }) + } +} + export interface Cached { etag: string expiration: number From 58d48fd46a95a3b144c1fa11be15658cce3de56f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mai=CC=81ra=20Bello?= Date: Mon, 9 Oct 2023 16:17:28 -0300 Subject: [PATCH 2/8] Handler errors during read/write to cache --- src/HttpClient/middlewares/cache.ts | 51 ++++++++++++++++------------- 1 file changed, 29 insertions(+), 22 deletions(-) diff --git a/src/HttpClient/middlewares/cache.ts b/src/HttpClient/middlewares/cache.ts index 004e4f5c..94e20fbc 100644 --- a/src/HttpClient/middlewares/cache.ts +++ b/src/HttpClient/middlewares/cache.ts @@ -108,9 +108,13 @@ export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { const cacheReadSpan = createCacheSpan(tracer, cacheType, 'read', span) - const cacheHasWithSegment = await storage.has(keyWithSegment) - const cached = cacheHasWithSegment ? await storage.get(keyWithSegment) : await storage.get(key) - cacheReadSpan?.finish() + let cached: void | Cached + try { + const cacheHasWithSegment = await storage.has(keyWithSegment) + cached = cacheHasWithSegment ? await storage.get(keyWithSegment) : await storage.get(key) + } finally { + cacheReadSpan?.finish() + } if (cached && cached.response) { const {etag: cachedEtag, response, expiration, responseType, responseEncoding} = cached as Cached @@ -207,25 +211,28 @@ export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { const expiration = Date.now() + (maxAge - currentAge) * 1000 const cacheWriteSpan = createCacheSpan(tracer, cacheType, 'write', span) - await storage.set(setKey, { - etag, - expiration, - response: {data: cacheableData, headers, status}, - responseEncoding, - responseType, - }) - cacheWriteSpan?.finish() - - 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, - }) + 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, + }) + } finally { + cacheWriteSpan?.finish() + } return } From ecb4e287d3fe0f58b1b09cb1f0a2c981fb081327 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mai=CC=81ra=20Bello?= Date: Tue, 10 Oct 2023 10:26:17 -0300 Subject: [PATCH 3/8] Remove unused param and add error handling --- src/HttpClient/HttpClient.ts | 4 ++-- src/HttpClient/middlewares/cache.ts | 22 ++++++++++++++-------- 2 files changed, 16 insertions(+), 10 deletions(-) diff --git a/src/HttpClient/HttpClient.ts b/src/HttpClient/HttpClient.ts index 471eafdb..5b3e4ab2 100644 --- a/src/HttpClient/HttpClient.ts +++ b/src/HttpClient/HttpClient.ts @@ -114,8 +114,8 @@ export class HttpClient { cancellationToken(cancellation), singleFlightMiddleware, acceptNotFoundMiddleware, - ...memoryCache ? [cacheMiddleware({ type: CacheType.Memory, storage: memoryCache, tracer })] : [], - ...diskCache ? [cacheMiddleware({ type: CacheType.Disk, storage: diskCache, tracer })] : [], + ...memoryCache ? [cacheMiddleware({ type: CacheType.Memory, storage: memoryCache })] : [], + ...diskCache ? [cacheMiddleware({ type: CacheType.Disk, storage: diskCache })] : [], notFoundFallbackMiddleware, routerCacheMiddleware, requestMiddleware(limit), diff --git a/src/HttpClient/middlewares/cache.ts b/src/HttpClient/middlewares/cache.ts index 94e20fbc..19131937 100644 --- a/src/HttpClient/middlewares/cache.ts +++ b/src/HttpClient/middlewares/cache.ts @@ -8,6 +8,7 @@ import { HttpLogEvents } from '../../tracing/LogEvents' import { HttpCacheLogFields } from '../../tracing/LogFields' import { CustomHttpTags } from '../../tracing/Tags' import { MiddlewareContext, RequestConfig } from '../typings' +import { ErrorReport } from '../../tracing' const RANGE_HEADER_QS_KEY = '__range_header' const cacheableStatusCodes = [200, 203, 204, 206, 300, 301, 404, 405, 410, 414, 501] // https://tools.ietf.org/html/rfc7231#section-6.1 @@ -81,10 +82,9 @@ const CacheTypeNames = { interface CacheOptions { type: CacheType storage: CacheLayer - tracer: IOContext['tracer'] } -export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { +export const cacheMiddleware = ({ type, storage }: CacheOptions) => { const CACHE_RESULT_TAG = type === CacheType.Disk ? CustomHttpTags.HTTP_DISK_CACHE_RESULT : CustomHttpTags.HTTP_MEMORY_CACHE_RESULT const cacheType = CacheTypeNames[type] @@ -93,7 +93,7 @@ export const cacheMiddleware = ({ type, storage, tracer }: 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] @@ -107,11 +107,14 @@ export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { }) - const cacheReadSpan = createCacheSpan(tracer, cacheType, 'read', span) - let cached: void | Cached + const cacheReadSpan = createCacheSpan(cacheType, 'read', tracer, span) + let cached: void | Cached = undefined 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() } @@ -210,7 +213,7 @@ export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { const expiration = Date.now() + (maxAge - currentAge) * 1000 - const cacheWriteSpan = createCacheSpan(tracer, cacheType, 'write', span) + const cacheWriteSpan = createCacheSpan(cacheType, 'write', tracer, span) try { await storage.set(setKey, { etag, @@ -230,6 +233,9 @@ export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { [HttpCacheLogFields.RESPONSE_ENCONDING]: responseEncoding, [HttpCacheLogFields.RESPONSE_TYPE]: responseType, }) + } catch (error) { + ErrorReport.create({ originalError: error }).injectOnSpan(cacheReadSpan) + logger?.warn({ message: 'Error writing to the HttpClient cache', error }) } finally { cacheWriteSpan?.finish() } @@ -241,8 +247,8 @@ export const cacheMiddleware = ({ type, storage, tracer }: CacheOptions) => { } } -const createCacheSpan = (tracer: IOContext['tracer'], cacheType: string, operation: 'read' | 'write', parentSpan?: Span) => { - if (tracer.isTraceSampled && cacheType === 'disk') { +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 }) } } From 73084b9b0f6dbbc327c2f7245f0be040cbdfc7d0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mai=CC=81ra=20Bello?= Date: Tue, 10 Oct 2023 11:18:25 -0300 Subject: [PATCH 4/8] Add retry fields to the current span --- .../request/setupAxios/interceptors/exponentialBackoff.ts | 6 +++++- src/tracing/Tags.ts | 3 +++ 2 files changed, 8 insertions(+), 1 deletion(-) diff --git a/src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts b/src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts index 94c869c0..17c70684 100644 --- a/src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts +++ b/src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts @@ -3,7 +3,7 @@ import { HttpLogEvents } from '../../../../../tracing/LogEvents' import { HttpRetryLogFields } from '../../../../../tracing/LogFields' import { isAbortedOrNetworkErrorOrRouterTimeout } from '../../../../../utils/retry' import { RequestConfig } from '../../../../typings' -import { TraceableRequestConfig } from '../../../tracing' +import { CustomHttpTags } from '../../../../../tracing/Tags' 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)) } diff --git a/src/tracing/Tags.ts b/src/tracing/Tags.ts index cdbe6524..d6047f10 100644 --- a/src/tracing/Tags.ts +++ b/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 = { From d32449c55992f41827d3580bf6e39821e29a17d0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mai=CC=81ra=20Bello?= Date: Tue, 10 Oct 2023 11:35:12 -0300 Subject: [PATCH 5/8] Fix lint errors --- src/HttpClient/middlewares/cache.ts | 4 ++-- .../request/setupAxios/interceptors/exponentialBackoff.ts | 4 ++-- src/tracing/Tags.ts | 2 +- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/src/HttpClient/middlewares/cache.ts b/src/HttpClient/middlewares/cache.ts index 19131937..7ed54258 100644 --- a/src/HttpClient/middlewares/cache.ts +++ b/src/HttpClient/middlewares/cache.ts @@ -4,11 +4,11 @@ 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' import { MiddlewareContext, RequestConfig } from '../typings' -import { ErrorReport } from '../../tracing' const RANGE_HEADER_QS_KEY = '__range_header' const cacheableStatusCodes = [200, 203, 204, 206, 300, 301, 404, 405, 410, 414, 501] // https://tools.ietf.org/html/rfc7231#section-6.1 @@ -108,7 +108,7 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => { const cacheReadSpan = createCacheSpan(cacheType, 'read', tracer, span) - let cached: void | Cached = undefined + let cached: void | Cached try { const cacheHasWithSegment = await storage.has(keyWithSegment) cached = cacheHasWithSegment ? await storage.get(keyWithSegment) : await storage.get(key) diff --git a/src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts b/src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts index 17c70684..a56a3156 100644 --- a/src/HttpClient/middlewares/request/setupAxios/interceptors/exponentialBackoff.ts +++ b/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 { CustomHttpTags } from '../../../../../tracing/Tags' function fixConfig(axiosInstance: AxiosInstance, config: RequestConfig) { if (axiosInstance.defaults.httpAgent === config.httpAgent) { @@ -68,7 +68,7 @@ const onResponseError = (http: AxiosInstance) => (error: any) => { 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 + [CustomHttpTags.HTTP_RETRY_ERROR_CODE]: error.code, }) return new Promise(resolve => setTimeout(() => resolve(http(config)), delay)) diff --git a/src/tracing/Tags.ts b/src/tracing/Tags.ts index d6047f10..35b60639 100644 --- a/src/tracing/Tags.ts +++ b/src/tracing/Tags.ts @@ -71,7 +71,7 @@ export const enum CustomHttpTags { HTTP_ROUTER_CACHE_RESULT = 'http.cache.router', HTTP_RETRY_ERROR_CODE = 'http.retry.error.code', - HTTP_RETRY_COUNT = 'http.retry.count' + HTTP_RETRY_COUNT = 'http.retry.count', } export const UserlandTags = { From dff7b51880a78bd0a33bf14e42d4f04fbe846e77 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mai=CC=81ra=20Bello?= Date: Wed, 25 Oct 2023 11:04:08 -0300 Subject: [PATCH 6/8] Add entry to CHANGELOG --- CHANGELOG.md | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 26025a4e..07ee3d84 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0. ## [Unreleased] +### Added + +- Add disk cache steps and retry count to tracing + ## [6.45.24] - 2023-10-05 ### Added From b5198019c2c19c585f2b82be214b9c120e2a79c1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mai=CC=81ra=20Bello?= Date: Wed, 25 Oct 2023 11:04:46 -0300 Subject: [PATCH 7/8] Fix variable name --- src/HttpClient/middlewares/cache.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/HttpClient/middlewares/cache.ts b/src/HttpClient/middlewares/cache.ts index 7ed54258..a0e84df2 100644 --- a/src/HttpClient/middlewares/cache.ts +++ b/src/HttpClient/middlewares/cache.ts @@ -234,7 +234,7 @@ export const cacheMiddleware = ({ type, storage }: CacheOptions) => { [HttpCacheLogFields.RESPONSE_TYPE]: responseType, }) } catch (error) { - ErrorReport.create({ originalError: error }).injectOnSpan(cacheReadSpan) + ErrorReport.create({ originalError: error }).injectOnSpan(cacheWriteSpan) logger?.warn({ message: 'Error writing to the HttpClient cache', error }) } finally { cacheWriteSpan?.finish() From e1e27b20ba2b3c4f376cbd4ce337f43b2e4d0d9a Mon Sep 17 00:00:00 2001 From: Filadelfo Date: Wed, 25 Oct 2023 19:53:38 -0300 Subject: [PATCH 8/8] Bump version --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index a05d8e89..53a0b1bc 100644 --- a/package.json +++ b/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",