diff --git a/src/driver/runtime-driver.ts b/src/driver/runtime-driver.ts index fc4e852f7..eaa71434e 100644 --- a/src/driver/runtime-driver.ts +++ b/src/driver/runtime-driver.ts @@ -117,15 +117,19 @@ export class RuntimeDriver implements Driver { connection.executeQuery = async ( compiledQuery ): Promise> => { + let caughtError: unknown const startTime = performanceNow() try { return await executeQuery.call(connection, compiledQuery) } catch (error) { + caughtError = error await this.#logError(error, compiledQuery, startTime) throw error } finally { - await this.#logQuery(compiledQuery, startTime) + if (!caughtError) { + await this.#logQuery(compiledQuery, startTime) + } } } } diff --git a/src/util/log.ts b/src/util/log.ts index 8191e3cfd..129e00cfb 100644 --- a/src/util/log.ts +++ b/src/util/log.ts @@ -72,7 +72,13 @@ function defaultLogger(event: LogEvent): void { if (event.error instanceof Error) { console.error(`kysely:error: ${event.error.stack ?? event.error.message}`) } else { - console.error(`kysely:error: ${event}`) + console.error( + `kysely:error: ${JSON.stringify({ + error: event.error, + query: event.query.sql, + queryDurationMillis: event.queryDurationMillis, + })}` + ) } } } diff --git a/test/node/src/log-once.test.ts b/test/node/src/log-once.test.ts index e2d7c61c7..76e7d9508 100644 --- a/test/node/src/log-once.test.ts +++ b/test/node/src/log-once.test.ts @@ -7,7 +7,11 @@ describe('logOnce', () => { const sandbox = createSandbox() before(() => { - logSpy = sandbox.spy(console, 'log') + logSpy = sandbox.stub(console, 'log') + }) + + after(() => { + sandbox.restore() }) it('should log each message once.', () => { diff --git a/test/node/src/logging.test.ts b/test/node/src/logging.test.ts new file mode 100644 index 000000000..13d877c49 --- /dev/null +++ b/test/node/src/logging.test.ts @@ -0,0 +1,183 @@ +import { SinonSandbox, SinonSpy, createSandbox } from 'sinon' +import { Database, expect } from './test-setup' +import { + DatabaseConnection, + Driver, + DummyDriver, + Kysely, + LogConfig, + PostgresDialect, +} from '../../..' + +describe('logging', () => { + let sandbox: SinonSandbox + let errorSpy: SinonSpy + let logSpy: SinonSpy + + beforeEach(() => { + sandbox = createSandbox() + errorSpy = sandbox.stub(console, 'error') + logSpy = sandbox.stub(console, 'log') + }) + + afterEach(() => { + sandbox.restore() + }) + + describe('when query execution succeeds', () => { + describe('when query logging is disabled', () => { + describe('when error logging is disabled', () => { + const db = getKysely([]) + + it('should not log query', async () => { + await run(db) + expect(logSpy.called).to.be.false + }) + + it('should not log error', async () => { + await run(db) + expect(errorSpy.called).to.be.false + }) + }) + + describe('when error logging is enabled', () => { + const db = getKysely(['error']) + + it('should not log query', async () => { + await run(db) + expect(logSpy.called).to.be.false + }) + + it('should not log error', async () => { + await run(db) + expect(errorSpy.called).to.be.false + }) + }) + }) + + describe('when query logging is enabled', () => { + describe('when error logging is disabled', () => { + const db = getKysely(['query']) + + it('should log query', async () => { + await run(db) + expect(logSpy.called).to.be.true + }) + + it('should not log error', async () => { + await run(db) + expect(errorSpy.called).to.be.false + }) + }) + + describe('when error logging is enabled', () => { + const db = getKysely(['query', 'error']) + + it('should log query', async () => { + await run(db) + expect(logSpy.called).to.be.true + }) + + it('should not log error', async () => { + await run(db) + expect(errorSpy.called).to.be.false + }) + }) + }) + }) + + describe('when query execution fails', () => { + const executeQuery = () => Promise.reject('oops') + + describe('when query logging is disabled', () => { + describe('when error logging is disabled', () => { + const db = getKysely([], executeQuery) + + it('should not log query', async () => { + await run(db) + expect(logSpy.called).to.be.false + }) + + it('should not log error', async () => { + await run(db) + expect(errorSpy.called).to.be.false + }) + }) + + describe('when error logging is enabled', () => { + const db = getKysely(['error'], executeQuery) + + it('should not log query', async () => { + await run(db) + expect(logSpy.called).to.be.false + }) + + it('should log error', async () => { + await run(db) + expect(errorSpy.called).to.be.true + }) + }) + }) + + describe('when query logging is enabled', () => { + describe('when error logging is disabled', () => { + const db = getKysely(['query'], executeQuery) + + it('should not log query', async () => { + await run(db) + expect(logSpy.called).to.be.false + }) + + it('should not log error', async () => { + await run(db) + expect(errorSpy.called).to.be.false + }) + }) + + describe('when error logging is enabled', () => { + const db = getKysely(['query', 'error'], executeQuery) + + it('should not log query', async () => { + await run(db) + expect(logSpy.called).to.be.false + }) + + it('should log error', async () => { + await run(db) + expect(errorSpy.called).to.be.true + }) + }) + }) + }) +}) + +function getKysely( + log: LogConfig, + executeQuery: DatabaseConnection['executeQuery'] = () => + Promise.resolve({ rows: [] }) +): Kysely { + return new Kysely({ + dialect: new (class extends PostgresDialect { + constructor() { + super({ pool: {} as any }) + } + createDriver(): Driver { + return new (class extends DummyDriver { + acquireConnection(): Promise { + return Promise.resolve({ + executeQuery, + streamQuery: (async () => {}) as any, + }) + } + })() + } + })(), + log, + }) +} + +async function run(db: Kysely) { + try { + await db.selectFrom('person').selectAll().execute() + } catch (err) {} +}