From e9893cdefec3eaf6cc1ce2ee98cb389abcd02ed1 Mon Sep 17 00:00:00 2001 From: Beebs <47253537+jahabeebs@users.noreply.github.com> Date: Fri, 8 Nov 2024 12:20:22 -0500 Subject: [PATCH] feat: log every rpc call across all the viem clients used (#85) --- apps/agent/src/index.ts | 1 + .../utilities/approveAccountingModules.ts | 3 +- .../src/providers/protocolProvider.ts | 63 ++++++++++++---- .../tests/mocks/eboActor.mocks.ts | 22 +++--- .../tests/mocks/eboProcessor.mocks.ts | 2 +- .../tests/services/eboActor/fixtures.ts | 10 ++- .../tests/services/protocolProvider.spec.ts | 35 +++++++++ packages/shared/package.json | 3 +- packages/shared/src/services/logger.ts | 72 +++++++++++++------ packages/shared/src/types/logger.ts | 8 +-- packages/shared/tests/services/logger.spec.ts | 59 +++++++++++++-- pnpm-lock.yaml | 3 + 12 files changed, 225 insertions(+), 56 deletions(-) diff --git a/apps/agent/src/index.ts b/apps/agent/src/index.ts index a39c8571..72d0ba9a 100644 --- a/apps/agent/src/index.ts +++ b/apps/agent/src/index.ts @@ -34,6 +34,7 @@ const main = async (): Promise => { config.protocolProvider.rpcsConfig, config.protocolProvider.contracts, config.protocolProvider.privateKey, + logger, blockNumberService, ); diff --git a/apps/scripts/utilities/approveAccountingModules.ts b/apps/scripts/utilities/approveAccountingModules.ts index 293de56a..c0f42f61 100644 --- a/apps/scripts/utilities/approveAccountingModules.ts +++ b/apps/scripts/utilities/approveAccountingModules.ts @@ -1,4 +1,5 @@ import { ProtocolProvider } from "@ebo-agent/automated-dispute/src/index.js"; +import { mockLogger } from "@ebo-agent/automated-dispute/tests/mocks/logger.mocks.js"; import { Caip2ChainId } from "@ebo-agent/shared"; import * as dotenv from "dotenv"; import { Address, Hex, isHex } from "viem"; @@ -102,7 +103,7 @@ const rpcConfig = { const contracts = env.CONTRACTS_ADDRESSES; -const provider = new ProtocolProvider(rpcConfig, contracts, env.PRIVATE_KEY as Hex); +const provider = new ProtocolProvider(rpcConfig, contracts, env.PRIVATE_KEY as Hex, mockLogger()); /** * Approves the necessary modules by calling approveModule on ProtocolProvider. diff --git a/packages/automated-dispute/src/providers/protocolProvider.ts b/packages/automated-dispute/src/providers/protocolProvider.ts index 14161879..452b56aa 100644 --- a/packages/automated-dispute/src/providers/protocolProvider.ts +++ b/packages/automated-dispute/src/providers/protocolProvider.ts @@ -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, @@ -114,12 +114,14 @@ export class ProtocolProvider implements IProtocolProvider { * @param rpcConfig The configuration for RPC connections including URLs, timeout, retry interval, and transaction receipt confirmations * @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 logger The logger instance * @param blockNumberService The service that will be used to fetch block numbers */ constructor( private readonly rpcConfig: ProtocolRpcConfig, contracts: ProtocolContractsAddresses, privateKey: Hex, + private readonly logger: ILogger, blockNumberService?: BlockNumberService, ) { const l1Chain = this.getViemChain(rpcConfig.l1.chainId); @@ -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)), ), }); } @@ -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 reqObject = { + url: request.url, + method: request.method, + headers: Array.from(request.headers.entries()), + body: await request.clone().text(), + }; + + this.logger.debug(`Fetch Request`, reqObject); + }, + onFetchResponse: async (response) => { + const respObject = { + url: response.url, + status: response.status, + headers: Array.from(response.headers.entries()), + body: await response.clone().text(), + }; + + this.logger.debug(`Fetch Response`, respObject); + }, + }); + } + private getViemChain(chainId: Caip2ChainId): Chain { switch (chainId) { case "eip155:1": diff --git a/packages/automated-dispute/tests/mocks/eboActor.mocks.ts b/packages/automated-dispute/tests/mocks/eboActor.mocks.ts index bb1fb909..7d3bde41 100644 --- a/packages/automated-dispute/tests/mocks/eboActor.mocks.ts +++ b/packages/automated-dispute/tests/mocks/eboActor.mocks.ts @@ -4,13 +4,9 @@ import { Mutex } from "async-mutex"; import { Block, pad } from "viem"; import { vi } from "vitest"; +import { NotificationService } from "../../src/index.js"; import { ProtocolProvider } from "../../src/providers/index.js"; -import { - EboActor, - EboMemoryRegistry, - NotificationService, - ProphetCodec, -} from "../../src/services/index.js"; +import { EboActor, EboMemoryRegistry, ProphetCodec } from "../../src/services/index.js"; import { Dispute, DisputeId, @@ -55,6 +51,7 @@ export function buildEboActor(request: Request, logger: ILogger) { }, DEFAULT_MOCKED_PROTOCOL_CONTRACTS, mockedPrivateKey, + logger, ); vi.spyOn(protocolProvider.read, "getEscalation").mockResolvedValue({ @@ -101,7 +98,17 @@ export function buildEboActor(request: Request, logger: ILogger) { const eventProcessingMutex = new Mutex(); const notificationService: NotificationService = { - notifyError: vi.fn().mockResolvedValue(undefined), + send: vi.fn().mockResolvedValue(undefined), + sendOrThrow: vi.fn().mockResolvedValue(undefined), + createErrorMessage: vi + .fn() + .mockImplementation((defaultMessage: string, context?: unknown, err?: unknown) => { + return { + title: defaultMessage, + description: err instanceof Error ? err.message : undefined, + }; + }), + sendError: vi.fn().mockResolvedValue(undefined), }; const actor = new EboActor( @@ -200,7 +207,6 @@ export function buildDispute( ): Dispute { const baseDispute: Dispute = { id: attributes.id || (pad("0x03") as DisputeId), - status: "Active", createdAt: { timestamp: (response.createdAt.timestamp + 1n) as UnixTimestamp, blockNumber: response.createdAt.blockNumber + 1n, diff --git a/packages/automated-dispute/tests/mocks/eboProcessor.mocks.ts b/packages/automated-dispute/tests/mocks/eboProcessor.mocks.ts index 89cd81ab..464bebfd 100644 --- a/packages/automated-dispute/tests/mocks/eboProcessor.mocks.ts +++ b/packages/automated-dispute/tests/mocks/eboProcessor.mocks.ts @@ -14,7 +14,6 @@ import { export function buildEboProcessor( logger: ILogger, accountingModules: AccountingModules = { - requestModule: "0x01", responseModule: "0x02", escalationModule: "0x03", }, @@ -57,6 +56,7 @@ export function buildEboProcessor( }, DEFAULT_MOCKED_PROTOCOL_CONTRACTS, mockedPrivateKey, + logger, blockNumberService, ); diff --git a/packages/automated-dispute/tests/services/eboActor/fixtures.ts b/packages/automated-dispute/tests/services/eboActor/fixtures.ts index d3b7ca1c..1e203a9b 100644 --- a/packages/automated-dispute/tests/services/eboActor/fixtures.ts +++ b/packages/automated-dispute/tests/services/eboActor/fixtures.ts @@ -104,8 +104,14 @@ export const DEFAULT_MOCKED_REQUEST_CREATED_DATA: Request = { export const DEFAULT_MOCKED_DISPUTE_DATA: Dispute = { id: pad("0x03") as DisputeId, - createdAt: 1625097800n, - status: "Active", + createdAt: { + timestamp: 1625097600n as UnixTimestamp, + blockNumber: 1n, + logIndex: 0, + }, + decodedData: { + status: "Active", + }, prophetData: { disputer: "0x5678901234567890123456789012345678901234", proposer: DEFAULT_MOCKED_RESPONSE_DATA.prophetData.proposer, diff --git a/packages/automated-dispute/tests/services/protocolProvider.spec.ts b/packages/automated-dispute/tests/services/protocolProvider.spec.ts index e2678283..7cacdeb7 100644 --- a/packages/automated-dispute/tests/services/protocolProvider.spec.ts +++ b/packages/automated-dispute/tests/services/protocolProvider.spec.ts @@ -30,6 +30,7 @@ import { import { ProtocolProvider } from "../../src/index.js"; import { ProtocolContractsAddresses } from "../../src/interfaces/index.js"; import { EboEvent } from "../../src/types/index.js"; +import { mockLogger } from "../mocks/logger.mocks.js"; import { DEFAULT_MOCKED_DISPUTE_DATA, DEFAULT_MOCKED_REQUEST_CREATED_DATA, @@ -169,6 +170,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -225,6 +227,7 @@ describe("ProtocolProvider", () => { { ...mockRpcConfig, l1: { ...mockRpcConfig.l1, urls: [] } }, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ), ).toThrowError(RpcUrlsEmpty); @@ -237,6 +240,7 @@ describe("ProtocolProvider", () => { { ...mockRpcConfig, l2: { ...mockRpcConfig.l2, urls: [] } }, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ), ).toThrowError(RpcUrlsEmpty); @@ -263,6 +267,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -295,6 +300,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), undefined, ); @@ -308,6 +314,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); const error = new Error("Failed to get current epoch"); @@ -328,6 +335,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); const error = new Error("Failed to get current epoch block"); @@ -355,6 +363,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -371,6 +380,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -391,6 +401,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -411,6 +422,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -434,6 +446,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -456,6 +469,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -477,6 +491,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -504,6 +519,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -525,6 +541,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -562,6 +579,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -578,6 +596,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -600,6 +619,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -636,6 +656,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -650,6 +671,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -666,6 +688,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -688,6 +711,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -707,6 +731,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -732,6 +757,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -753,6 +779,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -780,6 +807,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -808,6 +836,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -829,6 +858,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -855,6 +885,8 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), + mockBlockNumberService, ); const approvedModules = []; @@ -878,6 +910,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -900,6 +933,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); @@ -969,6 +1003,7 @@ describe("ProtocolProvider", () => { mockRpcConfig, mockContractAddress, mockedPrivateKey, + mockLogger(), mockBlockNumberService, ); diff --git a/packages/shared/package.json b/packages/shared/package.json index 42410bef..ad1712e4 100644 --- a/packages/shared/package.json +++ b/packages/shared/package.json @@ -23,7 +23,8 @@ "keywords": [], "author": "", "dependencies": { - "winston": "3.13.1" + "winston": "3.13.1", + "winston-transport": "4.8.0" }, "devDependencies": { "viem": "2.21.25" diff --git a/packages/shared/src/services/logger.ts b/packages/shared/src/services/logger.ts index 5457eee4..b99b9701 100644 --- a/packages/shared/src/services/logger.ts +++ b/packages/shared/src/services/logger.ts @@ -1,33 +1,60 @@ import { createLogger, format, transports, Logger as WinstonLogger } from "winston"; +import Transport from "winston-transport"; import { ILogger } from "../index.js"; type LogLevel = "error" | "warn" | "info" | "debug"; +type LogEntry = { + timestamp: string; + level: LogLevel; + message: string; + stack?: string; + data?: Record; +}; + const validLogLevels: LogLevel[] = ["error", "warn", "info", "debug"]; +/** + * Logger class that wraps the Winston logger. + * @class Logger + * @implements {ILogger} + */ export class Logger implements ILogger { private logger: WinstonLogger; private static instance: Logger | null; - private level: LogLevel; - private constructor() { + public readonly level: LogLevel; + + private constructor(transportsArray?: Transport[]) { 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.timestamp(), format.errors({ stack: true }), - format.printf(({ level, message, timestamp, stack }) => { - return `${timestamp} ${level}: ${stack ?? message ?? ""}`; - }), + format((info) => { + const { timestamp, level, message, stack, ...meta } = info; + const logEntry: LogEntry = { + timestamp, + level: this.isValidLogLevel(level) ? level : "info", + message, + }; + if (stack) { + logEntry.stack = stack; + } + if (Object.keys(meta).length > 0) { + logEntry.data = meta; + } + return logEntry; + })(), + format.json(), ), - 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. * @returns The instance of the Logger class. */ public static getInstance(): Logger { @@ -36,24 +63,29 @@ export class Logger implements ILogger { } return Logger.instance; } - isValidLogLevel(level: any): level is LogLevel { - return validLogLevels.includes(level); + + isValidLogLevel(level: string | undefined): level is LogLevel { + return validLogLevels.includes(level as LogLevel); } - info(message: string) { - this.logger.info(message); + info(message: string, meta?: 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); } } diff --git a/packages/shared/src/types/logger.ts b/packages/shared/src/types/logger.ts index b647e394..91ad80b5 100644 --- a/packages/shared/src/types/logger.ts +++ b/packages/shared/src/types/logger.ts @@ -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; } diff --git a/packages/shared/tests/services/logger.spec.ts b/packages/shared/tests/services/logger.spec.ts index f8ac1df9..cdb26a35 100644 --- a/packages/shared/tests/services/logger.spec.ts +++ b/packages/shared/tests/services/logger.spec.ts @@ -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(); @@ -14,14 +63,12 @@ describe("Logger Singleton", () => { const logger2 = Logger.getInstance(); expect(logger1).toBe(logger2); }); - it("sets level correctly based on LOG_LEVEL env var", () => { - let logger1 = Logger.getInstance(); - expect(logger1["level"]).toEqual("info"); + it("sets level correctly based on LOG_LEVEL env var", () => { Logger["instance"] = null; process.env.LOG_LEVEL = "debug"; - logger1 = Logger.getInstance(); + const logger = Logger.getInstance(); - expect(logger1["level"]).toEqual("debug"); + expect(logger.level).toEqual("debug"); }); }); diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index c1834a7c..40575988 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -194,6 +194,9 @@ importers: winston: specifier: 3.13.1 version: 3.13.1 + winston-transport: + specifier: 4.8.0 + version: 4.8.0 devDependencies: viem: specifier: 2.21.25