Skip to content

Commit 897fb47

Browse files
feat(kernel): surface kernel logs through Python logging on use_kernel (#824)
* feat(kernel): surface kernel logs through Python logging on use_kernel When the kernel backend loads, auto-initialize the kernel's tracing -> Python logging bridge so `use_kernel=True` users see kernel logs with no extra setup. Kernel logs land under the `databricks.sql.kernel` logger (a child of the connector's `databricks.sql.*` namespace), so an existing `logging.getLogger("databricks.sql").setLevel(...)` cascades to them. - `_errors.py` calls `databricks_sql_kernel.init_logging()` once at extension load (it's the canonical kernel-import site). The call is `getattr`-guarded so an older kernel wheel without the function still works — just without kernel logs. - e2e tests assert kernel records reach the `databricks.sql.kernel` logger (and the pyo3 boundary under `databricks.sql.kernel.pyo3`) and that the level set on the logger is respected. Creds-gated per the existing kernel e2e convention. Requires the companion kernel/pyo3 change (databricks-sql-kernel#120) that exposes `init_logging()`. Co-authored-by: Isaac Signed-off-by: Vikrant Puppala <vikrant.puppala@databricks.com> * fix(kernel): harden log-bridge init + address review feedback Review feedback from PR #824 (gopalldb): - P1: guard the init_logging() call against throwing, not just a missing function. A panic across the PyO3 boundary surfaces as pyo3_runtime.PanicException (a BaseException, not Exception), so a bare call could escape module import and fail every use_kernel=True connection over a non-essential logging feature. Wrap in try/except BaseException, log a debug breadcrumb, continue. This also neutralizes the idempotency concern regardless of the Rust impl. - P2: soften the level-control test docstring to make clear it asserts the effective customer-visible outcome (sub-threshold records don't surface), not source-side suppression — caplog filters after the FFI. - P2: downgrade the databricks.sql.kernel.pyo3 assertion to a soft warning so a benign kernel change to the boundary breadcrumb target doesn't break the connector e2e suite. The core databricks.sql.kernel contract is still hard-asserted. Co-authored-by: Isaac Signed-off-by: Vikrant Puppala <vikrant.puppala@databricks.com> --------- Signed-off-by: Vikrant Puppala <vikrant.puppala@databricks.com>
1 parent 614dd91 commit 897fb47

2 files changed

Lines changed: 112 additions & 0 deletions

File tree

src/databricks/sql/backend/kernel/_errors.py

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,8 @@
3838

3939
from __future__ import annotations
4040

41+
import logging
42+
4143
from databricks.sql.exc import (
4244
DatabaseError,
4345
Error,
@@ -57,6 +59,31 @@
5759
"(into the same venv as databricks-sql-connector)."
5860
) from exc
5961

62+
# Route the kernel's Rust-side logs into Python's ``logging`` as soon as
63+
# the extension loads. The kernel emits under the ``databricks.sql.kernel``
64+
# logger (a child of the connector's ``databricks.sql`` namespace), so a
65+
# customer who configures ``databricks.sql`` logging gets kernel logs for
66+
# free with no extra setup.
67+
#
68+
# This is a best-effort, non-essential feature: it must never take down
69+
# ``use_kernel=True`` for a process. ``getattr`` guards against an older
70+
# kernel wheel that predates the function. The ``try`` guards against the
71+
# call itself throwing — note ``except BaseException`` is deliberate: a
72+
# panic raised across the PyO3 boundary surfaces as
73+
# ``pyo3_runtime.PanicException``, which derives from ``BaseException``
74+
# (not ``Exception``), so a narrower clause would let it escape module
75+
# import and fail every kernel-backed connection. The kernel side is
76+
# idempotent and returns rather than panics on a double install, but we
77+
# do not rely on that here — the guard holds regardless of the Rust impl.
78+
_kernel_init_logging = getattr(_kernel, "init_logging", None)
79+
if _kernel_init_logging is not None:
80+
try:
81+
_kernel_init_logging()
82+
except BaseException as exc: # noqa: BLE001 - see comment above re: PanicException
83+
logging.getLogger(__name__).debug(
84+
"kernel log bridge init failed; continuing without it: %r", exc
85+
)
86+
6087

6188
# Map a kernel `code` slug to the PEP 249 exception class that best
6289
# captures it. The match isn't a perfect 1:1 — PEP 249 has a

