From dd7eafb93effbbcb5b4b15723f0dee8fa8781beb Mon Sep 17 00:00:00 2001 From: Anxo Rodriguez Date: Fri, 6 Dec 2024 14:10:06 +0000 Subject: [PATCH] feat: improve log debuggability (#170) # Description Improve logs to make them easier to debug issues. Logs were not great, and won't be great after this PR. The goal of this PR is to improve some aspects of the logs to make it easier to debug. It is very useful to be able to filter by block number, or by owner, or order number. Before this PR there was some context, but this context was missing in some parts, what made things like "filtering logs per block" to not work. Now all logs include the chain id and the block number. See example: Screenshot at Dec 05 22-17-10 Additionally, it simplifies some logger names and function names, and improve some messages so they are easier to read. It also shows information about the number of owners and orders and how many left to process. The PR also makes the logger utility to receive this context raw params, so we can make the logger prefix constant. Before we used to concatenate the fields, and we were not systematic with the order. Anyways, as mentioned, logging is still not great specially in terms of code cleanness, but at least now the logs are a bit easier to debug. --- src/commands/dumpDb.ts | 2 +- src/commands/run.ts | 4 +- src/domain/events/index.ts | 140 ++++++++++++++++++++--------------- src/domain/polling/index.ts | 143 ++++++++++++++++++++++++------------ src/domain/polling/poll.ts | 15 +++- src/services/api.ts | 4 +- src/services/chain.ts | 54 +++++++++----- src/services/storage.ts | 4 +- src/types/model.ts | 15 ++-- src/utils/context.ts | 4 +- src/utils/contracts.ts | 28 +++++-- src/utils/logging.ts | 59 ++++++++++----- src/utils/utils.spec.ts | 3 + 13 files changed, 307 insertions(+), 168 deletions(-) diff --git a/src/commands/dumpDb.ts b/src/commands/dumpDb.ts index 5f67f7c..553ba1a 100644 --- a/src/commands/dumpDb.ts +++ b/src/commands/dumpDb.ts @@ -7,7 +7,7 @@ import { getLogger } from "../utils"; * @param options A dict, but essentially just the chainId */ export async function dumpDb(options: DumpDbOptions) { - const log = getLogger("commands:dumpDb"); + const log = getLogger({ name: "commands:dumpDb" }); const { chainId, databasePath } = options; Registry.dump(DBService.getInstance(databasePath), chainId.toString()) diff --git a/src/commands/run.ts b/src/commands/run.ts index 0ad7745..873573f 100644 --- a/src/commands/run.ts +++ b/src/commands/run.ts @@ -7,7 +7,7 @@ import { DBService, ApiService, ChainContext } from "../services"; * @param options Specified by the CLI / environment for running the watch-tower */ export async function run(options: RunOptions) { - const log = getLogger("commands:run"); + const log = getLogger({ name: "commands:run" }); const { oneShot, disableApi, apiPort, databasePath, networks } = options; // Open the database @@ -66,7 +66,7 @@ export async function run(options: RunOptions) { * @param exitCode Exit code to return to the shell */ async function stop(exitCode?: number) { - const log = getLogger("commands:stop"); + const log = getLogger({ name: "commands:stop" }); const stopServices = [ ApiService.getInstance().stop(), DBService.getInstance().close(), diff --git a/src/domain/events/index.ts b/src/domain/events/index.ts index 6220577..dc1a754 100644 --- a/src/domain/events/index.ts +++ b/src/domain/events/index.ts @@ -17,79 +17,94 @@ import { Proof, Registry, } from "../../types"; -import { ConditionalOrder, ConditionalOrderParams } from "@cowprotocol/cow-sdk"; +import { + ConditionalOrder, + ConditionalOrderParams, + SupportedChainId, +} from "@cowprotocol/cow-sdk"; import { ChainContext } from "../../services/chain"; const composableCow = ComposableCoW__factory.createInterface(); /** - * Listens to these events on the `ComposableCoW` contract: + * Process a new order event for `ComposableCoW` contract: * - `ConditionalOrderCreated` * - `MerkleRootSet` + * * @param context chain context * @param event transaction event */ -export async function addContract( +export async function processNewOrderEvent( context: ChainContext, event: ConditionalOrderCreatedEvent ) { const { chainId } = context; - await metrics.measureTime({ - action: () => _addContract(context, event), - labelValues: [chainId.toString()], - durationMetric: metrics.addContractsRunDurationSeconds, - totalRunsMetric: metrics.addContractRunsTotal, - errorHandler: handleExecutionError, - errorMetric: metrics.addContractsErrorsTotal, - }); -} -async function _addContract( - context: ChainContext, - event: ConditionalOrderCreatedEvent -) { - const log = getLogger("addContract:_addContract"); - const { registry } = context; - const { transactionHash: tx, blockNumber } = event; + const action = async () => { + const { registry, chainId } = context; + const { transactionHash: tx, blockNumber } = event; - // Process the logs - let hasErrors = false; - let numContractsAdded = 0; + const log = getLogger({ + name: "processNewOrderEvent", + chainId, + blockNumber: event.blockNumber, + }); - const { error, added } = await registerNewOrder(event, registry); + // Process the logs + let hasErrors = false; + let numContractsAdded = 0; - if (added) { - metrics.ownersTotal.labels(context.chainId.toString()).inc(); - numContractsAdded++; - } else { - log.error( - `Failed to register Smart Order from tx ${tx} on block ${blockNumber}. Error: ${error}` - ); - } + const { error, added } = await decodeAndAddOrder(event, registry, chainId); + + if (added) { + metrics.ownersTotal.labels(context.chainId.toString()).inc(); + numContractsAdded++; + } else { + log.error( + `Failed to register Smart Order from tx ${tx} on block ${blockNumber}. Error: ${error}` + ); + } - hasErrors ||= error; + hasErrors ||= error; - if (numContractsAdded > 0) { - log.debug(`Added ${numContractsAdded} contracts`); + if (numContractsAdded > 0) { + log.debug(`Added ${numContractsAdded} conditional orders`); - // Write the registry to disk. Don't catch errors, let them bubble up - await registry.write(); + // Write the registry to disk. Don't catch errors, let them bubble up + await registry.write(); - // Throw execution error if there was at least one error - if (hasErrors) { - throw Error("Error adding conditional order. Event: " + event); + // Throw execution error if there was at least one error + if (hasErrors) { + throw Error("Error adding conditional order. Event: " + event); + } + } else { + log.info( + `No conditional order added for tx ${tx} on block ${blockNumber}` + ); } - } else { - log.info(`No contracts added for tx ${tx} on block ${blockNumber}`); - } + }; + + await metrics.measureTime({ + action, + labelValues: [chainId.toString()], + durationMetric: metrics.addContractsRunDurationSeconds, + totalRunsMetric: metrics.addContractRunsTotal, + errorHandler: handleExecutionError, + errorMetric: metrics.addContractsErrorsTotal, + }); } -async function registerNewOrder( +async function decodeAndAddOrder( event: ConditionalOrderCreatedEvent | MerkleRootSetEvent, - registry: Registry + registry: Registry, + chainId: SupportedChainId ): Promise<{ error: boolean; added: boolean }> { - const log = getLogger("addContract:registerNewOrder"); + const log = getLogger({ + name: "decodeAndAddOrder", + chainId, + blockNumber: event.blockNumber, + }); const { transactionHash: tx } = event; const { network } = registry; let added = false; @@ -108,13 +123,15 @@ async function registerNewOrder( ) as [string, IConditionalOrder.ConditionalOrderParamsStruct]; // Attempt to add the conditional order to the registry - add( + addOrder( eventLog.transactionHash, owner, toConditionalOrderParams(params), null, eventLog.address, - registry + registry, + chainId, + event.blockNumber ); added = true; metrics.singleOrdersTotal.labels(network).inc(); @@ -149,13 +166,15 @@ async function registerNewOrder( order as BytesLike ); // Attempt to add the conditional order to the registry - add( + addOrder( event.transactionHash, owner, toConditionalOrderParams(decodedOrder[1]), { merkleRoot: root, path: decodedOrder[0] }, eventLog.address, - registry + registry, + chainId, + event.blockNumber ); added = true; metrics.merkleRootTotal.labels(network).inc(); @@ -174,7 +193,7 @@ async function registerNewOrder( } /** - * Attempt to add an owner's conditional order to the registry + * Attempt to add a conditional order to the registry * * @param tx transaction that created the conditional order * @param owner to add the conditional order to @@ -183,25 +202,30 @@ async function registerNewOrder( * @param composableCow address of the contract that emitted the event * @param registry of all conditional orders */ -function add( +function addOrder( tx: string, owner: Owner, params: ConditionalOrderParams, proof: Proof | null, composableCow: string, - registry: Registry + registry: Registry, + chainId: SupportedChainId, + blockNumber: number ) { - const log = getLogger("addContract:add"); + const log = getLogger({ name: "addOrder", chainId, blockNumber }); const { handler, salt, staticInput } = params; const { network, ownerOrders } = registry; const conditionalOrderId = ConditionalOrder.leafToId(params); if (ownerOrders.has(owner)) { const conditionalOrders = ownerOrders.get(owner); - log.info( - `Adding conditional order to already existing owner contract ${owner}`, - { conditionalOrderId, tx, handler, salt, staticInput } - ); + log.info(`Adding conditional order to already existing owner ${owner}`, { + conditionalOrderId, + tx, + handler, + salt, + staticInput, + }); let exists = false; // Iterate over the conditionalOrders to make sure that the params are not already in the registry for (const conditionalOrder of conditionalOrders?.values() ?? []) { @@ -229,7 +253,7 @@ function add( metrics.activeOrdersTotal.labels(network).inc(); } } else { - log.info(`Adding conditional order to new owner contract ${owner}:`, { + log.info(`Adding conditional order to new owner ${owner}:`, { conditionalOrderId, tx, handler, diff --git a/src/domain/polling/index.ts b/src/domain/polling/index.ts index 1453af3..36ea339 100644 --- a/src/domain/polling/index.ts +++ b/src/domain/polling/index.ts @@ -107,7 +107,7 @@ export async function checkForAndPlaceOrder( blockTimestampOverride?: number ) { const { chainId, registry, filterPolicy } = context; - const { ownerOrders, numOrders } = registry; + const { ownerOrders, numOrders, numOwners } = registry; const blockNumber = blockNumberOverride || block.number; const blockTimestamp = blockTimestampOverride || block.timestamp; @@ -117,33 +117,41 @@ export async function checkForAndPlaceOrder( let orderCounter = 0; let updatedCount = 0; - const log = getLogger( - "checkForAndPlaceOrder:checkForAndPlaceOrder", - chainId.toString(), - blockNumber.toString() - ); - log.debug(`Total number of orders: ${numOrders}`); + const loggerParams = { + name: "checkForAndPlaceOrder", + chainId, + blockNumber, + }; + const log = getLogger(loggerParams); + log.debug(`The registry has ${numOwners} owners and ${numOrders} orders`); for (const [owner, conditionalOrders] of ownerOrders.entries()) { ownerCounter++; - const log = getLogger( - "checkForAndPlaceOrder:checkForAndPlaceOrder", - chainId.toString(), - blockNumber.toString(), - ownerCounter.toString() - ); + const log = getLogger({ + ...loggerParams, + ownerNumber: ownerCounter, + }); let ordersPendingDelete = []; - log.debug(`Process owner ${owner} (${conditionalOrders.size} orders)`); + log.debug( + `Process owner ${ownerCounter}/${numOwners}. Owner=${owner}. Orders=${conditionalOrders.size}` + ); for (const conditionalOrder of conditionalOrders) { orderCounter++; + const log = getLogger({ + ...loggerParams, + blockNumber, + ownerNumber: ownerCounter, + orderNumber: orderCounter, + }); + // Check if we reached the chunk size if (updatedCount % CHUNK_SIZE === 1 && updatedCount > 1) { // Delete orders pending delete, if any - _deleteOrders(ordersPendingDelete, conditionalOrders, log, chainId); + deleteOrders(ordersPendingDelete, conditionalOrders, log, chainId); // Reset tracker ordersPendingDelete = []; @@ -153,9 +161,7 @@ export async function checkForAndPlaceOrder( await registry.write(); } - const ownerRef = `${ownerCounter}.${orderCounter}`; - const orderRef = `${chainId}:${blockNumber}:${ownerRef}`; - const logOrderDetails = `Processing order ${conditionalOrder.id} from TX ${conditionalOrder.tx} with params:`; + const logOrderDetails = `Processing order ${orderCounter}/${numOrders} with ID ${conditionalOrder.id} from TX ${conditionalOrder.tx} with params:`; const { result: lastHint } = conditionalOrder.pollResult || {}; @@ -212,13 +218,14 @@ export async function checkForAndPlaceOrder( // Proceed with the normal check log.info(`${logOrderDetails}`, conditionalOrder.params); - const pollResult = await _processConditionalOrder( + const pollResult = await processConditionalOrder( owner, conditionalOrder, blockTimestamp, blockNumber, context, - orderRef + ownerCounter, + orderCounter ); // Don't try again the same order, in case that's the poll result @@ -246,7 +253,7 @@ export async function checkForAndPlaceOrder( (isError && pollResult.reason ? `. Reason: ${pollResult.reason}` : ""); log[unexpectedError ? "error" : "info"]( - `Check conditional order result for ${ + `Check conditional order result for order ${ conditionalOrder.id }: ${getEmojiByPollResult(pollResult?.result)} ${resultDescription}` ); @@ -261,7 +268,7 @@ export async function checkForAndPlaceOrder( } // Delete orders we don't want to keep watching - _deleteOrders(ordersPendingDelete, conditionalOrders, log, chainId); + deleteOrders(ordersPendingDelete, conditionalOrders, log, chainId); } // It may be handy in other versions of the watch tower implemented in other languages @@ -278,7 +285,7 @@ export async function checkForAndPlaceOrder( await registry.write(); log.debug( - `Total orders after processing all conditional orders: ${registry.numOrders}` + `After processing orders. Owners=${registry.numOwners}, Orders=${registry.numOrders}` ); // Throw execution error if there was at least one error @@ -287,14 +294,18 @@ export async function checkForAndPlaceOrder( } } -function _deleteOrders( +function deleteOrders( ordersPendingDelete: ConditionalOrder[], conditionalOrders: Set, log: LoggerWithMethods, chainId: SupportedChainId ) { ordersPendingDelete.length && - log.debug(`${ordersPendingDelete.length} to delete`); + log.debug( + `Delete ${ordersPendingDelete.length} orders: ${ordersPendingDelete.join( + ", " + )}` + ); for (const conditionalOrder of ordersPendingDelete) { const deleted = conditionalOrders.delete(conditionalOrder); @@ -307,21 +318,25 @@ function _deleteOrders( } } -async function _processConditionalOrder( +async function processConditionalOrder( owner: string, conditionalOrder: ConditionalOrder, blockTimestamp: number, blockNumber: number, context: ChainContext, - orderRef: string + ownerNumber: number, + orderNumber: number ): Promise { const { provider, orderBookApi, dryRun, chainId } = context; const { handler } = conditionalOrder.params; - const log = getLogger( - "checkForAndPlaceOrder:_processConditionalOrder", - orderRef - ); + const log = getLogger({ + name: "processConditionalOrder", + chainId, + blockNumber, + ownerNumber, + orderNumber, + }); const metricLabels = [ chainId.toString(), handler, @@ -348,11 +363,15 @@ async function _processConditionalOrder( provider, orderBookApi, }; + let pollResult = await pollConditionalOrder( conditionalOrder.id, pollParams, conditionalOrder.params, - orderRef + chainId, + blockNumber, + ownerNumber, + orderNumber ); if (!pollResult) { @@ -361,13 +380,15 @@ async function _processConditionalOrder( // TODO: Decide in the future what to do. Probably, move the error handling to the SDK and kill the poll Legacy pollResult = await metrics.measureTime({ action: () => - _pollLegacy( + pollLegacy( context, owner, conditionalOrder, proof, offchainInput, - orderRef + blockNumber, + ownerNumber, + orderNumber ), labelValues: metricLabels, durationMetric: metrics.pollingOnChainDurationSeconds, @@ -407,20 +428,23 @@ async function _processConditionalOrder( } // calculate the orderUid - const orderUid = _getOrderUid(chainId, orderToSubmit, owner); + const orderUid = getOrderUid(chainId, orderToSubmit, owner); // Place order, if the orderUid has not been submitted or filled if (!conditionalOrder.orders.has(orderUid)) { // Place order - const placeOrderResult = await _placeOrder({ + const placeOrderResult = await postDiscreteOrder({ conditionalOrder, orderUid, order: { ...orderToSubmit, from: owner, signature }, orderBookApi, blockTimestamp, - orderRef, dryRun, metricLabels, + chainId, + blockNumber, + ownerNumber, + orderNumber, }); // In case of error, return early @@ -457,7 +481,7 @@ async function _processConditionalOrder( } } -function _getOrderUid( +function getOrderUid( chainId: SupportedChainId, orderToSubmit: Order, owner: string @@ -501,27 +525,40 @@ export const _printUnfilledOrders = (orders: Map) => { * @param order to be placed on the cow protocol api * @param apiUrl rest api url */ -async function _placeOrder(params: { +async function postDiscreteOrder(params: { conditionalOrder: ConditionalOrder; orderUid: string; order: any; orderBookApi: OrderBookApi; - orderRef: string; blockTimestamp: number; dryRun: boolean; metricLabels: string[]; + chainId: SupportedChainId; + blockNumber: number; + ownerNumber: number; + orderNumber: number; }): Promise | PollResultErrors> { const { conditionalOrder, orderUid, order, orderBookApi, - orderRef, blockTimestamp, dryRun, metricLabels, + chainId, + blockNumber, + ownerNumber, + orderNumber, } = params; - const log = getLogger("checkForAndPlaceOrder:_placeOrder", orderRef); + const log = getLogger({ + name: "postDiscreteOrder", + chainId, + blockNumber, + ownerNumber, + orderNumber, + }); + try { const postOrder: OrderCreation = { kind: order.kind, @@ -557,7 +594,7 @@ async function _placeOrder(params: { const { status } = error.response; const { body } = error; - const handleErrorResult = _handleOrderBookError( + const handleErrorResult = handleOrderBookError( status, body, error, @@ -596,7 +633,7 @@ async function _placeOrder(params: { return { result: PollResultCode.SUCCESS }; } -function _handleOrderBookError( +function handleOrderBookError( status: any, body: any, error: any, @@ -687,16 +724,24 @@ function _handleOrderBookError( }; } -async function _pollLegacy( +async function pollLegacy( context: ChainContext, owner: string, conditionalOrder: ConditionalOrder, proof: string[], offchainInput: string, - orderRef: string + blockNumber: number, + ownerNumber: number, + orderNumber: number ): Promise { const { contract, multicall, chainId } = context; - const log = getLogger("checkForAndPlaceOrder:_pollLegacy", orderRef); + const log = getLogger({ + name: "pollLegacy", + chainId, + blockNumber, + ownerNumber, + orderNumber, + }); const { composableCow: target } = conditionalOrder; const { handler } = conditionalOrder.params; // as we going to use multicall, with `aggregate3Value`, there is no need to do any simulation as the @@ -750,12 +795,14 @@ async function _pollLegacy( // order types created that are _not_ adhering to the interface (and are therefore invalid). return handleOnChainCustomError({ owner, - orderRef, chainId, target, callData, revertData: returnData, metricLabels, + blockNumber, + ownerNumber, + orderNumber, }); } catch (error: any) { // We can only get here from some provider / ethers failure. As the contract hasn't had it's say diff --git a/src/domain/polling/poll.ts b/src/domain/polling/poll.ts index be1f139..6f86568 100644 --- a/src/domain/polling/poll.ts +++ b/src/domain/polling/poll.ts @@ -4,6 +4,7 @@ import { DEFAULT_CONDITIONAL_ORDER_REGISTRY, PollParams, PollResult, + SupportedChainId, } from "@cowprotocol/cow-sdk"; import { getLogger } from "../../utils/logging"; @@ -18,9 +19,19 @@ export async function pollConditionalOrder( conditionalOrderId: string, pollParams: PollParams, conditionalOrderParams: ConditionalOrderParams, - orderRef: string + chainId: SupportedChainId, + blockNumber: number, + ownerNumber: number, + orderNumber: number ): Promise { - const log = getLogger("pollConditionalOrder:pollConditionalOrder", orderRef); + const log = getLogger({ + name: "pollConditionalOrder", + chainId, + blockNumber, + ownerNumber, + orderNumber, + }); + const order = ordersFactory.fromParams(conditionalOrderParams); if (!order) { diff --git a/src/services/api.ts b/src/services/api.ts index 1d5b47e..cbc13f4 100644 --- a/src/services/api.ts +++ b/src/services/api.ts @@ -50,7 +50,7 @@ export class ApiService { async start(): Promise { return await new Promise((resolve, reject) => { try { - const log = getLogger("api:start"); + const log = getLogger({ name: "api:start" }); if (this.server?.listening) { throw new Error("Server is already running"); } @@ -74,7 +74,7 @@ export class ApiService { throw new Error("Server is not running"); } - const log = getLogger("api:stop"); + const log = getLogger({ name: "api:stop" }); log.info("Stopping Rest API server..."); this.server.once("close", resolve); diff --git a/src/services/chain.ts b/src/services/chain.ts index 7bdbdec..ace123e 100644 --- a/src/services/chain.ts +++ b/src/services/chain.ts @@ -5,7 +5,7 @@ import { } from "@cowprotocol/cow-sdk"; import { ethers, providers } from "ethers"; import { DBService } from "."; -import { addContract } from "../domain/events"; +import { processNewOrderEvent } from "../domain/events"; import { checkForAndPlaceOrder } from "../domain/polling"; import { policy } from "../domain/polling/filtering"; import { @@ -171,7 +171,7 @@ export class ChainContext { */ public async warmUp(oneShot?: boolean) { const { provider, chainId, processEveryNumBlocks } = this; - const log = getLogger("chainContext:warmUp", chainId.toString()); + const log = getLogger({ name: "warmUp", chainId }); let { lastProcessedBlock } = this.registry; const { pageSize } = this; @@ -290,7 +290,7 @@ export class ChainContext { } while (this.sync === ChainSync.SYNCING); log.info( - `💚 ${ + `☀️ ${ oneShot ? "Chain watcher is in sync" : "Chain watcher is warmed up" }` ); @@ -302,7 +302,7 @@ export class ChainContext { } // Otherwise, run the block watcher - return await this.runBlockWatcher(currentBlock); + return await this.subscribeToNewBlocks(currentBlock); } /** @@ -310,16 +310,22 @@ export class ChainContext { * 1. Check if there are any `ConditionalOrderCreated` events, and index these. * 2. Check if any orders want to create discrete orders. */ - private async runBlockWatcher(lastProcessedBlock: providers.Block) { + private async subscribeToNewBlocks(lastProcessedBlock: providers.Block) { const { provider, registry, chainId, watchdogTimeout } = this; - const log = getLogger("chainContext:runBlockWatcher", chainId.toString()); + const loggerName = "subscribeToNewBlocks"; + let log = getLogger({ name: loggerName, chainId }); // Watch for new blocks log.info(`👀 Start block watcher`); log.debug(`Watchdog timeout: ${watchdogTimeout} seconds`); let lastBlockReceived = lastProcessedBlock; provider.on("block", async (blockNumber: number) => { try { - log.debug(`New block ${blockNumber}`); + log = getLogger({ + name: loggerName, + chainId, + blockNumber, + }); + log.debug("New block received"); const block = await provider.getBlock(blockNumber); @@ -436,7 +442,7 @@ export class ChainContext { * @param blockNumberOverride to override the block number when polling the SDK * @param blockTimestampOverride to override the block timestamp when polling the SDK */ -async function processBlock( +async function processBlockEvent( context: ChainContext, block: providers.Block, events: ConditionalOrderCreatedEvent[], @@ -448,11 +454,11 @@ async function processBlock( .labels(context.chainId.toString()) .startTimer(); - const log = getLogger( - "chainContext:processBlock", - chainId.toString(), - block.number.toString() - ); + const log = getLogger({ + name: "processBlockEvent", + chainId, + blockNumber: block.number, + }); // Transaction watcher for adding new contracts let hasErrors = false; @@ -461,15 +467,22 @@ async function processBlock( if (receipt) { // run action - log.debug(`Running "addContract" action for TX ${event.transactionHash}`); - const result = await addContract(context, event) + log.debug(`Process new order event of TX ${event.transactionHash}`); + const result = await processNewOrderEvent(context, event) .then(() => true) .catch((e) => { hasErrors = true; - log.error(`Error running "addContract" action for TX:`, e); + log.error( + `Error processing new order event of TX ${event.transactionHash}:`, + e + ); return false; }); - log.info(`Result of "addContract": ${_formatResult(result)}`); + log.info( + `Result of processing new order event of TX ${ + event.transactionHash + }: ${_formatResult(result)}` + ); metrics.eventsProcessedTotal.labels(chainId.toString()).inc(); } } @@ -518,7 +531,7 @@ async function persistLastProcessedBlock(params: { // Save the registry await context.registry.write(); - log.debug(`Block ${blockNumber} has been processed`); + log.debug(`Block has been processed`); // Set the block height metric metrics.blockHeight.labels(context.chainId.toString()).set(blockNumber); @@ -542,7 +555,7 @@ async function processBlockAndPersist(params: { const _block = block || (await provider.getBlock(blockNumber)); try { - await processBlock( + await processBlockEvent( context, _block, events, @@ -598,7 +611,8 @@ function _formatResult(result: boolean) { } function getProvider(rpcUrl: string): providers.Provider { - const log = getLogger("getProvider", rpcUrl); + const log = getLogger({ name: "getProvider", args: [rpcUrl] }); + // if the rpcUrl is a websocket url, use the WebSocketProvider if (rpcUrl.startsWith("ws")) { log.debug("Instantiating WS"); diff --git a/src/services/storage.ts b/src/services/storage.ts index 7c3d145..153379c 100644 --- a/src/services/storage.ts +++ b/src/services/storage.ts @@ -28,13 +28,13 @@ export class DBService { } public async open() { - const log = getLogger("dbService:open"); + const log = getLogger({ name: "dbService:open" }); log.info("Opening database..."); await this.db.open(); } public async close() { - const log = getLogger("dbService:close"); + const log = getLogger({ name: "dbService:close" }); log.info("Closing database..."); await this.db.close(); } diff --git a/src/types/model.ts b/src/types/model.ts index 42ab571..f5216ec 100644 --- a/src/types/model.ts +++ b/src/types/model.ts @@ -110,7 +110,7 @@ export class Registry { network: string; lastNotifiedError: Date | null; lastProcessedBlock: RegistryBlock | null; - readonly logger = getLogger("Registry"); + readonly logger = getLogger({ name: "Registry" }); /** * Instantiates a registry. * @param ownerOrders What map to populate the registry with @@ -200,6 +200,10 @@ export class Registry { return getOrdersCountFromOrdersPerOwner(this.ownerOrders); } + get numOwners(): number { + return this.ownerOrders.size; + } + /** * Write the registry to storage. */ @@ -250,10 +254,9 @@ export class Registry { await batch.write(); this.logger.debug( - `write:${this.version}:${this.network}:${ - this.lastProcessedBlock?.number - }:${this.lastNotifiedError || ""}`, - "batch written 📝" + `${this.network}@${this.lastProcessedBlock?.number}:v${this.version}${ + this.lastNotifiedError ? ":lastError_" + this.lastNotifiedError : "" + } DB persisted` ); } @@ -293,7 +296,7 @@ async function loadOwnerOrders( storage: DBService, network: string ): Promise { - const loadOwnerOrdersLogger = getLogger("loadOwnerOrders"); + const loadOwnerOrdersLogger = getLogger({ name: "loadOwnerOrders" }); // Get the owner orders const db = storage.getDB(); const str = await db.get( diff --git a/src/utils/context.ts b/src/utils/context.ts index a094229..939f19a 100644 --- a/src/utils/context.ts +++ b/src/utils/context.ts @@ -59,7 +59,7 @@ function _getSlack(options: ContextOptions): Slack | undefined { } export async function handleExecutionError(e: any) { - const log = getLogger("context:handleExecutionError"); + const log = getLogger({ name: "context:handleExecutionError" }); try { const errorMessage = e?.message || "Unknown error"; const notified = sendSlack( @@ -80,7 +80,7 @@ export async function handleExecutionError(e: any) { } export function sendSlack(message: string): boolean { - const log = getLogger("context:sendSlack"); + const log = getLogger({ name: "context:sendSlack" }); if (!executionContext) { log.warn("Slack not initialized, ignoring message", message); return false; diff --git a/src/utils/contracts.ts b/src/utils/contracts.ts index 0bc6a18..80e9f4e 100644 --- a/src/utils/contracts.ts +++ b/src/utils/contracts.ts @@ -198,33 +198,44 @@ export function parseCustomError(revertData: string): ParsedCustomError { */ export function handleOnChainCustomError(params: { owner: string; - orderRef: string; chainId: SupportedChainId; target: string; callData: string; revertData: string; metricLabels: string[]; + blockNumber: number; + ownerNumber: number; + orderNumber: number; }): PollResultErrors { const { owner, - orderRef, chainId, target, callData, revertData, metricLabels, + blockNumber, + ownerNumber, + orderNumber, } = params; + const loggerParams = { + name: "handleOnChainCustomError", + chainId, + blockNumber, + ownerNumber, + orderNumber, + }; + try { // The below will throw if: // - the error is not a custom error (ie. the selector is not in the map) // - the error is a custom error, but the parameters are not as expected const parsedCustomError = parseCustomError(revertData); const { selector } = parsedCustomError; - const log = getLogger( - "contracts:handleOnChainCustomError", - orderRef, - selector - ); + const log = getLogger({ + ...loggerParams, + args: [selector], + }); const msgWithSelector = (message: string): string => `${selector}: ${message}`; const dropOrder = (reason: string): PollResultErrors => { @@ -293,7 +304,8 @@ export function handleOnChainCustomError(params: { } catch (err: any) { // Any errors thrown here can _ONLY_ come from non-compliant interfaces (ie. bad revert ABI encoding). // We log the error, and return a DONT_TRY_AGAIN result. - const log = getLogger("contracts:handleOnChainCustomError", orderRef); + const log = getLogger(loggerParams); + log.debug( `Non-compliant interface error thrown${ err.message ? `: ${err.message}` : "" diff --git a/src/utils/logging.ts b/src/utils/logging.ts index b8fdd69..d761cb9 100644 --- a/src/utils/logging.ts +++ b/src/utils/logging.ts @@ -6,6 +6,7 @@ import { import rootLogger from "loglevel"; import prefix from "loglevel-plugin-prefix"; import chalk, { Chalk } from "chalk"; +import { SupportedChainId } from "@cowprotocol/cow-sdk"; const DEFAULT_LOG_LEVEL = "INFO"; const LEVELS = ["TRACE", "DEBUG", "INFO", "WARN", "ERROR", "SILENT"]; @@ -54,36 +55,60 @@ export interface LoggerWithMethods { error: (...msg: any[]) => void; } -export function getLogger( - loggerName: string, - ...args: string[] -): LoggerWithMethods { +interface GetLoggerParams { + name: string; + chainId?: SupportedChainId; + blockNumber?: number; + ownerNumber?: number; + orderNumber?: number; + args?: string[]; +} + +/** + * Get the log prefix for a given logger. This is used to add context to the log messages. + */ +function getLogPrefix({ + chainId, + blockNumber, + ownerNumber, + orderNumber, + args = [], +}: GetLoggerParams) { + const chainString = chainId ? `${chainId}` : ""; + const blockString = blockNumber ? `@${blockNumber}` : ""; + const ownerString = ownerNumber ? `#${ownerNumber}` : ""; + const orderString = orderNumber ? `.${orderNumber}` : ""; + const argsString = args.length > 0 ? " " + args.join(":") : ""; + + return chainString + blockString + ownerString + orderString + argsString; +} + +export function getLogger(params: GetLoggerParams): LoggerWithMethods { if (!logLevelOverrides) { throw new Error("Logging hasn't been initialized"); } - const logger = getLoggerLogLevel(loggerName); + const { name } = params; + const logger = getLoggerLogLevel(name); + const prefix = getLogPrefix(params); const logLevelOverride = logLevelOverrides.find((override) => - override.regex.test(loggerName) + override.regex.test(name) ); if (logLevelOverride) { logger.setLevel(logLevelOverride.level); } - const fmtLogMessage = (args: string[], ...msg: any[]) => { - if (args.length) { - return [`${args.join(":")}: `, ...msg]; - } - return msg; - }; + const fmtLogMessage = (msg: any[]) => (prefix ? [prefix, ...msg] : msg); + const customLogger: LoggerWithMethods = { - trace: (...msg: any[]) => logger.trace(...fmtLogMessage(args, ...msg)), - debug: (...msg: any[]) => logger.debug(...fmtLogMessage(args, ...msg)), - info: (...msg: any[]) => logger.info(...fmtLogMessage(args, ...msg)), - warn: (...msg: any[]) => logger.warn(...fmtLogMessage(args, ...msg)), - error: (...msg: any[]) => logger.error(...fmtLogMessage(args, ...msg)), + trace: (...msg: any[]) => logger.trace(...fmtLogMessage(msg)), + debug: (...msg: any[]) => logger.debug(...fmtLogMessage(msg)), + info: (...msg: any[]) => logger.info(...fmtLogMessage(msg)), + warn: (...msg: any[]) => logger.warn(...fmtLogMessage(msg)), + error: (...msg: any[]) => logger.error(...fmtLogMessage(msg)), }; + return customLogger; } diff --git a/src/utils/utils.spec.ts b/src/utils/utils.spec.ts index 8c2af3d..878e9f2 100644 --- a/src/utils/utils.spec.ts +++ b/src/utils/utils.spec.ts @@ -65,6 +65,9 @@ describe("handle on-chain custom errors", () => { CUSTOM_ERROR_ABI_MAP[CustomErrorSelectors.SINGLE_ORDER_NOT_AUTHED] ), metricLabels: ["chain_id", "handler", "owner", "id"], + blockNumber: 123456, + ownerNumber: 2, + orderNumber: 3, }; it("should pass a known selector correctly", () => {