fix: use json format directly if available and add information on debugging (#1289)

* fix: use json format directly if available and add information on debugging

Signed-off-by: Debarati Basu-Nag <dbasunag@redhat.com>
Co-Authored-By: Claude <noreply@anthropic.com>

* feat: add --readable-logs CLI option for human-readable log output

Signed-off-by: fege <fmosca@redhat.com>

---------

Signed-off-by: Debarati Basu-Nag <dbasunag@redhat.com>
Signed-off-by: fege <fmosca@redhat.com>
Co-authored-by: Claude <noreply@anthropic.com>
Co-authored-by: fege <fmosca@redhat.com>
Co-authored-by: Jorge <jgarciao@users.noreply.github.com>

Author: 4 people

conftest.py

@@ -54,6 +54,7 @@ def pytest_addoption(parser: Parser) -> None:
     serving_arguments_group = parser.getgroup(name="Serving arguments")
     model_validation_automation_group = parser.getgroup(name="Model Validation Automation")
     hf_group = parser.getgroup(name="Hugging Face")
+    logging_group = parser.getgroup(name="Logging")
     model_registry_group = parser.getgroup(name="Model Registry options")
     # AWS config and credentials options
     aws_group.addoption(
@@ -206,6 +207,14 @@ def pytest_addoption(parser: Parser) -> None:
         help="Indicates if the model registry tests are to be run against custom namespace",
     )
 
+    # Logging options
+    logging_group.addoption(
+        "--readable-logs",
+        action="store_true",
+        default=False,
+        help="Write logs in human-readable format instead of JSON",
+    )
+
 
 def pytest_cmdline_main(config: Any) -> None:
     config.option.basetemp = py_config["tmp_base_dir"] = f"{config.option.basetemp}-{shortuuid.uuid()}"
@@ -326,6 +335,7 @@ def pytest_sessionstart(session: Session) -> None:
         log_level=log_level,
         thread_name=thread_name,
         enable_console=enable_console_value,
+        human_readable=session.config.getoption("--readable-logs"),
     )
 
     # Now safe to log after configuration is applied (only to file when console disabled)

docs/GETTING_STARTED.md

@@ -168,3 +168,28 @@ To run tests in containerized environment:
 ```bash
 podman run  -v $HOME:/mnt/host:Z  -e KUBECONFIG=/mnt/host/kubeconfig quay.io/opendatahub/opendatahub-tests
 ```
+
+## Debugging test failures
+
+### Human-readable log output
+
+By default, logs are written in JSON format to `pytest-tests.log`. To write logs in human-readable format instead, use the `--readable-logs` flag:
+
+```bash
+uv run pytest --readable-logs tests/my_test.py
+```
+
+This produces output like:
+
+```text
+2026-03-25T10:48:56.864955+00:00 conftest INFO Writing tests log to pytest-tests.log (conftest.py:342)
+2026-03-25T10:48:56.881095+00:00 ocp_resources.resource INFO Trying to get client via new_client_from_config (resource.py:272)
+```
+
+### Converting existing JSON logs
+
+To convert an existing JSON log file to readable format:
+
+```bash
+sed 's/^[^{]*//' pytest-tests.log | jq -r '"\(.timestamp) [\(.level)] \(.logger): \(.event)"'
+```

utilities/logger.py

@@ -4,7 +4,7 @@
 from logging.handlers import QueueHandler, QueueListener, RotatingFileHandler
 from typing import Any
 
-from utilities.opendatahub_logger import DuplicateFilter, WrapperLogFormatter
+from utilities.opendatahub_logger import DuplicateFilter, WrapperLogFormatter, set_human_readable
 
 LOGGER = logging.getLogger(__name__)
 
