refactor: add log level guards to prevent unnecessary string generati…

…on (#3154) * add log level guards to prevent unnecessary string generation Signed-off-by: belloibrahv <[email protected]> * remove logger check from utilities Signed-off-by: belloibrahv <[email protected]> --------- Signed-off-by: belloibrahv <[email protected]>
hashgraph · Nov 12, 2024 · 264d2cb · 264d2cb
1 parent 1b03981
commit 264d2cb
Show file tree

Hide file tree

Showing 33 changed files with 786 additions and 418 deletions.
diff --git a/packages/relay/src/lib/clients/cache/localLRUCache.ts b/packages/relay/src/lib/clients/cache/localLRUCache.ts
@@ -128,7 +128,9 @@ export class LocalLRUCache implements ICacheClient {
       const censoredKey = key.replace(Utils.IP_ADDRESS_REGEX, '<REDACTED>');
       const censoredValue = JSON.stringify(value).replace(/"ipAddress":"[^"]+"/, '"ipAddress":"<REDACTED>"');
       const message = `Returning cached value ${censoredKey}:${censoredValue} on ${callingMethod} call`;
-      this.logger.trace(`${requestDetails.formattedRequestId} ${message}`);
+      if (this.logger.isLevelEnabled('trace')) {
+        this.logger.trace(`${requestDetails.formattedRequestId} ${message}`);
+      }
       return value;
     }
 
@@ -145,9 +147,11 @@ export class LocalLRUCache implements ICacheClient {
   public async getRemainingTtl(key: string, callingMethod: string, requestDetails: RequestDetails): Promise<number> {
     const cache = this.getCacheInstance(key);
     const remainingTtl = cache.getRemainingTTL(key); // in milliseconds
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} returning remaining TTL ${key}:${remainingTtl} on ${callingMethod} call`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} returning remaining TTL ${key}:${remainingTtl} on ${callingMethod} call`,
+      );
+    }
     return remainingTtl;
   }
 
@@ -179,9 +183,11 @@ export class LocalLRUCache implements ICacheClient {
     const message = `Caching ${censoredKey}:${censoredValue} on ${callingMethod} for ${
       resolvedTtl > 0 ? `${resolvedTtl} ms` : 'indefinite time'
     }`;
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} ${message} (cache size: ${this.cache.size}, max: ${this.options.max})`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} ${message} (cache size: ${this.cache.size}, max: ${this.options.max})`,
+      );
+    }
   }
 
   /**
@@ -232,7 +238,9 @@ export class LocalLRUCache implements ICacheClient {
    * @param {RequestDetails} requestDetails - The request details for logging and tracking.
    */
   public async delete(key: string, callingMethod: string, requestDetails: RequestDetails): Promise<void> {
-    this.logger.trace(`${requestDetails.formattedRequestId} delete cache for ${key} on ${callingMethod} call`);
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(`${requestDetails.formattedRequestId} delete cache for ${key} on ${callingMethod} call`);
+    }
     const cache = this.getCacheInstance(key);
     cache.delete(key);
   }
@@ -290,9 +298,11 @@ export class LocalLRUCache implements ICacheClient {
 
     const matchingKeys = keys.filter((key) => regex.test(key));
 
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} retrieving keys matching ${pattern} on ${callingMethod} call`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} retrieving keys matching ${pattern} on ${callingMethod} call`,
+      );
+    }
     return matchingKeys;
   }
 

diff --git a/packages/relay/src/lib/clients/cache/redisCache.ts b/packages/relay/src/lib/clients/cache/redisCache.ts
@@ -141,7 +141,9 @@ export class RedisCache implements IRedisCacheClient {
       const censoredKey = key.replace(Utils.IP_ADDRESS_REGEX, '<REDACTED>');
       const censoredValue = result.replace(/"ipAddress":"[^"]+"/, '"ipAddress":"<REDACTED>"');
       const message = `Returning cached value ${censoredKey}:${censoredValue} on ${callingMethod} call`;
-      this.logger.trace(`${requestDetails.formattedRequestId} ${message}`);
+      if (this.logger.isLevelEnabled('trace')) {
+        this.logger.trace(`${requestDetails.formattedRequestId} ${message}`);
+      }
       // TODO: add metrics
       return JSON.parse(result);
     }
