Repository: dwavesystems/dwave-cloud-client
Pull request #623 (2024-06-03 20:41:37)

Logging update
Close #537.


Patch:
diff --git a/dwave/cloud/__init__.py b/dwave/cloud/__init__.py
index a03dc5a..77ec720 100644
--- a/dwave/cloud/__init__.py
+++ b/dwave/cloud/__init__.py
@@ -12,20 +12,50 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import io
 import os
 import re
 import sys
+import json
 import logging
+import datetime
 import importlib
+import typing
 
 from dwave.cloud.client import Client
 from dwave.cloud.solver import Solver
 from dwave.cloud.computation import Future
-from dwave.cloud.utils import set_loglevel
+from dwave.cloud.utils import parse_loglevel
 
 __all__ = ['Client', 'Solver', 'Future']
 
 
+# prevent log output (from library) when logging not configured by user/app
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
+
+# add TRACE log level and Logger.trace() method
+logging.TRACE = 5
+logging.addLevelName(logging.TRACE, "TRACE")
+
+def _trace(logger, message, *args, **kwargs):
+    logger.log(logging.TRACE, message, *args, **kwargs)
+
+logging.Logger.trace = _trace
+
+
+class ISOFormatter(logging.Formatter):
+    # target timezone, e.g. `datetime.timezone.utc`, or `None` for naive timestamp
+    as_tz: typing.Optional[datetime.timezone] = None
+
+    def __init__(self, *args, as_tz: typing.Optional[datetime.timezone] = None, **kwargs):
+        self.as_tz = as_tz
+        super().__init__(*args, **kwargs)
+
+    def formatTime(self, record: logging.LogRecord, datefmt: typing.Optional[str] = None) -> str:
+        return datetime.datetime.fromtimestamp(record.created, tz=self.as_tz).isoformat()
+
+
 class FilteredSecretsFormatter(logging.Formatter):
     """Logging formatter that filters out secrets (like Solver API tokens).
 
@@ -43,40 +73,78 @@ class FilteredSecretsFormatter(logging.Formatter):
     _UUID_TOKEN_PATTERN = re.compile(
         r'\b([0-9A-Fa-f]{3})([0-9A-Fa-f]{5}-[0-9A-Fa-f]{4}-[0-9A-Fa-f]{4}-[0-9A-Fa-f]{4}-[0-9A-Fa-f]{9})([0-9A-Fa-f]{3})\b')
 
-    def format(self, record):
+    def format(self, record: logging.LogRecord) -> str:
         output = super().format(record)
         output = re.sub(self._SAPI_TOKEN_PATTERN, r'\1...\3', output)
         output = re.sub(self._HEX_TOKEN_PATTERN, r'\1...\3', output)
         output = re.sub(self._UUID_TOKEN_PATTERN, r'\1...\3', output)
         return output
 
-# configure logger `dwave.cloud` root logger, inherited in submodules
-# (write level warning+ to stderr, include timestamp/module/level)
-_formatter = FilteredSecretsFormatter('%(asctime)s %(name)s %(levelname)s %(threadName)s %(message)s')
-_handler = logging.StreamHandler()
-_handler.setFormatter(_formatter)
 
-# expose the root logger to simplify access; for example:
-# `dwave.cloud.logger.setLevel(logging.DEBUG)`
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
-logger.addHandler(_handler)
+class JSONFormatter(ISOFormatter):
+    def format(self, record: logging.LogRecord) -> str:
+        super().format(record)
+        # filter out message template and potentially unserializable args
+        rec = record.__dict__.copy()
+        del rec['args']
+        del rec['msg']
+        return json.dumps(rec)
+
+
+def configure_logging(logger: typing.Optional[logging.Logger] = None,
+                      *,
+                      level: int = logging.WARNING,
+                      filter_secrets: bool = True,
+                      output_stream: io.IOBase = sys.stderr,
+                      in_utc: bool = False,
+                      structured_output: bool = False,
+                      ) -> logging.Logger:
+    """Configure cloud-client's `dwave.cloud` base logger.
+
+    Logging output from the cloud-client is suppressed by default. This utility
+    function can be used from user's (app) code to quickly setup basic logging
+    from the library.
+
+    .. versionadded:: 0.12.0
+       Explicit optional logging configuration. Previously, logger was minimally
+       configured by default.
+    """
+    if logger is None:
+        logger = logging.getLogger(__name__)
 
+    format = dict(
+        fmt='%(asctime)s %(name)s %(levelname)s %(threadName)s [%(funcName)s] %(message)s',
+        as_tz=datetime.timezone.utc if in_utc else None,
+    )
 
-# add TRACE log level and Logger.trace() method
-logging.TRACE = 5
-logging.addLevelName(logging.TRACE, "TRACE")
+    if structured_output:
+        formatter_base = JSONFormatter
+    else:
+        formatter_base = ISOFormatter
 
-def _trace(logger, message, *args, **kwargs):
-    if logger.isEnabledFor(logging.TRACE):
-        logger._log(logging.TRACE, message, args, **kwargs)
+    if filter_secrets:
+        class Formatter(FilteredSecretsFormatter, formatter_base):
+            pass
+    else:
+        Formatter = formatter_base
 
-logging.Logger.trace = _trace
+    formatter = Formatter(**format)
+    handler = logging.StreamHandler(stream=output_stream)
+    handler.setFormatter(formatter)
+
+    logger.setLevel(level)
+    logger.addHandler(handler)
+
+    return logger
 
 
-# apply DWAVE_LOG_LEVEL
+# configure logger if DWAVE_LOG_LEVEL present in environment
 def _apply_loglevel_from_env(logger):
-    set_loglevel(logger, os.getenv('DWAVE_LOG_LEVEL'))
+    if log_level := os.getenv('DWAVE_LOG_LEVEL', os.getenv('dwave_log_level')):
+        level = parse_loglevel(log_level)
+        log_format = os.getenv('DWAVE_LOG_FORMAT', os.getenv('dwave_log_format', ''))
+        structured = log_format.strip().lower() == 'json'
+        configure_logging(logger, level=level, structured_output=structured)
 
 _apply_loglevel_from_env(logger)
 
diff --git a/dwave/cloud/api/client.py b/dwave/cloud/api/client.py
index 08bed1c..ee3ca28 100644
--- a/dwave/cloud/api/client.py
+++ b/dwave/cloud/api/client.py
@@ -66,7 +66,7 @@ class LoggingSession(BaseUrlSession):
     RequestRecord = namedtuple('RequestRecord',
                                ('request', 'response', 'exception'))
 
-    def send(self, request: requests.PreparedRequest, **kwargs):
+    def send(self, request: requests.PreparedRequest, **kwargs) -> requests.Response:
         callee = type(self).__name__
         if logger.getEffectiveLevel() >= logging.DEBUG:
             logger.debug(f"[{callee!s}] send(method={request.method!r}, url={request.url!r}, ...)")
@@ -95,13 +95,13 @@ class LoggingSession(BaseUrlSession):
             logger.debug("[%s] request failed with %r", callee, exc)
 
             req = getattr(exc, 'request', None)
-            if req:
+            if req is not None:
                 logger.trace("[%s] failing request=%r", callee,
                              dict(method=req.method, url=req.url,
                                   headers=req.headers, body=req.body))
 
             res = getattr(exc, 'response', None)
-            if res:
+            if res is not None:
                 logger.trace("[%s] failing response=%r", callee,
                              dict(status_code=res.status_code,
                                   headers=res.headers, text=res.text))
diff --git a/dwave/cloud/auth/flows.py b/dwave/cloud/auth/flows.py
index be2e20d..f4dd92b 100644
--- a/dwave/cloud/auth/flows.py
+++ b/dwave/cloud/auth/flows.py
@@ -103,6 +103,20 @@ class AuthFlow:
             authorization_endpoint=authorization_endpoint,
             token_endpoint=token_endpoint)
 
+        # setup response logging
+        def log_response(response, **kwargs):
+            callee = type(self.session).__name__
+
+            req = getattr(response, 'request', None)
+            if req is not None:
+                logger.trace("[%s] request=%r", callee,
+                             dict(method=req.method, url=req.url,
+                                  headers=req.headers, body=req.body))
+
+            logger.trace("[%s] request(...) = (code=%r, body=%r, headers=%r, %r)",
+                         callee, response.status_code, response.text, response.headers, kwargs)
+        self.session.hooks["response"].append(log_response)
+
         # set default headers (overwritten by ``session_config['headers']``)
         self.session.headers.update({'User-Agent': default_user_agent()})
 
diff --git a/dwave/cloud/cli.py b/dwave/cloud/cli.py
index 5478cf7..93d60db 100644
--- a/dwave/cloud/cli.py
+++ b/dwave/cloud/cli.py
@@ -28,7 +28,7 @@ import click
 import requests.exceptions
 
 import dwave.cloud
-from dwave.cloud import Client
+from dwave.cloud import Client, configure_logging
 from dwave.cloud import api
 from dwave.cloud.solver import StructuredSolver, BaseUnstructuredSolver
 from dwave.cloud.utils import (
@@ -55,10 +55,12 @@ click.option = partial(click.option, show_default=True)
 
 def enable_logging(ctx, param, value):
     if value and not ctx.resilient_parsing:
+        configure_logging()
         set_loglevel(dwave.cloud.logger, param.name)
 
 def enable_loglevel(ctx, param, value):
     if value and not ctx.resilient_parsing:
+        configure_logging()
         set_loglevel(dwave.cloud.logger, value)
 
 def show_platform(ctx, param, value):
@@ -543,6 +545,7 @@ def solvers(config_file, profile, endpoint, region, client_type, solver_def,
         client_type = 'base'
         solver_def = '{}'
 
+    # TODO: handle exceptions like in `_get_client_solver` and `standardized_output`
     with Client.from_config(
             config_file=config_file, profile=profile,
             endpoint=endpoint, region=region,
diff --git a/dwave/cloud/client/hybrid.py b/dwave/cloud/client/hybrid.py
index 042ed11..010b4a4 100644
--- a/dwave/cloud/client/hybrid.py
+++ b/dwave/cloud/client/hybrid.py
@@ -12,7 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-"""
+r"""
 Interface to hybrid :term:`sampler`\ s available through the D-Wave Solver API
 (SAPI).
 """
