Merge pull request #43 from ecmwf-projects/improve-logging

improve logging

cads_api_client/legacy_api_client.py

@@ -1,8 +1,10 @@
 from __future__ import annotations
 
 import functools
+import logging
 import warnings
-from typing import Any, Callable, overload
+from types import TracebackType
+from typing import Any, Callable, TypeVar, cast, overload
 
 import cdsapi.api
 import requests
@@ -29,12 +31,43 @@
     "session",
 ]
 
+LOGGER = logging.getLogger(__name__)
+F = TypeVar("F", bound=Callable[..., Any])
 
-class LegacyApiClient(cdsapi.api.Client):  # type: ignore[misc]
-    def __new__(cls, *args: Any, **kwargs: Any) -> LegacyApiClient:
-        instantiated: LegacyApiClient = super(cdsapi.api.Client, cls).__new__(cls)
-        return instantiated
 
+class LoggingContext:
+    def __init__(self, logger: logging.Logger, quiet: bool, debug: bool) -> None:
+        self.logger = logger
+        self.old_level = self.logger.level
+
+        if quiet:
+            self.logger.setLevel(logging.WARNING)
+        else:
+            self.logger.setLevel(logging.DEBUG if debug else logging.INFO)
+
+        self.new_handlers = []
+        if not self.logger.handlers:
+            formatter = logging.Formatter("%(asctime)s %(levelname)s %(message)s")
+            handler = logging.StreamHandler()
+            handler.setFormatter(formatter)
+            self.logger.addHandler(handler)
+            self.new_handlers.append(handler)
+
+    def __enter__(self) -> logging.Logger:
+        return self.logger
+
+    def __exit__(
+        self,
+        exc_type: type[BaseException] | None,
+        exc_val: BaseException | None,
+        exc_tb: TracebackType | None,
+    ) -> None:
+        self.logger.setLevel(self.old_level)
+        for handler in self.new_handlers:
+            self.logger.removeHandler(handler)
+
+
+class LegacyApiClient(cdsapi.api.Client):  # type: ignore[misc]
     def __init__(
         self,
         url: str | None = None,
@@ -61,19 +94,47 @@ def __init__(
             "retry_after": self.sleep_max,
         }
 
+        self.quiet = kwargs.pop("quiet", False)
+        self._debug = kwargs.pop("debug", False)
+
         if kwargs:
             warnings.warn(
                 "This is a beta version."
                 f" The following parameters have not been implemented yet: {kwargs}.",
                 UserWarning,
             )
 
+        with LoggingContext(
+            logger=LOGGER, quiet=self.quiet, debug=self._debug
+        ) as logger:
+            logger.debug(
+                "CDSAPI %s",
+                {
+                    "url": self.url,
+                    "key": self.key,
+                    "quiet": self.quiet,
+                    "timeout": self.timeout,
+                    "sleep_max": self.sleep_max,
+                    "retry_max": self.retry_max,
+                },
+            )
+
     @classmethod
     def raise_not_implemented_error(self) -> None:
         raise NotImplementedError(
             "This is a beta version. This functionality has not been implemented yet."
         )
 
+    def logging_decorator(self, func: F) -> F:
+        @functools.wraps(func)
+        def wrapper(*args: Any, **kwargs: Any) -> Any:
+            with LoggingContext(
+                logger=processing.logger, quiet=self.quiet, debug=self._debug
+            ):
+                return func(*args, **kwargs)
+
+        return cast(F, wrapper)
+
     @overload
     def retrieve(self, name: str, request: dict[str, Any], target: str) -> str: ...
 
@@ -85,7 +146,7 @@ def retrieve(
     def retrieve(
         self, name: str, request: dict[str, Any], target: str | None = None
     ) -> str | processing.Results:
-        result = self.client.submit_and_wait_on_result(
+        result = self.logging_decorator(self.client.submit_and_wait_on_result)(
             collection_id=name,
             retry_options=self.retry_options,
             **request,
@@ -95,7 +156,7 @@ def retrieve(
             timeout=self.timeout,
             retry_options=self.retry_options,
         )
-        result.download = partial_download  # type: ignore[method-assign]
+        result.download = self.logging_decorator(partial_download)  # type: ignore[method-assign]
         return result if target is None else result.download(target)
 
     def service(self, name, *args, **kwargs):  # type: ignore

cads_api_client/processing.py

@@ -184,11 +184,10 @@ def _robust_status(self, retry_options: Dict[str, Any] = {}) -> str:
 
     def wait_on_result(self, retry_options: Dict[str, Any] = {}) -> None:
         sleep = 1.0
-        last_status = self._robust_status(retry_options=retry_options)
+        status = None
         while True:
-            status = self._robust_status(retry_options=retry_options)
-            if last_status != status:
-                logger.debug(f"status has been updated to {status}")
+            if status != (status := self._robust_status(retry_options=retry_options)):
+                logger.info(f"status has been updated to {status}")
             if status == "successful":
                 # workaround for the server-side 404 due to database replicas out od sync
                 time.sleep(1)

tests/integration_test_50_legacy_api_client.py

@@ -1,5 +1,7 @@
 import pathlib
 
+import pytest
+
 from cads_api_client import legacy_api_client
 
 
@@ -19,3 +21,24 @@ def test_retrieve(tmp_path: pathlib.Path, api_root_url: str, api_key: str) -> No
     actual_target = result.download(str(target))
     assert str(target) == actual_target
     assert target.stat().st_size == 1
+
+
+@pytest.mark.parametrize("quiet", [True, False])
+def test_quiet(
+    caplog: pytest.LogCaptureFixture, api_root_url: str, api_key: str, quiet: bool
+) -> None:
+    client = legacy_api_client.LegacyApiClient(
+        url=api_root_url, key=api_key, quiet=quiet
+    )
+    client.retrieve("test-adaptor-dummy", {})
+    records = [record for record in caplog.records if record.levelname == "INFO"]
+    assert not records if quiet else records
+
+
+@pytest.mark.parametrize("debug", [True, False])
+def test_debug(
+    caplog: pytest.LogCaptureFixture, api_root_url: str, api_key: str, debug: bool
+) -> None:
+    legacy_api_client.LegacyApiClient(url=api_root_url, key=api_key, debug=debug)
+    records = [record for record in caplog.records if record.levelname == "DEBUG"]
+    assert records if debug else not records