Add Logger to the ResultSet in the Node.js implementation (#265)

CHANGELOG.md

@@ -2,7 +2,13 @@
 
 ## 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 ([#263](https://github.com/ClickHouse/clickhouse-js/issues/263)).
+
+## 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.
 - Added missing `rows_before_limit_at_least` to the ResponseJSON type ([@0237h](https://github.com/0237h), [#267](https://github.com/ClickHouse/clickhouse-js/issues/267)).
 
 # 1.0.1 (Common, Node.js, Web)

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<Stream = unknown> {
   private readonly makeResultSet: MakeResultSet<Stream>
   private readonly valuesEncoder: ValuesEncoder<Stream>
   private readonly sessionId?: string
+  private readonly logWriter: LogWriter
 
   constructor(
     config: BaseClickHouseClientConfigOptions & ImplementationDetails<Stream>,
@@ -129,6 +131,7 @@ export class ClickHouseClient<Stream = unknown> {
       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<Stream = unknown> {
       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,
+        },
+      })
+    })
   }
 
   /**

packages/client-common/src/config.ts

@@ -90,6 +90,7 @@ export type MakeResultSet<Stream> = <
   stream: Stream,
   format: Format,
   query_id: string,
+  log_error: (err: Error) => void,
 ) => ResultSet
 
 export interface ValuesEncoder<Stream> {

packages/client-common/src/error/parse_error.ts

@@ -1,5 +1,6 @@
 const errorRe =
   /(Code|Error): (?<code>\d+).*Exception: (?<message>.+)\((?<type>(?=.+[A-Z]{3})[A-Z0-9_]+?)\)/s
+
 interface ParsedClickHouseError {
   message: string
   code: string

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)
   }
 }

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' }])
     })
   })

packages/client-node/__tests__/integration/node_logger.ts → 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,17 +56,17 @@ 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,
         },
       })
       await client.ping()
       // 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,
         },
       })