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