diff --git a/dwave/cloud/client/qpu.py b/dwave/cloud/client/qpu.py
index 8c128b5..3fcc16f 100644
--- a/dwave/cloud/client/qpu.py
+++ b/dwave/cloud/client/qpu.py
@@ -12,7 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-"""
+r"""
 An implementation of the REST client for D-Wave Solver API (SAPI) service.
 
 SAPI servers provide authentication, queuing, and scheduling services,
diff --git a/dwave/cloud/client/sw.py b/dwave/cloud/client/sw.py
index a8c567c..481079c 100644
--- a/dwave/cloud/client/sw.py
+++ b/dwave/cloud/client/sw.py
@@ -12,7 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-"""
+r"""
 Interface to software :term:`sampler`\ s available through the D-Wave Solver
 API (SAPI).
 
diff --git a/dwave/cloud/utils.py b/dwave/cloud/utils.py
index 3fa3e1e..daaca4d 100644
--- a/dwave/cloud/utils.py
+++ b/dwave/cloud/utils.py
@@ -869,6 +869,7 @@ def set_loglevel(logger, level_name):
     logger.setLevel(level)
     logger.info("Log level for %r namespace set to %r", logger.name, level)
 
+
 def pretty_argvalues():
     """Pretty-formatted function call arguments, from the caller's frame."""
     return inspect.formatargvalues(*inspect.getargvalues(inspect.currentframe().f_back))
