From a87ee5398267f0a73bd933a59983a41c05a15833 Mon Sep 17 00:00:00 2001 From: Mani Kaustubh Mathur Date: Tue, 14 Jul 2026 13:44:21 +0000 Subject: [PATCH 1/3] feat(kernel): route kernel logging through the driver log level + correlate MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Unify kernel-backend logging onto the driver's shared logger so the one knob that controls the rest of the driver — DATABRICKS_LOG_LEVEL / dbsql.SetLogLevel — governs it, and each binding line carries the structured connId/corrId/queryId fields that let it be correlated in a multi-connection process. Addresses vikrantpuppala's review on #393 (klog + the kernel Rust subscriber emitted unstructured lines straight to os.Stderr, uncorrelatable and gated on a separate DBSQL_KERNEL_DEBUG rather than the driver log level). Three parts: - Level: klog now emits through logger.Logger.Debug() instead of raw fmt.Fprintf(os.Stderr, ...). A cheap kernelDebugOff() front gate (GetLevel() > Debug) short-circuits before any formatting/allocation, so it stays a true no-op at the default Warn level — including during benchmarks. Replaces the old DBSQL_KERNEL_DEBUG bool + the caller-less KernelDebugEnabled. - Correlation: new klogCtx(ctx, ...) pulls connId/corrId/queryId off ctx via logger.WithContext (the exact idiom the Thrift/conn path uses); the conn layer already stuffs those IDs into ctx before calling the backend. Every hot-path site (execute, nextBatch, newKernelRows, Open/CloseSession) uses it; ctx-less sites degrade to klog. The WithContext allocation is behind the same up-front level gate, so it never runs below Debug. - Kernel Rust logs: initKernelLogging maps the driver level -> the kernel_init_logging level string (kernelLogLevel), so DATABRICKS_LOG_LEVEL drives the kernel's Rust logs too. DBSQL_KERNEL_DEBUG is kept as an advanced override (forces the subscriber on, defers to RUST_LOG for kernel verbosity). Known limitation (documented): the kernel's Rust lines are still plain text and do not yet carry the structured fields — that needs the kernel log-callback ABI (PECOBLR-3654 / K4). Only the Go binding lines are structured today. Tests: TestKernelLogLevel pins the level mapping; TestKernelLogNoAllocWhenOff uses testing.AllocsPerRun to prove klog/klogCtx allocate 0 times at Warn level (guards the hot-path zero-cost guarantee). Closes PECOBLR-3650. Co-authored-by: Isaac Signed-off-by: Mani Kaustubh Mathur --- doc.go | 34 ++++-- internal/backend/kernel/backend.go | 8 +- internal/backend/kernel/cgo.go | 150 ++++++++++++++++++------- internal/backend/kernel/kernel_test.go | 55 +++++++++ internal/backend/kernel/operation.go | 16 +-- internal/backend/kernel/rows.go | 8 +- 6 files changed, 202 insertions(+), 69 deletions(-) diff --git a/doc.go b/doc.go index a3511c3b..3378cdc3 100644 --- a/doc.go +++ b/doc.go @@ -186,16 +186,30 @@ the C header) under the cgo link path; `make build-kernel` does both steps: In a build without the tag, WithUseKernel(true) returns a clear error at connect time rather than silently using Thrift. -To see the kernel's own logs interleaved with the driver's, set DBSQL_KERNEL_DEBUG -to any non-empty value. That single flag turns on the driver's binding step tracer -AND installs the kernel's Rust log subscriber, so both write to the same stderr in -execution order. It is off by default (and must stay off during benchmarks — debug -logging perturbs latency). The kernel's verbosity is then controlled by RUST_LOG, -which the kernel honors directly; filter on the target databricks::sql::kernel -(note the colons — it is the kernel's explicit log target, NOT the crate module -path databricks_sql_kernel, which would match nothing): - - # kernel logs only: +Kernel-backend logging follows the same knob as the rest of the driver. The +binding-layer trace (session/statement/batch steps) is emitted through the shared +logger at Debug level, so DATABRICKS_LOG_LEVEL=debug or dbsql.SetLogLevel("debug") +turns it on — no separate switch — and each line carries the same structured +connId/corrId/queryId fields as the driver's other logs, so it can be correlated in +a multi-connection process. At the default Warn level the lines are suppressed with +no cost (zerolog no-ops a below-level event), including during benchmarks. + + dbsql.SetLogLevel("debug") // or DATABRICKS_LOG_LEVEL=debug + +The driver's log level is also mapped into the kernel's own Rust log subscriber, so +the same knob governs the kernel's internal (Rust) logs; they write to stderr and +interleave with the driver's output. Note the kernel's Rust lines are currently +plain text and do NOT yet carry the structured connId/corrId/queryId fields — that +needs a kernel log-callback ABI (tracked separately); only the Go binding lines are +structured today. + +For finer control of the kernel's Rust verbosity independent of the driver level, +set DBSQL_KERNEL_DEBUG to any non-empty value: it forces the kernel subscriber on +and defers to RUST_LOG for the kernel's threshold. Filter on the target +databricks::sql::kernel (note the colons — the kernel's explicit log target, NOT +the crate module path databricks_sql_kernel, which would match nothing): + + # kernel logs only, at the kernel's own verbosity: DBSQL_KERNEL_DEBUG=1 RUST_LOG=databricks::sql::kernel=debug ./your_app 2>&1 # kernel logs plus its HTTP stack (hyper/reqwest): DBSQL_KERNEL_DEBUG=1 RUST_LOG=debug ./your_app 2>&1 diff --git a/internal/backend/kernel/backend.go b/internal/backend/kernel/backend.go index e6540081..ad20c97c 100644 --- a/internal/backend/kernel/backend.go +++ b/internal/backend/kernel/backend.go @@ -113,7 +113,7 @@ func (k *KernelBackend) OpenSession(ctx context.Context) error { return err } initKernelLogging() - klog("OpenSession host=%s httpPath=%s warehouse=%s", k.cfg.Host, k.cfg.HTTPPath, k.cfg.WarehouseID) + klogCtx(ctx, "OpenSession host=%s httpPath=%s warehouse=%s", k.cfg.Host, k.cfg.HTTPPath, k.cfg.WarehouseID) var cfg *C.KernelSessionConfig if err := call(func() C.KernelStatusCode { return C.kernel_session_config_new(&cfg) }); err != nil { @@ -243,14 +243,14 @@ func (k *KernelBackend) OpenSession(ctx context.Context) error { // is logged (via lastError's Warn) rather than silently discarded — mirroring // CloseSession. The namespace error is authoritative and returned as-is. if closeErr := call(func() C.KernelStatusCode { return C.kernel_session_close(sess) }); closeErr != nil { - klog("close after initial-namespace failure also failed: %v", closeErr) + klogCtx(ctx, "close after initial-namespace failure also failed: %v", closeErr) } k.session = nil k.valid = false return err } - klog("OpenSession OK session=%s", k.sessionID) + klogCtx(ctx, "OpenSession OK session=%s", k.sessionID) return nil } @@ -400,7 +400,7 @@ func (k *KernelBackend) CloseSession(ctx context.Context) error { if k.session == nil { return nil } - klog("CloseSession session=%s", k.sessionID) + klogCtx(ctx, "CloseSession session=%s", k.sessionID) err := call(func() C.KernelStatusCode { return C.kernel_session_close(k.session) }) k.session = nil k.valid = false diff --git a/internal/backend/kernel/cgo.go b/internal/backend/kernel/cgo.go index 7aabd2cf..ae154593 100644 --- a/internal/backend/kernel/cgo.go +++ b/internal/backend/kernel/cgo.go @@ -34,44 +34,73 @@ package kernel import "C" import ( + "context" "fmt" "os" "runtime" "sync" "unsafe" + "github.com/databricks/databricks-sql-go/driverctx" "github.com/databricks/databricks-sql-go/logger" + "github.com/rs/zerolog" ) // ─── Debug logging ─────────────────────────────────────────────────────────── // -// Gated on DBSQL_KERNEL_DEBUG so it is OFF by default and, in particular, OFF -// during benchmarks (debug logging perturbs latency). Every binding step logs -// through klog when enabled — entry, status codes, handle addresses, batch -// counts — which is what makes a failing e2e cheap to diagnose. The same flag -// also installs the kernel's own Rust (tracing) logs via initKernelLogging, so -// binding and kernel logs interleave on stderr as one stream. -var kdebug = os.Getenv("DBSQL_KERNEL_DEBUG") != "" - -// Deferred (tracked): klog writes raw to stderr, NOT through the driver's -// logger.Logger, so its lines carry no connId/corrId/queryId and can't be -// correlated in a multi-conn process; it's also gated on its own -// DBSQL_KERNEL_DEBUG rather than the driver's DATABRICKS_LOG_LEVEL knob. Unifying -// kernel logging onto logger.Logger (which no-ops below its level, so no -// benchmark cost) is a tracked logging-unification follow-up, kept separate from -// this PR because it changes the debug-logging surface. +// Binding-level debug lines (entry, status codes, handle addresses, batch counts) +// go through the driver's shared logger.Logger at Debug level, so the SAME knob +// that controls the rest of the driver — DATABRICKS_LOG_LEVEL / dbsql.SetLogLevel +// — turns kernel binding logs on and off, and each line carries the structured +// connId/corrId/queryId fields (via klogCtx) that let it be correlated in a +// multi-conn process. zerolog no-ops a Debug() event when the level is above debug, +// so this stays zero-work (no allocation, no formatting) at the default Warn level +// — including during benchmarks, which run at the default level. +// +// DBSQL_KERNEL_DEBUG is retained only as an advanced override for the *kernel's own +// Rust logs* (see initKernelLogging): it forces the kernel subscriber on and lets +// RUST_LOG tune the kernel's verbosity independently. It no longer gates the Go +// binding lines — those follow the driver log level. + +// kernelDebugOff reports whether the driver log level is above Debug, i.e. kernel +// binding lines would be discarded. This is the cheap front gate for klog/klogCtx: +// GetLevel() is a plain field read, whereas building the event (and, for klogCtx, +// logger.WithContext → zerolog's With(), which eagerly make([]byte, 0, 500)s and +// formats the correlation keys) allocates BEFORE .Debug() consults the level. So we +// must short-circuit here to keep the hot path (per-batch nextBatch) allocation-free +// at the default Warn level — including during benchmarks. zerolog's own .Debug() +// no-op is not enough because the argument expressions run first. +func kernelDebugOff() bool { return logger.Logger.GetLevel() > zerolog.DebugLevel } + +// klog emits a binding-level debug line with no request context. Prefer klogCtx +// where a ctx is in scope so the line carries connId/corrId/queryId. Gated by the +// driver log level (Debug): a no-op — no formatting, no allocation — at the default. func klog(format string, args ...any) { - if !kdebug { + if kernelDebugOff() { return } - fmt.Fprintf(os.Stderr, "[kernel] "+format+"\n", args...) + logger.Logger.Debug().Msgf("[kernel] "+format, args...) } -// KernelDebugEnabled reports whether binding-level debug logging is on (i.e. -// DBSQL_KERNEL_DEBUG is set). Exposed so a benchmark can assert the flag is off -// before measuring — debug logging perturbs latency; there is no such benchmark -// in-tree yet, so this currently has no callers. -func KernelDebugEnabled() bool { return kdebug } +// klogCtx is klog with request correlation: it pulls connId/corrId/queryId off ctx +// (the conn layer stuffs them in before calling the backend, exactly as the Thrift +// path does) so a kernel binding line can be joined to the rest of a request's logs +// in a multi-conn process. A nil ctx degrades to klog. Level-gated up front so the +// logger.WithContext allocation never happens below Debug (see kernelDebugOff). +func klogCtx(ctx context.Context, format string, args ...any) { + if kernelDebugOff() { + return + } + if ctx == nil { + logger.Logger.Debug().Msgf("[kernel] "+format, args...) + return + } + logger.WithContext( + driverctx.ConnIdFromContext(ctx), + driverctx.CorrelationIdFromContext(ctx), + driverctx.QueryIdFromContext(ctx), + ).Debug().Msgf("[kernel] "+format, args...) +} // initLoggingOnce guards kernel_init_logging, which is process-wide and // first-call-wins in the kernel. We install the kernel subscriber lazily on the @@ -79,37 +108,72 @@ func KernelDebugEnabled() bool { return kdebug } // kernel session installs nothing. var initLoggingOnce sync.Once -// initKernelLogging turns on the kernel's own Rust (tracing) logs, gated on the -// same DBSQL_KERNEL_DEBUG flag as klog so both are OFF by default and, in -// particular, OFF during benchmarks — the subscriber is never installed in a -// benchmark run. level=NULL lets the kernel honor RUST_LOG (default warn); -// file_path=NULL sends kernel logs to stderr so they interleave with klog on one -// stream. Best-effort: Internal (e.g. the host already installed a global -// subscriber) is a documented, benign outcome — logged, never fatal to connect. +// initKernelLogging turns on the kernel's own Rust (tracing) logs and points their +// verbosity at the driver's log level, so DATABRICKS_LOG_LEVEL drives both the Go +// binding lines and the kernel's Rust lines from one knob. The mapped level is +// passed to kernel_init_logging (Go zerolog level → the kernel's OFF/ERROR/WARN/ +// INFO/DEBUG/TRACE string); DBSQL_KERNEL_DEBUG forces the subscriber on with a +// NULL level so the kernel honors RUST_LOG instead (the advanced override for +// tuning kernel-only verbosity). file_path=NULL sends kernel logs to stderr so they +// interleave with the driver's own output. +// +// Best-effort: an Internal return (e.g. the host already installed a global +// subscriber) is a documented, benign outcome — logged at Warn, never fatal to +// connect. Only installed when the effective level is at or below the kernel's +// threshold, so a driver left at the default Warn level (benchmarks included) that +// hasn't set DBSQL_KERNEL_DEBUG still installs the subscriber only at Warn — the +// kernel then emits nothing below Warn, so there is no hot-path cost. // // Scope caveat: the kernel subscriber is PROCESS-WIDE, first-call-wins, and never -// uninstalled. Because kdebug is read once from DBSQL_KERNEL_DEBUG at package -// init, the switch is process-global, not per-connection: in a long-lived -// multi-tenant process, the first kernel session opened with the flag set -// installs the subscriber (and its stderr output) for ALL subsequent kernel -// sessions in that process, and there is no way to scope it to one connection or -// turn it off afterward. The "off during benchmarks" guarantee therefore depends -// on DBSQL_KERNEL_DEBUG being unset before package init. Making this a -// per-process runtime knob (rather than an init-time env read) is tracked with -// the logging-unification follow-up. +// uninstalled — in a long-lived multi-tenant process the first kernel session's +// level/destination applies to ALL subsequent kernel sessions, with no way to +// re-scope or turn it off afterward. That is a kernel-ABI property, not a Go one. func initKernelLogging() { - if !kdebug { - return - } initLoggingOnce.Do(func() { + // DBSQL_KERNEL_DEBUG override: force the subscriber on and let RUST_LOG tune + // it (level=NULL). Otherwise map the driver's current log level in, so the + // one DATABRICKS_LOG_LEVEL knob governs kernel verbosity too. + var level cStr + if os.Getenv("DBSQL_KERNEL_DEBUG") != "" { + level = cStr{c: nil} // NULL → kernel honors RUST_LOG + } else { + level = newCStr(kernelLogLevel(logger.Logger.GetLevel())) + defer level.free() + } if err := call(func() C.KernelStatusCode { - return C.kernel_init_logging(nil, nil) + return C.kernel_init_logging(level.c, nil) }); err != nil { - klog("kernel_init_logging: %v (kernel logs unavailable; proceeding)", err) + // The kernel subscriber didn't install (commonly: the host already + // installed a global tracing subscriber). Non-fatal — surface it through + // the shared logger so it's visible without a separate stderr scrape. + logger.Logger.Warn().Msgf("databricks: kernel_init_logging: %v (kernel logs unavailable; proceeding)", err) } }) } +// kernelLogLevel maps a zerolog level to the level string kernel_init_logging +// accepts (OFF/ERROR/WARN/INFO/DEBUG/TRACE), so the driver's log level drives the +// kernel's Rust logs. An unrecognized level falls back to WARN (the kernel's own +// default), matching the driver's default. +func kernelLogLevel(l zerolog.Level) string { + switch l { + case zerolog.TraceLevel: + return "TRACE" + case zerolog.DebugLevel: + return "DEBUG" + case zerolog.InfoLevel: + return "INFO" + case zerolog.WarnLevel: + return "WARN" + case zerolog.ErrorLevel, zerolog.FatalLevel, zerolog.PanicLevel: + return "ERROR" + case zerolog.Disabled: + return "OFF" + default: + return "WARN" + } +} + // call runs a fallible kernel entry point and, on a non-Success status, reads // the kernel's thread-local last error into a Go error. // diff --git a/internal/backend/kernel/kernel_test.go b/internal/backend/kernel/kernel_test.go index 8582a501..d67da97c 100644 --- a/internal/backend/kernel/kernel_test.go +++ b/internal/backend/kernel/kernel_test.go @@ -8,8 +8,11 @@ import ( "errors" "testing" + "github.com/databricks/databricks-sql-go/driverctx" dbsqlerr "github.com/databricks/databricks-sql-go/errors" "github.com/databricks/databricks-sql-go/internal/backend" + "github.com/databricks/databricks-sql-go/logger" + "github.com/rs/zerolog" ) // setAuth maps each Auth mode to exactly one kernel_session_config_set_auth_* @@ -70,6 +73,58 @@ func TestSetKernelTLS(t *testing.T) { } } +// kernelLogLevel maps the driver's zerolog level to the kernel_init_logging level +// string, so DATABRICKS_LOG_LEVEL drives the kernel's Rust logs too. Pin the +// mapping (incl. the fatal/panic→ERROR collapse and the default→WARN fallback) so +// a level the kernel would reject can't silently ship. +func TestKernelLogLevel(t *testing.T) { + cases := []struct { + in zerolog.Level + want string + }{ + {zerolog.TraceLevel, "TRACE"}, + {zerolog.DebugLevel, "DEBUG"}, + {zerolog.InfoLevel, "INFO"}, + {zerolog.WarnLevel, "WARN"}, + {zerolog.ErrorLevel, "ERROR"}, + {zerolog.FatalLevel, "ERROR"}, + {zerolog.PanicLevel, "ERROR"}, + {zerolog.Disabled, "OFF"}, + {zerolog.NoLevel, "WARN"}, // unrecognized → the kernel's own default + } + for _, c := range cases { + if got := kernelLogLevel(c.in); got != c.want { + t.Errorf("kernelLogLevel(%v) = %q, want %q", c.in, got, c.want) + } + } +} + +// klog / klogCtx must be allocation-free at the default (above-Debug) log level — +// the "no hot-path cost, safe during benchmarks" guarantee. klogCtx is the one that +// matters: logger.WithContext eagerly allocates (zerolog's With() does +// make([]byte, 0, 500)) BEFORE the .Debug() gate, so without the up-front +// kernelDebugOff() guard this would allocate ~500 B per call — per Arrow batch on the +// nextBatch hot path. Guards against reintroducing that (an Isaac Review MAJOR). +func TestKernelLogNoAllocWhenOff(t *testing.T) { + prev := logger.Logger.GetLevel() + if err := logger.SetLogLevel("warn"); err != nil { // the default level + t.Fatal(err) + } + defer logger.SetLogLevel(prev.String()) //nolint:errcheck // restoring a known-good level + + ctx := driverctx.NewContextWithConnId(context.Background(), "conn-1") + if n := testing.AllocsPerRun(100, func() { + klog("hot path %d", 1) + }); n != 0 { + t.Errorf("klog allocated %v times at Warn level, want 0", n) + } + if n := testing.AllocsPerRun(100, func() { + klogCtx(ctx, "hot path %d", 1) + }); n != 0 { + t.Errorf("klogCtx allocated %v times at Warn level, want 0", n) + } +} + // The pure error-classifier tests (TestIsBadConnection, TestIsSessionFatal, // TestToConnError, TestToStatementErrorNeverBadConn) live in the untagged // errors_classify_test.go so they run under CGO_ENABLED=0. The tests below need a diff --git a/internal/backend/kernel/operation.go b/internal/backend/kernel/operation.go index 92a6c91b..1a550caa 100644 --- a/internal/backend/kernel/operation.go +++ b/internal/backend/kernel/operation.go @@ -37,7 +37,7 @@ func (k *KernelBackend) execute(ctx context.Context, req backend.ExecRequest) (b // Log the SQL length, not the text: query bodies can carry PII/secrets in // WHERE/INSERT/SET, and this goes to stderr. Matches the driver's own // debuglog convention (conn.ExecContext logs sql.len=%d). - klog("Execute sql.len=%d", len(req.Query)) + klogCtx(ctx, "Execute sql.len=%d", len(req.Query)) var stmt *C.kernel_statement_t if err := call(func() C.KernelStatusCode { @@ -76,7 +76,7 @@ func (k *KernelBackend) execute(ctx context.Context, req backend.ExecRequest) (b if err := call(func() C.KernelStatusCode { return C.kernel_statement_canceller_new(stmt, &canceller) }); err != nil { - klog("canceller_new failed (proceeding without cancel): %v", err) + klogCtx(ctx, "canceller_new failed (proceeding without cancel): %v", err) canceller = nil } @@ -111,11 +111,11 @@ func (k *KernelBackend) execute(ctx context.Context, req backend.ExecRequest) (b return default: } - klog("ctx.Done (%v) → firing canceller (with retry until dispatched)", ctx.Err()) + klogCtx(ctx, "ctx.Done (%v) → firing canceller (with retry until dispatched)", ctx.Err()) ticker := time.NewTicker(250 * time.Millisecond) defer ticker.Stop() if fireCancel(canceller) { - klog("cancel dispatched on first fire") + klogCtx(ctx, "cancel dispatched on first fire") return } for { @@ -124,7 +124,7 @@ func (k *KernelBackend) execute(ctx context.Context, req backend.ExecRequest) (b return case <-ticker.C: if fireCancel(canceller) { - klog("cancel dispatched, watcher stopping") + klogCtx(ctx, "cancel dispatched, watcher stopping") return } } @@ -165,11 +165,11 @@ func (k *KernelBackend) execute(ctx context.Context, req backend.ExecRequest) (b // otherwise a session-fatal failure racing a cancel would lose its // sqlstate/queryId, the one handle to what actually went wrong server-side. if ctx.Err() != nil { - klog("Execute failed under cancelled ctx: kernelErr=%v ctxErr=%v", execErr, ctx.Err()) + klogCtx(ctx, "Execute failed under cancelled ctx: kernelErr=%v ctxErr=%v", execErr, ctx.Err()) op.close() return op, fmt.Errorf("kernel: execute cancelled: %w (kernel error: %w)", ctx.Err(), toStatementError(execErr)) } - klog("Execute failed: %v", execErr) + klogCtx(ctx, "Execute failed: %v", execErr) // We still return the PLAIN error (toStatementError, never ErrBadConn), so the // conn is discarded without database/sql re-running the statement. op.close() @@ -192,7 +192,7 @@ func (k *KernelBackend) execute(ctx context.Context, req backend.ExecRequest) (b if qid := C.kernel_executed_statement_query_id(exec); qid != nil { op.statementID = C.GoString(qid) // deep-copies out of the borrowed C string } - klog("Execute OK stmt=%p exec=%p affectedRows=%d statementID=%q", stmt, exec, op.affectedRows, op.statementID) + klogCtx(ctx, "Execute OK stmt=%p exec=%p affectedRows=%d statementID=%q", stmt, exec, op.affectedRows, op.statementID) return op, nil } diff --git a/internal/backend/kernel/rows.go b/internal/backend/kernel/rows.go index 82df1920..b03290f4 100644 --- a/internal/backend/kernel/rows.go +++ b/internal/backend/kernel/rows.go @@ -76,7 +76,7 @@ func newKernelRows(ctx context.Context, op *kernelOp, stream *C.kernel_result_st for i, f := range fields { r.cols[i] = f.Name } - klog("newKernelRows: %d columns", len(r.cols)) + klogCtx(ctx, "newKernelRows: %d columns", len(r.cols)) return r, nil } @@ -101,7 +101,7 @@ func (r *kernelRows) Close() error { if r.op != nil { r.op.close() } - klog("kernelRows closed") + klogCtx(r.ctx, "kernelRows closed") return nil } @@ -161,7 +161,7 @@ func (r *kernelRows) nextBatch() error { } if carr.release == nil { r.eof = true - klog("nextBatch: EOF") + klogCtx(r.ctx, "nextBatch: EOF") return io.EOF } // Zero-copy import. The kernel exports self-contained batches (Rust to_ffi @@ -189,6 +189,6 @@ func (r *kernelRows) nextBatch() error { // reports — a fabricated number would be worse than a truthful zero. r.callbacks.OnChunkFetched(r.chunkCount, 0, 0, 0, 0) } - klog("nextBatch: %d rows (chunk %d)", rec.NumRows(), r.chunkCount) + klogCtx(r.ctx, "nextBatch: %d rows (chunk %d)", rec.NumRows(), r.chunkCount) return nil } From c3288b43f7a187a6d11691503d76cbbb83a729c6 Mon Sep 17 00:00:00 2001 From: Mani Kaustubh Mathur Date: Wed, 15 Jul 2026 07:06:54 +0000 Subject: [PATCH 2/3] fix(kernel): tighten logging docs + fatal/panic->OFF + correlation test MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Address the review comments on #401 — the Go binding logs now follow the live driver logger, but the Rust subscriber is process-wide/first-call-wins and stderr-only, so several "one unified knob" claims were stronger than the implementation. Fixes, all in the kernel backend (databricks_kernel tag; the default pure-Go build is unaffected): - doc.go: Rust logs are stderr-only and NOT routed through logger.SetLogOutput; Rust verbosity is fixed at the first kernel session (set the level before the first connection); "each line carries connId/corrId/queryId" softened to request-scoped lines where a ctx is in scope (bindParams / operation teardown stay uncorrelated). - cgo.go: kernelLogLevel maps FatalLevel/PanicLevel -> OFF (not ERROR), so the Rust subscriber is never louder than the driver the user configured — at driver=fatal the Go side suppresses even Error() lines. Tightened the initKernelLogging comment to state the first-session level sampling and the stderr-only sink, and dropped the inaccurate "only installed when the level is at or below the threshold" sentence. - kernel_test.go: TestKernelLogLevel updated for fatal/panic->OFF; new TestKernelLogCtxEmitsCorrelation captures logger output at debug level and asserts klogCtx emits the message + connId/corrId/queryId, then asserts silence at warn — the positive-behavior half the alloc test can't see. Verified: CGO_ENABLED=0 build+vet+test green; CGO_ENABLED=1 -tags databricks_kernel build+vet green, kernel package tests pass (incl. all three log tests). Co-authored-by: Isaac Signed-off-by: Mani Kaustubh Mathur --- doc.go | 34 +++++++++--- internal/backend/kernel/cgo.go | 27 ++++++--- internal/backend/kernel/kernel_test.go | 76 ++++++++++++++++++++++++-- 3 files changed, 116 insertions(+), 21 deletions(-) diff --git a/doc.go b/doc.go index 3378cdc3..6856d4da 100644 --- a/doc.go +++ b/doc.go @@ -189,19 +189,35 @@ time rather than silently using Thrift. Kernel-backend logging follows the same knob as the rest of the driver. The binding-layer trace (session/statement/batch steps) is emitted through the shared logger at Debug level, so DATABRICKS_LOG_LEVEL=debug or dbsql.SetLogLevel("debug") -turns it on — no separate switch — and each line carries the same structured -connId/corrId/queryId fields as the driver's other logs, so it can be correlated in -a multi-connection process. At the default Warn level the lines are suppressed with -no cost (zerolog no-ops a below-level event), including during benchmarks. +turns it on — no separate switch — and it lands in the same sink the rest of the +driver uses (including a custom one set via logger.SetLogOutput). Request-scoped +binding lines carry the same structured connId/corrId/queryId fields as the +driver's other logs where a context is in scope (session open/close, execute, +result-batch fetch), so they can be correlated in a multi-connection process; a few +context-less lines (parameter binds, operation teardown) are emitted without those +fields. At the default Warn level the lines are suppressed with no cost (zerolog +no-ops a below-level event), including during benchmarks. dbsql.SetLogLevel("debug") // or DATABRICKS_LOG_LEVEL=debug The driver's log level is also mapped into the kernel's own Rust log subscriber, so -the same knob governs the kernel's internal (Rust) logs; they write to stderr and -interleave with the driver's output. Note the kernel's Rust lines are currently -plain text and do NOT yet carry the structured connId/corrId/queryId fields — that -needs a kernel log-callback ABI (tracked separately); only the Go binding lines are -structured today. +the same knob governs the kernel's internal (Rust) verbosity. Two caveats apply to +the Rust logs specifically, both consequences of the kernel's process-wide logging +ABI rather than the Go layer: + + - They are written to stderr directly and are NOT affected by + logger.SetLogOutput — an app that routes the driver's Go logs to a file or an + app logger will still find the Rust lines on stderr, not interleaved with that + sink. + - The Rust verbosity is fixed at the level in effect when the FIRST kernel + session in the process is opened (the kernel subscriber is process-wide and + installed once); a later dbsql.SetLogLevel changes the Go binding lines but not + the already-installed Rust subscriber. Set the level before opening the first + kernel connection to control the Rust logs. + +The kernel's Rust lines are also currently plain text and do NOT yet carry the +structured connId/corrId/queryId fields — that needs a kernel log-callback ABI +(tracked separately); only the Go binding lines are structured today. For finer control of the kernel's Rust verbosity independent of the driver level, set DBSQL_KERNEL_DEBUG to any non-empty value: it forces the kernel subscriber on diff --git a/internal/backend/kernel/cgo.go b/internal/backend/kernel/cgo.go index ae154593..15303067 100644 --- a/internal/backend/kernel/cgo.go +++ b/internal/backend/kernel/cgo.go @@ -114,20 +114,25 @@ var initLoggingOnce sync.Once // passed to kernel_init_logging (Go zerolog level → the kernel's OFF/ERROR/WARN/ // INFO/DEBUG/TRACE string); DBSQL_KERNEL_DEBUG forces the subscriber on with a // NULL level so the kernel honors RUST_LOG instead (the advanced override for -// tuning kernel-only verbosity). file_path=NULL sends kernel logs to stderr so they -// interleave with the driver's own output. +// tuning kernel-only verbosity). file_path=NULL sends kernel logs to stderr — the +// kernel ABI has no sink hook, so the Rust lines always go to stderr and are NOT +// routed through logger.SetLogOutput (unlike the Go binding lines). // // Best-effort: an Internal return (e.g. the host already installed a global // subscriber) is a documented, benign outcome — logged at Warn, never fatal to -// connect. Only installed when the effective level is at or below the kernel's -// threshold, so a driver left at the default Warn level (benchmarks included) that -// hasn't set DBSQL_KERNEL_DEBUG still installs the subscriber only at Warn — the -// kernel then emits nothing below Warn, so there is no hot-path cost. +// connect. The subscriber installs at whatever level is mapped in; a driver left at +// the default Warn level (benchmarks included, and never having set +// DBSQL_KERNEL_DEBUG) installs it at WARN, so the kernel emits nothing below Warn +// and there is no hot-path cost. // // Scope caveat: the kernel subscriber is PROCESS-WIDE, first-call-wins, and never // uninstalled — in a long-lived multi-tenant process the first kernel session's // level/destination applies to ALL subsequent kernel sessions, with no way to // re-scope or turn it off afterward. That is a kernel-ABI property, not a Go one. +// A direct consequence: the driver level is sampled HERE, once, at the first kernel +// session — a later dbsql.SetLogLevel re-levels the Go binding lines (klog/klogCtx +// re-read GetLevel per call) but NOT the already-installed Rust subscriber. Set the +// level before opening the first kernel connection to govern the Rust logs. func initKernelLogging() { initLoggingOnce.Do(func() { // DBSQL_KERNEL_DEBUG override: force the subscriber on and let RUST_LOG tune @@ -155,6 +160,12 @@ func initKernelLogging() { // accepts (OFF/ERROR/WARN/INFO/DEBUG/TRACE), so the driver's log level drives the // kernel's Rust logs. An unrecognized level falls back to WARN (the kernel's own // default), matching the driver's default. +// +// FatalLevel/PanicLevel map to OFF, not ERROR: at those levels the Go driver +// suppresses even its own Error() lines, so the kernel's Rust subscriber must not +// be louder than the driver the user configured — the kernel has no fatal/panic +// threshold, and emitting ERROR lines there would leak stderr output a user who set +// DATABRICKS_LOG_LEVEL=fatal explicitly asked to silence. func kernelLogLevel(l zerolog.Level) string { switch l { case zerolog.TraceLevel: @@ -165,9 +176,9 @@ func kernelLogLevel(l zerolog.Level) string { return "INFO" case zerolog.WarnLevel: return "WARN" - case zerolog.ErrorLevel, zerolog.FatalLevel, zerolog.PanicLevel: + case zerolog.ErrorLevel: return "ERROR" - case zerolog.Disabled: + case zerolog.FatalLevel, zerolog.PanicLevel, zerolog.Disabled: return "OFF" default: return "WARN" diff --git a/internal/backend/kernel/kernel_test.go b/internal/backend/kernel/kernel_test.go index d67da97c..775b5854 100644 --- a/internal/backend/kernel/kernel_test.go +++ b/internal/backend/kernel/kernel_test.go @@ -3,9 +3,12 @@ package kernel import ( + "bytes" "context" "database/sql/driver" + "encoding/json" "errors" + "os" "testing" "github.com/databricks/databricks-sql-go/driverctx" @@ -75,8 +78,10 @@ func TestSetKernelTLS(t *testing.T) { // kernelLogLevel maps the driver's zerolog level to the kernel_init_logging level // string, so DATABRICKS_LOG_LEVEL drives the kernel's Rust logs too. Pin the -// mapping (incl. the fatal/panic→ERROR collapse and the default→WARN fallback) so -// a level the kernel would reject can't silently ship. +// mapping (incl. the fatal/panic→OFF collapse and the default→WARN fallback) so a +// level the kernel would reject can't silently ship. fatal/panic map to OFF, not +// ERROR: the Go driver suppresses even Error() lines at those levels, so the Rust +// subscriber must stay at least as quiet as the driver the user configured. func TestKernelLogLevel(t *testing.T) { cases := []struct { in zerolog.Level @@ -87,8 +92,8 @@ func TestKernelLogLevel(t *testing.T) { {zerolog.InfoLevel, "INFO"}, {zerolog.WarnLevel, "WARN"}, {zerolog.ErrorLevel, "ERROR"}, - {zerolog.FatalLevel, "ERROR"}, - {zerolog.PanicLevel, "ERROR"}, + {zerolog.FatalLevel, "OFF"}, // driver suppresses Error() here → kernel stays silent, not louder + {zerolog.PanicLevel, "OFF"}, {zerolog.Disabled, "OFF"}, {zerolog.NoLevel, "WARN"}, // unrecognized → the kernel's own default } @@ -125,6 +130,69 @@ func TestKernelLogNoAllocWhenOff(t *testing.T) { } } +// TestKernelLogCtxEmitsCorrelation proves the positive half of the contract the +// alloc test can't see: at debug level klogCtx actually EMITS through the shared +// logger AND attaches connId/corrId/queryId, and at the default warn level it emits +// nothing. Without this, a regression that silently stopped emitting or stopped +// attaching the fields would still pass TestKernelLogNoAllocWhenOff (0 allocs is +// also what "emit nothing" looks like). +func TestKernelLogCtxEmitsCorrelation(t *testing.T) { + prev := logger.Logger.GetLevel() + var buf bytes.Buffer + logger.SetLogOutput(&buf) + // Restore the package defaults (stderr sink, prior level) so we don't leak the + // buffer/level into sibling tests. + defer func() { + logger.SetLogOutput(os.Stderr) + _ = logger.SetLogLevel(prev.String()) + }() + + ctx := driverctx.NewContextWithConnId(context.Background(), "conn-1") + ctx = driverctx.NewContextWithCorrelationId(ctx, "corr-2") + ctx = driverctx.NewContextWithQueryId(ctx, "query-3") + + // Debug level: the line is emitted and carries all three correlation fields. + if err := logger.SetLogLevel("debug"); err != nil { + t.Fatal(err) + } + klogCtx(ctx, "step %s", "execute") + + var rec struct { + Level string `json:"level"` + Message string `json:"message"` + ConnID string `json:"connId"` + CorrID string `json:"corrId"` + QueryID string `json:"queryId"` + } + line := bytes.TrimSpace(buf.Bytes()) + if len(line) == 0 { + t.Fatal("klogCtx emitted nothing at debug level, want one line") + } + if err := json.Unmarshal(line, &rec); err != nil { + t.Fatalf("klogCtx output is not the expected JSON log line: %v (line: %s)", err, line) + } + if rec.Level != "debug" { + t.Errorf("level = %q, want %q", rec.Level, "debug") + } + if rec.Message != "[kernel] step execute" { + t.Errorf("message = %q, want %q", rec.Message, "[kernel] step execute") + } + if rec.ConnID != "conn-1" || rec.CorrID != "corr-2" || rec.QueryID != "query-3" { + t.Errorf("correlation fields = {connId:%q corrId:%q queryId:%q}, want {conn-1 corr-2 query-3}", + rec.ConnID, rec.CorrID, rec.QueryID) + } + + // Warn level (the default): nothing is emitted. + buf.Reset() + if err := logger.SetLogLevel("warn"); err != nil { + t.Fatal(err) + } + klogCtx(ctx, "step %s", "execute") + if got := bytes.TrimSpace(buf.Bytes()); len(got) != 0 { + t.Errorf("klogCtx emitted %q at warn level, want nothing", got) + } +} + // The pure error-classifier tests (TestIsBadConnection, TestIsSessionFatal, // TestToConnError, TestToStatementErrorNeverBadConn) live in the untagged // errors_classify_test.go so they run under CGO_ENABLED=0. The tests below need a From aa27368f97f72691b52478369b03a3b77da7664f Mon Sep 17 00:00:00 2001 From: Mani Kaustubh Mathur Date: Wed, 15 Jul 2026 08:22:55 +0000 Subject: [PATCH 3/3] test(kernel): add resolveKernelLogArg seam + untagged level tests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Follow-up to the #401 review (finding 5, thread on kernel_test.go): the level- resolution logic initKernelLogging feeds to kernel_init_logging was documented but not tested. Extract the pure decision so it can be pinned by CI without cgo. - New untagged logging_level.go holds kernelLogLevel (moved out of cgo.go) and a new resolveKernelLogArg() (level string, useNULL bool): the NULL-on- DBSQL_KERNEL_DEBUG override vs the mapped driver level. Mirrors the existing errors_classify.go pattern (pure logic, no build tag) so its tests run under CGO_ENABLED=0. cgo.go's initKernelLogging is now a thin caller of it. - New untagged logging_level_test.go: TestKernelLogLevel (moved) + new TestResolveKernelLogArg, which pins the two invariants the PR justifies in prose — DBSQL_KERNEL_DEBUG (non-empty) yields useNULL=true so the kernel honors RUST_LOG, and otherwise the driver level is mapped in (incl. fatal→OFF). Empty value is treated as unset. - Drops the now-unused os import from cgo.go and zerolog from kernel_test.go. Not covered (documented, cost/value flips): that the string is actually handed to C.kernel_init_logging and the sync.Once first-call-wins — asserting those needs a function-pointer seam over the cgo call plus resetting a package global, to test one assignment + stdlib sync.Once. Verified: CGO_ENABLED=0 build+vet+test green (both new tests run here); CGO_ENABLED=1 -tags databricks_kernel build+vet green, all four log tests pass. Co-authored-by: Isaac Signed-off-by: Mani Kaustubh Mathur --- internal/backend/kernel/cgo.go | 44 ++-------- internal/backend/kernel/kernel_test.go | 31 +------ internal/backend/kernel/logging_level.go | 67 ++++++++++++++ internal/backend/kernel/logging_level_test.go | 87 +++++++++++++++++++ 4 files changed, 163 insertions(+), 66 deletions(-) create mode 100644 internal/backend/kernel/logging_level.go create mode 100644 internal/backend/kernel/logging_level_test.go diff --git a/internal/backend/kernel/cgo.go b/internal/backend/kernel/cgo.go index 15303067..cd604121 100644 --- a/internal/backend/kernel/cgo.go +++ b/internal/backend/kernel/cgo.go @@ -36,7 +36,6 @@ import "C" import ( "context" "fmt" - "os" "runtime" "sync" "unsafe" @@ -135,16 +134,14 @@ var initLoggingOnce sync.Once // level before opening the first kernel connection to govern the Rust logs. func initKernelLogging() { initLoggingOnce.Do(func() { - // DBSQL_KERNEL_DEBUG override: force the subscriber on and let RUST_LOG tune - // it (level=NULL). Otherwise map the driver's current log level in, so the - // one DATABRICKS_LOG_LEVEL knob governs kernel verbosity too. + // resolveKernelLogArg decides the level (or NULL for the DBSQL_KERNEL_DEBUG + // override, which lets the kernel honor RUST_LOG). The pure decision lives in + // logging_level.go so it's unit-tested without cgo. var level cStr - if os.Getenv("DBSQL_KERNEL_DEBUG") != "" { - level = cStr{c: nil} // NULL → kernel honors RUST_LOG - } else { - level = newCStr(kernelLogLevel(logger.Logger.GetLevel())) + if lvl, useNULL := resolveKernelLogArg(); !useNULL { + level = newCStr(lvl) defer level.free() - } + } // else level stays {c: nil} → NULL → kernel honors RUST_LOG if err := call(func() C.KernelStatusCode { return C.kernel_init_logging(level.c, nil) }); err != nil { @@ -156,35 +153,6 @@ func initKernelLogging() { }) } -// kernelLogLevel maps a zerolog level to the level string kernel_init_logging -// accepts (OFF/ERROR/WARN/INFO/DEBUG/TRACE), so the driver's log level drives the -// kernel's Rust logs. An unrecognized level falls back to WARN (the kernel's own -// default), matching the driver's default. -// -// FatalLevel/PanicLevel map to OFF, not ERROR: at those levels the Go driver -// suppresses even its own Error() lines, so the kernel's Rust subscriber must not -// be louder than the driver the user configured — the kernel has no fatal/panic -// threshold, and emitting ERROR lines there would leak stderr output a user who set -// DATABRICKS_LOG_LEVEL=fatal explicitly asked to silence. -func kernelLogLevel(l zerolog.Level) string { - switch l { - case zerolog.TraceLevel: - return "TRACE" - case zerolog.DebugLevel: - return "DEBUG" - case zerolog.InfoLevel: - return "INFO" - case zerolog.WarnLevel: - return "WARN" - case zerolog.ErrorLevel: - return "ERROR" - case zerolog.FatalLevel, zerolog.PanicLevel, zerolog.Disabled: - return "OFF" - default: - return "WARN" - } -} - // call runs a fallible kernel entry point and, on a non-Success status, reads // the kernel's thread-local last error into a Go error. // diff --git a/internal/backend/kernel/kernel_test.go b/internal/backend/kernel/kernel_test.go index 775b5854..a293f915 100644 --- a/internal/backend/kernel/kernel_test.go +++ b/internal/backend/kernel/kernel_test.go @@ -15,7 +15,6 @@ import ( dbsqlerr "github.com/databricks/databricks-sql-go/errors" "github.com/databricks/databricks-sql-go/internal/backend" "github.com/databricks/databricks-sql-go/logger" - "github.com/rs/zerolog" ) // setAuth maps each Auth mode to exactly one kernel_session_config_set_auth_* @@ -76,33 +75,9 @@ func TestSetKernelTLS(t *testing.T) { } } -// kernelLogLevel maps the driver's zerolog level to the kernel_init_logging level -// string, so DATABRICKS_LOG_LEVEL drives the kernel's Rust logs too. Pin the -// mapping (incl. the fatal/panic→OFF collapse and the default→WARN fallback) so a -// level the kernel would reject can't silently ship. fatal/panic map to OFF, not -// ERROR: the Go driver suppresses even Error() lines at those levels, so the Rust -// subscriber must stay at least as quiet as the driver the user configured. -func TestKernelLogLevel(t *testing.T) { - cases := []struct { - in zerolog.Level - want string - }{ - {zerolog.TraceLevel, "TRACE"}, - {zerolog.DebugLevel, "DEBUG"}, - {zerolog.InfoLevel, "INFO"}, - {zerolog.WarnLevel, "WARN"}, - {zerolog.ErrorLevel, "ERROR"}, - {zerolog.FatalLevel, "OFF"}, // driver suppresses Error() here → kernel stays silent, not louder - {zerolog.PanicLevel, "OFF"}, - {zerolog.Disabled, "OFF"}, - {zerolog.NoLevel, "WARN"}, // unrecognized → the kernel's own default - } - for _, c := range cases { - if got := kernelLogLevel(c.in); got != c.want { - t.Errorf("kernelLogLevel(%v) = %q, want %q", c.in, got, c.want) - } - } -} +// TestKernelLogLevel and TestResolveKernelLogArg — the pure level-resolution tests — +// live in the untagged logging_level_test.go so they run under CGO_ENABLED=0. The +// tests below exercise klog/klogCtx and so need the cgo build. // klog / klogCtx must be allocation-free at the default (above-Debug) log level — // the "no hot-path cost, safe during benchmarks" guarantee. klogCtx is the one that diff --git a/internal/backend/kernel/logging_level.go b/internal/backend/kernel/logging_level.go new file mode 100644 index 00000000..a4a7d330 --- /dev/null +++ b/internal/backend/kernel/logging_level.go @@ -0,0 +1,67 @@ +package kernel + +import ( + "os" + + "github.com/databricks/databricks-sql-go/logger" + "github.com/rs/zerolog" +) + +// This file is intentionally NOT behind the `cgo && databricks_kernel` build tag. +// It holds the pure level-resolution logic that decides what verbosity the kernel's +// Rust subscriber is initialized with — the zerolog→kernel level mapping and the +// DBSQL_KERNEL_DEBUG override. Keeping it out of the cgo file lets its tests run in +// the default CGO_ENABLED=0 build (matching errors_classify.go), so the load-bearing +// decisions — that fatal/panic collapse to OFF, and that DBSQL_KERNEL_DEBUG yields a +// NULL level so the kernel honors RUST_LOG — are pinned by CI rather than only by +// comments. cgo.go's initKernelLogging is the thin cgo caller: it turns the result +// into a C string (or NULL) and hands it to kernel_init_logging. + +// kernelLogLevel maps a zerolog level to the level string kernel_init_logging +// accepts (OFF/ERROR/WARN/INFO/DEBUG/TRACE), so the driver's log level drives the +// kernel's Rust logs. An unrecognized level falls back to WARN (the kernel's own +// default), matching the driver's default. +// +// FatalLevel/PanicLevel map to OFF, not ERROR: at those levels the Go driver +// suppresses even its own Error() lines, so the kernel's Rust subscriber must not +// be louder than the driver the user configured — the kernel has no fatal/panic +// threshold, and emitting ERROR lines there would leak stderr output a user who set +// DATABRICKS_LOG_LEVEL=fatal explicitly asked to silence. +func kernelLogLevel(l zerolog.Level) string { + switch l { + case zerolog.TraceLevel: + return "TRACE" + case zerolog.DebugLevel: + return "DEBUG" + case zerolog.InfoLevel: + return "INFO" + case zerolog.WarnLevel: + return "WARN" + case zerolog.ErrorLevel: + return "ERROR" + case zerolog.FatalLevel, zerolog.PanicLevel, zerolog.Disabled: + return "OFF" + default: + return "WARN" + } +} + +// resolveKernelLogArg decides the level string to pass to kernel_init_logging and +// whether to pass NULL instead. It is the pure core of initKernelLogging, split out +// so it can be unit-tested without cgo. +// +// DBSQL_KERNEL_DEBUG (any non-empty value) is the advanced override: it returns +// useNULL=true so the cgo caller passes a NULL level, which makes the kernel honor +// RUST_LOG for its own verbosity — independent of the driver level, and with the +// per-target filtering (e.g. the hyper/reqwest HTTP stack) that the single mapped +// level can't express. The kernel reads RUST_LOG ONLY when the level is NULL; a +// non-NULL level shadows it. So without this override, RUST_LOG is inert — the +// mapped driver level always wins. Otherwise it returns the driver's current level +// mapped via kernelLogLevel, so the one DATABRICKS_LOG_LEVEL knob governs kernel +// verbosity too. When useNULL is true the level string is unused (empty). +func resolveKernelLogArg() (level string, useNULL bool) { + if os.Getenv("DBSQL_KERNEL_DEBUG") != "" { + return "", true + } + return kernelLogLevel(logger.Logger.GetLevel()), false +} diff --git a/internal/backend/kernel/logging_level_test.go b/internal/backend/kernel/logging_level_test.go new file mode 100644 index 00000000..90449f71 --- /dev/null +++ b/internal/backend/kernel/logging_level_test.go @@ -0,0 +1,87 @@ +package kernel + +import ( + "os" + "testing" + + "github.com/databricks/databricks-sql-go/logger" + "github.com/rs/zerolog" +) + +// kernelLogLevel maps the driver's zerolog level to the kernel_init_logging level +// string, so DATABRICKS_LOG_LEVEL drives the kernel's Rust logs too. Pin the +// mapping (incl. the fatal/panic→OFF collapse and the default→WARN fallback) so a +// level the kernel would reject can't silently ship. fatal/panic map to OFF, not +// ERROR: the Go driver suppresses even Error() lines at those levels, so the Rust +// subscriber must stay at least as quiet as the driver the user configured. Lives +// in the untagged file so it runs under CGO_ENABLED=0. +func TestKernelLogLevel(t *testing.T) { + cases := []struct { + in zerolog.Level + want string + }{ + {zerolog.TraceLevel, "TRACE"}, + {zerolog.DebugLevel, "DEBUG"}, + {zerolog.InfoLevel, "INFO"}, + {zerolog.WarnLevel, "WARN"}, + {zerolog.ErrorLevel, "ERROR"}, + {zerolog.FatalLevel, "OFF"}, // driver suppresses Error() here → kernel stays silent, not louder + {zerolog.PanicLevel, "OFF"}, + {zerolog.Disabled, "OFF"}, + {zerolog.NoLevel, "WARN"}, // unrecognized → the kernel's own default + } + for _, c := range cases { + if got := kernelLogLevel(c.in); got != c.want { + t.Errorf("kernelLogLevel(%v) = %q, want %q", c.in, got, c.want) + } + } +} + +// TestResolveKernelLogArg pins the level-vs-NULL decision initKernelLogging feeds to +// kernel_init_logging — the behavior the PR justifies in prose but the cgo path +// can't easily assert. Two invariants: DBSQL_KERNEL_DEBUG (any non-empty value) must +// yield useNULL=true so the kernel honors RUST_LOG (the whole point of retaining the +// knob — a NULL level is the ONLY way the kernel consults RUST_LOG); otherwise the +// driver's current level is mapped in, so DATABRICKS_LOG_LEVEL governs kernel +// verbosity too. Runs under CGO_ENABLED=0 (no cgo in the resolution path). +func TestResolveKernelLogArg(t *testing.T) { + // Save/restore the env var and the global logger level so this test leaves no + // state behind for its siblings. + prevEnv, hadEnv := os.LookupEnv("DBSQL_KERNEL_DEBUG") + prevLevel := logger.Logger.GetLevel() + t.Cleanup(func() { + if hadEnv { + os.Setenv("DBSQL_KERNEL_DEBUG", prevEnv) + } else { + os.Unsetenv("DBSQL_KERNEL_DEBUG") + } + logger.Logger.Logger = logger.Logger.Level(prevLevel) + }) + + // DBSQL_KERNEL_DEBUG set → NULL level (kernel honors RUST_LOG), regardless of the + // driver level. Pin it at debug to prove the override wins over the mapped level. + logger.Logger.Logger = logger.Logger.Level(zerolog.DebugLevel) + os.Setenv("DBSQL_KERNEL_DEBUG", "1") + if lvl, useNULL := resolveKernelLogArg(); !useNULL || lvl != "" { + t.Errorf("with DBSQL_KERNEL_DEBUG=1: got (level=%q, useNULL=%v), want (\"\", true)", lvl, useNULL) + } + + // An empty value is treated as unset (os.Getenv != "" is the gate), so it must + // NOT trigger the override — the mapped level is used. + os.Setenv("DBSQL_KERNEL_DEBUG", "") + if lvl, useNULL := resolveKernelLogArg(); useNULL || lvl != "DEBUG" { + t.Errorf("with DBSQL_KERNEL_DEBUG=\"\" at debug: got (level=%q, useNULL=%v), want (\"DEBUG\", false)", lvl, useNULL) + } + + // Unset → map the driver level. Check two levels to prove it tracks the logger, + // including the fatal→OFF collapse. + os.Unsetenv("DBSQL_KERNEL_DEBUG") + logger.Logger.Logger = logger.Logger.Level(zerolog.WarnLevel) + if lvl, useNULL := resolveKernelLogArg(); useNULL || lvl != "WARN" { + t.Errorf("unset at warn: got (level=%q, useNULL=%v), want (\"WARN\", false)", lvl, useNULL) + } + logger.Logger.Logger = logger.Logger.Level(zerolog.FatalLevel) + if lvl, useNULL := resolveKernelLogArg(); useNULL || lvl != "OFF" { + t.Errorf("unset at fatal: got (level=%q, useNULL=%v), want (\"OFF\", false)", lvl, useNULL) + } +}