@@ -179,7 +181,9 @@ export class RedisCache implements IRedisCacheClient {
     const message = `Caching ${censoredKey}:${censoredValue} on ${callingMethod} for ${
       resolvedTtl > 0 ? `${resolvedTtl} ms` : 'indefinite time'
     }`;
-    this.logger.trace(`${requestDetails.formattedRequestId} ${message}`);
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(`${requestDetails.formattedRequestId} ${message}`);
+    }
     // TODO: add metrics
   }
 
@@ -208,9 +212,11 @@ export class RedisCache implements IRedisCacheClient {
 
     // Log the operation
     const entriesLength = Object.keys(keyValuePairs).length;
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} caching multiple keys via ${callingMethod}, total keys: ${entriesLength}`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} caching multiple keys via ${callingMethod}, total keys: ${entriesLength}`,
+      );
+    }
   }
 
   /**
@@ -243,9 +249,11 @@ export class RedisCache implements IRedisCacheClient {
 
     // Log the operation
     const entriesLength = Object.keys(keyValuePairs).length;
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} caching multiple keys via ${callingMethod}, total keys: ${entriesLength}`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} caching multiple keys via ${callingMethod}, total keys: ${entriesLength}`,
+      );
+    }
   }
 
   /**
@@ -259,7 +267,9 @@ export class RedisCache implements IRedisCacheClient {
   async delete(key: string, callingMethod: string, requestDetails: RequestDetails): Promise<void> {
     const client = await this.getConnectedClient();
     await client.del(key);
-    this.logger.trace(`${requestDetails.formattedRequestId} delete cache for ${key} on ${callingMethod} call`);
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(`${requestDetails.formattedRequestId} delete cache for ${key} on ${callingMethod} call`);
+    }
     // TODO: add metrics
   }
 
@@ -327,7 +337,11 @@ export class RedisCache implements IRedisCacheClient {
   async incrBy(key: string, amount: number, callingMethod: string, requestDetails: RequestDetails): Promise<number> {
     const client = await this.getConnectedClient();
     const result = await client.incrBy(key, amount);
-    this.logger.trace(`${requestDetails.formattedRequestId} incrementing ${key} by ${amount} on ${callingMethod} call`);
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} incrementing ${key} by ${amount} on ${callingMethod} call`,
+      );
+    }
     return result;
   }
 
@@ -350,9 +364,11 @@ export class RedisCache implements IRedisCacheClient {
   ): Promise<any[]> {
     const client = await this.getConnectedClient();
     const result = await client.lRange(key, start, end);
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} retrieving range [${start}:${end}] from ${key} on ${callingMethod} call`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} retrieving range [${start}:${end}] from ${key} on ${callingMethod} call`,
+      );
+    }
     return result.map((item) => JSON.parse(item));
   }
 
@@ -369,9 +385,11 @@ export class RedisCache implements IRedisCacheClient {
     const client = await this.getConnectedClient();
     const serializedValue = JSON.stringify(value);
     const result = await client.rPush(key, serializedValue);
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} pushing ${serializedValue} to ${key} on ${callingMethod} call`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} pushing ${serializedValue} to ${key} on ${callingMethod} call`,
+      );
+    }
     return result;
   }
 
@@ -385,9 +403,11 @@ export class RedisCache implements IRedisCacheClient {
   async keys(pattern: string, callingMethod: string, requestDetails: RequestDetails): Promise<string[]> {
     const client = await this.getConnectedClient();
     const result = await client.keys(pattern);
-    this.logger.trace(
-      `${requestDetails.formattedRequestId} retrieving keys matching ${pattern} on ${callingMethod} call`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${requestDetails.formattedRequestId} retrieving keys matching ${pattern} on ${callingMethod} call`,
+      );
+    }
     return result;
   }
 }
diff --git a/packages/relay/src/lib/clients/mirrorNodeClient.ts b/packages/relay/src/lib/clients/mirrorNodeClient.ts
@@ -249,7 +249,9 @@ export class MirrorNodeClient {
         const requestId = request ? request.split('\n')[3].substring(11, 47) : '';
         const requestIdPrefix = formatRequestIdMessage(requestId);
         const delay = isDevMode ? mirrorNodeRetryDelayDevMode || 200 : mirrorNodeRetryDelay * retryCount;
-        this.logger.trace(`${requestIdPrefix} Retry delay ${delay} ms on '${error?.request?.path}'`);
+        if (this.logger.isLevelEnabled('trace')) {
+          this.logger.trace(`${requestIdPrefix} Retry delay ${delay} ms on '${error?.request?.path}'`);
+        }
         return delay;
       },
       retryCondition: (error) => {
@@ -364,7 +366,9 @@ export class MirrorNodeClient {
       }
 
       const ms = Date.now() - start;
-      this.logger.debug(`${requestDetails.formattedRequestId} [${method}] ${path} ${response.status} ${ms} ms`);
+      if (this.logger.isLevelEnabled('debug')) {
+        this.logger.debug(`${requestDetails.formattedRequestId} [${method}] ${path} ${response.status} ${ms} ms`);
+      }
       this.mirrorResponseHistogram.labels(pathLabel, response.status?.toString()).observe(ms);
       return response.data;
     } catch (error: any) {
@@ -421,17 +425,21 @@ export class MirrorNodeClient {
     const acceptedErrorResponses = MirrorNodeClient.acceptedErrorStatusesResponsePerRequestPathMap.get(pathLabel);
 
     if (error.response && acceptedErrorResponses?.includes(effectiveStatusCode)) {
-      this.logger.debug(`${requestIdPrefix} [${method}] ${path} ${effectiveStatusCode} status`);
+      if (this.logger.isLevelEnabled('debug')) {
+        this.logger.debug(`${requestIdPrefix} [${method}] ${path} ${effectiveStatusCode} status`);
+      }
       return null;
     }
 
     // Contract Call returns 400 for a CONTRACT_REVERT but is a valid response, expected and should not be logged as error:
     if (pathLabel === MirrorNodeClient.CONTRACT_CALL_ENDPOINT && effectiveStatusCode === 400) {
-      this.logger.debug(
-        `${requestIdPrefix} [${method}] ${path} Contract Revert: ( StatusCode: '${effectiveStatusCode}', StatusText: '${
-          error.response.statusText
-        }', Detail: '${JSON.stringify(error.response.detail)}',Data: '${JSON.stringify(error.response.data)}')`,
-      );
+      if (this.logger.isLevelEnabled('debug')) {
+        this.logger.debug(
+          `${requestIdPrefix} [${method}] ${path} Contract Revert: ( StatusCode: '${effectiveStatusCode}', StatusText: '${
+            error.response.statusText
+          }', Detail: '${JSON.stringify(error.response.detail)}',Data: '${JSON.stringify(error.response.data)}')`,
+        );
+      }
     } else {
       this.logger.error(
         new Error(error.message),
@@ -459,9 +467,11 @@ export class MirrorNodeClient {
 
     if (page === pageMax) {
       // max page reached
-      this.logger.trace(
-        `${requestDetails.formattedRequestId} Max page reached ${pageMax} with ${results.length} results`,
-      );
+      if (this.logger.isLevelEnabled('trace')) {
+        this.logger.trace(
+          `${requestDetails.formattedRequestId} Max page reached ${pageMax} with ${results.length} results`,
+        );
+      }
       throw predefined.PAGINATION_MAX(pageMax);
     }
 
@@ -1305,11 +1315,13 @@ export class MirrorNodeClient {
         break;
       }
 
-      this.logger.trace(
-        `${requestDetails?.formattedRequestId} Repeating request ${methodName} with args ${JSON.stringify(
-          args,
-        )} retry count ${i} of ${repeatCount}. Waiting ${this.MIRROR_NODE_RETRY_DELAY} ms before repeating request`,
-      );
+      if (this.logger.isLevelEnabled('trace')) {
+        this.logger.trace(
+          `${requestDetails?.formattedRequestId} Repeating request ${methodName} with args ${JSON.stringify(
+            args,
+          )} retry count ${i} of ${repeatCount}. Waiting ${this.MIRROR_NODE_RETRY_DELAY} ms before repeating request`,
+        );
+      }
 
       // Backoff before repeating request
       await new Promise((r) => setTimeout(r, this.MIRROR_NODE_RETRY_DELAY));
@@ -1337,9 +1349,11 @@ export class MirrorNodeClient {
   ): Promise<ITransactionRecordMetric> {
     const formattedRequestId = requestDetails.formattedRequestId;
 
-    this.logger.trace(
-      `${formattedRequestId} Get transaction record via mirror node: transactionId=${transactionId}, txConstructorName=${txConstructorName}, callerName=${callerName}`,
-    );
+    if (this.logger.isLevelEnabled('trace')) {
+      this.logger.trace(
+        `${formattedRequestId} Get transaction record via mirror node: transactionId=${transactionId}, txConstructorName=${txConstructorName}, callerName=${callerName}`,
+      );
+    }
 
     const transactionRecords = await this.repeatedRequest(
       this.getTransactionById.name,

diff --git a/packages/relay/src/lib/clients/sdkClient.ts b/packages/relay/src/lib/clients/sdkClient.ts
@@ -527,9 +527,11 @@ export class SDKClient {
         const sdkClientError = new SDKClientError(e, e.message);
         if (sdkClientError.isTimeoutExceeded()) {
           const delay = retries * 1000;
-          this.logger.trace(
-            `${requestDetails.formattedRequestId} Contract call query failed with status ${sdkClientError.message}. Retrying again after ${delay} ms ...`,
-          );
+          if (this.logger.isLevelEnabled('trace')) {
+            this.logger.trace(
+              `${requestDetails.formattedRequestId} Contract call query failed with status ${sdkClientError.message}. Retrying again after ${delay} ms ...`,
+            );
+          }
           retries++;
           await new Promise((r) => setTimeout(r, delay));
           continue;
@@ -642,9 +644,11 @@ export class SDKClient {
         throw predefined.REQUEST_TIMEOUT;
       }
 
-      this.logger.debug(
-        `${requestIdPrefix} Fail to execute ${queryConstructorName} query: paymentTransactionId=${query.paymentTransactionId}, callerName=${callerName}, status=${sdkClientError.status}(${sdkClientError.status._code}), cost=${queryCost} tinybars`,
-      );
+      if (this.logger.isLevelEnabled('debug')) {
+        this.logger.debug(
+          `${requestIdPrefix} Fail to execute ${queryConstructorName} query: paymentTransactionId=${query.paymentTransactionId}, callerName=${callerName}, status=${sdkClientError.status}(${sdkClientError.status._code}), cost=${queryCost} tinybars`,
+        );
+      }
 
       throw sdkClientError;
     } finally {
@@ -920,9 +924,11 @@ export class SDKClient {
         this.logger.warn(`${requestDetails.formattedRequestId} File ${fileId} is empty.`);
         throw new SDKClientError({}, `${requestDetails.formattedRequestId} Created file is empty. `);
       }
-      this.logger.trace(
-        `${requestDetails.formattedRequestId} Created file with fileId: ${fileId} and file size ${fileInfo.size}`,
-      );
+      if (this.logger.isLevelEnabled('trace')) {
+        this.logger.trace(
+          `${requestDetails.formattedRequestId} Created file with fileId: ${fileId} and file size ${fileInfo.size}`,
+        );
+      }
     }
 
     return fileId;
@@ -971,7 +977,9 @@ export class SDKClient {
       );
 
       if (fileInfo.isDeleted) {
-        this.logger.trace(`${requestDetails.formattedRequestId} Deleted file with fileId: ${fileId}`);
+        if (this.logger.isLevelEnabled('trace')) {
+          this.logger.trace(`${requestDetails.formattedRequestId} Deleted file with fileId: ${fileId}`);
+        }
       } else {
         this.logger.warn(`${requestDetails.formattedRequestId} Fail to delete file with fileId: ${fileId} `);
       }
@@ -1026,9 +1034,11 @@ export class SDKClient {
     let transactionFee: number = 0;
     let txRecordChargeAmount: number = 0;
     try {
-      this.logger.trace(
-        `${requestDetails.formattedRequestId} Get transaction record via consensus node: transactionId=${transactionId}, txConstructorName=${txConstructorName}, callerName=${callerName}`,
-      );
+      if (this.logger.isLevelEnabled('trace')) {
+        this.logger.trace(
+          `${requestDetails.formattedRequestId} Get transaction record via consensus node: transactionId=${transactionId}, txConstructorName=${txConstructorName}, callerName=${callerName}`,
+        );
+      }
 
       const transactionRecord = await new TransactionRecordQuery()
         .setTransactionId(transactionId)