diff --git a/releasenotes/notes/logging-refresh-d392732eac90f1d5.yaml b/releasenotes/notes/logging-refresh-d392732eac90f1d5.yaml
new file mode 100644
index 0000000..f85b970
--- /dev/null
+++ b/releasenotes/notes/logging-refresh-d392732eac90f1d5.yaml
@@ -0,0 +1,17 @@
+---
+features:
+  - |
+    Add request/response logging to ``AuthFlow``/``OAuth2Session``.
+  - |
+    Add basic support for structured logs (JSON output).
+  - |
+    Enable log format control with ``DWAVE_LOG_FORMAT`` env variable (set to
+    ``"json"`` for structured output.
+fixes:
+  - |
+    Log failing request/response details in the low-level API client.
+  - |
+    Suppress logging output from the cloud-client by default (as recommended
+    for libraries).
+  - |
+    Format log record date/time according to ISO 8601.


Test patch:
diff --git a/tests/test_cli.py b/tests/test_cli.py
index 23aede1..f9f6ff8 100644
--- a/tests/test_cli.py
+++ b/tests/test_cli.py
@@ -15,6 +15,7 @@
 import os
 import json
 import unittest
+import subprocess
 from unittest import mock
 
 from click.testing import CliRunner
@@ -716,5 +717,28 @@ class TestCliLive(unittest.TestCase):
         self.assertEqual(result.exit_code, 0)
 
 
+class TestLogging(unittest.TestCase):
+
+    def test_json_logs(self):
+        env = {
+            'DWAVE_CONFIG_FILE': test_config_path,
+            'DWAVE_LOG_LEVEL': 'debug',
+            'DWAVE_LOG_FORMAT': 'json',
+        }
+
+        with isolated_environ(add=env):
+            ret = subprocess.run('dwave ping', capture_output=True, shell=True)
+
+        # ping will fail because API token is undefined
+        self.assertEqual(ret.returncode, 1)
+
+        # but stderr should still contain one json log record per line
+        for line in ret.stderr.splitlines():
+            rec = json.loads(line)
+            self.assertIsInstance(rec, dict)
+            self.assertIn('message', rec)
+            self.assertIn('created', rec)
+
+
 if __name__ == '__main__':
     unittest.main()