Better debugging for the ORM [WIP]

[L-Mario564]

Addresses #376, #1957, #2414 & #2605.

This PR is WIP
Didn't mark it as draft as I'd like feedback on the API/implementation details for the work currently done before applying the same changes to other drivers and dialects.

This PR aims to implement improvements for the debugging experience, mainly improving error handling and logging.

Driver-agnostic errors
Previously, the way to handle query-related errors was dependent on the driver you used. Not the worst, but not the best. The shape of the error can be different depending on the driver and a lot of them don't have any way of identifying a query error (just thrown as a generic Error) and don't have type safety. We aim to improve this:

const users = pgTable('users', {
  id: serial().primaryKey(),
  email: text().unique()
});

await db.insert(users).values({ email: '[email protected]' });

try {
  await db.insert(users).values({ email: '[email protected]' });
} catch (err) {
  // Determines if it's a postgres unique constraint violation error
  if (is(err, PgError) && err.code === ERROR.INTEGRITY_CONSTRAINT_VIOLATION.UNIQUE_VIOLATION) {
    return error(400, 'email already exists')
  } else {
    // Some other kind of error...
  }
}

Errors are now only dependent on the dialect you're using and are type safe. This only handles query-related errors though, other errors like connection issues will still come from the driver and/or DB provider.

Here's another example using the getColumnNames method provided by Drizzle:

const posts = pgTable('posts', {
  id: serial().primaryKey(),
  slug: text().unique(),
  title: text(),
  userId: integer().notNull().references(() => users.id)
}, (t) => [
  unique('...').on(t.title, t.userId)
]);

