Improve logging, errors, and a couple bugfixes

.changeset/forty-tigers-fly.md

@@ -0,0 +1,5 @@
+---
+"@ponder/core": patch
+---
+
+Fixed a bug where the default finality checkpoint of several chains (including Arbitrum) was set to zero. The target finality interval for reorg-safe chains like Arbitrum and Optimism is now 10 seconds (e.g. 40 blocks on Arbitrum).

.changeset/happy-wasps-destroy.md

@@ -0,0 +1,5 @@
+---
+"@ponder/core": patch
+---
+
+Fixed a bug where the realtime sync service would process blocks out of order, leading to less efficient RPC request patterns.

.changeset/shy-tables-mix.md

@@ -0,0 +1,5 @@
+---
+"@ponder/core": patch
+---
+
+Updated Ponder's logging behavior. Stdout log lines will not include timestamps, log level, service name, and a message. Logs are also written to files located at `/.ponder/logs/{timestamp}.log` in JSON format. There are now more log levels: `"silent"`, `"fatal"`, `"error"`, `"warn"`, `"info"`, `"debug"`, and `"trace"`. These can be configured using the `PONDER_LOG_LEVEL` environment variable.

packages/core/package.json

@@ -46,6 +46,7 @@
     "p-queue": "^6.6.2",
     "pg": "^8.9.0",
     "picocolors": "^1.0.0",
+    "pino": "^8.14.1",
     "prettier": "^2.6.2",
     "prom-client": "^14.2.0",
     "react": "17",

packages/core/src/Ponder.ts

@@ -1,4 +1,4 @@
-import pico from "picocolors";
+import path from "node:path";
 
 import { CodegenService } from "@/codegen/service";
 import { buildContracts } from "@/config/contracts";
@@ -7,12 +7,13 @@ import { buildLogFilters, LogFilter } from "@/config/logFilters";
 import { type Network, buildNetwork } from "@/config/networks";
 import { type PonderOptions } from "@/config/options";
 import { type ResolvedPonderConfig } from "@/config/ponderConfig";
-import { ErrorService } from "@/errors/ErrorService";
+import { UserErrorService } from "@/errors/service";
 import { EventAggregatorService } from "@/event-aggregator/service";
 import { PostgresEventStore } from "@/event-store/postgres/store";
 import { SqliteEventStore } from "@/event-store/sqlite/store";
 import { type EventStore } from "@/event-store/store";
 import { HistoricalSyncService } from "@/historical-sync/service";
+import { LoggerService } from "@/logs/service";
 import { MetricsService } from "@/metrics/service";
 import { RealtimeSyncService } from "@/realtime-sync/service";
 import { ReloadService } from "@/reload/service";
@@ -22,13 +23,12 @@ import { EventHandlerService } from "@/user-handlers/service";
 import { PostgresUserStore } from "@/user-store/postgres/store";
 import { SqliteUserStore } from "@/user-store/sqlite/store";
 import { type UserStore } from "@/user-store/store";
-import { formatEta, formatPercentage } from "@/utils/format";
-import { LoggerService } from "@/utils/logger";
+import { formatEta } from "@/utils/format";
 
 export type Resources = {
   options: PonderOptions;
   logger: LoggerService;
-  errors: ErrorService;
+  errors: UserErrorService;
   metrics: MetricsService;
 };
 
@@ -55,6 +55,8 @@ export class Ponder {
   codegenService: CodegenService;
   uiService: UiService;
 
+  private killFunctions: (() => any)[] = [];
+
   constructor({
     options,
     config,
@@ -67,8 +69,11 @@ export class Ponder {
     eventStore?: EventStore;
     userStore?: UserStore;
   }) {
-    const logger = new LoggerService({ options });
-    const errors = new ErrorService();
+    const logger = new LoggerService({
+      level: options.logLevel,
+      dir: options.logDir,
+    });
+    const errors = new UserErrorService();
     const metrics = new MetricsService();
 
     const resources = { options, logger, errors, metrics };
@@ -103,12 +108,14 @@ export class Ponder {
         logFilters: logFiltersForNetwork,
         historicalSyncService: new HistoricalSyncService({
           metrics,
+          logger,
           eventStore: this.eventStore,
           network,
           logFilters: logFiltersForNetwork,
         }),
         realtimeSyncService: new RealtimeSyncService({
           metrics,
+          logger,
           eventStore: this.eventStore,
           network,
           logFilters: logFiltersForNetwork,
@@ -145,6 +152,14 @@ export class Ponder {
   }
 
   async setup() {
+    this.resources.logger.debug({
+      service: "app",
+      msg: `Started using config file: ${path.relative(
+        this.resources.options.rootDir,
+        this.resources.options.configFile
+      )}`,
+    });
+
     this.registerServiceDependencies();
     this.registerUiHandlers();
 
@@ -185,7 +200,7 @@ export class Ponder {
   async dev() {
     const setupError = await this.setup();
     if (setupError) {
-      this.resources.logger.logMessage("error", setupError.message);
+      // this.resources.logger.logMessage("error", setupError.message);
       return await this.kill();
     }
 
@@ -207,7 +222,7 @@ export class Ponder {
   async start() {
     const setupError = await this.setup();
     if (setupError) {
-      this.resources.logger.logMessage("error", setupError.message);
+      // this.resources.logger.error("error", setupError.message);
       return await this.kill();
     }
 
@@ -238,6 +253,7 @@ export class Ponder {
   }
 
   async kill() {
+    this.killFunctions.forEach((fn) => fn());
     this.eventAggregatorService.clearListeners();
 
     await Promise.all(
@@ -254,10 +270,19 @@ export class Ponder {
     this.eventHandlerService.kill();
     await this.serverService.teardown();
     await this.userStore.teardown();
+
+    this.resources.logger.debug({
+      service: "app",
+      msg: `Finished shutdown sequence`,
+    });
   }
 
   private registerServiceDependencies() {
     this.reloadService.on("ponderConfigChanged", async () => {
+      this.resources.logger.fatal({
+        service: "build",
+        msg: "Detected change in ponder.config.ts",
+      });
       await this.kill();
     });
 
@@ -275,8 +300,7 @@ export class Ponder {
     });
 
     this.networkSyncServices.forEach((networkSyncService) => {
-      const { network, historicalSyncService, realtimeSyncService } =
-        networkSyncService;
+      const { historicalSyncService, realtimeSyncService } = networkSyncService;
 
       historicalSyncService.on("historicalCheckpoint", ({ timestamp }) => {
         this.eventAggregatorService.handleNewHistoricalCheckpoint({
@@ -310,17 +334,6 @@ export class Ponder {
           timestamp: commonAncestorTimestamp,
         });
       });
-
-      // TODO: Decide what to do after a deep reorg.
-      realtimeSyncService.on(
-        "deepReorg",
-        ({ detectedAtBlockNumber, minimumDepth }) => {
-          this.resources.logger.logMessage(
-            "error",
-            `WARNING: Deep reorg detected on ${network.name} at block ${detectedAtBlockNumber} with a minimum depth of ${minimumDepth}`
-          );
-        }
-      );
     });
 
     this.eventAggregatorService.on("newCheckpoint", ({ timestamp }) => {
@@ -341,62 +354,24 @@ export class Ponder {
         this.eventAggregatorService.historicalSyncCompletedAt &&
         toTimestamp >= this.eventAggregatorService.historicalSyncCompletedAt
       ) {
-        this.serverService.isHistoricalEventProcessingComplete = true;
-        this.resources.logger.logMessage(
-          "indexer",
-          "historical sync complete (server now responding as healthy)"
-        );
+        this.serverService.setIsHistoricalEventProcessingComplete();
       }
     });
   }
 
   private registerUiHandlers() {
-    this.resources.errors.on("handlerError", ({ error }) => {
-      this.resources.logger.logMessage("error", error.message);
-    });
-
     this.networkSyncServices.forEach((networkSyncService) => {
-      const { historicalSyncService, realtimeSyncService, logFilters } =
-        networkSyncService;
-
-      historicalSyncService.on("error", ({ error }) => {
-        this.resources.logger.logMessage("error", error.message);
-      });
-
-      realtimeSyncService.on("error", ({ error }) => {
-        this.resources.logger.logMessage("error", error.message);
-      });
+      const { historicalSyncService, logFilters } = networkSyncService;
 
       historicalSyncService.on("syncStarted", () => {
         logFilters.forEach(({ name }) => {
           this.uiService.ui.historicalSyncLogFilterStats[name].startTimestamp =
             Date.now();
-
-          this.resources.logger.logMessage(
-            "historical",
-            `started historical sync for ${pico.bold(name)} (${formatPercentage(
-              historicalSyncService.stats.logFilters[name].cacheRate
-            )} cached)`
-          );
         });
       });
-
-      realtimeSyncService.on("finalityCheckpoint", ({ timestamp }) => {
-        this.resources.logger.logMessage(
-          "realtime",
-          `finality checkpoint, timestamp: ${timestamp}`
-        );
-      });
-
-      realtimeSyncService.on("shallowReorg", ({ commonAncestorTimestamp }) => {
-        this.resources.logger.logMessage(
-          "realtime",
-          `reorg detected, common ancestor timestamp: ${commonAncestorTimestamp}`
-        );
-      });
     });
 
-    setInterval(() => {
+    const interval = setInterval(() => {
       this.networkSyncServices.forEach((networkSyncService) => {
         const { network, realtimeSyncService } = networkSyncService;
 
@@ -423,7 +398,7 @@ export class Ponder {
         );
       }
 
-      this.uiService.ui.handlerError = this.eventHandlerService.metrics.error;
+      this.uiService.ui.handlerError = this.resources.errors.hasUserError;
       this.uiService.ui.handlersHandledTotal =
         this.eventHandlerService.metrics.eventsAddedToQueue;
       this.uiService.ui.handlersCurrent =
@@ -434,6 +409,10 @@ export class Ponder {
         this.eventHandlerService.metrics.latestHandledEventTimestamp;
     }, 17);
 
+    this.killFunctions.push(() => {
+      clearInterval(interval);
+    });
+
     this.eventHandlerService.on("reset", () => {
       this.uiService.ui.handlersCurrent = 0;
       this.uiService.ui.handlersTotal = 0;
@@ -442,7 +421,7 @@ export class Ponder {
     });
 
     this.eventHandlerService.on("taskCompleted", () => {
-      this.uiService.ui.handlerError = this.eventHandlerService.metrics.error;
+      this.uiService.ui.handlerError = this.resources.errors.hasUserError;
       this.uiService.ui.handlersHandledTotal =
         this.eventHandlerService.metrics.eventsAddedToQueue;
       this.uiService.ui.handlersCurrent =
@@ -454,27 +433,8 @@ export class Ponder {
       this.uiService.render();
     });
 
-    this.serverService.on("serverStarted", ({ desiredPort, port }) => {
-      if (desiredPort !== port) {
-        this.resources.logger.logMessage(
-          "event",
-          `port ${desiredPort} unavailable, server listening on port ${port}`
-        );
-      } else {
-        this.resources.logger.logMessage(
-          "event",
-          `server listening on port ${port}`
-        );
-      }
+    this.serverService.on("serverStarted", ({ port }) => {
       this.uiService.ui.port = port;
     });
-
-    this.resources.errors.on("handlerError", () => {
-      this.uiService.ui.handlerError = true;
-    });
-
-    this.resources.errors.on("handlerErrorCleared", () => {
-      this.uiService.ui.handlerError = false;
-    });
   }
 }

packages/core/src/_test/art-gobblers/app.test.ts

@@ -21,7 +21,11 @@ const setup = async ({ context }: { context: TestContext }) => {
       configFile: "ponder.config.ts",
     },
   });
-  const testOptions = { ...options, uiEnabled: false, logLevel: 1 };
+  const testOptions = {
+    ...options,
+    uiEnabled: false,
+    logLevel: "error",
+  } as const;
 
   const ponder = new Ponder({
     config: testConfig,

packages/core/src/_test/ens/app.test.ts

@@ -21,7 +21,11 @@ const setup = async ({ context }: { context: TestContext }) => {
       configFile: "ponder.config.ts",
     },
   });
-  const testOptions = { ...options, uiEnabled: false, logLevel: 1 };
+  const testOptions = {
+    ...options,
+    uiEnabled: false,
+    logLevel: "error",
+  } as const;
 
   const ponder = new Ponder({
     config: testConfig,

packages/core/src/_test/utils.ts

@@ -8,10 +8,10 @@ import {
 import { mainnet } from "viem/chains";
 
 import { buildOptions } from "@/config/options";
-import { ErrorService } from "@/errors/ErrorService";
+import { UserErrorService } from "@/errors/service";
+import { LoggerService } from "@/logs/service";
 import { MetricsService } from "@/metrics/service";
 import { Resources } from "@/Ponder";
-import { LoggerService } from "@/utils/logger";
 
 // Anvil test setup adapted from @viem/anvil `example-vitest` repository.
 // https://github.com/wagmi-dev/anvil.js/tree/main/examples/example-vitest
@@ -58,10 +58,10 @@ export const walletClient = createWalletClient({
 });
 
 export const testResources: Resources = {
-  logger: new LoggerService({ options: { logLevel: 0 } }),
+  logger: new LoggerService({ level: "silent" }),
   options: buildOptions({
     cliOptions: { configFile: "", rootDir: "" },
   }),
-  errors: new ErrorService(),
+  errors: new UserErrorService(),
   metrics: new MetricsService(),
 };

packages/core/src/bin/ponder.ts

@@ -72,7 +72,11 @@ cli
     const config = await buildPonderConfig({ configFile });
     const options = buildOptions({ cliOptions, configOptions: config.options });
 
-    const codegenOptions = { ...options, uiEnabled: false, logLevel: 0 };
+    const codegenOptions = {
+      ...options,
+      uiEnabled: false,
+      logLevel: "silent",
+    } as const;
 
     const ponder = new Ponder({ config, options: codegenOptions });
     registerKilledProcessListener(() => ponder.kill());