diff --git a/packages/google-api-core/google/api_core/_observability.py b/packages/google-api-core/google/api_core/_observability.py index 1ed10adf86c8..a5162e962700 100644 --- a/packages/google-api-core/google/api_core/_observability.py +++ b/packages/google-api-core/google/api_core/_observability.py @@ -1374,12 +1374,65 @@ def __init__( self._parent_span: Any = None self._cm: Any = None + def _log_http_attempt( + self, + status_code: int | str | None = None, + exc: BaseException | None = None, + status_message: str | None = None, + ) -> None: + """Emits a DEBUG transport attempt log for a failed HTTP request (fail-open). + + Note: + In GAPIC REST transports (``_shared_macros.j2``), ``trace_http_request`` + only wraps the raw ``session`` dispatch and ``record_response(response)``, + while HTTP status exceptions are raised outside the ``with`` block after + it exits. Because ``record_response`` and ``__exit__`` (``record_error``) + are mutually exclusive in transport execution, deduplication state is + not required here. + + Args: + status_code (int | str | None): HTTP response status code or error code. + exc (BaseException | None): Exception raised during HTTP dispatch, if any. + status_message (str | None): Extracted HTTP error message fallback. + """ + try: + resolved_url = ( + getattr(self._request, "url", None) + if self._request is not None + else self._url + ) + resolved_method = ( + getattr(self._request, "method", None) + if self._request is not None + else self._method + ) + log_transport_attempt( + span=self._span, + target=resolved_url, + status_code=status_code, + kind="http", + http_method=resolved_method, + exc=exc, + client_options=self._client_options, + status_message=status_message, + ) + # Intentionally catch broad Exception so telemetry logging fails open + # and never disrupts the caller's RPC flow. + except Exception: + pass + def record_response(self, response: Any) -> None: - """Record HTTP response attributes on the active span. + """Record HTTP response attributes on the active span and log failed attempts. Args: response (Any): The HTTP response object (e.g. requests.Response). """ + code_int = _extract_http_status_code(response) + error_msg: str | None = None + if code_int is not None and code_int >= 400: + error_msg = self._extract_http_error_message(response) + self._log_http_attempt(status_code=code_int, status_message=error_msg) + span = self._span if span is None or not hasattr(span, "set_attribute"): return @@ -1390,7 +1443,6 @@ def record_response(self, response: Any) -> None: StatusCode, ) - code_int = _extract_http_status_code(response) if code_int is not None: span.set_attribute("http.response.status_code", code_int) if self._parent_span is not None: @@ -1400,7 +1452,6 @@ def record_response(self, response: Any) -> None: if code_int >= 400: span.set_status(Status(StatusCode.ERROR)) span.set_attribute("error.type", str(code_int)) - error_msg = self._extract_http_error_message(response) if error_msg: span.set_attribute("status.message", error_msg) @@ -1423,7 +1474,7 @@ def record_response(self, response: Any) -> None: record_http_response = record_response def record_error(self, exc: BaseException | None) -> None: - """Record supplemental Cloud Observability error attributes on the active span. + """Record supplemental Cloud Observability error attributes on the active span and log failed attempts. Upstream OpenTelemetry's ``start_as_current_span`` context manager automatically records the exception event and marks the span status as ERROR when an unhandled @@ -1439,14 +1490,17 @@ def record_error(self, exc: BaseException | None) -> None: Args: exc (BaseException | None): The exception raised during dispatch. """ + if exc is None: + return + + status_code = getattr(exc, "code", None) or getattr(exc, "status_code", None) + self._log_http_attempt(status_code=status_code, exc=exc) + span = self._span - if span is None or exc is None: + if span is None: return try: - status_code = getattr(exc, "code", None) or getattr( - exc, "status_code", None - ) if status_code: span.set_attribute("error.type", str(status_code)) else: @@ -1529,10 +1583,12 @@ def __enter__(self) -> "_TraceContext": def __exit__(self, exc_type: Any, exc_val: Any, exc_tb: Any) -> None: if self._cm is not None: try: - if exc_val is not None and self._span is not None: + if exc_val is not None: self.record_error(exc_val) finally: self._cm.__exit__(exc_type, exc_val, exc_tb) + elif exc_val is not None: + self.record_error(exc_val) # Always return None so caller exceptions are never suppressed return None diff --git a/packages/google-api-core/tests/unit/test_observability.py b/packages/google-api-core/tests/unit/test_observability.py index 89b7cfacf06f..f62351293488 100644 --- a/packages/google-api-core/tests/unit/test_observability.py +++ b/packages/google-api-core/tests/unit/test_observability.py @@ -2894,3 +2894,70 @@ def test_get_otel_interceptors_with_logging_enabled( assert isinstance( async_list[2], _observability._AsyncSuppressingClientInterceptor ) + + +def test_trace_context_http_logging_on_error_status_and_exception(monkeypatch): + """Proves that _TraceContext logs HTTP error responses (>= 400) and dispatch exceptions when logging is enabled.""" + monkeypatch.setenv("GOOGLE_SDK_EXPERIMENTAL_PYTHON_TRACING_ENABLED", "false") + monkeypatch.setenv("GOOGLE_SDK_EXPERIMENTAL_PYTHON_LOGGING_ENABLED", "true") + + with mock.patch.object(_observability, "log_transport_attempt") as mock_log: + with _observability.trace_http_request( + method="POST", url="https://example.com/v1/echo" + ) as ctx: + ctx.record_response( + mock.Mock(status_code=503, headers={}, reason="Service Unavailable") + ) + mock_log.assert_called_once() + assert mock_log.call_args[1]["status_code"] == 503 + assert mock_log.call_args[1]["kind"] == "http" + assert mock_log.call_args[1]["status_message"] == "Service Unavailable" + + with mock.patch.object(_observability, "log_transport_attempt") as mock_log: + with pytest.raises(ConnectionError): + with _observability.trace_http_request( + method="GET", url="https://example.com/v1/echo" + ) as ctx: + ctx.record_error(None) + raise ConnectionError("reset") + mock_log.assert_called_once() + assert mock_log.call_args[1]["kind"] == "http" + assert isinstance(mock_log.call_args[1]["exc"], ConnectionError) + + with mock.patch.object( + _observability, "log_transport_attempt", side_effect=RuntimeError("log crash") + ): + ctx_err = _observability._TraceContext(method="GET", url="https://example.com") + ctx_err.record_error(ConnectionError("fail-open")) + ctx_err.record_response(mock.Mock(status_code=500, headers={})) + ctx_err.record_response(mock.Mock(status_code="invalid", headers={})) + + class BadTextResponse: + status_code = 500 + headers: dict = {} + + @property + def text(self): + raise RuntimeError("broken text") + + reason = "Fallback Reason" + + assert ( + _observability._TraceContext._extract_http_error_message(BadTextResponse()) + == "Fallback Reason" + ) + + monkeypatch.setenv("GOOGLE_SDK_EXPERIMENTAL_PYTHON_TRACING_ENABLED", "true") + mock_parent_span = mock.MagicMock() + mock_parent_span.is_recording.return_value = True + mock_parent_span.attributes = {} + mock_parent_span.set_attribute.side_effect = RuntimeError("parent attr crash") + mock_otel = mock.MagicMock() + mock_otel.trace.get_current_span.return_value = mock_parent_span + monkeypatch.setitem(sys.modules, "opentelemetry", mock_otel) + monkeypatch.setitem(sys.modules, "opentelemetry.trace", mock_otel.trace) + monkeypatch.setitem(sys.modules, "opentelemetry.instrumentation.grpc", mock.Mock()) + with _observability.trace_http_request( + method="GET", url="https://example.com/v1/echo", url_template="/v1/echo" + ): + pass