diff --git a/src/handlers/message.py b/src/handlers/message.py index 30b625c..b1a339c 100644 --- a/src/handlers/message.py +++ b/src/handlers/message.py @@ -6,7 +6,7 @@ from saic_ismart_client_ng.exceptions import SaicApiException, SaicLogoutException -from utils import ensure_datetime_aware, is_api_timeout, log_api_timeout +from utils import ensure_datetime_aware, is_transient_api_error, log_transient_api_error from vehicle import RefreshMode if TYPE_CHECKING: @@ -84,8 +84,10 @@ async def __polling(self) -> None: ) self.relogin_handler.relogin() except SaicApiException as e: - if is_api_timeout(e): - log_api_timeout(LOG, "MessageHandler poll failed, will retry", e) + if is_transient_api_error(e): + log_transient_api_error( + LOG, "MessageHandler poll failed, will retry", e + ) else: LOG.exception( "MessageHandler poll loop failed during SAIC API Call", exc_info=e diff --git a/src/handlers/vehicle.py b/src/handlers/vehicle.py index 9339a93..90e8400 100644 --- a/src/handlers/vehicle.py +++ b/src/handlers/vehicle.py @@ -18,7 +18,7 @@ import mqtt_topics from saic_api_listener import MqttGatewayAbrpListener, MqttGatewayOsmAndListener from status_publisher.vehicle_info import VehicleInfoPublisher -from utils import is_api_timeout, log_api_timeout +from utils import is_transient_api_error, log_transient_api_error from vehicle import RefreshMode if TYPE_CHECKING: @@ -169,8 +169,10 @@ async def handle_vehicle(self) -> None: self.relogin_handler.relogin() except SaicApiException as e: self.vehicle_state.mark_failed_refresh() - if is_api_timeout(e): - log_api_timeout(LOG, "Vehicle poll failed, will retry", e) + if is_transient_api_error(e): + log_transient_api_error( + LOG, "Vehicle poll failed, will retry", e + ) else: LOG.exception( "handle_vehicle loop failed during SAIC API call", diff --git a/src/handlers/vehicle_command.py b/src/handlers/vehicle_command.py index 48ac38c..825d267 100644 --- a/src/handlers/vehicle_command.py +++ b/src/handlers/vehicle_command.py @@ -9,7 +9,7 @@ from exceptions import MqttGatewayException from handlers.command import ALL_COMMAND_HANDLERS, CommandHandlerBase import mqtt_topics -from utils import is_api_timeout, log_api_timeout +from utils import is_transient_api_error, log_transient_api_error from vehicle import RefreshMode if TYPE_CHECKING: @@ -66,8 +66,10 @@ def __report_command_failure( detail: str, exc: Exception | None = None, ) -> None: - if exc is not None and is_api_timeout(exc): - log_api_timeout(LOG, f"Command {command} failed", exc) + if exc is not None and is_transient_api_error(exc): + log_transient_api_error( + LOG, f"Command {command} failed", exc, level=logging.ERROR + ) elif exc is not None: LOG.exception("Command %s failed: %s", command, detail, exc_info=exc) else: diff --git a/src/utils.py b/src/utils.py index 4bd5ed5..0b9730d 100644 --- a/src/utils.py +++ b/src/utils.py @@ -10,6 +10,7 @@ import httpx from saic_ismart_client_ng.api.schema import GpsStatus +from saic_ismart_client_ng.exceptions import SaicApiRetryException if TYPE_CHECKING: from saic_ismart_client_ng.api.vehicle import VehicleStatusResp @@ -17,15 +18,26 @@ LOG = logging.getLogger(__name__) -def is_api_timeout(exc: BaseException) -> bool: - """Whether ``exc`` was caused by an HTTP timeout talking to the SAIC API.""" - return isinstance(exc.__cause__, httpx.TimeoutException) +def is_transient_api_error(exc: BaseException) -> bool: + """Whether ``exc`` is a transient SAIC API failure. + + That is an HTTP timeout, or the server asking the client to retry later. + """ + return isinstance(exc, SaicApiRetryException) or isinstance( + exc.__cause__, httpx.TimeoutException + ) -def log_api_timeout(logger: logging.Logger, context: str, exc: BaseException) -> None: - """Log an API timeout as a short warning; keep the traceback for debug.""" - logger.warning( - "%s: SAIC API timed out, the server is not answering or busy: %s", +def log_transient_api_error( + logger: logging.Logger, + context: str, + exc: BaseException, + level: int = logging.WARNING, +) -> None: + """Log a transient API error as one line; keep the traceback for debug.""" + logger.log( + level, + "%s: SAIC API is not answering or is busy: %s", context, exc, exc_info=exc if logger.isEnabledFor(logging.DEBUG) else None, diff --git a/tests/test_utils.py b/tests/test_utils.py index c7a11ff..2a24cd8 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -9,12 +9,12 @@ import pytest from saic_ismart_client_ng.api.schema import GpsPosition, GpsStatus from saic_ismart_client_ng.api.vehicle import VehicleStatusResp -from saic_ismart_client_ng.exceptions import SaicApiException +from saic_ismart_client_ng.exceptions import SaicApiException, SaicApiRetryException from utils import ( get_update_timestamp, - is_api_timeout, - log_api_timeout, + is_transient_api_error, + log_transient_api_error, parse_timezone, ) @@ -153,21 +153,36 @@ def _wrapped(cause: BaseException | None) -> SaicApiException: exc.__cause__ = cause return exc - def test_is_api_timeout_true_for_httpx_timeout_cause(self) -> None: - assert is_api_timeout(self._wrapped(httpx.ReadTimeout("t"))) + def test_is_transient_api_error_true_for_httpx_timeout_cause(self) -> None: + assert is_transient_api_error(self._wrapped(httpx.ReadTimeout("t"))) - def test_is_api_timeout_false_for_other_cause(self) -> None: - assert not is_api_timeout(self._wrapped(httpx.ConnectError("c"))) - assert not is_api_timeout(self._wrapped(None)) + def test_is_transient_api_error_true_for_retry_exception(self) -> None: + exc = SaicApiRetryException("try again later", event_id="1", return_code=4) + assert is_transient_api_error(exc) - def test_log_api_timeout_traceback_only_in_debug( + def test_is_transient_api_error_false_for_other_cause(self) -> None: + assert not is_transient_api_error(self._wrapped(httpx.ConnectError("c"))) + assert not is_transient_api_error(self._wrapped(None)) + + def test_log_transient_api_error_traceback_only_in_debug( self, caplog: pytest.LogCaptureFixture ) -> None: logger = logging.getLogger("test_api_timeout") exc = self._wrapped(httpx.ReadTimeout("t")) with caplog.at_level(logging.INFO, logger=logger.name): - log_api_timeout(logger, "ctx", exc) + log_transient_api_error(logger, "ctx", exc) assert caplog.records[-1].exc_info is None with caplog.at_level(logging.DEBUG, logger=logger.name): - log_api_timeout(logger, "ctx", exc) + log_transient_api_error(logger, "ctx", exc) assert caplog.records[-1].exc_info is not None + + def test_log_transient_api_error_level( + self, caplog: pytest.LogCaptureFixture + ) -> None: + logger = logging.getLogger("test_api_level") + exc = self._wrapped(httpx.ReadTimeout("t")) + with caplog.at_level(logging.INFO, logger=logger.name): + log_transient_api_error(logger, "ctx", exc) + assert caplog.records[-1].levelno == logging.WARNING + log_transient_api_error(logger, "ctx", exc, level=logging.ERROR) + assert caplog.records[-1].levelno == logging.ERROR