From 14f65d5a684d53185cf688bbb72e2b878da74b0d Mon Sep 17 00:00:00 2001 From: Tobias Wochinger Date: Tue, 27 Feb 2024 18:31:51 +0100 Subject: [PATCH] feat: check tty / jupyter availability for logging config detection (#7226) * feat: check tty availability for logging config detection * chore: support jupyter + lower env variable * chore: also use jupyter util for check * test: set right mode --- haystack/logging.py | 19 +++- ...ogging-tty-detection-8136769cb4d1da67.yaml | 6 ++ test/test_logging.py | 92 ++++++++++++++++++- 3 files changed, 110 insertions(+), 7 deletions(-) create mode 100644 releasenotes/notes/logging-tty-detection-8136769cb4d1da67.yaml diff --git a/haystack/logging.py b/haystack/logging.py index 11ebde54c..94489ed0a 100644 --- a/haystack/logging.py +++ b/haystack/logging.py @@ -1,9 +1,12 @@ +import builtins import logging import os +import sys import typing -from typing import List +from typing import List, Optional import haystack.tracing.tracer +import haystack.utils.jupyter if typing.TYPE_CHECKING: from structlog.typing import Processor, WrappedLogger, EventDict @@ -27,7 +30,7 @@ def correlate_logs_with_traces(_: "WrappedLogger", __: str, event_dict: "EventDi return event_dict -def configure_logging(use_json: bool = False) -> None: +def configure_logging(use_json: Optional[bool] = None) -> None: """Configure logging for Haystack. - If `structlog` is not installed, we keep everything as it is. The user is responsible for configuring logging @@ -55,7 +58,17 @@ def configure_logging(use_json: bool = False) -> None: # https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging # This means that we use structlog to format the log entries for entries emitted via `logging` and `structlog`. - use_json = os.getenv(HAYSTACK_LOGGING_USE_JSON_ENV_VAR, "false").lower() == "true" or use_json + if use_json is None: # explicit parameter takes precedence over everything else + use_json_env_var = os.getenv(HAYSTACK_LOGGING_USE_JSON_ENV_VAR) + if use_json_env_var is None: + # We try to guess if we are in an interactive terminal or not + interactive_terminal = ( + sys.stderr.isatty() or hasattr(builtins, "__IPYTHON__") or haystack.utils.jupyter.is_in_jupyter() + ) + use_json = not interactive_terminal + else: + # User gave us an explicit value via environment variable + use_json = use_json_env_var.lower() == "true" shared_processors: List[Processor] = [ # Add the log level to the event_dict for structlog to use diff --git a/releasenotes/notes/logging-tty-detection-8136769cb4d1da67.yaml b/releasenotes/notes/logging-tty-detection-8136769cb4d1da67.yaml new file mode 100644 index 000000000..8493fe964 --- /dev/null +++ b/releasenotes/notes/logging-tty-detection-8136769cb4d1da67.yaml @@ -0,0 +1,6 @@ +--- +enhancements: + - | + The `logging` module now detects if the standard output is a TTY. If it is not and `structlog` is installed, it + will automatically disable the console renderer and log in JSON format. This behavior can be overridden by setting + the environment variable `HAYSTACK_LOGGING_USE_JSON` to `false`. diff --git a/test/test_logging.py b/test/test_logging.py index 2dbcba085..d2fc495e5 100644 --- a/test/test_logging.py +++ b/test/test_logging.py @@ -1,7 +1,6 @@ import builtins import json import logging -import os import sys from datetime import datetime, timezone from pathlib import Path @@ -14,6 +13,7 @@ from _pytest.monkeypatch import MonkeyPatch from haystack import logging as haystack_logging from test.tracing.utils import SpyingTracer +import haystack.utils.jupyter @pytest.fixture(autouse=True) @@ -60,7 +60,7 @@ class TestSkipLoggingConfiguration: class TestStructuredLoggingConsoleRendering: def test_log_filtering_when_using_debug(self, capfd: CaptureFixture) -> None: - haystack_logging.configure_logging() + haystack_logging.configure_logging(use_json=False) logger = logging.getLogger(__name__) logger.debug("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"}) @@ -70,7 +70,7 @@ class TestStructuredLoggingConsoleRendering: assert output == "" def test_log_filtering_when_using_debug_and_log_level_is_debug(self, capfd: CaptureFixture) -> None: - haystack_logging.configure_logging() + haystack_logging.configure_logging(use_json=False) logger = logging.getLogger(__name__) logger.setLevel(logging.DEBUG) @@ -79,7 +79,72 @@ class TestStructuredLoggingConsoleRendering: # Use `capfd` to capture the output of the final structlog rendering result output = capfd.readouterr().err - assert output != "" + assert "Hello, structured logging" in output + assert "{" not in output, "Seems JSON rendering is enabled when it should not be" + + def test_console_rendered_structured_log_even_if_no_tty_but_python_config( + self, capfd: CaptureFixture, monkeypatch: MonkeyPatch + ) -> None: + monkeypatch.setattr(sys.stderr, "isatty", lambda: False) + + haystack_logging.configure_logging(use_json=False) + + logger = logging.getLogger(__name__) + logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"}) + + # Use `capfd` to capture the output of the final structlog rendering result + output = capfd.readouterr().err + + assert "Hello, structured logging!" in output + assert "{" not in output, "Seems JSON rendering is enabled when it should not be" + + def test_console_rendered_structured_log_if_in_ipython( + self, capfd: CaptureFixture, monkeypatch: MonkeyPatch + ) -> None: + monkeypatch.setattr(builtins, "__IPYTHON__", "true", raising=False) + + haystack_logging.configure_logging() + + logger = logging.getLogger(__name__) + logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"}) + + # Use `capfd` to capture the output of the final structlog rendering result + output = capfd.readouterr().err + + assert "Hello, structured logging!" in output + assert "{" not in output, "Seems JSON rendering is enabled when it should not be" + + def test_console_rendered_structured_log_even_in_jupyter( + self, capfd: CaptureFixture, monkeypatch: MonkeyPatch + ) -> None: + monkeypatch.setattr(haystack.utils.jupyter, haystack.utils.jupyter.is_in_jupyter.__name__, lambda: True) + + haystack_logging.configure_logging() + + logger = logging.getLogger(__name__) + logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"}) + + # Use `capfd` to capture the output of the final structlog rendering result + output = capfd.readouterr().err + + assert "Hello, structured logging!" in output + assert "{" not in output, "Seems JSON rendering is enabled when it should not be" + + def test_console_rendered_structured_log_even_if_no_tty_but_forced_through_env( + self, capfd: CaptureFixture, monkeypatch: MonkeyPatch + ) -> None: + monkeypatch.setenv("HAYSTACK_LOGGING_USE_JSON", "false") + + haystack_logging.configure_logging() + + logger = logging.getLogger(__name__) + logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"}) + + # Use `capfd` to capture the output of the final structlog rendering result + output = capfd.readouterr().err + + assert "Hello, structured logging!" in output + assert "{" not in output, "Seems JSON rendering is enabled when it should not be" def test_console_rendered_structured_log(self, capfd: CaptureFixture) -> None: haystack_logging.configure_logging() @@ -122,6 +187,25 @@ class TestStructuredLoggingConsoleRendering: class TestStructuredLoggingJSONRendering: + def test_logging_as_json_if_not_atty(self, capfd: CaptureFixture, monkeypatch: MonkeyPatch) -> None: + monkeypatch.setattr(sys.stderr, "isatty", lambda: False) + haystack_logging.configure_logging() + + logger = logging.getLogger(__name__) + logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"}) + + # Use `capfd` to capture the output of the final structlog rendering result + output = capfd.readouterr().err + parsed_output = json.loads(output) # should not raise an error + + assert parsed_output == { + "event": "Hello, structured logging!", + "key1": "value1", + "key2": "value2", + "level": "warning", + "timestamp": ANY, + } + def test_logging_as_json(self, capfd: CaptureFixture) -> None: haystack_logging.configure_logging(use_json=True)