From 26acafeb4122cbff47114cd36566c9aed19f43fe Mon Sep 17 00:00:00 2001 From: Madhavendra Rathore Date: Thu, 4 Jun 2026 22:02:06 +0000 Subject: [PATCH 1/2] [SEA-NodeJS] Unify kernel + driver logging into one DBSQLLogger sink MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Rust kernel emits its diagnostics via `tracing`; in a Node process nothing subscribed to them, so kernel logs were silently dropped — the `DBSQLLogger` only ever saw driver-side lines. This wires the kernel into the SAME logger (and file) the driver uses, so logs from all three layers — driver, napi shim, kernel — land in one place. How: - `SeaBackend.connect()` calls `installKernelLogBridge(binding, logger, level)` (new `lib/sea/SeaLogging.ts`), which registers a JS callback with the binding's `initKernelLogging`. The callback maps each kernel `LogRecord` (`{ level, target, message }`) onto the driver's `LogLevel` and re-emits it through `IClientContext.getLogger()`, tagged `[kernel ] …`. - Kernel verbosity follows the driver logger's level: `IDBSQLLogger` gains an optional `getLevel()` (implemented by `DBSQLLogger`); the bridge passes it to the kernel so events the sink would drop never cross the bridge. Defaults to `info` for loggers that don't expose a level. - Process-global, last-writer-wins + graceful no-op on an older binding without the bridge export (logging is advisory) — see SeaLogging docs. Requires kernel napi `initKernelLogging`/`setKernelLogLevel`/`LogRecord` (databricks-sql-kernel#126); `KERNEL_REV` bumped + binding rebuilt so the generated `native/sea/index.d.ts` carries them. Verified: tsc clean, eslint + prettier clean, SEA unit suite 256 passing (incl. new SeaLogging unit tests), and a live end-to-end run confirms a single DBSQLLogger file holds both driver lines and 29 `[kernel databricks::sql::kernel]` lines for one `SELECT 1` (committed as tests/e2e/sea/logging-e2e.test.ts). Co-authored-by: Isaac Signed-off-by: Madhavendra Rathore --- KERNEL_REV | 2 +- lib/DBSQLLogger.ts | 4 + lib/contracts/IDBSQLLogger.ts | 9 +++ lib/sea/SeaBackend.ts | 11 +++ lib/sea/SeaLogging.ts | 110 +++++++++++++++++++++++++++ lib/sea/SeaNativeLoader.ts | 6 ++ native/sea/index.d.ts | 30 ++++++++ native/sea/index.js | 4 +- tests/e2e/sea/logging-e2e.test.ts | 81 ++++++++++++++++++++ tests/unit/sea/logging.test.ts | 122 ++++++++++++++++++++++++++++++ 10 files changed, 377 insertions(+), 2 deletions(-) create mode 100644 lib/sea/SeaLogging.ts create mode 100644 tests/e2e/sea/logging-e2e.test.ts create mode 100644 tests/unit/sea/logging.test.ts diff --git a/KERNEL_REV b/KERNEL_REV index 1603f791..84908c65 100644 --- a/KERNEL_REV +++ b/KERNEL_REV @@ -1 +1 @@ -8bedaabf69f5bce5a957a8775f29dbb8dbdd2e71 +99d6ffc8cb5165d304cd9ab8f57649e885493438 diff --git a/lib/DBSQLLogger.ts b/lib/DBSQLLogger.ts index e4270c80..a779f3d7 100644 --- a/lib/DBSQLLogger.ts +++ b/lib/DBSQLLogger.ts @@ -26,6 +26,10 @@ export default class DBSQLLogger implements IDBSQLLogger { this.logger.log({ level, message }); } + getLevel(): LogLevel { + return (this.transports.console.level as LogLevel) ?? LogLevel.info; + } + setLevel(level: LogLevel) { this.transports.console.level = level; if (this.transports.file) { diff --git a/lib/contracts/IDBSQLLogger.ts b/lib/contracts/IDBSQLLogger.ts index 7cad3346..295b32d8 100644 --- a/lib/contracts/IDBSQLLogger.ts +++ b/lib/contracts/IDBSQLLogger.ts @@ -5,6 +5,15 @@ export interface LoggerOptions { export default interface IDBSQLLogger { log(level: LogLevel, message: string): void; + + /** + * Optional: the logger's current level. When implemented, the SEA/kernel + * backend uses it to set the verbosity of the kernel-side (Rust) log bridge, + * so kernel logs are filtered at the same level as the driver's own logs and + * land in the same sink. Loggers that don't implement it leave the kernel + * bridge at its `info` default. + */ + getLevel?(): LogLevel; } export enum LogLevel { diff --git a/lib/sea/SeaBackend.ts b/lib/sea/SeaBackend.ts index d609cac9..ca6c6ebe 100644 --- a/lib/sea/SeaBackend.ts +++ b/lib/sea/SeaBackend.ts @@ -22,6 +22,7 @@ import HiveDriverError from '../errors/HiveDriverError'; import { getSeaNative, SeaNativeBinding, SeaConnection } from './SeaNativeLoader'; import { decodeNapiKernelError } from './SeaErrorMapping'; import { buildSeaConnectionOptions, SeaNativeConnectionOptions } from './SeaAuth'; +import { installKernelLogBridge } from './SeaLogging'; import SeaSessionBackend from './SeaSessionBackend'; export interface SeaBackendOptions { @@ -81,6 +82,16 @@ export default class SeaBackend implements IBackend { // we ever touch the native binding. this.nativeOptions = buildSeaConnectionOptions(options); + // Bridge the Rust kernel's `tracing` logs into the SAME `DBSQLLogger` the + // driver logs through, so logs from all three layers (driver, napi shim, + // kernel) land in one place — and one file when the logger has a file + // transport. Kernel verbosity follows the logger's own level; loggers that + // don't expose `getLevel()` leave the bridge at `info`. No-op on a binding + // that predates the bridge (logging is advisory). + const logger = this.context.getLogger(); + const kernelLogLevel = logger.getLevel?.() ?? LogLevel.info; + installKernelLogBridge(this.binding, logger, kernelLogLevel); + // Warn on the insecure combo: a `customCaCert` paired with // `checkServerCertificate: false` is almost always a mistake — verification // is fully off, so the custom trust anchor is never used. The combo is diff --git a/lib/sea/SeaLogging.ts b/lib/sea/SeaLogging.ts new file mode 100644 index 00000000..c48d4141 --- /dev/null +++ b/lib/sea/SeaLogging.ts @@ -0,0 +1,110 @@ +// Copyright (c) 2026 Databricks, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +/** + * Kernel → driver log bridge. + * + * The Rust kernel emits its diagnostics via `tracing`. In a Node process those + * events have no subscriber and are dropped — so by default the driver's + * `DBSQLLogger` only ever saw JS-side lines. The napi binding's + * `initKernelLogging` installs a process-global subscriber that forwards + * kernel events (batched) to a JS callback; this module wires that callback + * into the **same** `IDBSQLLogger` the driver logs through, so logs from all + * three layers (driver, napi shim, kernel) land in one place — and one file + * when the logger has a file transport. + * + * Verbosity follows the driver's logger level (see `installKernelLogBridge`), + * filtered kernel-side so we don't pay the channel/bridge cost for events the + * sink would discard anyway. + */ + +import IDBSQLLogger, { LogLevel } from '../contracts/IDBSQLLogger'; +import { SeaNativeBinding, SeaNativeLogRecord } from './SeaNativeLoader'; + +/** + * Map a kernel level string (`error`/`warn`/`info`/`debug`/`trace`) onto the + * driver's `LogLevel`. The kernel's `trace` has no `LogLevel` analogue, so it + * folds into `debug` (the most verbose driver level). + */ +export function kernelLevelToLogLevel(level: string): LogLevel { + switch (level) { + case 'error': + return LogLevel.error; + case 'warn': + return LogLevel.warn; + case 'info': + return LogLevel.info; + case 'debug': + case 'trace': + return LogLevel.debug; + default: + // Unknown kernel level — surface it rather than drop it; debug is the + // least surprising bucket for an unrecognised severity. + return LogLevel.debug; + } +} + +/** + * Map a driver `LogLevel` onto the kernel level string the napi bridge expects. + * The `LogLevel` enum values are already the kernel-compatible lower-case + * strings, so this is the identity at runtime — kept as an explicit function so + * the boundary is named and a future divergence has one place to live. + */ +export function logLevelToKernelLevel(level: LogLevel): string { + return level; +} + +/** + * Format one kernel log record into a single driver log line, tagged with its + * origin so kernel lines are distinguishable from driver lines in a shared + * sink/file. + */ +export function formatKernelLine(record: SeaNativeLogRecord): string { + return `[kernel ${record.target}] ${record.message}`; +} + +/** + * Install the kernel→driver log bridge: forward kernel `tracing` events into + * `logger` at `level`. + * + * - **Verbosity** is set kernel-side to `level` so events the sink would drop + * never cross the bridge. + * - **Process-global, last-writer-wins:** the napi binding holds a single + * process-global subscriber + sink (a `tracing` global subscriber installs + * once). Each call retargets the sink to `logger`, so in a multi-client + * process the most recently connected client's logger receives kernel logs — + * mirroring the Python connector's `pyo3_log` model. Single-client apps, the + * common case, are unaffected. + * - **Graceful on older bindings:** if the loaded `.node` predates + * `initKernelLogging`, this is a no-op (kernel logs simply stay unbridged) + * rather than a hard failure — logging is advisory. + */ +export function installKernelLogBridge(binding: SeaNativeBinding, logger: IDBSQLLogger, level: LogLevel): void { + // Defensive: a stale/older binding without the bridge export must not break + // connect() — logging is non-critical. + if (typeof binding.initKernelLogging !== 'function') { + return; + } + + const callback = (err: Error | null, records: Array): void => { + if (err || !records) { + return; + } + for (const record of records) { + logger.log(kernelLevelToLogLevel(record.level), formatKernelLine(record)); + } + }; + + binding.initKernelLogging(callback, logLevelToKernelLevel(level)); +} diff --git a/lib/sea/SeaNativeLoader.ts b/lib/sea/SeaNativeLoader.ts index 80352be6..5ffae497 100644 --- a/lib/sea/SeaNativeLoader.ts +++ b/lib/sea/SeaNativeLoader.ts @@ -39,6 +39,7 @@ import type { AsyncStatement as NativeAsyncStatement, AsyncResultHandle as NativeAsyncResultHandle, CancellableExecution as NativeCancellableExecution, + LogRecord as NativeLogRecord, } from '../../native/sea'; // SEA-prefixed re-exports. The kernel-generated `.d.ts` keeps the @@ -78,6 +79,11 @@ export type SeaNativeAsyncResultHandle = NativeAsyncResultHandle; // returns. export type SeaNativeCancellableExecution = NativeCancellableExecution; +// One kernel log event forwarded over the napi log bridge (see SeaLogging.ts): +// `{ level, target, message }`. Re-exported so the bridge can name the shape +// without re-declaring it (stays in lock-step with the kernel contract). +export type SeaNativeLogRecord = NativeLogRecord; + /** * The full native binding surface, derived from the generated module * so it can never drift from the `.d.ts` contract: when the kernel diff --git a/native/sea/index.d.ts b/native/sea/index.d.ts index 4ecd1ad6..12ed153d 100644 --- a/native/sea/index.d.ts +++ b/native/sea/index.d.ts @@ -285,6 +285,36 @@ export interface ConnectionOptions { * to camelCase for free functions). */ export declare function openSession(options: ConnectionOptions): Promise +/** + * One kernel log event, as handed to JS. `level` is a lower-case string + * (`error`/`warn`/`info`/`debug`/`trace`) the Node side maps onto its + * `LogLevel`; `target` is the originating `tracing` target (e.g. + * `databricks::sql::kernel`); `message` is the rendered event plus any + * structured `key=value` fields. + */ +export interface LogRecord { + level: string + target: string + message: string +} +/** + * Install (idempotently) the kernel→JS log bridge and set its level. + * + * `callback` is invoked with **an array of [`LogRecord`]s** (`(err, records)`) + * for each forwarded batch. `level` is one of + * `off`/`error`/`warn`/`info`/`debug`/`trace` (case-insensitive); unknown + * values fall back to `warn`. + * + * Safe to call more than once: the process-global subscriber is installed on + * the first call only, while every call refreshes the sink + level (last + * writer wins — see module docs). + */ +export declare function initKernelLogging(callback: (err: Error | null, arg: Array) => any, level: string): void +/** + * Live-retarget the bridge's level (one of + * `off`/`error`/`warn`/`info`/`debug`/`trace`, case-insensitive). + */ +export declare function setKernelLogLevel(level: string): void /** * JS-visible binding for a single positional parameter. * diff --git a/native/sea/index.js b/native/sea/index.js index d800a6cd..9d9d9b2d 100644 --- a/native/sea/index.js +++ b/native/sea/index.js @@ -310,7 +310,7 @@ if (!nativeBinding) { throw new Error(`Failed to load native binding`) } -const { AsyncStatement, AsyncResultHandle, CancellableExecution, Connection, AuthMode, openSession, Statement, version } = nativeBinding +const { AsyncStatement, AsyncResultHandle, CancellableExecution, Connection, AuthMode, openSession, initKernelLogging, setKernelLogLevel, Statement, version } = nativeBinding module.exports.AsyncStatement = AsyncStatement module.exports.AsyncResultHandle = AsyncResultHandle @@ -318,5 +318,7 @@ module.exports.CancellableExecution = CancellableExecution module.exports.Connection = Connection module.exports.AuthMode = AuthMode module.exports.openSession = openSession +module.exports.initKernelLogging = initKernelLogging +module.exports.setKernelLogLevel = setKernelLogLevel module.exports.Statement = Statement module.exports.version = version diff --git a/tests/e2e/sea/logging-e2e.test.ts b/tests/e2e/sea/logging-e2e.test.ts new file mode 100644 index 00000000..b6472852 --- /dev/null +++ b/tests/e2e/sea/logging-e2e.test.ts @@ -0,0 +1,81 @@ +// Copyright (c) 2026 Databricks, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// End-to-end proof that kernel (Rust) logs and Node-driver logs land in the +// SAME `DBSQLLogger` sink — here, one file. Goes through the full public +// `DBSQLClient` surface (not the raw binding) so the `SeaBackend` → +// `installKernelLogBridge` → napi `initKernelLogging` wiring is exercised. + +import { expect } from 'chai'; +import fs from 'fs'; +import os from 'os'; +import path from 'path'; +import { tryGetSeaNative } from '../../../lib/sea/SeaNativeLoader'; +import { DBSQLClient } from '../../../lib'; +import DBSQLLogger from '../../../lib/DBSQLLogger'; +import { LogLevel } from '../../../lib/contracts/IDBSQLLogger'; +import config from '../utils/config'; +import { InternalConnectionOptions } from '../../../lib/contracts/InternalConnectionOptions'; + +const delay = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms)); + +describe('SEA — unified kernel + driver logging', function unifiedLogging() { + // Live-warehouse round-trip plus async log flush. + this.timeout(60_000); + + const binding = tryGetSeaNative(); + if (binding === undefined) { + it.skip('SEA native binding not available on this platform'); + return; + } + + it('routes kernel (Rust) logs into the same DBSQLLogger file as driver logs', async () => { + const logFile = path.join(fs.mkdtempSync(path.join(os.tmpdir(), 'dbsql-kernel-log-')), 'unified.log'); + // debug so the kernel's per-statement lifecycle events cross the bridge. + const logger = new DBSQLLogger({ level: LogLevel.debug, filepath: logFile }); + const client = new DBSQLClient({ logger }); + + await client.connect({ + host: config.host, + path: config.path, + token: config.token, + // Route through the kernel backend (internal opt-in flag). + ...({ useSEA: true } as InternalConnectionOptions), + }); + const session = await client.openSession(); + const operation = await session.executeStatement('SELECT 1'); + await operation.fetchAll(); + await operation.close(); + await session.close(); + await client.close(); + + // winston's file transport + the batched kernel bridge are async; give them + // a beat to flush before reading the file back. + await delay(1_500); + + const contents = fs.readFileSync(logFile, 'utf8'); + const lines = contents.split('\n').filter((l) => l.trim().length > 0); + + const kernelLines = lines.filter((l) => l.includes('[kernel ')); + const driverLines = lines.filter((l) => !l.includes('[kernel ')); + + // Both layers present in the one file → unified. + expect(driverLines.length, 'expected driver-origin log lines').to.be.greaterThan(0); + expect(kernelLines.length, 'expected kernel-origin ([kernel …) log lines').to.be.greaterThan(0); + // The kernel target tag is preserved. + expect(contents).to.match(/\[kernel databricks::sql::kernel\]/); + + fs.rmSync(path.dirname(logFile), { recursive: true, force: true }); + }); +}); diff --git a/tests/unit/sea/logging.test.ts b/tests/unit/sea/logging.test.ts new file mode 100644 index 00000000..374bbb44 --- /dev/null +++ b/tests/unit/sea/logging.test.ts @@ -0,0 +1,122 @@ +// Copyright (c) 2026 Databricks, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +import { expect } from 'chai'; +import { + kernelLevelToLogLevel, + logLevelToKernelLevel, + formatKernelLine, + installKernelLogBridge, +} from '../../../lib/sea/SeaLogging'; +import { LogLevel } from '../../../lib/contracts/IDBSQLLogger'; +import { SeaNativeBinding, SeaNativeLogRecord } from '../../../lib/sea/SeaNativeLoader'; + +// Minimal recording logger. +function recordingLogger() { + const lines: Array<{ level: LogLevel; message: string }> = []; + return { + lines, + log(level: LogLevel, message: string) { + lines.push({ level, message }); + }, + }; +} + +// A binding stub that captures the registered bridge callback + level. +function captureBinding(overrides: Partial> = {}) { + const captured: { cb?: (err: Error | null, records: Array) => void; level?: string } = {}; + const binding = { + initKernelLogging: (cb: (err: Error | null, records: Array) => void, level: string) => { + captured.cb = cb; + captured.level = level; + }, + ...overrides, + } as unknown as SeaNativeBinding; + return { binding, captured }; +} + +describe('SeaLogging', () => { + describe('kernelLevelToLogLevel', () => { + it('maps the kernel levels onto driver LogLevels', () => { + expect(kernelLevelToLogLevel('error')).to.equal(LogLevel.error); + expect(kernelLevelToLogLevel('warn')).to.equal(LogLevel.warn); + expect(kernelLevelToLogLevel('info')).to.equal(LogLevel.info); + expect(kernelLevelToLogLevel('debug')).to.equal(LogLevel.debug); + }); + + it('folds kernel `trace` (no driver analogue) into debug', () => { + expect(kernelLevelToLogLevel('trace')).to.equal(LogLevel.debug); + }); + + it('buckets an unknown level into debug rather than dropping it', () => { + expect(kernelLevelToLogLevel('weird')).to.equal(LogLevel.debug); + }); + }); + + describe('logLevelToKernelLevel', () => { + it('passes the lower-case level string through to the kernel', () => { + expect(logLevelToKernelLevel(LogLevel.error)).to.equal('error'); + expect(logLevelToKernelLevel(LogLevel.debug)).to.equal('debug'); + }); + }); + + describe('formatKernelLine', () => { + it('tags the line with the kernel origin + target', () => { + const line = formatKernelLine({ level: 'info', target: 'databricks::sql::kernel', message: 'hi' }); + expect(line).to.equal('[kernel databricks::sql::kernel] hi'); + }); + }); + + describe('installKernelLogBridge', () => { + it('registers with the kernel at the requested level', () => { + const { binding, captured } = captureBinding(); + installKernelLogBridge(binding, recordingLogger(), LogLevel.debug); + expect(captured.level).to.equal('debug'); + expect(captured.cb).to.be.a('function'); + }); + + it('forwards a batch of kernel records into the logger, level-mapped + tagged', () => { + const { binding, captured } = captureBinding(); + const logger = recordingLogger(); + installKernelLogBridge(binding, logger, LogLevel.debug); + + captured.cb!(null, [ + { level: 'warn', target: 'databricks::sql::kernel', message: 'retrying' }, + { level: 'trace', target: 'databricks_sql_kernel::session', message: 'span enter' }, + ]); + + expect(logger.lines).to.have.length(2); + expect(logger.lines[0]).to.deep.equal({ + level: LogLevel.warn, + message: '[kernel databricks::sql::kernel] retrying', + }); + // trace → debug + expect(logger.lines[1].level).to.equal(LogLevel.debug); + expect(logger.lines[1].message).to.contain('span enter'); + }); + + it('drops a batch that arrives with an error and never calls the logger', () => { + const { binding, captured } = captureBinding(); + const logger = recordingLogger(); + installKernelLogBridge(binding, logger, LogLevel.info); + captured.cb!(new Error('tsfn failure'), []); + expect(logger.lines).to.have.length(0); + }); + + it('is a no-op (no throw) on an older binding without the bridge export', () => { + const binding = {} as unknown as SeaNativeBinding; + expect(() => installKernelLogBridge(binding, recordingLogger(), LogLevel.info)).to.not.throw(); + }); + }); +}); From 45995493f9bbdc8c02fe7d8a4870b140bb295de5 Mon Sep 17 00:00:00 2001 From: Madhavendra Rathore Date: Thu, 4 Jun 2026 22:16:52 +0000 Subject: [PATCH 2/2] [SEA-NodeJS] Retarget kernel log level on runtime logger.setLevel() MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Follow-up to the unified-logging wiring: a runtime `logger.setLevel(...)` now retargets the kernel-side bridge too, not just the driver's own transports — keeping kernel verbosity in lock-step with the driver's at runtime, not only at connect. - `IDBSQLLogger` gains an optional `onLevelChange(listener) => unsubscribe`; `DBSQLLogger` implements it (fires subscribers from `setLevel`, swallowing a throwing listener so it can't break level setting). - `installKernelLogBridge` now returns an unsubscribe handle and, when both the logger can notify (`onLevelChange`) and the binding can retarget (`setKernelLogLevel`), subscribes to forward level changes to the kernel. - `SeaBackend` stores the handle and drops it on `close()` (no stale listener; the process-global kernel sink follows the existing last-writer-wins model). Backend-agnostic: `DBSQLLogger` never references the SEA binding — the SEA layer subscribes via the interface. Loggers without `onLevelChange` keep the connect-time level; older bindings without `setKernelLogLevel` simply don't subscribe. Verified: tsc / eslint / prettier clean; unit suite 1183 passing incl. new `DBSQLLogger` level-subscription tests + `SeaLogging` runtime-retarget tests (retarget, unsubscribe, no-notify logger, no-retarget binding). Live: with the logger started at `warn`, a healthy SELECT logged 0 kernel lines; after `logger.setLevel('debug')` mid-session the next SELECT logged 12 `[kernel databricks::sql::kernel]` lines — proving the kernel was retargeted. Co-authored-by: Isaac Signed-off-by: Madhavendra Rathore --- lib/DBSQLLogger.ts | 22 ++++++++ lib/contracts/IDBSQLLogger.ts | 10 ++++ lib/sea/SeaBackend.ts | 13 ++++- lib/sea/SeaLogging.ts | 25 ++++++++- tests/e2e/sea/logging-e2e.test.ts | 5 +- tests/unit/DBSQLLogger.test.ts | 62 +++++++++++++++++++++ tests/unit/sea/logging.test.ts | 92 +++++++++++++++++++++++++++++-- 7 files changed, 220 insertions(+), 9 deletions(-) create mode 100644 tests/unit/DBSQLLogger.test.ts diff --git a/lib/DBSQLLogger.ts b/lib/DBSQLLogger.ts index a779f3d7..38863a6d 100644 --- a/lib/DBSQLLogger.ts +++ b/lib/DBSQLLogger.ts @@ -9,6 +9,10 @@ export default class DBSQLLogger implements IDBSQLLogger { file?: winston.transports.FileTransportInstance; }; + // Subscribers notified on `setLevel(...)` — used by the SEA/kernel backend to + // keep the kernel-side log bridge's verbosity in lock-step with this logger. + private levelListeners: Array<(level: LogLevel) => void> = []; + constructor({ level = LogLevel.info, filepath }: LoggerOptions = {}) { this.transports = { console: new winston.transports.Console({ handleExceptions: true, level }), @@ -30,10 +34,28 @@ export default class DBSQLLogger implements IDBSQLLogger { return (this.transports.console.level as LogLevel) ?? LogLevel.info; } + onLevelChange(listener: (level: LogLevel) => void): () => void { + this.levelListeners.push(listener); + return () => { + const index = this.levelListeners.indexOf(listener); + if (index >= 0) { + this.levelListeners.splice(index, 1); + } + }; + } + setLevel(level: LogLevel) { this.transports.console.level = level; if (this.transports.file) { this.transports.file.level = level; } + for (const listener of this.levelListeners) { + // A subscriber must never break level setting for the rest. + try { + listener(level); + } catch { + // swallow — level-change notification is advisory + } + } } } diff --git a/lib/contracts/IDBSQLLogger.ts b/lib/contracts/IDBSQLLogger.ts index 295b32d8..23ab3df3 100644 --- a/lib/contracts/IDBSQLLogger.ts +++ b/lib/contracts/IDBSQLLogger.ts @@ -14,6 +14,16 @@ export default interface IDBSQLLogger { * bridge at its `info` default. */ getLevel?(): LogLevel; + + /** + * Optional: subscribe to runtime level changes. When implemented, the + * SEA/kernel backend subscribes so a runtime `setLevel(...)` retargets the + * kernel-side log bridge too (not just the driver's own transports) — keeping + * kernel verbosity in lock-step with the driver's. Returns an unsubscribe + * function. Loggers that don't implement it still get the connect-time level; + * only *runtime* retargeting of the kernel is unavailable. + */ + onLevelChange?(listener: (level: LogLevel) => void): () => void; } export enum LogLevel { diff --git a/lib/sea/SeaBackend.ts b/lib/sea/SeaBackend.ts index ca6c6ebe..6f1bd5f0 100644 --- a/lib/sea/SeaBackend.ts +++ b/lib/sea/SeaBackend.ts @@ -71,6 +71,11 @@ export default class SeaBackend implements IBackend { private nativeOptions?: SeaNativeConnectionOptions; + // Drops the kernel-log level-change listener on close. No-op until connect() + // installs the bridge (and a no-op closure if the logger/binding can't + // retarget at runtime). + private kernelLogUnsubscribe: () => void = () => {}; + constructor(options: SeaBackendOptions) { this.context = options.context; this.binding = options.nativeBinding ?? getSeaNative(); @@ -90,7 +95,7 @@ export default class SeaBackend implements IBackend { // that predates the bridge (logging is advisory). const logger = this.context.getLogger(); const kernelLogLevel = logger.getLevel?.() ?? LogLevel.info; - installKernelLogBridge(this.binding, logger, kernelLogLevel); + this.kernelLogUnsubscribe = installKernelLogBridge(this.binding, logger, kernelLogLevel); // Warn on the insecure combo: a `customCaCert` paired with // `checkServerCertificate: false` is almost always a mistake — verification @@ -160,5 +165,11 @@ export default class SeaBackend implements IBackend { // No backend-level resources to release — each `SeaSessionBackend` // owns its own napi `Connection` lifecycle. this.nativeOptions = undefined; + + // Stop retargeting the (process-global) kernel log level from this backend's + // logger; the kernel sink itself is process-global and is replaced by the + // next connect, matching the bridge's last-writer-wins model. + this.kernelLogUnsubscribe(); + this.kernelLogUnsubscribe = () => {}; } } diff --git a/lib/sea/SeaLogging.ts b/lib/sea/SeaLogging.ts index c48d4141..653dae5b 100644 --- a/lib/sea/SeaLogging.ts +++ b/lib/sea/SeaLogging.ts @@ -86,15 +86,24 @@ export function formatKernelLine(record: SeaNativeLogRecord): string { * process the most recently connected client's logger receives kernel logs — * mirroring the Python connector's `pyo3_log` model. Single-client apps, the * common case, are unaffected. + * - **Runtime retargeting:** if `logger` exposes `onLevelChange` (as + * `DBSQLLogger` does), the bridge subscribes so a later `logger.setLevel(...)` + * also retargets the kernel-side filter via `setKernelLogLevel` — keeping + * kernel verbosity in lock-step with the driver's at runtime, not just at + * connect. Loggers without it still get the connect-time level. * - **Graceful on older bindings:** if the loaded `.node` predates * `initKernelLogging`, this is a no-op (kernel logs simply stay unbridged) * rather than a hard failure — logging is advisory. + * + * Returns an **unsubscribe** function the caller must invoke on teardown + * (`SeaBackend.close()`) to drop the level-change listener; it is a safe no-op + * when nothing was subscribed. */ -export function installKernelLogBridge(binding: SeaNativeBinding, logger: IDBSQLLogger, level: LogLevel): void { +export function installKernelLogBridge(binding: SeaNativeBinding, logger: IDBSQLLogger, level: LogLevel): () => void { // Defensive: a stale/older binding without the bridge export must not break // connect() — logging is non-critical. if (typeof binding.initKernelLogging !== 'function') { - return; + return () => {}; } const callback = (err: Error | null, records: Array): void => { @@ -107,4 +116,16 @@ export function installKernelLogBridge(binding: SeaNativeBinding, logger: IDBSQL }; binding.initKernelLogging(callback, logLevelToKernelLevel(level)); + + // Keep the kernel's level in lock-step with runtime `logger.setLevel(...)` + // calls. Requires both a logger that notifies (`onLevelChange`) and a binding + // that can retarget (`setKernelLogLevel`); otherwise the connect-time level + // stands and there is nothing to unsubscribe. + if (typeof logger.onLevelChange === 'function' && typeof binding.setKernelLogLevel === 'function') { + return logger.onLevelChange((newLevel) => { + binding.setKernelLogLevel(logLevelToKernelLevel(newLevel)); + }); + } + + return () => {}; } diff --git a/tests/e2e/sea/logging-e2e.test.ts b/tests/e2e/sea/logging-e2e.test.ts index b6472852..74f170e8 100644 --- a/tests/e2e/sea/logging-e2e.test.ts +++ b/tests/e2e/sea/logging-e2e.test.ts @@ -28,7 +28,10 @@ import { LogLevel } from '../../../lib/contracts/IDBSQLLogger'; import config from '../utils/config'; import { InternalConnectionOptions } from '../../../lib/contracts/InternalConnectionOptions'; -const delay = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms)); +const delay = (ms: number) => + new Promise((resolve) => { + setTimeout(resolve, ms); + }); describe('SEA — unified kernel + driver logging', function unifiedLogging() { // Live-warehouse round-trip plus async log flush. diff --git a/tests/unit/DBSQLLogger.test.ts b/tests/unit/DBSQLLogger.test.ts new file mode 100644 index 00000000..05cb60b6 --- /dev/null +++ b/tests/unit/DBSQLLogger.test.ts @@ -0,0 +1,62 @@ +// Copyright (c) 2026 Databricks, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +import { expect } from 'chai'; +import DBSQLLogger from '../../lib/DBSQLLogger'; +import { LogLevel } from '../../lib/contracts/IDBSQLLogger'; + +describe('DBSQLLogger level subscription', () => { + it('getLevel reflects the configured level', () => { + const logger = new DBSQLLogger({ level: LogLevel.warn }); + expect(logger.getLevel()).to.equal(LogLevel.warn); + }); + + it('onLevelChange fires subscribers with the new level on setLevel', () => { + const logger = new DBSQLLogger({ level: LogLevel.info }); + const seen: LogLevel[] = []; + logger.onLevelChange((level) => seen.push(level)); + + logger.setLevel(LogLevel.debug); + logger.setLevel(LogLevel.error); + + expect(seen).to.deep.equal([LogLevel.debug, LogLevel.error]); + // setLevel still updates the logger's own level. + expect(logger.getLevel()).to.equal(LogLevel.error); + }); + + it('the returned unsubscribe stops further notifications', () => { + const logger = new DBSQLLogger({ level: LogLevel.info }); + const seen: LogLevel[] = []; + const unsubscribe = logger.onLevelChange((level) => seen.push(level)); + + logger.setLevel(LogLevel.debug); + unsubscribe(); + logger.setLevel(LogLevel.warn); + + expect(seen).to.deep.equal([LogLevel.debug]); + }); + + it('a throwing subscriber does not break setLevel or other subscribers', () => { + const logger = new DBSQLLogger({ level: LogLevel.info }); + const seen: LogLevel[] = []; + logger.onLevelChange(() => { + throw new Error('boom'); + }); + logger.onLevelChange((level) => seen.push(level)); + + expect(() => logger.setLevel(LogLevel.debug)).to.not.throw(); + expect(seen).to.deep.equal([LogLevel.debug]); + expect(logger.getLevel()).to.equal(LogLevel.debug); + }); +}); diff --git a/tests/unit/sea/logging.test.ts b/tests/unit/sea/logging.test.ts index 374bbb44..087cf737 100644 --- a/tests/unit/sea/logging.test.ts +++ b/tests/unit/sea/logging.test.ts @@ -22,25 +22,55 @@ import { import { LogLevel } from '../../../lib/contracts/IDBSQLLogger'; import { SeaNativeBinding, SeaNativeLogRecord } from '../../../lib/sea/SeaNativeLoader'; -// Minimal recording logger. -function recordingLogger() { +// Minimal recording logger. With `withLevelChange` (default) it exposes +// `onLevelChange` + an `emitLevelChange` test helper to simulate a runtime +// `setLevel(...)`; pass `false` to model a logger that can't notify. +function recordingLogger(opts: { withLevelChange?: boolean } = {}) { const lines: Array<{ level: LogLevel; message: string }> = []; - return { + const listeners: Array<(level: LogLevel) => void> = []; + const logger = { lines, log(level: LogLevel, message: string) { lines.push({ level, message }); }, + // test-only: simulate the driver's `setLevel(...)` firing its subscribers + emitLevelChange(level: LogLevel) { + listeners.forEach((l) => l(level)); + }, + } as { + lines: Array<{ level: LogLevel; message: string }>; + log(level: LogLevel, message: string): void; + emitLevelChange(level: LogLevel): void; + onLevelChange?(listener: (level: LogLevel) => void): () => void; }; + if (opts.withLevelChange !== false) { + logger.onLevelChange = (listener: (level: LogLevel) => void) => { + listeners.push(listener); + return () => { + const i = listeners.indexOf(listener); + if (i >= 0) listeners.splice(i, 1); + }; + }; + } + return logger; } -// A binding stub that captures the registered bridge callback + level. +// A binding stub that captures the registered bridge callback + initial level, +// and records each `setKernelLogLevel` retarget. function captureBinding(overrides: Partial> = {}) { - const captured: { cb?: (err: Error | null, records: Array) => void; level?: string } = {}; + const captured: { + cb?: (err: Error | null, records: Array) => void; + level?: string; + levelChanges: string[]; + } = { levelChanges: [] }; const binding = { initKernelLogging: (cb: (err: Error | null, records: Array) => void, level: string) => { captured.cb = cb; captured.level = level; }, + setKernelLogLevel: (level: string) => { + captured.levelChanges.push(level); + }, ...overrides, } as unknown as SeaNativeBinding; return { binding, captured }; @@ -119,4 +149,56 @@ describe('SeaLogging', () => { expect(() => installKernelLogBridge(binding, recordingLogger(), LogLevel.info)).to.not.throw(); }); }); + + describe('runtime level retargeting', () => { + it('retargets the kernel level when the logger level changes at runtime', () => { + const { binding, captured } = captureBinding(); + const logger = recordingLogger(); + installKernelLogBridge(binding, logger, LogLevel.warn); + expect(captured.level).to.equal('warn'); // connect-time level + + logger.emitLevelChange(LogLevel.debug); + logger.emitLevelChange(LogLevel.error); + expect(captured.levelChanges).to.deep.equal(['debug', 'error']); + }); + + it('stops retargeting once the returned unsubscribe is called', () => { + const { binding, captured } = captureBinding(); + const logger = recordingLogger(); + const unsubscribe = installKernelLogBridge(binding, logger, LogLevel.info); + + logger.emitLevelChange(LogLevel.debug); + unsubscribe(); + logger.emitLevelChange(LogLevel.error); // after unsubscribe → ignored + + expect(captured.levelChanges).to.deep.equal(['debug']); + }); + + it('does not subscribe when the logger cannot notify (no onLevelChange)', () => { + const { binding, captured } = captureBinding(); + const logger = recordingLogger({ withLevelChange: false }); + const unsubscribe = installKernelLogBridge(binding, logger, LogLevel.info); + logger.emitLevelChange(LogLevel.debug); + expect(captured.levelChanges).to.have.length(0); + expect(unsubscribe).to.be.a('function'); // safe no-op + expect(() => unsubscribe()).to.not.throw(); + }); + + it('does not subscribe when the binding cannot retarget (no setKernelLogLevel)', () => { + // initKernelLogging present, setKernelLogLevel absent (partial/older binding). + const captured: { installed: boolean } = { installed: false }; + const binding = { + initKernelLogging: () => { + captured.installed = true; + }, + } as unknown as SeaNativeBinding; + const logger = recordingLogger(); + const unsubscribe = installKernelLogBridge(binding, logger, LogLevel.info); + expect(captured.installed).to.equal(true); + expect(() => { + logger.emitLevelChange(LogLevel.debug); + unsubscribe(); + }).to.not.throw(); + }); + }); });