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.

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

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

Merged
merged 2 commits into from
Nov 12, 2024

Conversation

belloibrahv
Copy link
Contributor

Description:
This PR optimizes logging performance by implementing proper log level guards using Pino's isLevelEnabled API.
Changes made:

  • Add isLevelEnabled checks before debug and trace logging calls
  • Wrap existing debug/trace logs with level guards
  • Implement consistent logging patterns across the codebase

Example of optimized logging:

if (cachedResponse) {
  if (this.logger.isLevelEnabled('debug')) {
    this.logger.debug(
      `${requestIdPrefix} getTransactionReceipt returned cached response: ${JSON.stringify(cachedResponse)}`,
    );
  }
  return cachedResponse;
}

if (!syntheticLogs.length) {
  if (this.logger.isLevelEnabled('trace')) {
    this.logger.trace(`${requestIdPrefix} no receipt for ${hash}`);
  }
  return null;
}

Related issue(s):
Fixes #1118

Notes for reviewer:

  • The implemented guards prevent unnecessary string interpolation and JSON.stringify operations when debug/trace logging is disabled
  • Pattern is consistently applied across debug and trace level logs
  • No functional changes to the logging output - only performance optimization

Checklist

  • Documented (Code comments, README, etc.)
  • Tested (unit, integration, etc.)
    • Verified log output with different log levels
    • Confirmed debug/trace messages are properly guarded
    • Tested with logging enabled and disabled to ensure proper functionality

@Nana-EC
Copy link
Collaborator

Nana-EC commented Oct 24, 2024

@belloibrahv you might want to rebase, there's a lot of unrelated changes that were pulled in

@belloibrahv belloibrahv changed the title add log level guards to prevent unnecessary string generation feat: add log level guards to prevent unnecessary string generation Oct 24, 2024
@belloibrahv
Copy link
Contributor Author

@Nana-EC, I've rebased the branch and cleaned up the PR to only include the log level guard changes.

@quiet-node quiet-node added enhancement New feature or request P3 perf performance gains good first issue candidate Issues that can become a good first issue but need more description/context. hacktoberfest Issues shown by lists for the Hacktoberfest and made for newcomers to do the first contribution. labels Oct 24, 2024
@quiet-node quiet-node added this to the 0.59.0 milestone Oct 24, 2024
@Nana-EC
Copy link
Collaborator

Nana-EC commented Oct 25, 2024

@Nana-EC, I've rebased the branch and cleaned up the PR to only include the log level guard changes.

@belloibrahv please double check.
Looking at https://github.com/hashgraph/hedera-json-rpc-relay/pull/3154/files I'm still seeing 176 files getting changed, with many not relating to logs at all

@ebadiere ebadiere modified the milestones: 0.59.0, 0.60.0 Oct 30, 2024
@belloibrahv
Copy link
Contributor Author

belloibrahv commented Oct 31, 2024

@ebadiere @quiet-node @shemnon @Nana-EC please help review my PR. Thank you

@quiet-node
Copy link
Member

@belloibrahv hey thanks for the good work!

Looks like the DCO CI didn't pass due to this commit refactor: reduce code duplication in relay package didn't get signed off. Looking at the Details of the DCO job, it suggeests to run the commands below to fix it:

git rebase HEAD~7 --signoff
git push --force-with-lease origin issue-1118-log-level-guard

@belloibrahv
Copy link
Contributor Author

@ebadiere @quiet-node @shemnon @Nana-EC please help review my PR. Thank you

@quiet-node
Copy link
Member

heyy @belloibrahv thanks for updating the PR! However, the DCO still seems to fail. Also it seems like the PR now has some conflicts. Please Pull and resolve the conflicts.

@belloibrahv
Copy link
Contributor Author

@Nana-EC @quiet-node @ebadiere @shemnon kindly help review the PR, Thank you.

@belloibrahv
Copy link
Contributor Author

Hello @Nana-EC @quiet-node @ebadiere @shemnon, I ran the npm run build-and-test command as part of my latest changes, and encountered an issue with the npm run test script. The build (npm run build) and acceptance tests (npm run acceptancetest) work perfectly without any issues, but npm run test and npm run build-and-test are failing with the following error:

npm error Lifecycle script `test` failed with error:
npm error code 2
npm error path /Users/ibrahimbello/Desktop/portfolio/hacktoberfest/hedera/hedera-json-rpc-relay/packages/relay
npm error workspace @hashgraph/[email protected]
npm error location /Users/ibrahimbello/Desktop/portfolio/hacktoberfest/hedera/hedera-json-rpc-relay/packages/relay
npm error command failed
npm error command sh -c nyc ts-mocha --recursive './tests/**/*.spec.ts' './tests/**/**/*.spec.ts' --exit

I have addressed the previous logger code issue highlighted in my last pushed changes, but I need some assistance with the failing tests. If you could provide some guidance on resolving this, I’d greatly appreciate it!

Thank you for your help.

@belloibrahv belloibrahv changed the title feat: add log level guards to prevent unnecessary string generation refactor: add log level guards to prevent unnecessary string generation Nov 6, 2024
@quiet-node
Copy link
Member

@belloibrahv nice thanks a lot for the effort! CIs are looking so much better now! The PR Check / Title Check CI job is expected to fail and the team is working on an internal fix right now so no worries on that. The PR Label and Milestone Check should work now as I updated the milestone for the issue. The only thing we need to worry is the Tests / Tests CI looks like some tests fail. I'll take a look into this later today and will see what other approaches we can take to address them.

Again thanks a lot for the patient and your contribution! Looking forward to getting this commit merged in!

@quiet-node
Copy link
Member

@belloibrahv

I looked into the updates, and it seems the failed tests were due to the default logging level in Pino. In the failed test suites, the logger was initialized as const logger = pino();, which defaults to info level. This configuration causes logs set at trace or debug levels to be ignored, leading to the test failures.

This is an easy fix. For each failed test suite, update the initialization as follows:

- const logger = pino();
+ const logger = pino({ level: 'trace' });

This change should resolve the issue.

Looks like only two suites failed because of this—poller.spec.ts and subscriptionController.spec.ts. Please navigate to these suites and update the logger as suggested. That should work.

Let me know if there's any other issues you're running into! Happy to help!

@quiet-node
Copy link
Member

@belloibrahv
Second thing, we just pushed in an internal fix for the PR Check / Title Check CI job. Please fetch upstream/main and merge it for the latest updates. Thanks!

@belloibrahv
Copy link
Contributor Author

I'll make this update and verify the tests pass.

@belloibrahv
Copy link
Contributor Author

belloibrahv commented Nov 7, 2024

@quiet-node, I've implemented the required changes in poller.spec.ts and subscriptionController.spec.ts and pulled the latest changes from upstream main. However, tests are still failing. The Lerna test output shows that 1/2 targets failed, specifically the @hashgraph/json-rpc-relay:test target.

@quiet-node
Copy link
Member

@quiet-node, I've implemented the required changes in poller.spec.ts and subscriptionController.spec.ts and pulled the latest changes from upstream main. However, tests are still failing. The Lerna test output shows that 1/2 targets failed, specifically the @hashgraph/json-rpc-relay:test target.

@belloibrahv could you kindly push the changes up so I can review?

Copy link
Member

@quiet-node quiet-node left a comment

Choose a reason for hiding this comment

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

@belloibrahv It appears there are conflicts during the merging and rebasing that need to be resolved or reverted (see here). These conflicts are unfortunately inevitable, as the Relay is progressing rapidly with numerous contributions added daily.

I also noticed that some log messages have been updated. I suggest keeping them in their original version to avoid confusion.

Please keep me posted on how the process is going! Happy to help!

Copy link

codecov bot commented Nov 11, 2024

Codecov Report

Attention: Patch coverage is 25.51020% with 219 lines in your changes missing coverage. Please review.

Project coverage is 52.80%. Comparing base (3bd07ef) to head (7a5ea41).
Report is 2 commits behind head on main.

