feat(kernel): route kernel logging through the driver log level + correlate

doc.go

@@ -186,16 +186,46 @@ 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 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) 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
+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

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

internal/backend/kernel/cgo.go

@@ -34,78 +34,121 @@ 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
 // first session open rather than in init(), so a process that never opens a
 // 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 — 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. 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. 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.
+// 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() {
-	if !kdebug {
-		return
-	}
 	initLoggingOnce.Do(func() {
+		// 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 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(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)
 		}
 	})
 }

internal/backend/kernel/kernel_test.go

@@ -3,13 +3,18 @@
 package kernel
 
 import (
+	"bytes"
 	"context"
 	"database/sql/driver"
+	"encoding/json"
 	"errors"
+	"os"
 	"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"
 )
 
 // setAuth maps each Auth mode to exactly one kernel_session_config_set_auth_*
@@ -70,6 +75,99 @@ func TestSetKernelTLS(t *testing.T) {
 	}
 }
 
+// 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
+// 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)
+	}
+}
+
+// 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