Different query duration in error and query events

[vladshcherbin]

Hi 👋

I'm logging queries using log property and when there's an error I can see two logs, first for error event, second for query event.

They have different queryDurationMillis. Does it mean the query is executed twice or what's the reasoning for that?

Example:

import { CamelCasePlugin, Kysely, PostgresDialect } from 'kysely'
import pg from 'pg'
import environment from './modules/environment.js'
import type { Database } from './types/database.d.js'

const database = new Kysely<Database>({
  dialect: new PostgresDialect({
    pool: new pg.Pool({
      database: environment.DATABASE_NAME,
      host: environment.DATABASE_HOST,
      password: environment.DATABASE_PASSWORD,
      port: environment.DATABASE_PORT,
      user: environment.DATABASE_USER
    })
  }),
  log: (event) => {
    console.log(event.level)
    console.log(event.query.sql)
    console.log(event.queryDurationMillis)
  },
  plugins: [
    new CamelCasePlugin()
  ]
})

try {
  await database.selectFrom('brands').where('nonExistentColumn', '=', 1).execute()
} catch (error) {
  // do nothing
} finally {
  await database.destroy()
}

Output:

kysely - 0.26.3 pg - 8.11.3 node - 20.8.0

[vladshcherbin]

Found the reason from some other issue in codebase:

https://github.com/kysely-org/kysely/blob/0.26.3/src/driver/runtime-driver.ts#L122-L129

It and code below explain why it's logged twice with different duration.

Should it be different though? It's the same one query and its duration should remain the same 🤔

[koskimas]

The double logging is clearly a bug. Thanks for letting us know!

I'm guessing the difference in time mostly comes from the actual logging. Writing the first log line to stdout takes that extra 0.5ms.

[vladshcherbin]

yep, from driver codebase - when error is thrown, catch block logs 'error' log with calculated duration and then finally block logs 'query' log with re-calculated duration at that time.

This explains double log, why error log comes before query log and why duration differs in current implementation.

[vladshcherbin]

as a fix, maybe 'query' logging can be moved from finally block to try block - this would potentially remove double logging