improve logging

ponder-sh · Jan 15, 2025 · 9533501 · 9533501
1 parent 24d76c8
commit 9533501
Show file tree

Hide file tree

Showing 4 changed files with 514 additions and 496 deletions.
diff --git a/packages/core/src/database/index.ts b/packages/core/src/database/index.ts
@@ -155,6 +155,7 @@ export const createDatabase = ({
       internal: new HeadlessKysely({
         name: "internal",
         common,
+        includeTraceLogs: true,
         dialect: kyselyDialect,
         log(event) {
           if (event.level === "query") {
@@ -194,6 +195,7 @@ export const createDatabase = ({
       sync: new HeadlessKysely<PonderSyncSchema>({
         name: "sync",
         common: common,
+        includeTraceLogs: true,
         dialect: kyselyDialect,
         log(event) {
           if (event.level === "query") {
@@ -255,6 +257,7 @@ export const createDatabase = ({
       internal: new HeadlessKysely({
         name: "internal",
         common: common,
+        includeTraceLogs: true,
         dialect: new PostgresDialect({ pool: driver.internal }),
         log(event) {
           if (event.level === "query") {
@@ -294,6 +297,7 @@ export const createDatabase = ({
       sync: new HeadlessKysely<PonderSyncSchema>({
         name: "sync",
         common: common,
+        includeTraceLogs: true,
         dialect: new PostgresDialect({ pool: driver.sync }),
         log(event) {
           if (event.level === "query") {

diff --git a/packages/core/src/database/kysely.ts b/packages/core/src/database/kysely.ts
@@ -10,24 +10,31 @@ const BASE_DURATION = 125;
 export class HeadlessKysely<DB> extends Kysely<DB> {
   private common: Common;
   private name: string;
+  private includeTraceLogs: boolean;
   private isKilled = false;
 
   constructor({
     common,
     name,
+    includeTraceLogs = false,
     ...args
-  }: (KyselyConfig | KyselyProps) & { name: string; common: Common }) {
+  }: (KyselyConfig | KyselyProps) & {
+    name: string;
+    common: Common;
+    includeTraceLogs?: boolean;
+  }) {
     super(args);
     this.common = common;
     this.name = name;
+    this.includeTraceLogs = includeTraceLogs;
   }
 
   override async destroy() {
     this.isKilled = true;
   }
 
   wrap = async <T>(
-    options: { method: string; shouldRetry?: (error: Error) => boolean },
+    options: { method: string },
     fn: () => Promise<T>,
     // TypeScript can't infer that we always return or throw.
     // @ts-ignore
@@ -38,6 +45,15 @@ export class HeadlessKysely<DB> extends Kysely<DB> {
 
     for (let i = 0; i <= RETRY_COUNT; i++) {
       const endClock = startClock();
+
+      const id = crypto.randomUUID().slice(0, 8);
+      if (this.includeTraceLogs) {
+        this.common.logger.trace({
+          service: this.name,
+          msg: `Started '${options.method}' database method (id=${id})`,
+        });
+      }
+
       try {
         const result = await fn();
         this.common.metrics.ponder_database_method_duration.observe(
@@ -60,7 +76,7 @@ export class HeadlessKysely<DB> extends Kysely<DB> {
         if (this.isKilled) {
           this.common.logger.trace({
             service: this.name,
-            msg: `Ignored error during '${options.method}' database method (service is killed)`,
+            msg: `Ignored error during '${options.method}' database method, service is killed (id=${id})`,
           });
           throw new IgnorableError();
         }
@@ -70,33 +86,39 @@ export class HeadlessKysely<DB> extends Kysely<DB> {
           firstError = error;
         }
 
-        if (
-          error instanceof NonRetryableError ||
-          options.shouldRetry?.(error) === false
-        ) {
+        if (error instanceof NonRetryableError) {
           this.common.logger.warn({
             service: this.name,
-            msg: `Failed '${options.method}' database method `,
+            msg: `Failed '${options.method}' database method (id=${id})`,
+            error,
           });
           throw error;
         }
 
         if (i === RETRY_COUNT) {
           this.common.logger.warn({
             service: this.name,
-            msg: `Failed '${options.method}' database method after '${i + 1}' attempts`,
+            msg: `Failed '${options.method}' database method after '${i + 1}' attempts (id=${id})`,
             error,
           });
           throw firstError;
         }
 
         const duration = BASE_DURATION * 2 ** i;
+
         this.common.logger.debug({
           service: this.name,
-          msg: `Failed '${options.method}' database method, retrying after ${duration} milliseconds`,
+          msg: `Failed '${options.method}' database method, retrying after ${duration} milliseconds (id=${id})`,
           error,
         });
         await wait(duration);
+      } finally {
+        if (this.includeTraceLogs) {
+          this.common.logger.trace({
+            service: this.name,
+            msg: `Completed '${options.method}' database method in ${Math.round(endClock())}ms (id=${id})`,
+          });
+        }
       }
     }
   };