@@ -22,7 +22,11 @@ def __repr__(self) -> str:
 
 
 def setup_logging(
-    log_level: int, log_file: str = "/tmp/pytest-tests.log", thread_name: str | None = None, enable_console: bool = True
+    log_level: int,
+    log_file: str = "/tmp/pytest-tests.log",
+    thread_name: str | None = None,
+    enable_console: bool = True,
+    human_readable: bool = False,
 ) -> QueueListener:
     """
     Setup basic/root logging using QueueHandler/QueueListener
@@ -118,6 +122,8 @@ def setup_logging(
         if handler != root_log_queue_handler:
             logging.root.removeHandler(hdlr=handler)
 
+    set_human_readable(enabled=human_readable)
+
     log_listener.start()
     return log_listener
 

utilities/opendatahub_logger.py

@@ -103,20 +103,59 @@ def format(self, record: logging.LogRecord) -> str:
 
 
 class ThirdPartyJSONFormatter(logging.Formatter):
-    """Custom formatter that converts third-party logging to JSON format"""
+    """Custom formatter that converts third-party logging to JSON format.
+
+    If the message is already valid JSON (e.g. from structlog), it is passed through as-is.
+    """
 
     def format(self, record: logging.LogRecord) -> str:
-        return json.dumps({
-            "timestamp": datetime.fromtimestamp(record.created, tz=UTC).isoformat(),
-            "logger": record.name,
-            "level": record.levelname.lower(),
-            "event": record.getMessage(),
-            "filename": record.pathname.split("/")[-1] if record.pathname else "",
-            "lineno": str(record.lineno),
-        })
+        msg = record.getMessage()
+        try:
+            json.loads(msg)
+            return msg
+        except json.JSONDecodeError, TypeError:
+            return json.dumps({
+                "timestamp": datetime.fromtimestamp(record.created, tz=UTC).isoformat(),
+                "logger": record.name,
+                "level": record.levelname.lower(),
+                "event": msg,
+                "filename": record.pathname.split("/")[-1] if record.pathname else "",
+                "lineno": str(record.lineno),
+            })
 
 
 _initialized = False
+_human_readable = False
+_original_add_handler = logging.Logger.addHandler
+
+
+def set_human_readable(enabled: bool) -> None:
+    """Set log output format and re-initialize structlog if already configured."""
+    global _human_readable, _initialized
+    _human_readable = enabled
+    _initialized = False
+    _initialize()
+
+
+_LEVEL_COLORS = {
+    "DEBUG": _FG_CODES["cyan"],
+    "INFO": _FG_CODES["green"],
+    "WARNING": _FG_CODES["yellow"],
+    "ERROR": _FG_CODES["red"],
+    "CRITICAL": _FG_CODES["red"] + _BG_CODES["white"],
+}
+
+
+class ThirdPartyHumanReadableFormatter(logging.Formatter):
+    """Formatter for third-party logs in human-readable mode with colors and source location."""
+
+    def format(self, record: logging.LogRecord) -> str:
+        timestamp = datetime.fromtimestamp(record.created, tz=UTC).isoformat()
+        color = _LEVEL_COLORS.get(record.levelname, "")
+        reset = _RESET if color else ""
+        filename = record.pathname.rsplit("/", 1)[-1] if record.pathname else ""
+        msg = record.getMessage()
+        return f"{timestamp} {record.name} {color}{record.levelname}{reset} {msg} ({filename}:{record.lineno})"
 
 
 def _initialize() -> None:
@@ -125,36 +164,51 @@ def _initialize() -> None:
     if _initialized:
         return
 
-    structlog.configure(
-        processors=[
+    if _human_readable:
+        processors = [
+            structlog.processors.KeyValueRenderer(key_order=["event"]),
+        ]
+    else:
+        processors = [
             structlog.stdlib.add_logger_name,
             structlog.stdlib.add_log_level,
             structlog.processors.TimeStamper(fmt="ISO", utc=True),
             structlog.processors.JSONRenderer(),
-        ],
+        ]
+
+    structlog.configure(
+        processors=processors,
         wrapper_class=structlog.stdlib.BoundLogger,
         logger_factory=structlog.stdlib.LoggerFactory(),
-        cache_logger_on_first_use=True,
+        cache_logger_on_first_use=False,
     )
 
-    # Patch addHandler so new loggers get JSON formatting
-    original_add_handler = logging.Logger.addHandler
+    third_party_formatter = ThirdPartyHumanReadableFormatter() if _human_readable else ThirdPartyJSONFormatter()
+
+    # Formatters that should not be replaced:
+    # - JSONOnlyFormatter: used by StructlogWrapper (structlog already formats the message)
+    # - WrapperLogFormatter: used by setup_logging's QueueHandlers (only protected in HR mode)
+    _skip_formatters: tuple[type, ...] = (JSONOnlyFormatter,)
+    if _human_readable:
+        _skip_formatters = (*_skip_formatters, WrapperLogFormatter)
 
+    # Patch addHandler so new loggers (e.g. from ocp_resources/simple_logger)
+    # get the correct formatter on their handlers.
     def patched_add_handler(self: logging.Logger, hdlr: logging.Handler) -> None:
-        if not isinstance(hdlr.formatter, (ThirdPartyJSONFormatter, JSONOnlyFormatter)):
-            hdlr.setFormatter(fmt=ThirdPartyJSONFormatter())
-        original_add_handler(self, hdlr)  # noqa: FCN001
+        if not isinstance(hdlr.formatter, _skip_formatters):
+            hdlr.setFormatter(fmt=third_party_formatter)
+        _original_add_handler(self, hdlr)  # noqa: FCN001
 
     logging.Logger.addHandler = patched_add_handler  # type: ignore[method-assign]
 
-    # Apply JSON formatter to all existing handlers on all loggers
+    # Apply formatter to all existing handlers on all loggers
     all_loggers = [logging.getLogger()] + [
         logger for logger in logging.root.manager.loggerDict.values() if isinstance(logger, logging.Logger)
     ]
     for logger in all_loggers:
         for handler in logger.handlers:
-            if isinstance(handler.formatter, (logging.Formatter, type(None))):
-                handler.setFormatter(fmt=ThirdPartyJSONFormatter())
+            if not isinstance(handler.formatter, _skip_formatters):
+                handler.setFormatter(fmt=third_party_formatter)
 
     _initialized = True
 
@@ -177,8 +231,14 @@ def _log(self, level: str, msg: Any, *args: Any, **kwargs: Any) -> None:
         if args:
             msg_str = msg_str % args
 
-        log_method = getattr(self._logger, level.lower())
-        log_method(event=msg_str, **kwargs)
+        if _human_readable:
+            std_logger = logging.getLogger(self.name)
+            log_method = getattr(std_logger, level.lower())
+            extra_str = " ".join(f"{k}={v}" for k, v in kwargs.items()) if kwargs else ""
+            log_method(f"{msg_str} {extra_str}" if extra_str else msg_str, stacklevel=3)  # noqa: FCN001
+        else:
+            log_method = getattr(self._logger, level.lower())
+            log_method(event=msg_str, **kwargs)
 
     def info(self, msg: Any, *args: Any, **kwargs: Any) -> None:
         self._log("info", msg, *args, **kwargs)  # noqa: FCN001