From fa0638faae85cf819a1eba428d919adfc35ee087 Mon Sep 17 00:00:00 2001 From: Serge Klochkov Date: Thu, 9 May 2024 14:07:38 +0200 Subject: [PATCH 1/4] Remove unnecessary error logs from the ResultSet on close --- CHANGELOG.md | 10 ++++- packages/client-common/src/client.ts | 16 +++++++- packages/client-common/src/config.ts | 1 + .../client-common/src/error/parse_error.ts | 1 + packages/client-common/src/logger.ts | 14 +++---- .../__tests__/integration/node_exec.test.ts | 9 ++++- .../__tests__/unit/node_result_set.test.ts | 32 ++++++++-------- packages/client-node/src/config.ts | 9 ++++- packages/client-node/src/result_set.ts | 38 ++++++++++++++++--- 9 files changed, 98 insertions(+), 32 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d1bb445b..db2b79e4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,8 +1,16 @@ # 1.0.2 (Common, Node.js) +Node.js only. No changes in the Web version. + ## Bug fixes -- (Node.js only) The `command` method now drains the response stream properly, as the previous implementation could cause the Keep-Alive socket to close after each request. +- The `command` method now drains the response stream properly, as the previous implementation could cause the `Keep-Alive` socket to close after each request. +- Removed an unnecessary error log in the `ResultSet.stream` method if the request was aborted or the result set was closed. + +## Improvements + +- `ResultSet.stream` logs an error via the `Logger` instance, if the stream emits an error event instead of a simple `console.error` call. +- Minor adjustments to the `DefaultLogger` log messages formatting. # 1.0.1 (Common, Node.js, Web) diff --git a/packages/client-common/src/client.ts b/packages/client-common/src/client.ts index 2a8f6f88..8e6b85bb 100644 --- a/packages/client-common/src/client.ts +++ b/packages/client-common/src/client.ts @@ -4,6 +4,7 @@ import type { Connection, ConnExecResult, IsSame, + LogWriter, MakeResultSet, WithClickHouseSummary, } from '@clickhouse/client-common' @@ -116,6 +117,7 @@ export class ClickHouseClient { private readonly makeResultSet: MakeResultSet private readonly valuesEncoder: ValuesEncoder private readonly sessionId?: string + private readonly logWriter: LogWriter constructor( config: BaseClickHouseClientConfigOptions & ImplementationDetails, @@ -129,6 +131,7 @@ export class ClickHouseClient { config.impl.handle_specific_url_params ?? null, ) const connectionParams = getConnectionParams(configWithURL, logger) + this.logWriter = connectionParams.log_writer this.clientClickHouseSettings = connectionParams.clickhouse_settings this.sessionId = config.session_id this.connection = config.impl.make_connection( @@ -155,7 +158,18 @@ export class ClickHouseClient { query, ...this.withClientQueryParams(params), }) - return this.makeResultSet(stream, format, query_id) + return this.makeResultSet(stream, format, query_id, (err) => { + this.logWriter.error({ + err, + module: 'Client', + message: 'Error while processing the ResultSet.', + args: { + session_id: this.sessionId, + query, + query_id, + }, + }) + }) } /** diff --git a/packages/client-common/src/config.ts b/packages/client-common/src/config.ts index 17503c75..fa3ba9f7 100644 --- a/packages/client-common/src/config.ts +++ b/packages/client-common/src/config.ts @@ -90,6 +90,7 @@ export type MakeResultSet = < stream: Stream, format: Format, query_id: string, + log_error: (err: Error) => void, ) => ResultSet export interface ValuesEncoder { diff --git a/packages/client-common/src/error/parse_error.ts b/packages/client-common/src/error/parse_error.ts index ad692702..bf870557 100644 --- a/packages/client-common/src/error/parse_error.ts +++ b/packages/client-common/src/error/parse_error.ts @@ -1,5 +1,6 @@ const errorRe = /(Code|Error): (?\d+).*Exception: (?.+)\((?(?=.+[A-Z]{3})[A-Z0-9_]+?)\)/s + interface ParsedClickHouseError { message: string code: string diff --git a/packages/client-common/src/logger.ts b/packages/client-common/src/logger.ts index fdbfe2ce..93da94f6 100644 --- a/packages/client-common/src/logger.ts +++ b/packages/client-common/src/logger.ts @@ -20,7 +20,7 @@ export class DefaultLogger implements Logger { formatMessage({ module, message, level: 'TRACE' }), ] if (args) { - params.push('Arguments:', args) + params.push('\nArguments:', args) } console.debug(...params) } @@ -30,7 +30,7 @@ export class DefaultLogger implements Logger { formatMessage({ module, message, level: 'DEBUG' }), ] if (args) { - params.push('Arguments:', args) + params.push('\nArguments:', args) } console.debug(...params) } @@ -40,7 +40,7 @@ export class DefaultLogger implements Logger { formatMessage({ module, message, level: 'INFO' }), ] if (args) { - params.push('Arguments:', args) + params.push('\nArguments:', args) } console.info(...params) } @@ -50,10 +50,10 @@ export class DefaultLogger implements Logger { formatMessage({ module, message, level: 'WARN' }), ] if (args) { - params.push('Arguments:', args) + params.push('\nArguments:', args) } if (err) { - params.push('Caused by:', err) + params.push('\nCaused by:', err) } console.warn(...params) } @@ -63,9 +63,9 @@ export class DefaultLogger implements Logger { formatMessage({ module, message, level: 'ERROR' }), ] if (args) { - params.push('Arguments:', args) + params.push('\nArguments:', args) } - params.push('Caused by:', err) + params.push('\nCaused by:', err) console.error(...params) } } diff --git a/packages/client-node/__tests__/integration/node_exec.test.ts b/packages/client-node/__tests__/integration/node_exec.test.ts index 76ea9030..dcaeb722 100644 --- a/packages/client-node/__tests__/integration/node_exec.test.ts +++ b/packages/client-node/__tests__/integration/node_exec.test.ts @@ -54,7 +54,14 @@ describe('[Node.js] exec result streaming', () => { default_format: format, }, }) - const rs = new ResultSet(stream, format, query_id) + const rs = ResultSet.instance({ + stream, + format, + query_id, + log_error: (err) => { + console.error(err) + }, + }) expect(await rs.json()).toEqual([{ number: '0' }]) }) }) diff --git a/packages/client-node/__tests__/unit/node_result_set.test.ts b/packages/client-node/__tests__/unit/node_result_set.test.ts index a6b053e5..6b83e6a7 100644 --- a/packages/client-node/__tests__/unit/node_result_set.test.ts +++ b/packages/client-node/__tests__/unit/node_result_set.test.ts @@ -4,6 +4,10 @@ import Stream, { Readable } from 'stream' import { ResultSet } from '../../src' describe('[Node.js] ResultSet', () => { + const dataStream = Readable.from([ + Buffer.from('{"foo":"bar"}\n'), + Buffer.from('{"qaz":"qux"}\n'), + ]) const expectedText = `{"foo":"bar"}\n{"qaz":"qux"}\n` const expectedJson = [{ foo: 'bar' }, { qaz: 'qux' }] @@ -13,7 +17,7 @@ describe('[Node.js] ResultSet', () => { }) it('should consume the response as text only once', async () => { - const rs = makeResultSet() + const rs = makeResultSet(dataStream) expect(await rs.text()).toEqual(expectedText) await expectAsync(rs.text()).toBeRejectedWith(err) @@ -21,7 +25,7 @@ describe('[Node.js] ResultSet', () => { }) it('should consume the response as JSON only once', async () => { - const rs = makeResultSet() + const rs = makeResultSet(dataStream) expect(await rs.json()).toEqual(expectedJson) await expectAsync(rs.json()).toBeRejectedWith(err) @@ -29,7 +33,7 @@ describe('[Node.js] ResultSet', () => { }) it('should consume the response as a stream of Row instances', async () => { - const rs = makeResultSet() + const rs = makeResultSet(dataStream) const stream = rs.stream() expect(stream.readableEnded).toBeFalsy() @@ -50,10 +54,8 @@ describe('[Node.js] ResultSet', () => { }) it('should be able to call Row.text and Row.json multiple times', async () => { - const rs = new ResultSet( + const rs = makeResultSet( Stream.Readable.from([Buffer.from('{"foo":"bar"}\n')]), - 'JSONEachRow', - guid(), ) const allRows: Row[] = [] for await (const rows of rs.stream()) { @@ -67,14 +69,14 @@ describe('[Node.js] ResultSet', () => { expect(row.json()).toEqual({ foo: 'bar' }) }) - function makeResultSet() { - return new ResultSet( - Readable.from([ - Buffer.from('{"foo":"bar"}\n'), - Buffer.from('{"qaz":"qux"}\n'), - ]), - 'JSONEachRow', - guid(), - ) + function makeResultSet(stream: Stream.Readable) { + return ResultSet.instance({ + stream, + format: 'JSONEachRow', + query_id: guid(), + log_error: (err) => { + console.error(err) + }, + }) } }) diff --git a/packages/client-node/src/config.ts b/packages/client-node/src/config.ts index c4504ff7..bf714d7c 100644 --- a/packages/client-node/src/config.ts +++ b/packages/client-node/src/config.ts @@ -102,5 +102,12 @@ export const NodeConfigImpl: Required< stream: Stream.Readable, format: DataFormat, query_id: string, - ) => new ResultSet(stream, format, query_id)) as any, + log_error: (err: Error) => void, + ) => + ResultSet.instance({ + stream, + format, + query_id, + log_error, + })) as any, } diff --git a/packages/client-node/src/result_set.ts b/packages/client-node/src/result_set.ts index d0458cd9..fb188fca 100644 --- a/packages/client-node/src/result_set.ts +++ b/packages/client-node/src/result_set.ts @@ -38,14 +38,27 @@ export type StreamReadable = Omit & { ): Stream.Readable } +export interface ResultSetOptions { + stream: Stream.Readable + format: Format + query_id: string + log_error: (error: Error) => void +} + export class ResultSet implements BaseResultSet { + private readonly log_error: (error: Error) => void + constructor( private _stream: Stream.Readable, private readonly format: Format, public readonly query_id: string, - ) {} + log_error?: (error: Error) => void, + ) { + // eslint-disable-next-line no-console + this.log_error = log_error ?? ((err: Error) => console.error(err)) + } /** See {@link BaseResultSet.text}. */ async text(): Promise { @@ -96,6 +109,7 @@ export class ResultSet validateStreamFormat(this.format) let incompleteChunks: Buffer[] = [] + const logError = this.log_error const toRows = new Transform({ transform( chunk: Buffer, @@ -157,10 +171,12 @@ export class ResultSet this._stream, toRows, function pipelineCb(err) { - if (err) { - // FIXME: use logger instead - // eslint-disable-next-line no-console - console.error(err) + if ( + err && + err.name !== 'AbortError' && + err.message !== resultSetClosedMessage + ) { + logError(err) } }, ) @@ -168,8 +184,18 @@ export class ResultSet } close() { - this._stream.destroy() + this._stream.destroy(new Error(resultSetClosedMessage)) + } + + static instance({ + stream, + format, + query_id, + log_error, + }: ResultSetOptions): ResultSet { + return new ResultSet(stream, format, query_id, log_error) } } const streamAlreadyConsumedMessage = 'Stream has been already consumed' +const resultSetClosedMessage = 'ResultSet has been closed' From 5d0e51cb863bf41dfb68bb41864fef68c3cefc52 Mon Sep 17 00:00:00 2001 From: Serge Klochkov Date: Thu, 9 May 2024 14:16:31 +0200 Subject: [PATCH 2/4] Fix tests --- .../__tests__/unit/node_result_set.test.ts | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/packages/client-node/__tests__/unit/node_result_set.test.ts b/packages/client-node/__tests__/unit/node_result_set.test.ts index 6b83e6a7..c4e1d164 100644 --- a/packages/client-node/__tests__/unit/node_result_set.test.ts +++ b/packages/client-node/__tests__/unit/node_result_set.test.ts @@ -4,10 +4,6 @@ import Stream, { Readable } from 'stream' import { ResultSet } from '../../src' describe('[Node.js] ResultSet', () => { - const dataStream = Readable.from([ - Buffer.from('{"foo":"bar"}\n'), - Buffer.from('{"qaz":"qux"}\n'), - ]) const expectedText = `{"foo":"bar"}\n{"qaz":"qux"}\n` const expectedJson = [{ foo: 'bar' }, { qaz: 'qux' }] @@ -17,7 +13,7 @@ describe('[Node.js] ResultSet', () => { }) it('should consume the response as text only once', async () => { - const rs = makeResultSet(dataStream) + const rs = makeResultSet(getDataStream()) expect(await rs.text()).toEqual(expectedText) await expectAsync(rs.text()).toBeRejectedWith(err) @@ -25,17 +21,15 @@ describe('[Node.js] ResultSet', () => { }) it('should consume the response as JSON only once', async () => { - const rs = makeResultSet(dataStream) - + const rs = makeResultSet(getDataStream()) expect(await rs.json()).toEqual(expectedJson) await expectAsync(rs.json()).toBeRejectedWith(err) await expectAsync(rs.text()).toBeRejectedWith(err) }) it('should consume the response as a stream of Row instances', async () => { - const rs = makeResultSet(dataStream) + const rs = makeResultSet(getDataStream()) const stream = rs.stream() - expect(stream.readableEnded).toBeFalsy() const result: unknown[] = [] @@ -79,4 +73,11 @@ describe('[Node.js] ResultSet', () => { }, }) } + + function getDataStream() { + return Readable.from([ + Buffer.from('{"foo":"bar"}\n'), + Buffer.from('{"qaz":"qux"}\n'), + ]) + } }) From d9ea905a5b54207550c0c73f5b160a220f1449db Mon Sep 17 00:00:00 2001 From: slvrtrn Date: Fri, 17 May 2024 18:03:19 +0200 Subject: [PATCH 3/4] Rename logger tests --- .../integration/{node_logger.ts => node_logger_support.test.ts} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename packages/client-node/__tests__/integration/{node_logger.ts => node_logger_support.test.ts} (100%) diff --git a/packages/client-node/__tests__/integration/node_logger.ts b/packages/client-node/__tests__/integration/node_logger_support.test.ts similarity index 100% rename from packages/client-node/__tests__/integration/node_logger.ts rename to packages/client-node/__tests__/integration/node_logger_support.test.ts From 68f79474124e287c4aa3b9f4e0368770da3bf914 Mon Sep 17 00:00:00 2001 From: slvrtrn Date: Fri, 17 May 2024 18:54:51 +0200 Subject: [PATCH 4/4] Reorganize the logger tests --- .../integration/node_logger_support.test.ts | 44 ++-- .../unit/node_default_logger.test.ts | 198 +++++++++++++++++ .../__tests__/unit/node_logger.test.ts | 202 ------------------ 3 files changed, 218 insertions(+), 226 deletions(-) create mode 100644 packages/client-node/__tests__/unit/node_default_logger.test.ts delete mode 100644 packages/client-node/__tests__/unit/node_logger.test.ts diff --git a/packages/client-node/__tests__/integration/node_logger_support.test.ts b/packages/client-node/__tests__/integration/node_logger_support.test.ts index 0d037bea..4687128e 100644 --- a/packages/client-node/__tests__/integration/node_logger_support.test.ts +++ b/packages/client-node/__tests__/integration/node_logger_support.test.ts @@ -1,5 +1,6 @@ -import type { +import { ClickHouseClient, + ClickHouseLogLevel, ErrorLogParams, Logger, LogParams, @@ -20,29 +21,25 @@ describe('[Node.js] logger support', () => { }) describe('Logger support', () => { - const logLevelKey = 'CLICKHOUSE_LOG_LEVEL' - let defaultLogLevel: string | undefined - beforeEach(() => { - defaultLogLevel = process.env[logLevelKey] - }) - afterEach(() => { - if (defaultLogLevel === undefined) { - delete process.env[logLevelKey] - } else { - process.env[logLevelKey] = defaultLogLevel - } - }) - it('should use the default logger implementation', async () => { - process.env[logLevelKey] = 'DEBUG' - client = createTestClient() - const consoleSpy = spyOn(console, 'log') + const infoSpy = spyOn(console, 'info') + client = createTestClient({ + log: { + level: ClickHouseLogLevel.DEBUG, + }, + }) + expect(infoSpy).toHaveBeenCalledOnceWith( + jasmine.stringContaining('Log level is set to DEBUG'), + ) + + const debugSpy = spyOn(console, 'debug') await client.ping() - // logs[0] are about current log level - expect(consoleSpy).toHaveBeenCalledOnceWith( - jasmine.stringContaining('Got a response from ClickHouse'), + expect(debugSpy).toHaveBeenCalledOnceWith( + jasmine.stringContaining('Ping: got a response from ClickHouse'), + jasmine.stringContaining('\nArguments:'), jasmine.objectContaining({ request_headers: { + connection: jasmine.stringMatching(/Keep-Alive/i), 'user-agent': jasmine.any(String), }, request_method: 'GET', @@ -59,9 +56,9 @@ describe('[Node.js] logger support', () => { }) it('should provide a custom logger implementation', async () => { - process.env[logLevelKey] = 'DEBUG' client = createTestClient({ log: { + level: ClickHouseLogLevel.DEBUG, LoggerClass: TestLogger, }, }) @@ -69,7 +66,7 @@ describe('[Node.js] logger support', () => { // logs[0] are about current log level expect(logs[1]).toEqual( jasmine.objectContaining({ - message: 'Got a response from ClickHouse', + message: 'Ping: got a response from ClickHouse', args: jasmine.objectContaining({ request_path: '/ping', request_method: 'GET', @@ -79,10 +76,9 @@ describe('[Node.js] logger support', () => { }) it('should provide a custom logger implementation (but logs are disabled)', async () => { - process.env[logLevelKey] = 'OFF' client = createTestClient({ log: { - // enable: false, + // the default level is OFF LoggerClass: TestLogger, }, }) diff --git a/packages/client-node/__tests__/unit/node_default_logger.test.ts b/packages/client-node/__tests__/unit/node_default_logger.test.ts new file mode 100644 index 00000000..8f907c58 --- /dev/null +++ b/packages/client-node/__tests__/unit/node_default_logger.test.ts @@ -0,0 +1,198 @@ +import { + ClickHouseLogLevel, + DefaultLogger, + LogWriter, +} from '@clickhouse/client-common' + +describe('[Node.js] Logger/LogWriter', () => { + type LogLevel = 'TRACE' | 'DEBUG' | 'INFO' | 'WARN' | 'ERROR' + + const module = 'LoggerTest' + const message = 'very informative' + const err = new Error('boo') + + let debugSpy: jasmine.Spy + let infoSpy: jasmine.Spy + let warnSpy: jasmine.Spy + let errSpy: jasmine.Spy + + beforeEach(() => { + debugSpy = spyOn(console, 'debug') + infoSpy = spyOn(console, 'info') + warnSpy = spyOn(console, 'warn') + errSpy = spyOn(console, 'error') + }) + + it('should use OFF by default', async () => { + const logWriter = new LogWriter(new DefaultLogger(), module) + logEveryLogLevel(logWriter) + expect(debugSpy).toHaveBeenCalledTimes(0) + expect(infoSpy).toHaveBeenCalledTimes(0) + expect(warnSpy).toHaveBeenCalledTimes(0) + expect(errSpy).toHaveBeenCalledTimes(0) + }) + + it('should explicitly use TRACE', async () => { + const logWriter = new LogWriter( + new DefaultLogger(), + module, + ClickHouseLogLevel.TRACE, + ) + + checkLogLevelSet('TRACE') + logEveryLogLevel(logWriter) + + // TRACE + DEBUG + expect(debugSpy).toHaveBeenCalledTimes(2) + checkLog(debugSpy, 'TRACE', 0) + checkLog(debugSpy, 'DEBUG', 1) + + // + set log level call + expect(infoSpy).toHaveBeenCalledTimes(2) + checkLog(infoSpy, 'INFO', 1) + + expect(warnSpy).toHaveBeenCalledTimes(1) + checkLog(warnSpy, 'WARN') + + expect(errSpy).toHaveBeenCalledTimes(1) + checkErrorLog() + }) + + it('should explicitly use DEBUG', async () => { + const logWriter = new LogWriter( + new DefaultLogger(), + module, + ClickHouseLogLevel.DEBUG, + ) + + checkLogLevelSet('DEBUG') + logEveryLogLevel(logWriter) + + // No TRACE, only DEBUG + expect(debugSpy).toHaveBeenCalledTimes(1) + checkLog(debugSpy, 'DEBUG', 0) + + // + set log level call + expect(infoSpy).toHaveBeenCalledTimes(2) + checkLog(infoSpy, 'INFO', 1) + + expect(warnSpy).toHaveBeenCalledTimes(1) + checkLog(warnSpy, 'WARN') + + expect(errSpy).toHaveBeenCalledTimes(1) + checkErrorLog() + }) + + it('should explicitly use INFO', async () => { + const logWriter = new LogWriter( + new DefaultLogger(), + module, + ClickHouseLogLevel.INFO, + ) + + checkLogLevelSet('INFO') + logEveryLogLevel(logWriter) + + // No TRACE or DEBUG logs + expect(debugSpy).toHaveBeenCalledTimes(0) + + // + set log level call + expect(infoSpy).toHaveBeenCalledTimes(2) + checkLog(infoSpy, 'INFO', 1) + + expect(warnSpy).toHaveBeenCalledTimes(1) + checkLog(warnSpy, 'WARN') + + expect(errSpy).toHaveBeenCalledTimes(1) + checkErrorLog() + }) + + it('should explicitly use WARN', async () => { + const logWriter = new LogWriter( + new DefaultLogger(), + module, + ClickHouseLogLevel.WARN, + ) + + logEveryLogLevel(logWriter) + + // No TRACE, DEBUG, or INFO logs + expect(debugSpy).toHaveBeenCalledTimes(0) + expect(infoSpy).toHaveBeenCalledTimes(0) + + expect(warnSpy).toHaveBeenCalledTimes(1) + checkLog(warnSpy, 'WARN') + + expect(errSpy).toHaveBeenCalledTimes(1) + checkErrorLog() + }) + + it('should explicitly use WARN', async () => { + const logWriter = new LogWriter( + new DefaultLogger(), + module, + ClickHouseLogLevel.ERROR, + ) + + logEveryLogLevel(logWriter) + + // No TRACE, DEBUG, INFO, or WARN logs + expect(debugSpy).toHaveBeenCalledTimes(0) + expect(infoSpy).toHaveBeenCalledTimes(0) + expect(warnSpy).toHaveBeenCalledTimes(0) + + expect(errSpy).toHaveBeenCalledTimes(1) + checkErrorLog() + }) + + function checkLogLevelSet(level: LogLevel) { + expect(infoSpy.calls.first().args).toEqual([ + jasmine.stringContaining( + `[INFO][@clickhouse/client][${module}] Log level is set to ${level}`, + ), + ]) + expect(infoSpy).toHaveBeenCalledTimes(1) + } + + function checkLog(spy: jasmine.Spy, level: LogLevel, callNumber: number = 0) { + expect(spy.calls.all()[callNumber].args).toEqual([ + jasmine.stringContaining( + `[${level}][@clickhouse/client][${module}] ${message}`, + ), + jasmine.stringContaining('\nArguments:'), + { foo: `${level.toLowerCase()}-42` }, + ]) + } + + function checkErrorLog() { + expect(errSpy.calls.first().args).toEqual([ + jasmine.stringContaining( + `[ERROR][@clickhouse/client][${module}] ${message}`, + ), + jasmine.stringContaining('\nArguments:'), + { foo: 'err-42' }, + jasmine.stringContaining('\nCaused by:'), + err, + ]) + } + + function logEveryLogLevel(logWriter: LogWriter) { + for (const level of ['trace', 'debug', 'info', 'warn']) { + // eslint-disable-next-line @typescript-eslint/ban-ts-comment + // @ts-ignore + logWriter[level]({ + message, + args: { + foo: `${level}-42`, + }, + }) + } + logWriter.error({ + message, + err, + args: { + foo: 'err-42', + }, + }) + } +}) diff --git a/packages/client-node/__tests__/unit/node_logger.test.ts b/packages/client-node/__tests__/unit/node_logger.test.ts deleted file mode 100644 index c6d41402..00000000 --- a/packages/client-node/__tests__/unit/node_logger.test.ts +++ /dev/null @@ -1,202 +0,0 @@ -import type { - ErrorLogParams, - Logger, - LogParams, -} from '@clickhouse/client-common' -import { ClickHouseLogLevel, LogWriter } from '@clickhouse/client-common' - -describe('[Node.js] Logger/LogWriter', () => { - type LogLevel = 'trace' | 'debug' | 'info' | 'warn' | 'error' - - const module = 'LoggerTest' - const message = 'very informative' - const err = new Error('boo') - - let logs: Array = [] - - afterEach(() => { - logs = [] - }) - - it('should use OFF by default', async () => { - const logWriter = new LogWriter(new TestLogger(), 'LoggerTest') - logEveryLogLevel(logWriter) - expect(logs.length).toEqual(0) - }) - - it('should explicitly use TRACE', async () => { - const logWriter = new LogWriter( - new TestLogger(), - 'LoggerTest', - ClickHouseLogLevel.TRACE, - ) - checkLogLevelSet('TRACE') - logEveryLogLevel(logWriter) - expect(logs[0]).toEqual({ - level: 'trace', - message, - module, - }) - expect(logs[1]).toEqual({ - level: 'debug', - message, - module, - }) - expect(logs[2]).toEqual({ - level: 'info', - message, - module, - }) - expect(logs[3]).toEqual({ - level: 'warn', - message, - module, - }) - expect(logs[4]).toEqual({ - level: 'error', - message, - module, - err, - }) - expect(logs.length).toEqual(5) - }) - - it('should explicitly use DEBUG', async () => { - const logWriter = new LogWriter( - new TestLogger(), - 'LoggerTest', - ClickHouseLogLevel.DEBUG, - ) - checkLogLevelSet('DEBUG') - logEveryLogLevel(logWriter) - expect(logs[0]).toEqual({ - level: 'debug', - message, - module, - }) - expect(logs[1]).toEqual({ - level: 'info', - message, - module, - }) - expect(logs[2]).toEqual({ - level: 'warn', - message, - module, - }) - expect(logs[3]).toEqual({ - level: 'error', - message, - module, - err, - }) - expect(logs.length).toEqual(4) - }) - - it('should explicitly use INFO', async () => { - const logWriter = new LogWriter( - new TestLogger(), - 'LoggerTest', - ClickHouseLogLevel.INFO, - ) - checkLogLevelSet('INFO') - logEveryLogLevel(logWriter) - expect(logs[0]).toEqual({ - level: 'info', - message, - module, - }) - expect(logs[1]).toEqual({ - level: 'warn', - message, - module, - }) - expect(logs[2]).toEqual({ - level: 'error', - message, - module, - err, - }) - expect(logs.length).toEqual(3) - }) - - it('should explicitly use WARN', async () => { - const logWriter = new LogWriter( - new TestLogger(), - 'LoggerTest', - ClickHouseLogLevel.WARN, - ) - logEveryLogLevel(logWriter) - expect(logs[0]).toEqual({ - level: 'warn', - message, - module, - }) - expect(logs[1]).toEqual({ - level: 'error', - message, - module, - err, - }) - expect(logs.length).toEqual(2) - }) - - it('should explicitly use ERROR', async () => { - const logWriter = new LogWriter( - new TestLogger(), - 'LoggerTest', - ClickHouseLogLevel.ERROR, - ) - logEveryLogLevel(logWriter) - expect(logs[0]).toEqual({ - level: 'error', - message, - module, - err, - }) - expect(logs.length).toEqual(1) - }) - - function checkLogLevelSet(level: string) { - expect(logs).toEqual([ - { - level: 'info', - module: 'LoggerTest', - message: `Log level is set to ${level}`, - }, - ]) - logs = [] - } - - function logEveryLogLevel(logWriter: LogWriter) { - for (const level of ['trace', 'debug', 'info', 'warn']) { - // eslint-disable-next-line @typescript-eslint/ban-ts-comment - // @ts-ignore - logWriter[level]({ - message, - }) - } - logWriter.error({ - message, - err, - }) - } - - class TestLogger implements Logger { - trace(params: LogParams) { - logs.push({ ...params, level: 'trace' }) - } - debug(params: LogParams) { - logs.push({ ...params, level: 'debug' }) - } - info(params: LogParams) { - logs.push({ ...params, level: 'info' }) - } - warn(params: LogParams) { - logs.push({ ...params, level: 'warn' }) - } - error(params: ErrorLogParams) { - logs.push({ ...params, level: 'error' }) - } - } -})