Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

feat: add log level guards to prevent unnecessary string generation #3154

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
+781 −413
Open

feat: add log level guards to prevent unnecessary string generation #3154

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
e2b3d2f
Fix bugs on PR
belloibrahv Nov 5, 2024
9a66249
Merge branch 'main' into issue-1118-log-level-guard
belloibrahv Nov 5, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 21 additions & 11 deletions packages/relay/src/lib/clients/cache/localLRUCache.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand All @@ -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;
}

Expand Down Expand Up @@ -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})`,
);
}
}

/**
Expand Down Expand Up @@ -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);
}
Expand Down Expand Up @@ -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;
}

Expand Down
58 changes: 39 additions & 19 deletions packages/relay/src/lib/clients/cache/redisCache.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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}`,
);
}
}

/**
Expand Down Expand Up @@ -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}`,
);
}
}

/**
Expand All @@ -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
}

Expand Down Expand Up @@ -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;
}

Expand All @@ -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));
}

Expand All @@ -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;
}

Expand All @@ -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;
}
}
52 changes: 33 additions & 19 deletions packages/relay/src/lib/clients/mirrorNodeClient.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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) => {
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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),
Expand Down Expand Up @@ -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);
}

Expand Down Expand Up @@ -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));
Expand Down Expand Up @@ -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,
Expand Down
36 changes: 23 additions & 13 deletions packages/relay/src/lib/clients/sdkClient.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -587,9 +587,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;
Expand Down Expand Up @@ -702,9 +704,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 {
Expand Down Expand Up @@ -982,9 +986,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;
Expand Down Expand Up @@ -1033,7 +1039,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} `);
}
Expand Down Expand Up @@ -1088,9 +1096,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)
Expand Down
12 changes: 8 additions & 4 deletions packages/relay/src/lib/config/hbarSpendingPlanConfigService.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -131,7 +131,9 @@ export class HbarSpendingPlanConfigService {
const spendingPlanConfig = ConfigService.get('HBAR_SPENDING_PLANS_CONFIG') as string;

if (!spendingPlanConfig) {
logger.trace('HBAR_SPENDING_PLANS_CONFIG is undefined');
if (this.logger.isLevelEnabled('trace')) {
Copy link
Member

@quiet-node quiet-node Nov 5, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@belloibrahv This line is causing the CI failures because this class doesn’t have a logger property. This can be easily fixed by using the logger instance from the arguments, which should resolve the CI issues.

Suggested change
if (this.logger.isLevelEnabled('trace')) {
if (logger.isLevelEnabled('trace')) {

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice catch @quiet-node.
@belloibrahv please run an npm run build-and-test before pushing to confirm everything builds and unit tests run well.
Looking forward to getting this PR in.
Thanks

logger.trace('HBAR_SPENDING_PLANS_CONFIG is undefined');
}
return [];
}

Expand Down Expand Up @@ -244,9 +246,11 @@ export class HbarSpendingPlanConfigService {
requestDetails: RequestDetails,
): Promise<void> {
for (const planConfig of spendingPlanConfigs) {
this.logger.trace(
`Updating associations for HBAR spending plan '${planConfig.name}' with ID ${planConfig.id}...`,
);
if (this.logger.isLevelEnabled('trace')) {
this.logger.trace(
`Updating associations for HBAR spending plan '${planConfig.name}' with ID ${planConfig.id}...`,
);
}
await this.deleteObsoleteEthAddressAssociations(planConfig, requestDetails);
await this.deleteObsoleteIpAddressAssociations(planConfig, requestDetails);
await this.updateEthAddressAssociations(planConfig, requestDetails);
Expand Down
Loading
Loading