Coverage for haystack/logging.py: 97%
129 statements
« prev ^ index » next coverage.py v7.15.4, created at 2026-08-21 13:53 +0000
1# SPDX-FileCopyrightText: 2022-present deepset GmbH <info@deepset.ai>
2#
3# SPDX-License-Identifier: Apache-2.0
5import builtins
6import functools
7import logging
8import os
9import sys
10import typing
11from collections.abc import Sequence
12from typing import Any
14import haystack.utils.jupyter
16if typing.TYPE_CHECKING:
17 from structlog.typing import EventDict, Processor, WrappedLogger
19HAYSTACK_LOGGING_USE_JSON_ENV_VAR = "HAYSTACK_LOGGING_USE_JSON"
20HAYSTACK_LOGGING_IGNORE_STRUCTLOG_ENV_VAR = "HAYSTACK_LOGGING_IGNORE_STRUCTLOG"
22# Attribute set on a logger once we have patched its methods. `logging.getLogger` returns a shared singleton, so we
23# use this marker to patch each logger only once and avoid wrapping the already-wrapped methods on repeated calls.
24_PATCHED_MARKER = "_haystack_patched"
26# Name of the formatting handler we install. We use it to find and remove our own handler across (re)configurations.
27_HANDLER_NAME = "HaystackLoggingHandler"
30def _is_haystack_logging_handler(handler: logging.Handler) -> bool:
31 """Return whether the given handler is the one installed by `configure_logging`."""
32 return isinstance(handler, logging.StreamHandler) and getattr(handler, "name", None) == _HANDLER_NAME
35class PatchedLogger(typing.Protocol):
36 """Class which enables using type checkers to find wrong logger usage."""
38 def debug(
39 self,
40 msg: str,
41 *,
42 _: Any = None,
43 exc_info: Any = None,
44 stack_info: Any = False,
45 stacklevel: int = 1,
46 **kwargs: Any,
47 ) -> None:
48 """Log a debug message."""
50 def info(
51 self,
52 msg: str,
53 *,
54 _: Any = None,
55 exc_info: Any = None,
56 stack_info: Any = False,
57 stacklevel: int = 1,
58 **kwargs: Any,
59 ) -> None:
60 """Log an info message."""
62 def warn(
63 self,
64 msg: str,
65 *,
66 _: Any = None,
67 exc_info: Any = None,
68 stack_info: Any = False,
69 stacklevel: int = 1,
70 **kwargs: Any,
71 ) -> None:
72 """Log a warning message."""
74 def warning(
75 self,
76 msg: str,
77 *,
78 _: Any = None,
79 exc_info: Any = None,
80 stack_info: Any = False,
81 stacklevel: int = 1,
82 **kwargs: Any,
83 ) -> None:
84 """Log a warning message."""
86 def error(
87 self,
88 msg: str,
89 *,
90 _: Any = None,
91 exc_info: Any = None,
92 stack_info: Any = False,
93 stacklevel: int = 1,
94 **kwargs: Any,
95 ) -> None:
96 """Log an error message."""
98 def critical(
99 self,
100 msg: str,
101 *,
102 _: Any = None,
103 exc_info: Any = None,
104 stack_info: Any = False,
105 stacklevel: int = 1,
106 **kwargs: Any,
107 ) -> None:
108 """Log a critical message."""
110 def exception(
111 self,
112 msg: str,
113 *,
114 _: Any = None,
115 exc_info: Any = None,
116 stack_info: Any = False,
117 stacklevel: int = 1,
118 **kwargs: Any,
119 ) -> None:
120 """Log an exception message."""
122 def fatal(
123 self,
124 msg: str,
125 *,
126 _: Any = None,
127 exc_info: Any = None,
128 stack_info: Any = False,
129 stacklevel: int = 1,
130 **kwargs: Any,
131 ) -> None:
132 """Log a fatal message."""
134 def log(
135 self,
136 level: int,
137 msg: str,
138 *,
139 _: Any = None,
140 exc_info: Any = None,
141 stack_info: Any = False,
142 stacklevel: int = 1,
143 **kwargs: Any,
144 ) -> None:
145 """Log a message."""
147 def setLevel(self, level: int) -> None:
148 """Set the logging level."""
151def patch_log_method_to_kwargs_only(func: typing.Callable) -> typing.Callable:
152 """A decorator to make sure that a function is only called with keyword arguments."""
154 @functools.wraps(func)
155 def _log_only_with_kwargs(
156 msg: str, *, _: Any = None, exc_info: Any = None, stack_info: Any = False, stacklevel: int = 1, **kwargs: Any
157 ) -> typing.Callable: # we need the `_` to avoid a syntax error
158 existing_extra = kwargs.pop("extra", {})
159 return func(
160 # we need to increase the stacklevel by 1 to point to the correct caller
161 # (otherwise it points to this function)
162 msg,
163 exc_info=exc_info,
164 stack_info=stack_info,
165 stacklevel=stacklevel + 1,
166 extra={**existing_extra, **kwargs},
167 )
169 return _log_only_with_kwargs
172def patch_log_with_level_method_to_kwargs_only(func: typing.Callable) -> typing.Callable:
173 """A decorator to make sure that a function is only called with keyword arguments."""
175 @functools.wraps(func)
176 def _log_only_with_kwargs(
177 level: int | str,
178 msg: str,
179 *,
180 _: Any = None,
181 exc_info: Any = None,
182 stack_info: Any = False,
183 stacklevel: int = 1,
184 **kwargs: Any, # we need the `_` to avoid a syntax error
185 ) -> typing.Callable:
186 existing_extra = kwargs.pop("extra", {})
188 return func(
189 level,
190 msg,
191 exc_info=exc_info,
192 stack_info=stack_info,
193 # we need to increase the stacklevel by 1 to point to the correct caller
194 # (otherwise it points to this function)
195 stacklevel=stacklevel + 1,
196 extra={**existing_extra, **kwargs},
197 )
199 return _log_only_with_kwargs
202def patch_make_records_to_use_kwarg_string_interpolation(original_make_records: typing.Callable) -> typing.Callable:
203 """A decorator to ensure string interpolation is used."""
205 @functools.wraps(original_make_records)
206 def _wrapper(
207 name: str,
208 level: int | str,
209 fn: str,
210 lno: int,
211 msg: str,
212 args: Any, # noqa: ARG001
213 exc_info: Any,
214 func: Any = None,
215 extra: Any = None,
216 sinfo: Any = None,
217 ) -> typing.Callable:
218 safe_extra = extra or {}
219 try:
220 interpolated_msg = msg.format(**safe_extra)
221 except (KeyError, ValueError, IndexError):
222 interpolated_msg = msg
223 return original_make_records(name, level, fn, lno, interpolated_msg, (), exc_info, func, extra, sinfo)
225 return _wrapper
228def _patch_structlog_call_information(logger: logging.Logger) -> None:
229 # structlog patches the findCaller to hide itself from the traceback.
230 # We need to patch their patch to hide `haystack.logging` from the traceback.
231 try:
232 from structlog._frames import _find_first_app_frame_and_name, _format_stack
233 from structlog.stdlib import _FixedFindCallerLogger
235 if not isinstance(logger, _FixedFindCallerLogger):
236 return
238 # Copied from structlog's `_FixedFindCallerLogger.findCaller`, adding `haystack.logging` to the ignored
239 # frames. We don't forward `stacklevel` to `_find_first_app_frame_and_name` (added in structlog 25.5.0):
240 # structlog is optional and may be older.
241 def findCaller(stack_info: bool = False, stacklevel: int = 1) -> tuple[str, int, str, str | None]: # noqa: ARG001
242 f, _name = _find_first_app_frame_and_name(["logging", "haystack.logging"])
243 sinfo = _format_stack(f) if stack_info else None
244 return f.f_code.co_filename, f.f_lineno, f.f_code.co_name, sinfo
246 logger.findCaller = findCaller # type: ignore
247 except ImportError:
248 pass
251def getLogger(name: str) -> PatchedLogger:
252 """
253 Get the Haystack logger, a patched version of the one from the standard library.
255 We patch the default logger methods to make sure that they are only called with keyword arguments.
256 We enforce keyword-arguments because
257 - it brings in consistency
258 - it makes structure logging effective, not just an available feature
259 """
260 logger = logging.getLogger(name)
261 if getattr(logger, _PATCHED_MARKER, False):
262 # Already patched: `logging.getLogger` returned the same singleton, so re-patching would stack the wrappers
263 # and interpolate the message more than once.
264 return typing.cast(PatchedLogger, logger)
266 logger.debug = patch_log_method_to_kwargs_only(logger.debug) # type: ignore
267 logger.info = patch_log_method_to_kwargs_only(logger.info) # type: ignore
268 logger.warn = patch_log_method_to_kwargs_only(logger.warn) # type: ignore
269 logger.warning = patch_log_method_to_kwargs_only(logger.warning) # type: ignore
270 logger.error = patch_log_method_to_kwargs_only(logger.error) # type: ignore
271 logger.critical = patch_log_method_to_kwargs_only(logger.critical) # type: ignore
272 logger.exception = patch_log_method_to_kwargs_only(logger.exception) # type: ignore
273 logger.fatal = patch_log_method_to_kwargs_only(logger.fatal) # type: ignore
274 logger.log = patch_log_with_level_method_to_kwargs_only(logger.log) # type: ignore
276 _patch_structlog_call_information(logger)
278 # We also patch the `makeRecord` method to use keyword string interpolation
279 logger.makeRecord = patch_make_records_to_use_kwarg_string_interpolation(logger.makeRecord) # type: ignore
281 setattr(logger, _PATCHED_MARKER, True)
283 return typing.cast(PatchedLogger, logger)
286def add_line_and_file(_: "WrappedLogger", __: str, event_dict: "EventDict") -> "EventDict":
287 """Add line and file to log entries."""
288 stdlib_record = event_dict.get("_record")
289 if not stdlib_record:
290 return event_dict
292 event_dict["lineno"] = stdlib_record.lineno
293 event_dict["module"] = stdlib_record.name
295 return event_dict
298def correlate_logs_with_traces(_: "WrappedLogger", __: str, event_dict: "EventDict") -> "EventDict":
299 """
300 Add correlation data for logs.
302 This is useful if you want to correlate logs with traces.
303 """
304 import haystack.tracing.tracer # to avoid circular imports
306 if not haystack.tracing.is_tracing_enabled():
307 return event_dict
309 current_span = haystack.tracing.tracer.current_span()
310 if current_span:
311 event_dict.update(current_span.get_correlation_data_for_logs())
313 return event_dict
316def configure_logging(
317 use_json: bool | None = None,
318 logger_name: str | Sequence[str] = ("haystack", "haystack_integrations", "haystack_experimental"),
319 propagate: bool = True,
320 configure_structlog: bool = True,
321) -> None:
322 """
323 Configure logging for Haystack.
325 - If `structlog` is not installed, we keep everything as it is. The user is responsible for configuring logging
326 themselves.
327 - If `structlog` is installed, we configure it to format log entries including its key-value data. To disable this
328 behavior set the environment variable `HAYSTACK_LOGGING_IGNORE_STRUCTLOG` to `true`.
329 - If `structlog` is installed, you can JSON format all logs. Enable this by
330 - setting the `use_json` parameter to `True` when calling this function
331 - setting the environment variable `HAYSTACK_LOGGING_USE_JSON` to `true`
333 :param use_json: Whether to format logs as JSON. If `None`, we try to guess based on the environment.
334 :param logger_name:
335 The name (or names) of the logger our formatting handler is attached to. Defaults to Haystack's own
336 namespaces (`"haystack"`, `"haystack_integrations"` and `"haystack_experimental"`), so that we only touch
337 Haystack's own loggers and leave the logging configuration of the host application and any other libraries
338 running in the same process untouched. Pass an empty string (`""`) to attach the handler to the root logger
339 instead - this restores the legacy behavior of formatting *every* log record in the process.
340 :param propagate:
341 Whether the configured loggers should propagate their records to ancestor loggers (ultimately the root
342 logger). The default (`True`) keeps records flowing to handlers configured by the host application and to
343 capturing tools such as `pytest`'s `caplog`. Set it to `False` to make Haystack fully own the output of its
344 own logs - this avoids duplicate log lines when the host application also configures the root logger. It has
345 no effect when `logger_name=""` (the root logger has no ancestors).
346 :param configure_structlog:
347 Whether to configure the process-global `structlog` (thereby taking over any configuration set up by someone
348 else). The default (`True`) is what an explicit call should do. Pass `False` (as the import-time call in
349 `haystack/__init__.py` does) to leave the global `structlog` configuration untouched and only install our own
350 scoped handler so Haystack's own logs are formatted. This keeps merely importing Haystack from reconfiguring
351 `structlog` for the host application's own native `structlog` loggers.
352 """
353 try:
354 import structlog
355 from structlog.processors import ExceptionRenderer
356 from structlog.tracebacks import ExceptionDictTransformer
358 except ImportError:
359 # structlog is not installed - fall back to standard logging
360 return
362 if os.getenv(HAYSTACK_LOGGING_IGNORE_STRUCTLOG_ENV_VAR, "false").lower() == "true":
363 # If the user wants to ignore structlog, we don't configure it and fall back to standard logging
364 return
366 # We roughly follow the structlog documentation here:
367 # https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging
368 # This means that we use structlog to format the log entries for entries emitted via `logging` and `structlog`.
370 if use_json is None: # explicit parameter takes precedence over everything else
371 use_json_env_var = os.getenv(HAYSTACK_LOGGING_USE_JSON_ENV_VAR)
372 if use_json_env_var is None:
373 # We try to guess if we are in an interactive terminal or not
374 interactive_terminal = (
375 sys.stderr.isatty() or hasattr(builtins, "__IPYTHON__") or haystack.utils.jupyter.is_in_jupyter()
376 )
377 use_json = not interactive_terminal
378 else:
379 # User gave us an explicit value via environment variable
380 use_json = use_json_env_var.lower() == "true"
382 shared_processors: list[Processor] = [
383 # Add the log level to the event_dict for structlog to use
384 structlog.stdlib.add_log_level,
385 # Adds the current timestamp in ISO format to logs
386 structlog.processors.TimeStamper(fmt="iso"),
387 structlog.contextvars.merge_contextvars,
388 add_line_and_file,
389 ]
391 if use_json:
392 # We only need that in sophisticated production setups where we want to correlate logs with traces
393 shared_processors.append(correlate_logs_with_traces)
395 # `structlog.configure` is process-global: it affects every native structlog logger, not just Haystack's. We only
396 # configure it when explicitly asked (`configure_structlog`).
397 if configure_structlog:
398 structlog.configure(
399 # `filter_by_level` reads the effective level from the underlying stdlib logger on *every* call, so
400 # changes to the log level made after `configure_logging` runs (e.g. by the host app) are respected.
401 processors=[
402 structlog.stdlib.filter_by_level,
403 *shared_processors,
404 structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
405 ],
406 logger_factory=structlog.stdlib.LoggerFactory(ignore_frame_names=["haystack.logging"]),
407 cache_logger_on_first_use=True,
408 wrapper_class=structlog.stdlib.BoundLogger,
409 )
411 renderers: list[Processor]
412 if use_json:
413 renderers = [
414 ExceptionRenderer(
415 # don't show locals in production logs - this can be quite sensitive information
416 ExceptionDictTransformer(show_locals=False)
417 ),
418 structlog.processors.JSONRenderer(),
419 ]
420 else:
421 renderers = [structlog.dev.ConsoleRenderer()]
423 formatter = structlog.stdlib.ProcessorFormatter(
424 # These run ONLY on `logging` entries that do NOT originate within
425 # structlog.
426 foreign_pre_chain=shared_processors
427 + [
428 # Add the information from the `logging` `extras` to the event dictionary
429 structlog.stdlib.ExtraAdder()
430 ],
431 # These run on ALL entries after the pre_chain is done.
432 processors=[
433 # Remove _record & _from_structlog. to avoid that this metadata is added to the final log record
434 structlog.stdlib.ProcessorFormatter.remove_processors_meta,
435 *renderers,
436 ],
437 )
439 handler = logging.StreamHandler()
440 handler.name = _HANDLER_NAME
441 # Use OUR `ProcessorFormatter` to format all `logging` entries.
442 handler.setFormatter(formatter)
444 # Attach the handler to the target logger(s) - Haystack's own namespaces by default (see `logger_name`).
445 logger_names = [logger_name] if isinstance(logger_name, str) else list(logger_name)
447 # Remove our handler from every logger that carries it before re-installing: keeps re-configuration idempotent and
448 # prevents double emission when the target changes (e.g. switching to the root logger via `logger_name=""`).
449 existing_loggers = [logging.getLogger(), *logging.Logger.manager.loggerDict.values()]
450 for existing_logger in existing_loggers:
451 if isinstance(existing_logger, logging.Logger) and any(
452 _is_haystack_logging_handler(h) for h in existing_logger.handlers
453 ):
454 existing_logger.handlers = [h for h in existing_logger.handlers if not _is_haystack_logging_handler(h)]
456 for name in logger_names:
457 target_logger = logging.getLogger(name)
458 target_logger.handlers = [handler, *target_logger.handlers]
459 target_logger.propagate = propagate