try {
  await db.insert(posts).values(...);
} catch (err) {
  if (is(err, PgError) && err.code === ERROR.INTEGRITY_CONSTRAINT_VIOLATION.UNIQUE_VIOLATION) {
    const columns = err.getColumnNames();
    
    if (err.columnName === 'slug') {
      return error(400, 'slug already in use');
    } else if (columns[0] === 'title' && columns[1] === 'user_id' {
      return error(400, 'title already used by this user';
    } else {
      // Some other unique constraint violation...
    }
  }
}

More customization for TransactionRollbackError

try {
  await db.transaction(async (tx) => {
    await tx.insert(users).values({ balance: 100 });
    tx.rollback('custom message', { id: 'insert-user-tx' });
  });
} catch (err) {
  if (is(err, TransactionRollbackError)) {
    console.log(err.message); // Rollback: custom message;
    console.log(err.details); // { id: 'insert-user-tx' }
  }
}

Improved logging

Example 1: Query fails

await db.execute(sql`selec 1`).catch(() => {});
await db.execute(sql`select 1`);

Logs:

Failed query [166ms]: selec 1
Query [170ms]: select 1

Example 2: Query execution time for each operation

await db.select().from(User);
await db.insert(User).values({ name: 'Jon' });
await db.update(User).set({ name: 'John' }).where(eq(User.id, 1));
await db.delete(User).where(eq(User.id, 1));

Logs:

Query [173ms]: select "id", "name" from "user"
Query [338ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["Jon"]
Query [334ms]: update "user" set "name" = $1 where "user"."id" = $2 -- params: ["John", 1]
Query [341ms]: delete from "user" where "user"."id" = $1 -- params: [1]

Example 3: Better transaction logging. Includes where it begins, end and how long it took. Each query in a transaction can be identified by a randomly generated id/name.

await db.transaction(async (tx) => {
  await tx.insert(User).values({ name: 'Jane' });
});

Logs:

Begin transaction d46b
Query in transaction d46b [345ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["Jane"]
Commit transaction d46b [680ms]

Example 4: Specifying a name for the logs

await db.transaction(async (tx) => {
  await tx.insert(User).values({ name: 'Jane' });
}, {
  name: 'insert-user-tx'
});

Logs:

Begin transaction insert-user-tx
Query in transaction insert-user-tx [345ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["Jane"]
Commit transaction insert-user-tx [680ms]

Example 5: Rollback transaction

await db.transaction(async (tx) => {
  await tx.insert(User).values({ name: 'Jane' });
  tx.rollback();
}).catch(() => {});

Logs:

Begin transaction dce9
Query in transaction dce9 [334ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["Jane"]
Rollback transaction dce9 [675ms]

Example 6: Error inside transaction

await db.transaction(async (tx) => {
  await tx.insert(User).values({ name: 'Jane' });
  throw new Error('whoops!');
}).catch(() => {});

Logs:

Begin transaction 851b
Query in transaction 851b [333ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["Jane"]
Failed transaction 851b [681ms]

Example 7: Nested transactions

await db.transaction(async (tx) => {
  await tx.insert(User).values({ name: 'John' });
  
  await tx.transaction(async (tx) => {
    await tx.insert(User).values({ name: 'Jane' });
  }, {
    name: 'insert-jane-tx'
  });
}, {
  name: 'insert-john-tx'
});

Logs:

Begin transaction insert-john-tx
Query in transaction insert-john-tx [338ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["John"]
Begin savepoint insert-jane-tx
Query in savepoint insert-jane-tx [346ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["Jane"]
Commit savepoint insert-jane-tx [515ms]
Commit transaction insert-john-tx [1201ms]

With all of these changes, there's also more methods you can implement in your logger:

logQuery(
  query: string,
  params: unknown[],
  duration: number, // Query time execution
  failed: boolean, // If it errored
  transaction?: { // If the query was executed within a transaction
    name: string;
    type: 'transaction' | 'savepoint';
  } | undefined
)

logTransactionBegin(name: string, type: 'transaction' | 'savepoint')

logTransactionEnd(
  name: string,
  type: 'transaction' | 'savepoint',
  duration: number; // Total time to execute transaction
  status: 'commit' | 'rollback' | 'error';
)

Todo:

• Log iterator queries.
• Currently the error handling is only available for postgres.js driver, have to implement it for the rest of the drivers and dialects.

[AlexBlokh]

I think errors should definitely be instanceof-able

try {
 const res = await db.select().from(users);
} catch(e) {
 if(e instanceof DrizzleErr) {
   ...
 }
 e.printStackTrace(); // is it java?
 console.error(e);
}

[AlexBlokh]

I also think we should wrap both execution and connection/io level errors, by providing original error into cause property of a wrapper error

this way we can have a typed error which will let developers handle errors exhaustively on type level

} catch(e) {
 if(e instanceof DrizzleError){
  if(e.type === "io") { ... }
  if(e.type === "sql") { ... }

  assertUnreachable(e.type); // future proof, will show a type level error if we extend subset of errors. Opt-in for everybody
 }
 console.error(e);
}

[AlexBlokh]

regarding profiling - there's an outstanding issues which Dan abandoned ~2 years ago and it's OpenTelemetry integration/compatibility, which we should potentially discuss and design before going into:

Query [173ms]: select "id", "name" from "user"
Query [338ms]: insert into "user" ("id", "name") values (default, $1) -- params: ["Jon"]
Query [334ms]: update "user" set "name" = $1 where "user"."id" = $2 -- params: ["John", 1]
Query [341ms]: delete from "user" where "user"."id" = $1 -- params: [1]

[L-Mario564]

@AlexBlokh

I think errors should definitely be instanceof-able

This is already possible, the examples use is since the Drizzle docs recommends comparing classes and their instances that way. but it should work perfectly fine with instanceof.

I also think we should wrap both execution and connection/io level errors, by providing original error into cause property of a wrapper error

This would be great to implement, but I haven't done so due to some drivers not providing the proper tools to distinguish between generic Errors and query/driver/connection errors to begin with.

postgres.js and @vercel/postgres do have their own custom error classes (PostgresError and VercelPostgresError respectively), but even those don't have any way to distinguish between connection errors and query errors. Other packages like @electric-sql/pglite and @neondatabase/serverless only throw the generic Error which make it even harder to distinguish that from runtime-specific errors (Node, Bun, Deno, etc.), driver specific errors, connection errors and query errors.

You can see how difficult it could be to categorize errors by looking at the source code of the drivers mentioned above:

• postgres.js: https://github.com/search?q=repo%3Aporsager%2Fpostgres%20throw&type=code
• @neondatabase/serverless: https://github.com/search?q=repo%3Aneondatabase%2Fserverless%20throw&type=code
• @electric-sql/pglite: https://github.com/search?q=repo%3Aelectric-sql%2Fpglite%20throw&type=code
• @vercel/postgres: https://github.com/search?q=repo%3Avercel%2Fstorage%20throw&type=code

regarding profiling - there's an outstanding issues which Dan abandoned ~2 years ago and it's OpenTelemetry integration/compatibility, which we should potentially discuss and design before going into:

I'm not too familiar working with OpenTelemetry, but from some brief research, an integration with it could be it's entirely separate package (like drizzle-open-telemetry or something like that). I think it would be another great addition, but not sure if it's within the scope of this PR. There's an open issue about OpenTelemetry support that I didn't mention here for that exact reason.

Also, I think we can still have query execution time in logs. I personally have a small app in prod that would benefit from having a simple metric to determine query performance while keeping its codebase simple and not add additional packages (like OpenTelemetry). I feel like for a lot of people getting started, this can be a way to easily measure query performance. Larger codebases and apps would of course require something like OpenTelemetry, but I don't think that means that we should remove the simple query time execution logs altogether.

An improvement I can definitely see is making it toggable, that way, you can avoid the tiny bit of overhead added by performance.now between queries:

const db = drizzle('...', { logger: true, queryExecutionTime: false });

await db.select().from(users);
// Query: select * from "users"

const db = drizzle('...', { logger: true, queryExecutionTime: true });

await db.select().from(users);
// Query [250ms]: select * from "users"