Files with missing lines Patch % Lines
packages/relay/src/lib/eth.ts 34.14% 38 Missing and 43 partials ⚠️
packages/relay/src/lib/precheck.ts 5.00% 18 Missing and 1 partial ⚠️
...sitories/hbarLimiter/hbarSpendingPlanRepository.ts 25.00% 10 Missing and 5 partials ⚠️
packages/relay/src/lib/clients/cache/redisCache.ts 22.22% 10 Missing and 4 partials ⚠️
...s/relay/src/lib/services/hbarLimitService/index.ts 31.57% 6 Missing and 7 partials ⚠️
...kages/relay/src/lib/clients/cache/localLRUCache.ts 0.00% 10 Missing ⚠️
packages/relay/src/lib/clients/mirrorNodeClient.ts 33.33% 4 Missing and 6 partials ⚠️
.../lib/services/ethService/ethFilterService/index.ts 16.66% 8 Missing and 2 partials ⚠️
packages/relay/src/lib/clients/sdkClient.ts 20.00% 6 Missing and 2 partials ⚠️
packages/relay/src/lib/subscriptionController.ts 0.00% 8 Missing ⚠️
... and 8 more

❗ There is a different number of reports uploaded between BASE (3bd07ef) and HEAD (7a5ea41). Click for more details.

HEAD has 4 uploads less than BASE
Flag BASE (3bd07ef) HEAD (7a5ea41)
config-service 1 0
relay 1 0
server 1 0
ws-server 1 0
Additional details and impacted files
@@             Coverage Diff             @@
##             main    #3154       +/-   ##
===========================================
- Coverage   83.17%   52.80%   -30.37%     
===========================================
  Files          66       65        -1     
  Lines        4314     4416      +102     
  Branches      843     1001      +158     
===========================================
- Hits         3588     2332     -1256     
- Misses        483     1642     +1159     
- Partials      243      442      +199     
Flag Coverage Δ
config-service ?
relay ?
server ?
ws-server ?

Flags with carried forward coverage won't be shown. Click here to find out more.

Files with missing lines Coverage Δ
.../lib/services/ethService/ethCommonService/index.ts 64.12% <50.00%> (-25.11%) ⬇️
...ay/src/lib/services/metricService/metricService.ts 83.72% <50.00%> (-9.14%) ⬇️
...kages/relay/src/lib/services/debugService/index.ts 14.28% <0.00%> (-62.53%) ⬇️
packages/server/src/server.ts 61.97% <50.00%> (-9.29%) ⬇️
...barLimiter/ethAddressHbarSpendingPlanRepository.ts 34.88% <25.00%> (-57.43%) ⬇️
...hbarLimiter/ipAddressHbarSpendingPlanRepository.ts 23.80% <0.00%> (-71.07%) ⬇️
packages/relay/src/lib/poller.ts 22.97% <0.00%> (-48.86%) ⬇️
...ay/src/lib/config/hbarSpendingPlanConfigService.ts 25.86% <22.22%> (-69.64%) ⬇️
packages/relay/src/lib/clients/sdkClient.ts 38.24% <20.00%> (-19.08%) ⬇️
packages/relay/src/lib/subscriptionController.ts 35.29% <0.00%> (-64.71%) ⬇️
... and 8 more

... and 35 files with indirect coverage changes

@belloibrahv
Copy link
Contributor Author

@Nana-EC @quiet-node @ebadiere @shemnon kindly help review the PR, Thank you.

Copy link
Member

@quiet-node quiet-node left a comment

Choose a reason for hiding this comment

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

LGTM! Thanks for the great work!

Copy link
Collaborator

@ebadiere ebadiere left a comment

Choose a reason for hiding this comment

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

LG.

@quiet-node
Copy link
Member

@belloibrahv Hey wonderful work the team has reviewed the PR and approved upon it. However, the commits in this PR were signed by your GPG key. They would need to be signed with the GPG key first before it can be merged in main. Here’s a helpful resource: Signing Commits.

Copy link

sonarcloud bot commented Nov 11, 2024

@quiet-node quiet-node merged commit 264d2cb into hashgraph:main Nov 12, 2024
37 checks passed
@quiet-node
Copy link
Member

@belloibrahv merged! Thank you once again for the excellent work! The team appreciates it and looks forward to more contributions in the future!

Cheers!

@quiet-node quiet-node added Internal For changes that affect the project's internal workings but not its outward-facing functionality. and removed enhancement New feature or request labels Nov 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
good first issue candidate Issues that can become a good first issue but need more description/context. hacktoberfest Issues shown by lists for the Hacktoberfest and made for newcomers to do the first contribution. Internal For changes that affect the project's internal workings but not its outward-facing functionality. P3 perf performance gains
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add logging level guarding
5 participants