From 55c013fe2d053848ba1cb75bb6ddb0cd852c8f5e Mon Sep 17 00:00:00 2001 From: igalklebanov Date: Mon, 4 Dec 2023 23:38:01 +0200 Subject: [PATCH 1/4] deny logging query and error onerror. also deny catching custom log err. --- src/driver/runtime-driver.ts | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/src/driver/runtime-driver.ts b/src/driver/runtime-driver.ts index fc4e852f7..8c45ccd69 100644 --- a/src/driver/runtime-driver.ts +++ b/src/driver/runtime-driver.ts @@ -118,14 +118,18 @@ export class RuntimeDriver implements Driver { compiledQuery ): Promise> => { const startTime = performanceNow() + let caughtError: unknown 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) + } } } } From 8e5e8889482840a051801759f20981f05a1a8985 Mon Sep 17 00:00:00 2001 From: igalklebanov Date: Mon, 4 Dec 2023 23:52:47 +0200 Subject: [PATCH 2/4] move caughtError declaration so it doesn't take up "execution time". --- src/driver/runtime-driver.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/driver/runtime-driver.ts b/src/driver/runtime-driver.ts index 8c45ccd69..eaa71434e 100644 --- a/src/driver/runtime-driver.ts +++ b/src/driver/runtime-driver.ts @@ -117,8 +117,8 @@ export class RuntimeDriver implements Driver { connection.executeQuery = async ( compiledQuery ): Promise> => { - const startTime = performanceNow() let caughtError: unknown + const startTime = performanceNow() try { return await executeQuery.call(connection, compiledQuery) From 8259d75aea5213a0ab10ad8291907dc332ac56b4 Mon Sep 17 00:00:00 2001 From: igalklebanov Date: Tue, 5 Dec 2023 01:22:28 +0200 Subject: [PATCH 3/4] fix defaultLogger error handling when not Error. --- src/util/log.ts | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) 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, + })}` + ) } } } From 7bdd416bfe65c6b3f01011ee83896de17e17ec92 Mon Sep 17 00:00:00 2001 From: igalklebanov Date: Tue, 5 Dec 2023 01:22:48 +0200 Subject: [PATCH 4/4] test logging. --- test/node/src/log-once.test.ts | 6 +- test/node/src/logging.test.ts | 183 +++++++++++++++++++++++++++++++++ 2 files changed, 188 insertions(+), 1 deletion(-) create mode 100644 test/node/src/logging.test.ts 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) {} +}