Improve info in case of tracing activities

[Neurone]

Description:
While conducting debug activities you often enable trace log level, and you want to check the actual requests and response between client and server (i.e., #1802).

This PR:

• adds info about request and response bodies when trace log level is enabled.
• reduces the default log level to info instead of trace

Related issue(s):

N/A

Notes for reviewer:

N/A

Checklist

• Documented (Code comments, README, etc.)
• Tested (unit, integration, etc.)

[sonarcloud]

Kudos, SonarCloud Quality Gate passed!   

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

No Coverage information
0.0% Duplication

[codecov-commenter]

Codecov Report

All modified lines are covered by tests ✅

Comparison is base (63953ee) 77.73% compared to head (53bdad4) 77.75%.

❗ Current head 53bdad4 differs from pull request most recent head 748d373. Consider uploading reports for the commit 748d373 to get more accurate results

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1817      +/-   ##
==========================================
+ Coverage   77.73%   77.75%   +0.02%     
==========================================
  Files          40       40              
  Lines        3023     3026       +3     
  Branches      603      603              
==========================================
+ Hits         2350     2353       +3     
  Misses        489      489              
  Partials      184      184              

Files	Coverage Δ
packages/server/src/koaJsonRpc/index.ts	68.22% <100.00%> (+0.60%)	⬆️
packages/server/src/server.ts	69.51% <100.00%> (+0.12%)	⬆️

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[Nana-EC]

Simple enough change.

@Neurone can you add an example of the logs emitted after a simple call to say eth_getTransactionCount(..)
One concern here is the expansion of logs and this will result in duplication of log details. Logging every request and response body can be very large.

All the important details should be logged down the line. Are there specific HTTP properties you're looking for that are missing?

[Neurone]

Hi Nana, those lines show the payload sent by the client and the relay's response, so it depends.

Adding those logs was essential, for example, to track down the bug described in #1802, and here is an example of what you can see before and after adding that tracing while receiving requests for that use case:

Old log, with LOG_LEVEL="trace"

[2023-10-19 15:21:47.525 +0000] WARN (koa-rpc/14646 on devmachine2204): [6c2eb549-3a47-4a8e-91a6-d121ce23aaef] Invalid request, body.jsonrpc: undefined, body[method]: undefined, body[id]: undefined, ctx.request.method: POST
[2023-10-19 15:21:47.525 +0000] INFO (rpc-server/14646 on devmachine2204): [Request ID: 6c2eb549-3a47-4a8e-91a6-d121ce23aaef] [POST]: undefined 400 (INVALID REQUEST) 0 ms

New log, with LOG_LEVEL="trace"

[2023-10-19 15:25:13.343 +0000] TRACE (koa-rpc/16392 on devmachine2204): [Request ID: 45991684-7965-4875-b298-d54423f2516d] Request body [{"method":"eth_chainId","params":[],"id":2,"jsonrpc":"2.0"},{"method":"eth_blockNumber","params":[],"id":3,"jsonrpc":"2.0"}]
[2023-10-19 15:25:13.343 +0000] WARN (koa-rpc/16392 on devmachine2204): [45991684-7965-4875-b298-d54423f2516d] Invalid request, body.jsonrpc: undefined, body[method]: undefined, body[id]: undefined, ctx.request.method: POST
[2023-10-19 15:25:13.343 +0000] INFO (rpc-server/16392 on devmachine2204): [Request ID: 45991684-7965-4875-b298-d54423f2516d] [POST]: undefined 400 (INVALID REQUEST) 1 ms
[2023-10-19 15:25:13.343 +0000] TRACE (rpc-server/16392 on devmachine2204): [Request ID: 45991684-7965-4875-b298-d54423f2516d] [POST]: undefined 400 (INVALID REQUEST) {"error":{"message":"Invalid Request","code":-32600},"jsonrpc":"2.0","id":null}

The log's type is trace, so the maximum logging level. As a developer, when I enable that level of logging, I expect to receive many messages to track as many details as possible about what's happening.

To avoid bloating the log files, I also suggested changing the default log level from trace to info in this PR.

[Nana-EC]

This may result in repeated info in the logs as some methods log the contents of the body which are params.
In a few cases that's transaction bytes or a whole contract.
So we might need some coordination on that

[ebadiere]

@Neurone Is this still an issue?

[Neurone]

The code of the PR must be probably updated at this point, but yes, imho the issue this PR tries to solve is still there.

I think when as a developer I set TRACE as a log level, I want to see anything because I'm doing this for heavy debugging activities. The PR includes the answers and the responses bodies to the logs, and this info is essential for debugging purposes.

At the same time, I think the default log level should be INFO, not TRACE as we use now. In general I think using INFO as default is a good practice, and in this case it shows another good reason why. If we use TRACE as our default, when adding more data to the log it seems too much (as reported by Nana) but the problem for me it's not there, because when I enable trace I want to see everything, and duplicated data are not an issue at all and in some cases are very useful (because I can see nothing happened to those data during the business flow).

If this make sense, I can work on updating the PR for being merged, if you disagree or want to create a different broader task for this topic, you can close this PR.