tests/e2e/test_kernel_backend.py

Lines changed: 85 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -127,6 +127,91 @@ def test_fetchall_arrow(conn):
127127
assert table.column_names == ["a", "b"]
128128

129129

130+
# ─── Logging (Rust kernel -> Python logging bridge) ──────────────────────────
131+
#
132+
# Layer 3 of the logger-name drift guard (see also the Rust tests
133+
# `klog::tests::klog_emits_contract_target` and
134+
# `logging::tests::kernel_target_matches_contract` in the kernel repo).
135+
# Asserts the *customer-facing* contract end-to-end: kernel logs reach
136+
# Python `logging` under the `databricks.sql.kernel` logger, respect the
137+
# level set on it, and the pyo3 boundary surfaces under
138+
# `databricks.sql.kernel.pyo3`. If the kernel's tracing target or the
139+
# pyo3-log wiring ever drifts, these fail.
140+
141+
import logging
142+
143+
144+
def test_kernel_logs_reach_python_logging(kernel_conn_params, caplog):
145+
"""A query at DEBUG produces records on the `databricks.sql.kernel`
146+
logger — proving the tracing -> log -> pyo3-log -> logging chain."""
147+
with caplog.at_level(logging.DEBUG, logger="databricks.sql.kernel"):
148+
c = sql.connect(**kernel_conn_params)
149+
try:
150+
with c.cursor() as cur:
151+
cur.execute("SELECT 1 AS a")
152+
cur.fetchall()
153+
finally:
154+
c.close()
155+
156+
kernel_records = [
157+
r for r in caplog.records if r.name.startswith("databricks.sql.kernel")
158+
]
159+
assert kernel_records, (
160+
"expected log records under the 'databricks.sql.kernel' logger; "
161+
"the kernel tracing -> Python logging bridge did not deliver any"
162+
)
163+
# The core kernel logger (not just any child) must be present — this
164+
# is the customer-facing contract.
165+
assert any(
166+
r.name == "databricks.sql.kernel" for r in kernel_records
167+
), "expected core kernel records on the exact 'databricks.sql.kernel' logger"
168+
# The pyo3-boundary breadcrumb (`databricks.sql.kernel.pyo3`) is a
169+
# nice-to-have, but the exact sub-target is a kernel-internal naming
170+
# detail — assert softly so a benign kernel change to the boundary
171+
# breadcrumbs doesn't break the connector e2e suite.
172+
if not any(r.name == "databricks.sql.kernel.pyo3" for r in kernel_records):
173+
import warnings
174+
175+
warnings.warn(
176+
"no 'databricks.sql.kernel.pyo3' boundary records seen; "
177+
"the kernel may have changed its pyo3 breadcrumb target",
178+
stacklevel=2,
179+
)
180+
181+
182+
def test_kernel_log_level_is_respected(kernel_conn_params, caplog):
183+
"""At WARNING on the kernel logger, no DEBUG/INFO kernel records reach
184+
`caplog.records` — i.e. level control on `databricks.sql.kernel`
185+
behaves like any other Python logger.
186+
187+
Scope note: `caplog.at_level` sets the logger's level and attaches a
188+
handler, so this asserts the *effective* outcome a customer sees
189+
(sub-threshold records don't surface), not specifically that the Rust
190+
side suppressed them at source. A DEBUG record that crossed the FFI
191+
would still be dropped by Python's level check before reaching
192+
`caplog`. Source-side suppression (and its per-record FFI cost
193+
avoidance) is covered by the kernel-side filtering, not asserted
194+
here."""
195+
with caplog.at_level(logging.WARNING, logger="databricks.sql.kernel"):
196+
c = sql.connect(**kernel_conn_params)
197+
try:
198+
with c.cursor() as cur:
199+
cur.execute("SELECT 1 AS a")
200+
cur.fetchall()
201+
finally:
202+
c.close()
203+
204+
debug_records = [
205+
r
206+
for r in caplog.records
207+
if r.name.startswith("databricks.sql.kernel") and r.levelno < logging.WARNING
208+
]
209+
assert not debug_records, (
210+
"DEBUG/INFO kernel records leaked through at WARNING level: "
211+
f"{[(r.name, r.levelname, r.getMessage()) for r in debug_records]}"
212+
)
213+
214+
130215
# ── Metadata ──────────────────────────────────────────────────────
131216

132217

0 commit comments

Comments
 (0)