feat(logger): format logs and errors like ponder

packages/typewriter/simulation-test/clock.ts

@@ -51,7 +51,7 @@ export function makeSimClock(
       });
     });
 
-  const nanos = () => BigInt(now) * 1_000_000n;
+  const nanos = () => BigInt(Math.round(now * 1_000_000));
 
   return {
     currentTimeMillisUnsafe: () => now,

packages/typewriter/simulation-test/index.ts

@@ -9,7 +9,7 @@ import {
   Exit,
   FiberSet,
   Layer,
-  type LogLevel,
+  Logger,
   Option,
   Random,
   Scope,
@@ -20,7 +20,7 @@ import { KeyType } from "../src/client";
 import type { TypewriterManifest } from "../src/config";
 import { Database, makeDb } from "../src/db";
 import { encodeEnqueueCalldata } from "../src/encoding";
-import { loggerLayer } from "../src/logger";
+import { logger, loggerLayer } from "../src/logger";
 import { layerRpc } from "../src/rpc";
 import { loadSolidityTypewriterApp } from "../src/sol-parse";
 import { createTypewriterEffect, type ProgramError } from "../src/typewriter";
@@ -201,12 +201,6 @@ const CLIENT = "0x70997970C51812dc3A010C7d01b50e0d17dc79C8";
  */
 const ENQUEUE_GAS = Hex.fromNumber(1_000_000);
 
-/**
- * Logs a lifecycle event of the run. `None` is the one level that no minimum
- * level filters out, so these print at every `TYPEWRITER_LOG_LEVEL`.
- */
-const logSim = Effect.logWithLevel("None" as LogLevel.Severity);
-
 /**
  * A database of its own for the run. It is dropped when the run passes, and
  * kept for inspection when it fails or is interrupted.
@@ -232,12 +226,12 @@ const makeDatabase = Effect.acquireRelease(
           await admin.close();
         }).pipe(
           Effect.andThen(
-            logSim("dropped database").pipe(
+            Effect.logInfo("Dropped simulation database").pipe(
               Effect.annotateLogs({ database: name }),
             ),
           ),
         )
-      : logSim("kept database").pipe(
+      : Effect.logInfo("Kept simulation database").pipe(
           Effect.annotateLogs({
             database: name,
             seed: SIM.seed,
@@ -248,17 +242,17 @@ const makeDatabase = Effect.acquireRelease(
 );
 
 const program = Effect.gen(function* () {
-  yield* logSim("starting simulation").pipe(
+  yield* Effect.logInfo("Started simulation").pipe(
     Effect.annotateLogs({ seed: SIM.seed, config: SIM }),
   );
   const chain = yield* makeChain();
   const address = yield* deploy({ chain, deployer: SCHEDULER.address });
   const chainId = Number(yield* chain.request({ method: "eth_chainId" }));
-  yield* logSim("deployed contract").pipe(
-    Effect.annotateLogs({ address, chainId }),
+  yield* Effect.logInfo("Deployed simulation contract").pipe(
+    Effect.annotateLogs({ address, chain_id: chainId }),
   );
   const database = yield* makeDatabase;
-  yield* logSim("created database").pipe(
+  yield* Effect.logInfo("Created simulation database").pipe(
     Effect.annotateLogs({ database: database.name }),
   );
   const app = yield* Effect.promise(() =>
@@ -474,9 +468,12 @@ const program = Effect.gen(function* () {
     Effect.provide(
       Layer.effect(Random.Random, makeRandom(SIM.seed, "runtime")),
     ),
+    // `TYPEWRITER_LOG_LEVEL` applies to the runtime only. The run's own logs
+    // print at every level.
+    Effect.provide(loggerLayer),
   );
 
-  yield* logSim("running world").pipe(
+  yield* Effect.logInfo("Started simulation world").pipe(
     Effect.annotateLogs({
       accounts: signers.length,
       steps: plan.length,
@@ -511,11 +508,11 @@ const program = Effect.gen(function* () {
     clock.advanceTo(next);
   }
   const typewriter = yield* exit;
-  yield* logSim("settled mutations").pipe(
+  yield* Effect.logInfo("Settled simulation mutations").pipe(
     Effect.annotateLogs({
       mutations,
-      virtualMs: clock.currentTimeMillisUnsafe() - startMs,
-      wallMs: Math.round(performance.now() - wallStart),
+      virtual_ms: Math.round(clock.currentTimeMillisUnsafe() - startMs),
+      wall_ms: Math.round(performance.now() - wallStart),
     }),
   );
 
@@ -533,21 +530,22 @@ const program = Effect.gen(function* () {
     ordering: SIM.typewriter.ordering,
   });
 
-  yield* logSim("validated run").pipe(
+  yield* Effect.logInfo("Validated simulation run").pipe(
     Effect.annotateLogs({
       mutations,
       blocks: blockEvents.length,
       batches: batchEvents.length,
-      wallMs: Math.round(performance.now() - wallStart),
+      wall_ms: Math.round(performance.now() - wallStart),
     }),
   );
 });
 
 BunRuntime.runMain(
   program.pipe(
+    Effect.tapCause((cause) => Effect.logError("Failed simulation", cause)),
     Effect.scoped,
-    Effect.annotateLogs({ category: "sim" }),
-    Effect.provide(loggerLayer),
+    Effect.provide(Logger.layer([logger])),
     Effect.provide(BunServices.layer),
   ),
+  { disableErrorReporting: true },
 );

packages/typewriter/src/config.ts

@@ -1,5 +1,6 @@
 import type { AbiParameterToPrimitiveType } from "abitype";
 import type { PgTable } from "drizzle-orm/pg-core";
+import { Data } from "effect";
 import type { Address } from "ox";
 import type { StorageLayout } from "storage-layout";
 import type { Abi, AbiParameter, PrivateKeyAccount } from "viem";
@@ -15,6 +16,12 @@ import {
   FIRST_BUILTIN_MUTATION_ID,
 } from "./typewriter-constants";
 
+/** An invalid typewriter config or Solidity entrypoint. */
+export class ConfigError extends Data.TaggedError("ConfigError")<{
+  message: string;
+  cause?: unknown;
+}> {}
+
 export type StorageConfig = StorageLayout;
 export type MutationConfig = {
   params: readonly AbiParameter[];
@@ -129,13 +136,15 @@ function assertSafeNonNegativeInteger(
 ): void {
   if (value === undefined) return;
   if (!Number.isSafeInteger(value) || value < 0) {
-    throw new Error(`${name} must be a safe non-negative integer`);
+    throw new ConfigError({
+      message: `${name} must be a safe non-negative integer`,
+    });
   }
 }
 
 export function validateConfig(config: TypewriterConfig): void {
   if (Array.isArray(config.rpcUrl) && config.rpcUrl.length === 0) {
-    throw new Error("At least one RPC URL is required");
+    throw new ConfigError({ message: "At least one RPC URL is required" });
   }
 
   assertSafeNonNegativeInteger(
@@ -152,15 +161,15 @@ export function validateConfig(config: TypewriterConfig): void {
     config.sequencing !== undefined && "batchOrder" in config.sequencing;
 
   if (config.sequencing?.order === "batch" && hasBatchOrder === false) {
-    throw new Error(
-      "config.sequencing.batchOrder is required for batch ordering",
-    );
+    throw new ConfigError({
+      message: "config.sequencing.batchOrder is required for batch ordering",
+    });
   }
 
   if (config.sequencing?.order === "fifo" && hasBatchOrder) {
-    throw new Error(
-      "config.sequencing.batchOrder is only valid for batch ordering",
-    );
+    throw new ConfigError({
+      message: "config.sequencing.batchOrder is only valid for batch ordering",
+    });
   }
 }
 
@@ -174,28 +183,32 @@ function validateMutationDefinitions(mutations: {
       mutation.id < 0 ||
       mutation.id > 255
     ) {
-      throw new Error(`mutation ID must be a uint8: ${mutation.id}`);
+      throw new ConfigError({
+        message: `Mutation ${name} has ID ${mutation.id}; mutation IDs must be uint8s`,
+      });
     }
     if (mutationIDs.has(mutation.id)) {
-      throw new Error(`duplicate mutation ID: ${mutation.id}`);
+      throw new ConfigError({
+        message: `Mutation ${name} reuses mutation ID ${mutation.id}`,
+      });
     }
     if (
       !Object.hasOwn(BUILTIN_MUTATIONS, name) &&
       mutation.id >= FIRST_BUILTIN_MUTATION_ID
     ) {
-      throw new Error(
-        `app mutation ID must be below ${FIRST_BUILTIN_MUTATION_ID}: ${name}=${mutation.id}`,
-      );
+      throw new ConfigError({
+        message: `Mutation ${name} has reserved mutation ID ${mutation.id}; app mutation IDs must be below ${FIRST_BUILTIN_MUTATION_ID}`,
+      });
     }
     mutationIDs.add(mutation.id);
   }
 
   for (const [name, builtin] of Object.entries(BUILTIN_MUTATIONS)) {
     const mutation = mutations[name];
     if (mutation === undefined || mutation.id !== builtin.id) {
-      throw new Error(
-        `missing built-in mutation ${name} with ID ${builtin.id}`,
-      );
+      throw new ConfigError({
+        message: `Could not find built-in mutation ${name} with ID ${builtin.id}`,
+      });
     }
   }
 }
@@ -217,9 +230,9 @@ export function createTypewriterApp(params: {
 
   const schemaName = `typewriter_${deploymentKey(config.chainId, config.address)}`;
   if (schemaName.length > MAX_IDENTIFIER_LENGTH) {
-    throw new Error(
-      `config.chainId is too long for the Postgres schema name: ${schemaName}`,
-    );
+    throw new ConfigError({
+      message: `config.chainId is too long for the Postgres schema name: ${schemaName}`,
+    });
   }
   const confirmations = {
     finalizedBlockDepth:

packages/typewriter/src/db.ts

@@ -62,7 +62,12 @@ export class DbError extends Data.TaggedError("DbError")<{
   cause: unknown;
   /** Set when the work is known to have not applied, so a retry is safe. */
   notApplied?: boolean;
-}> {}
+}> {
+  override get message() {
+    const sql = this.sql.replaceAll(/\s+/g, " ").trim();
+    return `Failed database query: ${sql.length > 120 ? `${sql.slice(0, 120)}...` : sql}`;
+  }
+}
 
 const dialect = new PgDialect();
 

packages/typewriter/src/index.ts

@@ -1,4 +1,4 @@
-import { Effect, Exit, Layer, Scope } from "effect";
+import { Cause, Effect, Exit, Layer, Scope } from "effect";
 import type {
   MutationConfig,
   MutationsConfig,
@@ -7,6 +7,7 @@ import type {
   TypewriterConfig,
 } from "./config";
 import { layerDatabase } from "./db";
+import { loggerLayer } from "./logger";
 import { layerRpc } from "./rpc";
 import { makeHttpTransport } from "./rpc-transport";
 import {
@@ -96,6 +97,15 @@ export {
   type WatchError,
 } from "./watch";
 
+/**
+ * Logs `cause` and exits the process. A typewriter that failed to start or
+ * stopped can't accept mutations, so it crashes rather than serve stale state.
+ */
+function exit(msg: string, cause: Cause.Cause<unknown>): never {
+  Effect.runSync(Effect.logError(msg, cause).pipe(Effect.provide(loggerLayer)));
+  process.exit(1);
+}
+
 type EntrypointMetadata<entrypoint> =
   entrypoint extends TypewriterSolidityEntrypoint<infer metadata>
     ? metadata
@@ -134,17 +144,20 @@ export async function createTypewriter<
     sequencingConfig
   >;
 
-  const app = await loadSolidityTypewriterApp(entrypoint, config);
+  const app = await loadSolidityTypewriterApp(entrypoint, config).catch(
+    (error: unknown) => exit("Failed to start typewriter", Cause.fail(error)),
+  );
   // TODO(kyle) expose a way to close the scope. Until then the typewriter
   // runs until the process exits.
   const scope = Effect.runSync(Scope.make());
 
   try {
-    const typewriter = await Effect.runPromise(
+    const { typewriter, services } = await Effect.runPromise(
       Effect.gen(function* () {
         const [rpcUrl, ...rpcUrls] = app.rpcUrls;
         const services = yield* Layer.buildWithScope(
-          Layer.merge(
+          Layer.mergeAll(
+            loggerLayer,
             layerRpc([
               makeHttpTransport(rpcUrl),
               ...rpcUrls.map(makeHttpTransport),
@@ -162,24 +175,24 @@ export async function createTypewriter<
           Effect.provideService(Scope.Scope, scope),
         );
         yield* typewriter.program.pipe(
-          // A failed program can't accept mutations. Crash the process rather
-          // than serve stale state.
-          Effect.tapError((error) =>
-            Effect.sync(() =>
-              queueMicrotask(() => {
-                throw error;
-              }),
-            ),
+          Effect.provide(services),
+          Effect.tapCause((cause) =>
+            Cause.hasInterruptsOnly(cause)
+              ? Effect.void
+              : Effect.sync(() => exit("Stopped typewriter", cause)),
           ),
           Effect.forkIn(scope),
         );
-        return typewriter;
+        return { typewriter, services };
       }),
     );
 
     const execute = ((
       submitted: TypewriterMutationInput<EntrypointMutationsConfig<entrypoint>>,
-    ) => Effect.runPromise(typewriter.execute(submitted))) as Result["execute"];
+    ) =>
+      Effect.runPromise(
+        typewriter.execute(submitted).pipe(Effect.provide(services)),
+      )) as Result["execute"];
 
     const on = ((
       event: "mutation" | "batch" | "block",
@@ -206,6 +219,6 @@ export async function createTypewriter<
     } as Result;
   } catch (error) {
     await Effect.runPromise(Scope.close(scope, Exit.void));
-    throw error;
+    exit("Failed to start typewriter", Cause.fail(error));
   }
 }