feat: log every rpc call across all the viem clients used #85

jahabeebs · 2024-11-07T01:09:30Z

🤖 Linear

Closes GRT-239

Description

Logs every RPC call using some resources linked below regarding viem's HTTP transport
transportsArray now injected into logger instantiation
some changes to the logger class to log out metadata well

https://viem.sh/docs/clients/transports/http.html#onfetchrequest-optional
https://viem.sh/docs/clients/transports/http.html#onfetchresponse-optional
wevm/viem#2244 (ended up using the clone function suggested here) - https://developer.mozilla.org/en-US/docs/Web/API/Response/clone

linear · 2024-11-07T01:09:32Z

GRT-239 Log every RPC call (requests and responses) across all the viem clients used

0xyaco

Nice one!

0xyaco · 2024-11-07T09:07:49Z

packages/automated-dispute/src/providers/protocolProvider.ts

     */
    constructor(
        private readonly rpcConfig: ProtocolRpcConfig,
        contracts: ProtocolContractsAddresses,
        privateKey: Hex,
        blockNumberService?: BlockNumberService,
+        private readonly logger?: ILogger,


Any particular reason for logger to be optional?

I was doing this for not needing to inject for tests and scripts but you're right we should have it mandatory--did the refactor

0xyaco · 2024-11-07T09:13:43Z

packages/automated-dispute/src/providers/protocolProvider.ts

+            onFetchRequest: async (request) => {
+                const clonedRequest = {
+                    url: request.url,
+                    method: request.method,
+                    headers: Array.from(request.headers.entries()),
+                    body: await request.clone().text(),
+                };
+
+                this.logger?.debug(`Fetch Request`, clonedRequest);
+            },
+            onFetchResponse: async (response) => {
+                const clonedResponse = {
+                    url: response.url,
+                    status: response.status,
+                    headers: Array.from(response.headers.entries()),
+                    body: await response.clone().text(),
+                };
+
+                this.logger?.debug(`Fetch Response`, clonedResponse);
+            },


Nice!

Mind sharing an example for a logged read request/response + a logged write request/response? Interested in seeing the body mostly, to know if operators will have enough data for their debugging.

i add a comment on same lines, if logger is undefined, we can omit doing the clone object (i think the delay is minimum but we have await operations on the clone() method)

however, this question is related to Yaco's one

@0xyaco I am having some difficulties with running the e2e tests but here are some logs from the unit tests:

@ebo-agent/shared:test: stdout | tests/services/logger.spec.ts > Logger Methods > includes metadata in log output @ebo-agent/shared:test: 2024-11-07 16:26:37 info: Test message {"key":"value"} @ebo-agent/shared:test: @ebo-agent/shared:test: stdout | tests/services/logger.spec.ts > Logger Methods > handles errors with metadata @ebo-agent/shared:test: 2024-11-07 16:26:37 error: Error: An error occurred @ebo-agent/shared:test: at /Users/jacob/Documents/Programming/EBO-agent/packages/shared/tests/services/logger.spec.ts:28:23 @ebo-agent/shared:test: at file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:146:14 @ebo-agent/shared:test: at file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:533:11 @ebo-agent/shared:test: at runWithTimeout (file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:61:7) @ebo-agent/shared:test: at runTest (file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:986:17) @ebo-agent/shared:test: at processTicksAndRejections (node:internal/process/task_queues:105:5) @ebo-agent/shared:test: at runSuite (file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:1142:15) @ebo-agent/shared:test: at runSuite (file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:1142:15) @ebo-agent/shared:test: at runFiles (file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:1199:5) @ebo-agent/shared:test: at startTests (file:///Users/jacob/Documents/Programming/EBO-agent/node_modules/.pnpm/@[email protected]/node_modules/@vitest/runner/dist/index.js:1208:3) {"key":"value"}

note the value at the bottom there ^

also, this is what it would look like theoretically (before the below refactor to the JSON format) if I could get the e2e tests running on this branch lol

2024-11-07 16:45:23 debug: Fetch Request { "url": "https://l2-node.example.com", "method": "POST", "headers": [ ["Content-Type", "application/json"] ], "body": "{\"jsonrpc\":\"2.0\",\"method\":\"eth_getBlockByNumber\",\"params\":[\"latest\",false],\"id\":1}" } 2024-11-07 16:45:23 debug: Fetch Response { "url": "https://l2-node.example.com", "status": 200, "headers": [ ["Content-Type", "application/json"] ], "body": "{\"jsonrpc\":\"2.0\",\"id\":1,\"result\":{\"number\":\"0x10d4f\",\"hash\":\"0x...\",\"...\":\"...\"}}" } 2024-11-07 16:45:25 debug: Fetch Request { "url": "https://l2-node.example.com", "method": "POST", "headers": [ ["Content-Type", "application/json"] ], "body": "{\"jsonrpc\":\"2.0\",\"method\":\"eth_sendRawTransaction\",\"params\":[\"0xf86c808504a817c80082520894...\"],\"id\":2}" } 2024-11-07 16:45:25 debug: Fetch Response { "url": "https://l2-node.example.com", "status": 200, "headers": [ ["Content-Type", "application/json"] ], "body": "{\"jsonrpc\":\"2.0\",\"id\":2,\"result\":\"0xtransactionHash...\"}" }

@0xnigir1 got rid of the clone 👍🏻

0xyaco · 2024-11-07T09:38:38Z

packages/shared/src/services/logger.ts

+                    const { level, message, timestamp, stack, ...meta } = info;
+                    const metaString = Object.keys(meta).length ? ` ${stringify(meta)}` : "";
+                    return `${timestamp} ${level}: ${stack ?? message ?? ""}${metaString}`;


Awesome!

Now that we have the possibility of passing some extra metadata while logging, I think we are ready to change the logging format from the current one to a more "tooling-consumable" format (ie JSON):

{ "timestamp": <timestamp>, "level": <level>, "message": <message>, "stack": <stack>, "data": <stack> }

With stack and data included only if their values are defined.

✅ refactored the logger class

0xyaco · 2024-11-07T09:41:32Z

packages/shared/src/services/logger.ts

@@ -10,50 +12,53 @@ export class Logger implements ILogger {
    private logger: WinstonLogger;
    private static instance: Logger | null;
    private level: LogLevel;
-    private constructor() {
+    private constructor(transportsArray?: Transport[]) {


Are we setting the transportsArray somewhere while initializing the logger?

actually I didn't end up needing this so I've removed it

0xyaco · 2024-11-07T09:41:57Z

packages/shared/src/services/logger.ts

        }
        return Logger.instance;
    }
    isValidLogLevel(level: any): level is LogLevel {
        return validLogLevels.includes(level);
    }

-    info(message: string) {
-        this.logger.info(message);
+    info(message: string, meta?: unknown) {


Nice usage of unknown 👍

0xnigir1

nice pr 💯

0xnigir1 · 2024-11-07T12:54:12Z

packages/shared/package.json

@@ -23,7 +23,8 @@
    "keywords": [],
    "author": "",
    "dependencies": {
-        "winston": "3.13.1"
+        "winston": "3.13.1",
+        "winston-transport": "^4.8.0"


0xnigir1 · 2024-11-07T12:56:45Z

packages/automated-dispute/src/providers/protocolProvider.ts

+            onFetchRequest: async (request) => {
+                const clonedRequest = {
+                    url: request.url,
+                    method: request.method,
+                    headers: Array.from(request.headers.entries()),
+                    body: await request.clone().text(),
+                };
+
+                this.logger?.debug(`Fetch Request`, clonedRequest);
+            },
+            onFetchResponse: async (response) => {
+                const clonedResponse = {
+                    url: response.url,
+                    status: response.status,
+                    headers: Array.from(response.headers.entries()),
+                    body: await response.clone().text(),
+                };
+
+                this.logger?.debug(`Fetch Response`, clonedResponse);
+            },


i add a comment on same lines, if logger is undefined, we can omit doing the clone object (i think the delay is minimum but we have await operations on the clone() method)

however, this question is related to Yaco's one

0xyaco · 2024-11-08T09:39:03Z

packages/automated-dispute/src/providers/protocolProvider.ts

                    url: response.url,
                    status: response.status,
                    headers: Array.from(response.headers.entries()),
-                    body: await response.clone().text(),
+                    body: await response.text(),


@jahabeebs won't removing the clone() call here consume the response stream and cause the response to be used by our protocol provider later to be empty? 🤔

Asking based on this issue I sent you before: wevm/viem#2244

hmm yes you're right, I confused what nigiri mentioned 😅

0xyaco · 2024-11-08T09:47:39Z

packages/shared/src/services/logger.ts

-                }),
+                format((info) => {
+                    const { timestamp, level, message, stack, ...meta } = info;
+                    const logEntry: any = {


Let's define LogEntry type and change this to avoid using any:

Suggested change

const logEntry: any = {

const logEntry: LogEntry = {

added better typing ✅

jahabeebs added 2 commits November 6, 2024 19:38

feat: log every call

7bab396

chore: no example

c6a6627

jahabeebs requested review from 0xkenj1, 0xnigir1 and 0xyaco November 7, 2024 01:09

jahabeebs self-assigned this Nov 7, 2024

jahabeebs changed the title ~~feat: log every RPC call across all the viem clients used~~ feat: log every rpc call across all the viem clients used Nov 7, 2024

0xyaco reviewed Nov 7, 2024

View reviewed changes

0xnigir1 reviewed Nov 7, 2024

View reviewed changes

jahabeebs added 3 commits November 7, 2024 18:37

fix: pr comments

9936fcf

fix: pr comments

6bc1954

chore: transports param

71631ea

jahabeebs requested review from 0xyaco and 0xnigir1 November 7, 2024 23:55

0xnigir1 previously approved these changes Nov 8, 2024

View reviewed changes

0xyaco reviewed Nov 8, 2024

View reviewed changes

fix: pr comments

4c2d2f1

jahabeebs dismissed 0xnigir1’s stale review via 4c2d2f1 November 8, 2024 16:40

jahabeebs requested a review from 0xyaco November 8, 2024 16:42

0xyaco approved these changes Nov 8, 2024

View reviewed changes

jahabeebs requested a review from 0xnigir1 November 8, 2024 17:04

0xnigir1 approved these changes Nov 8, 2024

View reviewed changes

jahabeebs merged commit e9893cd into dev Nov 8, 2024
5 checks passed

jahabeebs deleted the feat/grt-239-log-every-rpc-call branch November 8, 2024 17:20

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: log every rpc call across all the viem clients used #85

feat: log every rpc call across all the viem clients used #85

jahabeebs commented Nov 7, 2024

linear bot commented Nov 7, 2024

0xyaco left a comment

0xyaco Nov 7, 2024

jahabeebs Nov 7, 2024

0xyaco Nov 7, 2024 •

edited

Loading

0xnigir1 Nov 7, 2024

jahabeebs Nov 7, 2024 •

edited

Loading

0xyaco Nov 7, 2024 •

edited

Loading

jahabeebs Nov 7, 2024

0xyaco Nov 7, 2024

jahabeebs Nov 7, 2024

0xyaco Nov 7, 2024

0xnigir1 left a comment

0xnigir1 Nov 7, 2024

jahabeebs Nov 7, 2024

0xnigir1 Nov 7, 2024

0xyaco Nov 8, 2024

jahabeebs Nov 8, 2024

0xyaco Nov 8, 2024

jahabeebs Nov 8, 2024

feat: log every rpc call across all the viem clients used #85

feat: log every rpc call across all the viem clients used #85

Conversation

jahabeebs commented Nov 7, 2024

🤖 Linear

Description

linear bot commented Nov 7, 2024

0xyaco left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

0xyaco Nov 7, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jahabeebs Nov 7, 2024 • edited Loading

Choose a reason for hiding this comment

0xyaco Nov 7, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

0xnigir1 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

0xyaco Nov 7, 2024 •

edited

Loading

jahabeebs Nov 7, 2024 •

edited

Loading

0xyaco Nov 7, 2024 •

edited

Loading