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

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

Merged
merged 6 commits into from
Nov 8, 2024
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
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
63 changes: 50 additions & 13 deletions packages/automated-dispute/src/providers/protocolProvider.ts
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
import { BlockNumberService, UnsupportedChain } from "@ebo-agent/blocknumber";
import { Caip2ChainId, HexUtils, UnixTimestamp } from "@ebo-agent/shared";
import { Caip2ChainId, HexUtils, ILogger, UnixTimestamp } from "@ebo-agent/shared";
import {
Account,
Address,
Expand Down Expand Up @@ -115,12 +115,14 @@ export class ProtocolProvider implements IProtocolProvider {
* @param contracts The addresses of the protocol contracts that will be instantiated
* @param privateKey The private key of the account that will be used to interact with the contracts
* @param blockNumberService The service that will be used to fetch block numbers
* @param logger The logger instance
*/
constructor(
private readonly rpcConfig: ProtocolRpcConfig,
contracts: ProtocolContractsAddresses,
privateKey: Hex,
blockNumberService?: BlockNumberService,
private readonly logger?: ILogger,
Copy link
Collaborator

Choose a reason for hiding this comment

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

Any particular reason for logger to be optional?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

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

) {
const l1Chain = this.getViemChain(rpcConfig.l1.chainId);
const l2Chain = this.getViemChain(rpcConfig.l2.chainId);
Expand Down Expand Up @@ -206,12 +208,7 @@ export class ProtocolProvider implements IProtocolProvider {
return createPublicClient({
chain: chain,
transport: fallback(
urls.map((url) =>
http(url, {
timeout: timeout,
retryDelay: retryInterval,
}),
),
urls.map((url) => this.createHttpTransportWithLogging(url, timeout, retryInterval)),
),
});
}
Expand All @@ -227,17 +224,57 @@ export class ProtocolProvider implements IProtocolProvider {
return createWalletClient({
chain: chain,
transport: fallback(
urls.map((url) =>
http(url, {
timeout: timeout,
retryDelay: retryInterval,
}),
),
urls.map((url) => this.createHttpTransportWithLogging(url, timeout, retryInterval)),
),
account: account,
});
}

/**
* Creates an HTTP transport with logging capabilities for requests and responses.
*
* This function sets up a custom HTTP transport that logs the details of each
* HTTP request and response, including the URL, method, headers, and body.
* The logging captures and logs the cloned `Request` and `Response` objects,
* ensuring the original objects remain unaltered.
*
* @param {string} url - The base URL for the HTTP transport.
* @param {number} timeout - The timeout duration in milliseconds for each HTTP request.
* @param {number} retryInterval - The delay in milliseconds before retrying a failed request.
* @returns {HttpTransport} The configured HTTP transport with logging enabled.
*
*/
private createHttpTransportWithLogging(
url: string,
timeout: number,
retryInterval: number,
): HttpTransport {
return http(url, {
timeout: timeout,
retryDelay: retryInterval,
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);
},
Copy link
Collaborator

@0xyaco 0xyaco Nov 7, 2024

Choose a reason for hiding this comment

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

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.

Copy link
Collaborator

Choose a reason for hiding this comment

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

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

Copy link
Collaborator Author

@jahabeebs jahabeebs Nov 7, 2024

Choose a reason for hiding this comment

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

@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 👍🏻

});
}

private getViemChain(chainId: Caip2ChainId): Chain {
switch (chainId) {
case "eip155:1":
Expand Down
3 changes: 2 additions & 1 deletion packages/shared/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,8 @@
"keywords": [],
"author": "",
"dependencies": {
"winston": "3.13.1"
"winston": "3.13.1",
"winston-transport": "^4.8.0"
Copy link
Collaborator

Choose a reason for hiding this comment

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

carettt

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

sigh

},
"devDependencies": {
"viem": "2.21.25"
Expand Down
37 changes: 21 additions & 16 deletions packages/shared/src/services/logger.ts
Original file line number Diff line number Diff line change
@@ -1,4 +1,6 @@
import { stringify } from "viem";
import { createLogger, format, transports, Logger as WinstonLogger } from "winston";
import Transport from "winston-transport";

import { ILogger } from "../index.js";

Expand All @@ -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[]) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Are we setting the transportsArray somewhere while initializing the logger?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

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

this.level = this.isValidLogLevel(process.env.LOG_LEVEL) ? process.env.LOG_LEVEL : "info";
this.logger = createLogger({
level: this.level,
format: format.combine(
format.colorize(),
format.timestamp({ format: "YYYY-MM-DD HH:mm:ss" }),
format.errors({ stack: true }),
format.printf(({ level, message, timestamp, stack }) => {
return `${timestamp} ${level}: ${stack ?? message ?? ""}`;
format.printf((info) => {
const { level, message, timestamp, stack, ...meta } = info;
const metaString = Object.keys(meta).length ? ` ${stringify(meta)}` : "";
return `${timestamp} ${level}: ${stack ?? message ?? ""}${metaString}`;
Copy link
Collaborator

@0xyaco 0xyaco Nov 7, 2024

Choose a reason for hiding this comment

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

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.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

✅ refactored the logger class

}),
),
transports: [new transports.Console()],
transports: transportsArray || [new transports.Console()],
});
}
/**
* Returns the instance of the Logger class.
* @param level The log level to be used by the logger.
* @param transportsArray - An array of transports to use with the logger.
* @returns The instance of the Logger class.
*/
public static getInstance(): Logger {
public static getInstance(transportsArray?: Transport[]): Logger {
if (!Logger.instance) {
Logger.instance = new Logger();
Logger.instance = new Logger(transportsArray);
}
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) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Nice usage of unknown 👍

this.logger.info(message, meta);
}
error(error: Error | string): void {
error(error: Error | string, meta?: unknown): void {
const metaData = meta ? (meta as object) : {};
if (error instanceof Error) {
this.logger.error(error);
this.logger.error(error.message, { stack: error.stack, ...metaData });
} else {
this.logger.error(new Error(error));
this.logger.error(error, metaData);
}
}
warn(message: string) {
this.logger.warn(message);
warn(message: string, meta?: unknown) {
this.logger.warn(message, meta);
}
debug(message: string) {
this.logger.debug(message);
debug(message: string, meta?: unknown) {
this.logger.debug(message, meta);
}
}
8 changes: 4 additions & 4 deletions packages/shared/src/types/logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,8 @@
* Generic logger interface.
*/
export interface ILogger {
error: (error: Error | string) => void;
info: (message: string) => void;
warn: (message: string) => void;
debug: (message: string) => void;
error: (error: Error | string, meta?: unknown) => void;
info: (message: string, meta?: unknown) => void;
warn: (message: string, meta?: unknown) => void;
debug: (message: string, meta?: unknown) => void;
}
53 changes: 51 additions & 2 deletions packages/shared/tests/services/logger.spec.ts
Original file line number Diff line number Diff line change
@@ -1,7 +1,56 @@
import { describe, expect, it } from "vitest";
import { beforeEach, describe, expect, it, vi } from "vitest";

import { Logger } from "../../src/services/index.js";

describe("Logger Methods", () => {
beforeEach(() => {
Logger["instance"] = null;
delete process.env.LOG_LEVEL;
});

it("includes metadata in log output", () => {
const logger = Logger.getInstance();
const mockInfo = vi.spyOn(logger["logger"], "info");

const message = "Test message";
const meta = { key: "value" };

logger.info(message, meta);

expect(mockInfo).toHaveBeenCalledWith(message, meta);
mockInfo.mockRestore();
});

it("handles errors with metadata", () => {
const logger = Logger.getInstance();
const mockError = vi.spyOn(logger["logger"], "error");

const error = new Error("An error occurred");
const meta = { key: "value" };

logger.error(error, meta);

expect(mockError).toHaveBeenCalledWith(
error.message,
expect.objectContaining({ stack: error.stack, ...meta }),
);
mockError.mockRestore();
});

it("includes metadata in debug log output", () => {
const logger = Logger.getInstance();
const mockDebug = vi.spyOn(logger["logger"], "debug");

const message = "Debug message";
const meta = { debugKey: "debugValue" };

logger.debug(message, meta);

expect(mockDebug).toHaveBeenCalledWith(message, meta);
mockDebug.mockRestore();
});
});

describe("Logger Singleton", () => {
it("creates a logger instance with the given log level", () => {
const logger = Logger.getInstance();
Expand All @@ -16,7 +65,7 @@ describe("Logger Singleton", () => {
});
it("sets level correctly based on LOG_LEVEL env var", () => {
let logger1 = Logger.getInstance();
expect(logger1["level"]).toEqual("info");
expect(logger1["level"]).toContain("info");

Logger["instance"] = null;
process.env.LOG_LEVEL = "debug";
Expand Down
3 changes: 3 additions & 0 deletions pnpm-lock.yaml

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.