From 64a8dfaa079ce80abba4780821af342e3db769fb Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Wed, 11 Nov 2026 09:46:35 +0000 Subject: [PATCH 1/2] fix(cli): report an unreachable ClickHouse endpoint without the driver's log line A refused connection or unresolvable host printed clickhouse_connect's own 'Unexpected Http Driver Exception' warning above SQLTide's error. SQLTide's message now carries what that line stood for, the endpoint and a short cause: Plan could not connect to ClickHouse at db.example.com:8123: connection refused The translated AdapterUnavailableError records the endpoint and reason, and a logging filter on the driver's HTTP client logger demotes that one line to DEBUG while a refused or unresolved connection is being handled: it is dropped unless DEBUG is enabled for the logger. Other driver records, and the same line for other transport failures, are unchanged. Refs: CHI-1214 --- crates/sqltide-python/src/cli/render.rs | 18 ++- .../sqltide-python/src/clickhouse_adapter.rs | 102 +++++++++++-- .../src/clickhouse_connection.rs | 1 + src/sqltide/_native.pyi | 6 + src/sqltide/adapter/exceptions.py | 5 + .../adapters/clickhouse/_test_types.py | 18 +++ .../sqltide/adapters/clickhouse/helpers.py | 41 ++++- .../adapters/clickhouse/test_errors.py | 142 +++++++++++++++++- tests/unit/src/sqltide/cli/_test_types.py | 10 ++ tests/unit/src/sqltide/cli/helpers.py | 14 ++ .../src/sqltide/cli/test_connection_errors.py | 97 ++++++++++++ tests/unit/src/sqltide/cli/test_main.py | 3 +- 12 files changed, 439 insertions(+), 18 deletions(-) create mode 100644 tests/unit/src/sqltide/cli/test_connection_errors.py diff --git a/crates/sqltide-python/src/cli/render.rs b/crates/sqltide-python/src/cli/render.rs index 9452d828..1fdbde2d 100644 --- a/crates/sqltide-python/src/cli/render.rs +++ b/crates/sqltide-python/src/cli/render.rs @@ -360,10 +360,24 @@ pub(crate) fn render_expected_warehouse_error( "Retry the command after checking warehouse availability.".to_owned(), ] } else if is("AdapterUnavailableError")? { + let detail = |name: &str| -> PyResult> { + let value: Bound<'_, PyAny> = error + .getattr(name) + .unwrap_or_else(|_| py.None().into_bound(py)); + if value.is_none() { + Ok(None) + } else { + Ok(Some(value.str()?.to_string())) + } + }; + let endpoint: String = + detail("endpoint")?.map_or_else(String::new, |endpoint| format!(" at {endpoint}")); + let reason: String = detail("reason")?.unwrap_or_else(|| { + "the connection was refused or the host could not be resolved".to_owned() + }); vec![ - format!("{command} could not connect to ClickHouse"), + format!("{command} could not connect to ClickHouse{endpoint}: {reason}"), format!("Database: {database}"), - "Reason: the connection was refused or the host could not be resolved.".to_owned(), String::new(), "Check:".to_owned(), "- that ClickHouse is running and reachable from this machine".to_owned(), diff --git a/crates/sqltide-python/src/clickhouse_adapter.rs b/crates/sqltide-python/src/clickhouse_adapter.rs index e3418ff1..f0ffc269 100644 --- a/crates/sqltide-python/src/clickhouse_adapter.rs +++ b/crates/sqltide-python/src/clickhouse_adapter.rs @@ -17,6 +17,11 @@ const SECRET_PLACEHOLDER_SUFFIX: &str = "__"; const TIMEOUT_ERROR_MARKERS: [&str; 2] = ["timeout", "timed out"]; /// How many causes or contexts of a driver error are searched for a connection failure. const MAX_CAUSE_DEPTH: usize = 16; +/// The line clickhouse_connect logs at WARNING before raising any HTTP transport failure. +const DRIVER_HTTP_LOGGER: &str = "clickhouse_connect.driver.httpclient"; +const DRIVER_HTTP_FAILURE_LOG: &str = "Unexpected Http Driver Exception"; +const REFUSED_REASON: &str = "connection refused"; +const UNRESOLVED_REASON: &str = "host not found"; const DEAD_LETTERS_TABLE: &str = "_sqltide_dead_letters"; const MATERIALIZED_VIEW_NAME_PREFIX: &str = "mv__"; const DEAD_LETTERS_VIEW_SUFFIX: &str = "__dead_letters"; @@ -52,7 +57,8 @@ fn translate_clickhouse_driver_error<'py>(error: &Bound<'py, PyAny>) -> PyResult let text: String = message.to_string_lossy().into_owned(); // A refused or unresolved connection never timed out, so it is checked before the timeout // markers, which the request URL in the message can contain as a setting name. - let class: &str = if caused_by_unreachable_host(error)? { + let unreachable: Option<&str> = unreachable_host_reason(error)?; + let class: &str = if unreachable.is_some() { "AdapterUnavailableError" } else if TIMEOUT_ERROR_MARKERS .iter() @@ -68,36 +74,107 @@ fn translate_clickhouse_driver_error<'py>(error: &Bound<'py, PyAny>) -> PyResult } else { "AdapterWarehouseError" }; - py.import(ADAPTER_EXCEPTIONS)? + let translated: Value<'py> = py + .import(ADAPTER_EXCEPTIONS)? .getattr(class)? - .call1((message,)) + .call1((message,))?; + if let Some(reason) = unreachable { + // What the driver's own log line used to show, for the operator-facing message. + translated.setattr("endpoint", connection_endpoint(&text))?; + translated.setattr("reason", reason)?; + } + Ok(translated) } -/// Whether the driver error was caused by a refused connection or an unresolvable host, as the -/// HTTP client chains them under the driver's own error. Like a traceback, it follows -/// `__context__` only when `__cause__` is unset and the context is not suppressed. -fn caused_by_unreachable_host(error: &Bound<'_, PyAny>) -> PyResult { +/// `refused` or `unresolved` reason when the driver error was caused by a refused connection or +/// an unresolvable host, as the HTTP client chains them under the driver's own error. Like a +/// traceback, it follows `__context__` only when `__cause__` is unset and the context is not +/// suppressed. +fn unreachable_host_reason(error: &Bound<'_, PyAny>) -> PyResult> { let py: Python<'_> = error.py(); let refused: Value<'_> = py.import("builtins")?.getattr("ConnectionRefusedError")?; let unresolved: Value<'_> = py.import("socket")?.getattr("gaierror")?; let mut current: Value<'_> = error.clone(); for _ in 0..MAX_CAUSE_DEPTH { - if current.is_instance(&refused)? || current.is_instance(&unresolved)? { - return Ok(true); + if current.is_instance(&refused)? { + return Ok(Some(REFUSED_REASON)); + } + if current.is_instance(&unresolved)? { + return Ok(Some(UNRESOLVED_REASON)); } let cause: Value<'_> = current.getattr("__cause__")?; current = if !cause.is_none() { cause } else if current.getattr("__suppress_context__")?.is_truthy()? { - return Ok(false); + return Ok(None); } else { current.getattr("__context__")? }; if current.is_none() { - return Ok(false); + return Ok(None); + } + } + Ok(None) +} + +/// `host:port` of the HTTP connection pool a driver message names, as urllib3 renders it: +/// `HTTPConnectionPool(host='db.example.com', port=8123)`. +fn connection_endpoint(message: &str) -> Option { + let rest: &str = &message[message.find("host='")? + "host='".len()..]; + let (host, rest) = rest.split_once("', port=")?; + let digits: usize = rest.find(|character: char| !character.is_ascii_digit())?; + (!host.is_empty() && digits > 0).then(|| format!("{host}:{}", &rest[..digits])) +} + +/// Logging filter on clickhouse_connect's HTTP client logger that demotes its generic +/// transport-failure warning to DEBUG while a refused connection or unresolvable host is being +/// handled, because SQLTide reports that failure itself. The record is dropped unless DEBUG is +/// enabled for the logger; every other record passes unchanged. +#[pyclass(module = "sqltide._native", frozen)] +pub(crate) struct UnreachableHostLogFilter; + +#[pymethods] +impl UnreachableHostLogFilter { + #[new] + fn new() -> Self { + Self + } + + fn filter(&self, record: &Bound<'_, PyAny>) -> PyResult { + let py: Python<'_> = record.py(); + if !record.getattr("msg")?.eq(DRIVER_HTTP_FAILURE_LOG)? { + return Ok(true); + } + let handled: Value<'_> = py.import("sys")?.call_method0("exc_info")?.get_item(1)?; + if handled.is_none() || unreachable_host_reason(&handled)?.is_none() { + return Ok(true); + } + let logging: Bound<'_, PyModule> = py.import("logging")?; + let debug: Value<'_> = logging.getattr("DEBUG")?; + let enabled: bool = logging + .call_method1("getLogger", (record.getattr("name")?,))? + .call_method1("isEnabledFor", (&debug,))? + .is_truthy()?; + if enabled { + record.setattr("levelno", &debug)?; + record.setattr("levelname", "DEBUG")?; + } + Ok(enabled) + } +} + +/// Add [`UnreachableHostLogFilter`] to clickhouse_connect's HTTP client logger once. +pub(crate) fn install_unreachable_host_log_filter(py: Python<'_>) -> PyResult<()> { + let logger: Value<'_> = py + .import("logging")? + .call_method1("getLogger", (DRIVER_HTTP_LOGGER,))?; + for existing in logger.getattr("filters")?.try_iter()? { + if existing?.is_instance_of::() { + return Ok(()); } } - Ok(false) + logger.call_method1("addFilter", (UnreachableHostLogFilter,))?; + Ok(()) } /// The leftmost `__sqltide_secret__NAME__` placeholder as `(placeholder, NAME)`, matching @@ -525,6 +602,7 @@ fn build_clickhouse_connection_config<'py>( } pub(crate) fn register(module: &Bound<'_, PyModule>) -> PyResult<()> { + module.add_class::()?; module.add_function(wrap_pyfunction!(translate_clickhouse_driver_error, module)?)?; module.add_function(wrap_pyfunction!(render_clickhouse_resource, module)?)?; module.add_function(wrap_pyfunction!(realize_clickhouse_source, module)?)?; diff --git a/crates/sqltide-python/src/clickhouse_connection.rs b/crates/sqltide-python/src/clickhouse_connection.rs index 344b8ab6..87e1c3bb 100644 --- a/crates/sqltide-python/src/clickhouse_connection.rs +++ b/crates/sqltide-python/src/clickhouse_connection.rs @@ -1119,6 +1119,7 @@ impl ClickHouseAdapterCore { /// Open a ClickHouse connection for the resolved configuration. fn connect<'py>(slf: &Bound<'py, Self>, config: Any<'py>) -> PyResult> { let py: Python<'py> = slf.py(); + crate::clickhouse_adapter::install_unreachable_host_log_filter(py)?; let raw_client: Any<'py> = driver_call(py, || slf.call_method1("_open_raw_client", (config,)))?; attr(py, CONNECTION_CLASS, "ClickHouseConnection")?.call1((raw_client,)) diff --git a/src/sqltide/_native.pyi b/src/sqltide/_native.pyi index 79910231..97611224 100644 --- a/src/sqltide/_native.pyi +++ b/src/sqltide/_native.pyi @@ -1,4 +1,5 @@ import argparse +import logging import os import threading from collections.abc import Callable, Iterable, Mapping, Sequence @@ -5728,6 +5729,11 @@ def direct_model_identity_metadata( tuple[str, list[str], str | None, str | None, list[tuple[str, str]] | None] | None, ], ) -> str: ... + +class UnreachableHostLogFilter: + def __new__(cls) -> Self: ... + def filter(self, record: logging.LogRecord) -> bool: ... + def translate_clickhouse_driver_error(error: Exception) -> AdapterWarehouseError: ... def render_clickhouse_resource( *, diff --git a/src/sqltide/adapter/exceptions.py b/src/sqltide/adapter/exceptions.py index 8283cac2..37964ac7 100644 --- a/src/sqltide/adapter/exceptions.py +++ b/src/sqltide/adapter/exceptions.py @@ -36,6 +36,11 @@ class AdapterWarehouseError(AdapterError): class AdapterUnavailableError(AdapterWarehouseError): """Raised when the warehouse refuses the connection or its host cannot be resolved.""" + endpoint: str | None = None + """The `host:port` the connection was attempted to, when the adapter knows it.""" + reason: str | None = None + """A short cause such as `connection refused` or `host not found`.""" + class AdapterTimeoutError(AdapterWarehouseError): """Raised when a warehouse operation exceeds its available time.""" diff --git a/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py b/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py index 67b0e36a..3aad4dc3 100644 --- a/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py +++ b/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py @@ -499,3 +499,21 @@ class OffsetDedupeRenderTestCase: description: str dedupe_offsets: bool expected_clause_present: bool + + +@dataclass(frozen=True) +class UnreachableHostDetailsTestCase: + description: str + driver_error: Exception + expected_endpoint: str | None + expected_reason: str + + +@dataclass(frozen=True) +class DriverLogFilterTestCase: + description: str + message: str + handled_errors: tuple[BaseException, ...] + logger_level: int + expected_kept: bool + expected_level: str diff --git a/tests/unit/src/sqltide/adapters/clickhouse/helpers.py b/tests/unit/src/sqltide/adapters/clickhouse/helpers.py index 5bc9bb44..46a8ec00 100644 --- a/tests/unit/src/sqltide/adapters/clickhouse/helpers.py +++ b/tests/unit/src/sqltide/adapters/clickhouse/helpers.py @@ -1,9 +1,10 @@ +import logging from collections.abc import Iterator, Mapping, Sequence from typing import cast from clickhouse_connect.driver.exceptions import OperationalError -from sqltide._native import sql_canonicalize +from sqltide._native import UnreachableHostLogFilter, sql_canonicalize from sqltide.adapter.exceptions import AdapterWarehouseError from sqltide.adapter.models import ( AdapterManifest, @@ -352,3 +353,41 @@ def connection_failure( setattr(driver_error, link, transport_error) driver_error.__suppress_context__ = suppress_context return driver_error + + +def filter_driver_record( + *, message: str, handled_errors: tuple[BaseException, ...], logger_level: int +) -> tuple[bool, str]: + """Run the driver log filter on one driver record while the first of `handled_errors` (if + any) is being handled, as clickhouse_connect logs it, at `logger_level`; return whether the + record is kept and its final level name.""" + logger: logging.Logger = logging.getLogger("clickhouse_connect.driver.httpclient") + record: logging.LogRecord = logger.makeRecord( + logger.name, logging.WARNING, __file__, 0, message, (), None + ) + previous_level: int = logger.level + logger.setLevel(logger_level) + outcome: _FilterOutcome = _FilterOutcome(record=record) + with outcome: + _ = [_raise(error) for error in handled_errors] + logger.setLevel(previous_level) + return outcome.kept, record.levelname + + +class _FilterOutcome: + """Applies the filter in `__exit__`, where the raised error is the one being handled.""" + + def __init__(self, *, record: logging.LogRecord) -> None: + self.record: logging.LogRecord = record + self.kept: bool = False + + def __enter__(self) -> None: + return None + + def __exit__(self, *_: object) -> bool: + self.kept = UnreachableHostLogFilter().filter(self.record) + return True + + +def _raise(error: BaseException) -> None: + raise error diff --git a/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py b/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py index 1bba2136..aa06cbb4 100644 --- a/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py +++ b/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py @@ -1,4 +1,6 @@ +import logging import socket +from typing import cast import pytest from clickhouse_connect.driver.exceptions import DatabaseError, OperationalError @@ -14,8 +16,13 @@ ) from tests.unit.src.sqltide.adapters.clickhouse._test_types import ( DriverErrorTranslationTestCase, + DriverLogFilterTestCase, + UnreachableHostDetailsTestCase, +) +from tests.unit.src.sqltide.adapters.clickhouse.helpers import ( + connection_failure, + filter_driver_record, ) -from tests.unit.src.sqltide.adapters.clickhouse.helpers import connection_failure _AUTHENTICATION_FAILED_MESSAGE: str = ( "Code: 516. DB::Exception: Authentication failed. (AUTHENTICATION_FAILED)" @@ -33,6 +40,7 @@ "Error HTTPConnectionPool(host='warehouse.example.com', port=8123): Max retries exceeded " "executing HTTP request attempt 1 (http://warehouse.example.com:8123)" ) +_DRIVER_FAILURE_LOG: str = "Unexpected Http Driver Exception" _REFUSED_WITH_TIMEOUT_SETTING_MESSAGE: str = ( "Error HTTPConnectionPool(host='warehouse.example.com', port=8123): Max retries exceeded " "with url: /?receive_timeout=30&database=orders executing HTTP request attempt 1" @@ -127,3 +135,135 @@ def test_given_driver_error_when_translating_then_it_returns_the_neutral_equival assert type(translated) is test_case.expected_error_type assert str(translated) == test_case.expected_message + + +@pytest.mark.parametrize( + "test_case", + [ + UnreachableHostDetailsTestCase( + description="names the endpoint and a refused connection", + driver_error=connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=ConnectionRefusedError(111, "Connection refused"), + link="__cause__", + ), + expected_endpoint="warehouse.example.com:8123", + expected_reason="connection refused", + ), + UnreachableHostDetailsTestCase( + description="names the endpoint and an unresolvable host", + driver_error=connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=socket.gaierror(-2, "Name or service not known"), + link="__context__", + ), + expected_endpoint="warehouse.example.com:8123", + expected_reason="host not found", + ), + UnreachableHostDetailsTestCase( + description="leaves the endpoint unknown when the message names no pool", + driver_error=connection_failure( + "Error executing HTTP request attempt 1", + cause=ConnectionRefusedError(111, "Connection refused"), + link="__cause__", + ), + expected_endpoint=None, + expected_reason="connection refused", + ), + ], + ids=lambda case: case.description, +) +def test_given_unreachable_host_when_translating_then_endpoint_and_reason_are_attached( + test_case: UnreachableHostDetailsTestCase, +) -> None: + translated: AdapterUnavailableError = cast( + AdapterUnavailableError, translate_clickhouse_driver_error(test_case.driver_error) + ) + + assert (type(translated), translated.endpoint, translated.reason) == ( + AdapterUnavailableError, + test_case.expected_endpoint, + test_case.expected_reason, + ) + + +@pytest.mark.parametrize( + "test_case", + [ + DriverLogFilterTestCase( + description="hides the driver line for a refused connection without debug logging", + message=_DRIVER_FAILURE_LOG, + handled_errors=( + connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=ConnectionRefusedError(111, "Connection refused"), + link="__cause__", + ), + ), + logger_level=logging.WARNING, + expected_kept=False, + expected_level="WARNING", + ), + DriverLogFilterTestCase( + description="demotes the driver line for an unresolvable host to debug", + message=_DRIVER_FAILURE_LOG, + handled_errors=( + connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=socket.gaierror(-2, "Name or service not known"), + link="__cause__", + ), + ), + logger_level=logging.DEBUG, + expected_kept=True, + expected_level="DEBUG", + ), + DriverLogFilterTestCase( + description="keeps the driver line for other transport failures", + message=_DRIVER_FAILURE_LOG, + handled_errors=( + connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=ConnectionResetError(104, "Connection reset by peer"), + link="__cause__", + ), + ), + logger_level=logging.WARNING, + expected_kept=True, + expected_level="WARNING", + ), + DriverLogFilterTestCase( + description="keeps the driver line when no failure is being handled", + message=_DRIVER_FAILURE_LOG, + handled_errors=(), + logger_level=logging.WARNING, + expected_kept=True, + expected_level="WARNING", + ), + DriverLogFilterTestCase( + description="keeps other driver warnings during a refused connection", + message="Unrecognized setting", + handled_errors=( + connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=ConnectionRefusedError(111, "Connection refused"), + link="__cause__", + ), + ), + logger_level=logging.WARNING, + expected_kept=True, + expected_level="WARNING", + ), + ], + ids=lambda case: case.description, +) +def test_given_driver_record_when_filtering_then_only_unreachable_failures_are_demoted( + test_case: DriverLogFilterTestCase, +) -> None: + kept, level = filter_driver_record( + message=test_case.message, + handled_errors=test_case.handled_errors, + logger_level=test_case.logger_level, + ) + + assert (kept, level) == (test_case.expected_kept, test_case.expected_level) diff --git a/tests/unit/src/sqltide/cli/_test_types.py b/tests/unit/src/sqltide/cli/_test_types.py index 2738b426..3fcba6a5 100644 --- a/tests/unit/src/sqltide/cli/_test_types.py +++ b/tests/unit/src/sqltide/cli/_test_types.py @@ -1,3 +1,4 @@ +from collections.abc import Callable from dataclasses import dataclass from sqltide.adapter.exceptions import AdapterWarehouseError @@ -295,3 +296,12 @@ class CliAuditBackfillProjectContextTestCase: expected_exit_code: int expected_project_dir_name: str expected_pipelines_root_name: str + + +@dataclass(frozen=True) +class UnreachableClickHouseStderrTestCase: + description: str + host: str + port: Callable[[], int] + logging_prelude: str + expected_stderr: str diff --git a/tests/unit/src/sqltide/cli/helpers.py b/tests/unit/src/sqltide/cli/helpers.py index 0e35b695..17956545 100644 --- a/tests/unit/src/sqltide/cli/helpers.py +++ b/tests/unit/src/sqltide/cli/helpers.py @@ -1,4 +1,5 @@ import json +import socket from collections.abc import Callable from dataclasses import replace from pathlib import Path @@ -468,3 +469,16 @@ def refused_driver_error() -> OperationalError: ) error.__cause__ = ConnectionRefusedError(111, "Connection refused") return error + + +def closed_local_port() -> int: + """A loopback TCP port nothing listens on: bound once by the OS, then released.""" + with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as probe: + probe.bind(("127.0.0.1", 0)) + port: int = probe.getsockname()[1] + return port + + +def default_clickhouse_port() -> int: + """ClickHouse's default HTTP port, for hosts that never resolve.""" + return 8123 diff --git a/tests/unit/src/sqltide/cli/test_connection_errors.py b/tests/unit/src/sqltide/cli/test_connection_errors.py new file mode 100644 index 00000000..ab35431d --- /dev/null +++ b/tests/unit/src/sqltide/cli/test_connection_errors.py @@ -0,0 +1,97 @@ +import subprocess +import sys + +import pytest + +from tests.unit.src.sqltide.cli._test_types import UnreachableClickHouseStderrTestCase +from tests.unit.src.sqltide.cli.helpers import closed_local_port, default_clickhouse_port + +_CHECKS: str = ( + "Database: analytics\n" + "\n" + "Check:\n" + "- that ClickHouse is running and reachable from this machine\n" + "- the host and port in your connection settings\n" +) +_DEBUG_PRELUDE: str = ( + "import logging; handler = logging.StreamHandler(); " + "handler.setFormatter(logging.Formatter('%(levelname)s:%(name)s:%(message)s')); " + "driver = logging.getLogger('clickhouse_connect.driver.httpclient'); " + "driver.addHandler(handler); driver.setLevel(logging.DEBUG); " +) + + +@pytest.mark.parametrize( + "test_case", + [ + UnreachableClickHouseStderrTestCase( + description="reports a refused connection once, without the driver log line", + host="127.0.0.1", + port=closed_local_port, + logging_prelude="", + expected_stderr=( + "Plan could not connect to ClickHouse at 127.0.0.1:{port}: " + "connection refused\n" + _CHECKS + ), + ), + UnreachableClickHouseStderrTestCase( + description="reports an unresolvable host once, without the driver log line", + host="clickhouse.invalid", + port=default_clickhouse_port, + logging_prelude="", + expected_stderr=( + "Plan could not connect to ClickHouse at clickhouse.invalid:{port}: " + "host not found\n" + _CHECKS + ), + ), + UnreachableClickHouseStderrTestCase( + description="keeps the driver line at debug level when debug logging is on", + host="127.0.0.1", + port=closed_local_port, + logging_prelude=_DEBUG_PRELUDE, + expected_stderr=( + "DEBUG:clickhouse_connect.driver.httpclient:Unexpected Http Driver Exception\n" + "Plan could not connect to ClickHouse at 127.0.0.1:{port}: " + "connection refused\n" + _CHECKS + ), + ), + ], + ids=lambda case: case.description, +) +def test_given_unreachable_clickhouse_when_planning_then_stderr_is_exactly_the_cli_error( + test_case: UnreachableClickHouseStderrTestCase, +) -> None: + port: int = test_case.port() + + completed: subprocess.CompletedProcess[str] = subprocess.run( + [ + sys.executable, + "-B", + "-c", + test_case.logging_prelude + + "import sys; from sqltide._native import run_cli; sys.exit(run_cli(sys.argv[1:]))", + "sqt", + "plan", + "--project-dir", + "tests/fixtures/basic_project", + "--host", + test_case.host, + "--port", + str(port), + "--username", + "sqltide", + "--password", + "sqltide", + "--database", + "analytics", + ], + capture_output=True, + text=True, + check=False, + timeout=120, + ) + + assert (completed.returncode, completed.stderr) == ( + 1, + test_case.expected_stderr.format(port=port), + ) diff --git a/tests/unit/src/sqltide/cli/test_main.py b/tests/unit/src/sqltide/cli/test_main.py index 73aad97f..138729b1 100644 --- a/tests/unit/src/sqltide/cli/test_main.py +++ b/tests/unit/src/sqltide/cli/test_main.py @@ -1307,9 +1307,8 @@ def test_given_apply_flag_when_running_janitor_then_it_passes_apply_to_command( ), expected_exit_code=1, expected_error_fragments=( - "Plan could not connect to ClickHouse", + "Plan could not connect to ClickHouse at localhost:8123: connection refused", "Database: analytics", - "the connection was refused or the host could not be resolved", ), ), ], From 8fa5f38479476a7be06355323f17b6bd907c660c Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Wed, 11 Nov 2026 09:54:28 +0000 Subject: [PATCH 2/2] fix(cli): bracket IPv6 endpoints, name proxies and temporary DNS failures Follow-up to the unreachable ClickHouse message: - an IPv6 host is shown as [::1]:8123 rather than ::1:8123 - when urllib3 reports a ProxyError, the endpoint is the configured proxy, so the message reads 'could not connect to ClickHouse through proxy :' instead of naming the proxy as ClickHouse - a socket.gaierror with errno EAI_AGAIN is reported as a temporary DNS failure; other resolution errors stay 'host not found'. The errno is used, not the message text Refs: CHI-1214 --- crates/sqltide-python/src/cli/render.rs | 11 ++- .../sqltide-python/src/clickhouse_adapter.rs | 68 ++++++++++++++----- src/sqltide/adapter/exceptions.py | 2 + .../adapters/clickhouse/_test_types.py | 1 + .../sqltide/adapters/clickhouse/helpers.py | 13 ++++ .../adapters/clickhouse/test_errors.py | 63 ++++++++++++++++- tests/unit/src/sqltide/cli/helpers.py | 16 +++++ tests/unit/src/sqltide/cli/test_main.py | 29 ++++++++ 8 files changed, 183 insertions(+), 20 deletions(-) diff --git a/crates/sqltide-python/src/cli/render.rs b/crates/sqltide-python/src/cli/render.rs index 1fdbde2d..60faac6a 100644 --- a/crates/sqltide-python/src/cli/render.rs +++ b/crates/sqltide-python/src/cli/render.rs @@ -370,8 +370,15 @@ pub(crate) fn render_expected_warehouse_error( Ok(Some(value.str()?.to_string())) } }; - let endpoint: String = - detail("endpoint")?.map_or_else(String::new, |endpoint| format!(" at {endpoint}")); + let through_proxy: bool = error + .getattr("through_proxy") + .map_or(Ok(false), |value| value.is_truthy())?; + let endpoint: String = match (detail("endpoint")?, through_proxy) { + (Some(endpoint), true) => format!(" through proxy {endpoint}"), + (Some(endpoint), false) => format!(" at {endpoint}"), + (None, true) => " through a proxy".to_owned(), + (None, false) => String::new(), + }; let reason: String = detail("reason")?.unwrap_or_else(|| { "the connection was refused or the host could not be resolved".to_owned() }); diff --git a/crates/sqltide-python/src/clickhouse_adapter.rs b/crates/sqltide-python/src/clickhouse_adapter.rs index f0ffc269..cdf4a7f9 100644 --- a/crates/sqltide-python/src/clickhouse_adapter.rs +++ b/crates/sqltide-python/src/clickhouse_adapter.rs @@ -22,6 +22,7 @@ const DRIVER_HTTP_LOGGER: &str = "clickhouse_connect.driver.httpclient"; const DRIVER_HTTP_FAILURE_LOG: &str = "Unexpected Http Driver Exception"; const REFUSED_REASON: &str = "connection refused"; const UNRESOLVED_REASON: &str = "host not found"; +const TEMPORARY_DNS_REASON: &str = "temporary DNS failure"; const DEAD_LETTERS_TABLE: &str = "_sqltide_dead_letters"; const MATERIALIZED_VIEW_NAME_PREFIX: &str = "mv__"; const DEAD_LETTERS_VIEW_SUFFIX: &str = "__dead_letters"; @@ -57,7 +58,7 @@ fn translate_clickhouse_driver_error<'py>(error: &Bound<'py, PyAny>) -> PyResult let text: String = message.to_string_lossy().into_owned(); // A refused or unresolved connection never timed out, so it is checked before the timeout // markers, which the request URL in the message can contain as a setting name. - let unreachable: Option<&str> = unreachable_host_reason(error)?; + let unreachable: Option = unreachable_host(error)?; let class: &str = if unreachable.is_some() { "AdapterUnavailableError" } else if TIMEOUT_ERROR_MARKERS @@ -78,29 +79,54 @@ fn translate_clickhouse_driver_error<'py>(error: &Bound<'py, PyAny>) -> PyResult .import(ADAPTER_EXCEPTIONS)? .getattr(class)? .call1((message,))?; - if let Some(reason) = unreachable { + if let Some(unreachable) = unreachable { // What the driver's own log line used to show, for the operator-facing message. translated.setattr("endpoint", connection_endpoint(&text))?; - translated.setattr("reason", reason)?; + translated.setattr("reason", unreachable.reason)?; + translated.setattr("through_proxy", unreachable.through_proxy)?; } Ok(translated) } -/// `refused` or `unresolved` reason when the driver error was caused by a refused connection or -/// an unresolvable host, as the HTTP client chains them under the driver's own error. Like a -/// traceback, it follows `__context__` only when `__cause__` is unset and the context is not -/// suppressed. -fn unreachable_host_reason(error: &Bound<'_, PyAny>) -> PyResult> { +/// Why a connection could not be opened, and whether the unreachable endpoint is a proxy. +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +struct Unreachable { + reason: &'static str, + /// The failed pool is a configured proxy (urllib3 `ProxyError` in the chain). + through_proxy: bool, +} + +/// The refused connection or unresolvable host that caused the driver error, as the HTTP +/// client chains them under the driver's own error. Like a traceback, it follows `__context__` +/// only when `__cause__` is unset and the context is not suppressed. A `socket.gaierror` with +/// errno `EAI_AGAIN` is a temporary DNS failure; any other is a host that was not found. +fn unreachable_host(error: &Bound<'_, PyAny>) -> PyResult> { let py: Python<'_> = error.py(); let refused: Value<'_> = py.import("builtins")?.getattr("ConnectionRefusedError")?; - let unresolved: Value<'_> = py.import("socket")?.getattr("gaierror")?; + let socket: Bound<'_, PyModule> = py.import("socket")?; + let unresolved: Value<'_> = socket.getattr("gaierror")?; + let temporary: Value<'_> = socket.getattr("EAI_AGAIN")?; + let proxy: Value<'_> = py.import("urllib3.exceptions")?.getattr("ProxyError")?; + let mut through_proxy: bool = false; let mut current: Value<'_> = error.clone(); for _ in 0..MAX_CAUSE_DEPTH { - if current.is_instance(&refused)? { - return Ok(Some(REFUSED_REASON)); - } - if current.is_instance(&unresolved)? { - return Ok(Some(UNRESOLVED_REASON)); + through_proxy |= current.is_instance(&proxy)?; + let reason: Option<&'static str> = if current.is_instance(&refused)? { + Some(REFUSED_REASON) + } else if current.is_instance(&unresolved)? { + Some(if current.getattr("errno")?.eq(&temporary)? { + TEMPORARY_DNS_REASON + } else { + UNRESOLVED_REASON + }) + } else { + None + }; + if let Some(reason) = reason { + return Ok(Some(Unreachable { + reason, + through_proxy, + })); } let cause: Value<'_> = current.getattr("__cause__")?; current = if !cause.is_none() { @@ -118,12 +144,20 @@ fn unreachable_host_reason(error: &Bound<'_, PyAny>) -> PyResult Option { let rest: &str = &message[message.find("host='")? + "host='".len()..]; let (host, rest) = rest.split_once("', port=")?; let digits: usize = rest.find(|character: char| !character.is_ascii_digit())?; - (!host.is_empty() && digits > 0).then(|| format!("{host}:{}", &rest[..digits])) + if host.is_empty() || digits == 0 { + return None; + } + let port: &str = &rest[..digits]; + Some(if host.contains(':') && !host.starts_with('[') { + format!("[{host}]:{port}") + } else { + format!("{host}:{port}") + }) } /// Logging filter on clickhouse_connect's HTTP client logger that demotes its generic @@ -146,7 +180,7 @@ impl UnreachableHostLogFilter { return Ok(true); } let handled: Value<'_> = py.import("sys")?.call_method0("exc_info")?.get_item(1)?; - if handled.is_none() || unreachable_host_reason(&handled)?.is_none() { + if handled.is_none() || unreachable_host(&handled)?.is_none() { return Ok(true); } let logging: Bound<'_, PyModule> = py.import("logging")?; diff --git a/src/sqltide/adapter/exceptions.py b/src/sqltide/adapter/exceptions.py index 37964ac7..744aa04d 100644 --- a/src/sqltide/adapter/exceptions.py +++ b/src/sqltide/adapter/exceptions.py @@ -40,6 +40,8 @@ class AdapterUnavailableError(AdapterWarehouseError): """The `host:port` the connection was attempted to, when the adapter knows it.""" reason: str | None = None """A short cause such as `connection refused` or `host not found`.""" + through_proxy: bool = False + """Whether `endpoint` is a configured proxy rather than ClickHouse itself.""" class AdapterTimeoutError(AdapterWarehouseError): diff --git a/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py b/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py index 3aad4dc3..35d40971 100644 --- a/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py +++ b/tests/unit/src/sqltide/adapters/clickhouse/_test_types.py @@ -507,6 +507,7 @@ class UnreachableHostDetailsTestCase: driver_error: Exception expected_endpoint: str | None expected_reason: str + expected_through_proxy: bool @dataclass(frozen=True) diff --git a/tests/unit/src/sqltide/adapters/clickhouse/helpers.py b/tests/unit/src/sqltide/adapters/clickhouse/helpers.py index 46a8ec00..6dc5e7a4 100644 --- a/tests/unit/src/sqltide/adapters/clickhouse/helpers.py +++ b/tests/unit/src/sqltide/adapters/clickhouse/helpers.py @@ -3,6 +3,7 @@ from typing import cast from clickhouse_connect.driver.exceptions import OperationalError +from urllib3.exceptions import ProxyError from sqltide._native import UnreachableHostLogFilter, sql_canonicalize from sqltide.adapter.exceptions import AdapterWarehouseError @@ -355,6 +356,18 @@ def connection_failure( return driver_error +def proxy_failure(message: str, *, cause: BaseException) -> OperationalError: + """A driver error for a configured proxy that could not be reached, chained as urllib3 wraps + the proxy's connection failure in a `ProxyError`.""" + transport_error: OSError = OSError("Failed to establish a new connection") + transport_error.__cause__ = cause + proxy_error: ProxyError = ProxyError("Unable to connect to proxy", transport_error) + proxy_error.__context__ = transport_error + driver_error: OperationalError = OperationalError(message) + driver_error.__cause__ = proxy_error + return driver_error + + def filter_driver_record( *, message: str, handled_errors: tuple[BaseException, ...], logger_level: int ) -> tuple[bool, str]: diff --git a/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py b/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py index aa06cbb4..57eea362 100644 --- a/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py +++ b/tests/unit/src/sqltide/adapters/clickhouse/test_errors.py @@ -22,6 +22,7 @@ from tests.unit.src.sqltide.adapters.clickhouse.helpers import ( connection_failure, filter_driver_record, + proxy_failure, ) _AUTHENTICATION_FAILED_MESSAGE: str = ( @@ -41,6 +42,14 @@ "executing HTTP request attempt 1 (http://warehouse.example.com:8123)" ) _DRIVER_FAILURE_LOG: str = "Unexpected Http Driver Exception" +_IPV6_CONNECTION_FAILED_MESSAGE: str = ( + "Error HTTPConnectionPool(host='::1', port=8123): Max retries exceeded " + "executing HTTP request attempt 1 (http://[::1]:8123)" +) +_PROXY_CONNECTION_FAILED_MESSAGE: str = ( + "Error HTTPConnectionPool(host='proxy.example.com', port=3128): Max retries exceeded " + "executing HTTP request attempt 1 (http://warehouse.example.com:8123)" +) _REFUSED_WITH_TIMEOUT_SETTING_MESSAGE: str = ( "Error HTTPConnectionPool(host='warehouse.example.com', port=8123): Max retries exceeded " "with url: /?receive_timeout=30&database=orders executing HTTP request attempt 1" @@ -149,6 +158,7 @@ def test_given_driver_error_when_translating_then_it_returns_the_neutral_equival ), expected_endpoint="warehouse.example.com:8123", expected_reason="connection refused", + expected_through_proxy=False, ), UnreachableHostDetailsTestCase( description="names the endpoint and an unresolvable host", @@ -159,6 +169,7 @@ def test_given_driver_error_when_translating_then_it_returns_the_neutral_equival ), expected_endpoint="warehouse.example.com:8123", expected_reason="host not found", + expected_through_proxy=False, ), UnreachableHostDetailsTestCase( description="leaves the endpoint unknown when the message names no pool", @@ -169,6 +180,50 @@ def test_given_driver_error_when_translating_then_it_returns_the_neutral_equival ), expected_endpoint=None, expected_reason="connection refused", + expected_through_proxy=False, + ), + UnreachableHostDetailsTestCase( + description="brackets an IPv6 endpoint", + driver_error=connection_failure( + _IPV6_CONNECTION_FAILED_MESSAGE, + cause=ConnectionRefusedError(111, "Connection refused"), + link="__cause__", + ), + expected_endpoint="[::1]:8123", + expected_reason="connection refused", + expected_through_proxy=False, + ), + UnreachableHostDetailsTestCase( + description="marks a refused configured proxy", + driver_error=proxy_failure( + _PROXY_CONNECTION_FAILED_MESSAGE, + cause=ConnectionRefusedError(111, "Connection refused"), + ), + expected_endpoint="proxy.example.com:3128", + expected_reason="connection refused", + expected_through_proxy=True, + ), + UnreachableHostDetailsTestCase( + description="reports EAI_AGAIN as a temporary DNS failure", + driver_error=connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=socket.gaierror(socket.EAI_AGAIN, "Name or service not known"), + link="__cause__", + ), + expected_endpoint="warehouse.example.com:8123", + expected_reason="temporary DNS failure", + expected_through_proxy=False, + ), + UnreachableHostDetailsTestCase( + description="reports EAI_NONAME as host not found whatever the message says", + driver_error=connection_failure( + _CONNECTION_FAILED_MESSAGE, + cause=socket.gaierror(socket.EAI_NONAME, "Temporary failure in name resolution"), + link="__cause__", + ), + expected_endpoint="warehouse.example.com:8123", + expected_reason="host not found", + expected_through_proxy=False, ), ], ids=lambda case: case.description, @@ -180,10 +235,16 @@ def test_given_unreachable_host_when_translating_then_endpoint_and_reason_are_at AdapterUnavailableError, translate_clickhouse_driver_error(test_case.driver_error) ) - assert (type(translated), translated.endpoint, translated.reason) == ( + assert ( + type(translated), + translated.endpoint, + translated.reason, + translated.through_proxy, + ) == ( AdapterUnavailableError, test_case.expected_endpoint, test_case.expected_reason, + test_case.expected_through_proxy, ) diff --git a/tests/unit/src/sqltide/cli/helpers.py b/tests/unit/src/sqltide/cli/helpers.py index 17956545..ff0c908a 100644 --- a/tests/unit/src/sqltide/cli/helpers.py +++ b/tests/unit/src/sqltide/cli/helpers.py @@ -6,6 +6,7 @@ from textwrap import dedent from clickhouse_connect.driver.exceptions import OperationalError +from urllib3.exceptions import ProxyError from sqltide._native import ( render_clickhouse_replay_coverage_query, @@ -471,6 +472,21 @@ def refused_driver_error() -> OperationalError: return error +def proxy_refused_driver_error() -> OperationalError: + """The driver error for a configured proxy that refused the connection, chained as urllib3 + wraps it in a `ProxyError`.""" + proxy_error: ProxyError = ProxyError( + "Unable to connect to proxy", ConnectionRefusedError(111, "Connection refused") + ) + proxy_error.__cause__ = ConnectionRefusedError(111, "Connection refused") + error: OperationalError = OperationalError( + "Error HTTPConnectionPool(host='proxy.example.com', port=3128): Max retries exceeded " + "executing HTTP request attempt 1 (http://warehouse.example.com:8123)" + ) + error.__cause__ = proxy_error + return error + + def closed_local_port() -> int: """A loopback TCP port nothing listens on: bound once by the OS, then released.""" with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as probe: diff --git a/tests/unit/src/sqltide/cli/test_main.py b/tests/unit/src/sqltide/cli/test_main.py index 138729b1..604d896d 100644 --- a/tests/unit/src/sqltide/cli/test_main.py +++ b/tests/unit/src/sqltide/cli/test_main.py @@ -55,6 +55,7 @@ FakeCliClickHouseClient, handlers_with_overrides, normalize_json_output, + proxy_refused_driver_error, refused_driver_error, write_cli_compilation_project, write_cli_target_project, @@ -1311,6 +1312,31 @@ def test_given_apply_flag_when_running_janitor_then_it_passes_apply_to_command( "Database: analytics", ), ), + CliMainErrorTestCase( + description="names a refused proxy as a proxy, not as ClickHouse", + argv=( + "sqt", + "reconcile", + "--project-dir", + "tests/fixtures/basic_project", + "--host", + "warehouse.example.com", + "--port", + "8123", + "--username", + "sqltide", + "--password", + "sqltide", + "--database", + "analytics", + ), + expected_exit_code=1, + expected_error_fragments=( + "Reconcile could not connect to ClickHouse through proxy " + "proxy.example.com:3128: connection refused\n", + "Database: analytics", + ), + ), ], ids=lambda case: case.description, ) @@ -1328,6 +1354,9 @@ def test_given_expected_command_errors_when_running_entrypoint_then_it_prints_cl ) ), run_plan=FailingCommandRunner(translate_clickhouse_driver_error(refused_driver_error())), + run_reconcile=FailingCommandRunner( + translate_clickhouse_driver_error(proxy_refused_driver_error()) + ), ) clickhouse_client: AdapterConnection = cast(AdapterConnection, FakeCliClickHouseClient())