Skip to content

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

Open
mani-mathur-arch wants to merge 3 commits into
mani/sea-kernel-richer-tlsfrom
mani/sea-kernel-log-unify
Open

feat(kernel): route kernel logging through the driver log level + correlate#401
mani-mathur-arch wants to merge 3 commits into
mani/sea-kernel-richer-tlsfrom
mani/sea-kernel-log-unify

Conversation

@mani-mathur-arch

@mani-mathur-arch mani-mathur-arch commented Jul 14, 2026

Copy link
Copy Markdown
Collaborator

Context for reviewers

Part of the SEA-via-kernel backend for the Go driver (an alternative to Thrift that talks to Databricks SQL through the Rust databricks-sql-kernel static library over a C ABI, behind the databricks_kernel build tag; the default pure-Go build is unaffected). This PR makes the kernel backend's logging behave like the rest of the driver's.

Stack position:

#399  OAuth / namespace / metric-view / params / types / query-id   (base)
  └─ #400  richer TLS options
       └─ #401  kernel logging → driver log level    ← THIS PR
            └─ #402  nightly E2E workflow
                 └─ #403  CI dispatch label + CLOSE_STATEMENT telemetry

Where to focus review: the hot-path allocation guard (see the review note below) — this is the load-bearing correctness point, since a debug log that allocates when disabled would regress the per-batch fetch path.


What

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 comment: klog and 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.

Closes PECOBLR-3650.

Three parts (the ticket was scoped as one, the review surfaced two more)

The JIRA row was originally just "route kernel debug logging through DATABRICKS_LOG_LEVEL instead of DBSQL_KERNEL_DEBUG." The review raised a second, distinct problem (unstructured, uncorrelatable lines), so the complete fix is three parts:

  • Levelklog 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, benchmarks included. Replaces the old DBSQL_KERNEL_DEBUG bool and 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 at connection.go:139); 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 (bindParams, kernelOp.close, lastError) degrade to klog. The WithContext allocation is behind the same up-front level gate, so it never runs below Debug.
  • Kernel Rust logsinitKernelLogging maps the driver's zerolog level → the kernel_init_logging level string (kernelLogLevel), so DATABRICKS_LOG_LEVEL drives the kernel's Rust logs too. The accepted level strings were verified against kernel source (src/c_abi/session.rs; a bad level safely falls back to RUST_LOG). DBSQL_KERNEL_DEBUG is kept as an advanced override (forces the subscriber on, defers to RUST_LOG for kernel-only verbosity).

Why DBSQL_KERNEL_DEBUG is retained (not just RUST_LOG)

The kernel reads RUST_LOG only when it's passed a NULL level — the moment a concrete level is supplied it builds the filter from that and never consults RUST_LOG (src/logging.rs). Since the normal path now always passes the mapped driver level, RUST_LOG alone is inert; DBSQL_KERNEL_DEBUG is the one switch that makes the Go side pass NULL, unlocking RUST_LOG. That buys two things the driver level structurally can't: a kernel-Rust verbosity decoupled from the driver level, and per-target filtering — including the HTTP stack (RUST_LOG=debughyper/reqwest), which the driver-level mapping (scoped to databricks::sql::kernel) never surfaces.

Known limitation (documented)

The kernel's Rust log lines are still plain text — they do not yet carry the structured fields, because they're emitted inside Rust. Fully structuring them needs the kernel log-callback ABI (PECOBLR-3654 / K4). Only the Go binding lines are structured today. doc.go states this.

Testing

  • Default CGO_ENABLED=0 and tagged CGO_ENABLED=1 -tags databricks_kernel: build + vet + test — 24 pkg ok, 0 fail each.
  • TestKernelLogLevel pins the zerolog→kernel level mapping (incl. fatal/panic→ERROR, default→WARN).
  • TestKernelLogNoAllocWhenOff uses testing.AllocsPerRun to prove klog/klogCtx allocate 0 times at the default Warn level — the hot-path zero-cost guarantee, kept as a regression guard.

Review note (why the alloc guard exists)

Isaac Review, 2 passes: the first pass caught 2 legitimate MAJORs — klogCtx built logger.WithContext (which eagerly make([]byte, 0, 500)s inside zerolog's With()) before the .Debug() gate, so it allocated ~500 B per call even at Warn, on the per-batch nextBatch path. logger.Logger.Debug().Msgf(...) is not allocation-free when off if the arguments themselves allocate — the .Debug() no-op only discards the event, after the arg expressions have already run. Fixed with the up-front kernelDebugOff() gate + the AllocsPerRun regression test; second pass clean (0/0/0). Two info items filtered: a non-issue nil-ctx path, and a pre-existing global-logger data race that predates this change and affects the Thrift path equally.

Stacking

Stacked on #400 (mani/sea-kernel-richer-tls), which is stacked on #399. No KERNEL_REV change (inherits #399's pin).

This pull request and its description were written by Isaac.

@mani-mathur-arch mani-mathur-arch left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The main theme is that the Go binding logs now follow the live driver logger, but the Rust subscriber remains process-wide/first-call-wins and stderr-only, so the public logging contract should be tightened or the implementation needs a stronger sink/level API.

Comment thread internal/backend/kernel/cgo.go
Comment thread doc.go Outdated
Comment thread doc.go Outdated
Comment thread internal/backend/kernel/cgo.go Outdated
Comment thread internal/backend/kernel/kernel_test.go
mani-mathur-arch added a commit that referenced this pull request Jul 15, 2026
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 <mani.mathur@databricks.com>
mani-mathur-arch added a commit that referenced this pull request Jul 15, 2026
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 <mani.mathur@databricks.com>
@mani-mathur-arch mani-mathur-arch marked this pull request as ready for review July 15, 2026 08:39
mani-mathur-arch added a commit that referenced this pull request Jul 15, 2026
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 <mani.mathur@databricks.com>
mani-mathur-arch added a commit that referenced this pull request Jul 15, 2026
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 <mani.mathur@databricks.com>
@mani-mathur-arch mani-mathur-arch force-pushed the mani/sea-kernel-log-unify branch from ef7e5ec to 752e19b Compare July 15, 2026 09:19
…relate

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 <mani.mathur@databricks.com>
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 <mani.mathur@databricks.com>
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 <mani.mathur@databricks.com>
@mani-mathur-arch mani-mathur-arch force-pushed the mani/sea-kernel-log-unify branch from 752e19b to 125eec7 Compare July 15, 2026 09:48
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant