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: <img width="1699" alt="Screenshot at Dec 05 22-17-10" src="https://github.com/user-attachments/assets/642e92e7-0577-42ca-bca1-721338dc5e82"> 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.
cowprotocol · Dec 6, 2024 · dd7eafb · dd7eafb
1 parent dbb2a8c
commit dd7eafb
Show file tree

Hide file tree

Showing 13 changed files with 307 additions and 168 deletions.
diff --git 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
@@ -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
@@ -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,