Coverage for haystack/logging.py: 97%
142 statements
« prev ^ index » next coverage.py v7.16.2, created at 2026-10-12 09:42 +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 = True,
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, *, default_exc_info: Any = None) -> typing.Callable:
156 """
157 A decorator to make sure that a function is only called with keyword arguments.
159 :param func: The log method to wrap.
160 :param default_exc_info: The `exc_info` to pass when the caller omits it. Use `True` for `exception`.
161 """
163 @functools.wraps(func)
164 def _log_only_with_kwargs(
165 msg: str,
166 *,
167 _: Any = None,
168 exc_info: Any = default_exc_info,
169 stack_info: Any = False,
170 stacklevel: int = 1,
171 **kwargs: Any,
172 ) -> typing.Callable: # we need the `_` to avoid a syntax error
173 existing_extra = kwargs.pop("extra", {})
174 return func(
175 # we need to increase the stacklevel by 1 to point to the correct caller
176 # (otherwise it points to this function)
177 msg,
178 exc_info=exc_info,
179 stack_info=stack_info,
180 stacklevel=stacklevel + 1,
181 extra={**existing_extra, **kwargs},
182 )
184 return _log_only_with_kwargs
187def patch_log_with_level_method_to_kwargs_only(func: typing.Callable) -> typing.Callable:
188 """A decorator to make sure that a function is only called with keyword arguments."""
190 @functools.wraps(func)
191 def _log_only_with_kwargs(
192 level: int | str,
193 msg: str,
194 *,
195 _: Any = None,
196 exc_info: Any = None,
197 stack_info: Any = False,
198 stacklevel: int = 1,
199 **kwargs: Any, # we need the `_` to avoid a syntax error
200 ) -> typing.Callable:
201 existing_extra = kwargs.pop("extra", {})
203 return func(
204 level,
205 msg,
206 exc_info=exc_info,
207 stack_info=stack_info,
208 # we need to increase the stacklevel by 1 to point to the correct caller
209 # (otherwise it points to this function)
210 stacklevel=stacklevel + 1,
211 extra={**existing_extra, **kwargs},
212 )
214 return _log_only_with_kwargs
217def patch_make_records_to_use_kwarg_string_interpolation(original_make_records: typing.Callable) -> typing.Callable:
218 """A decorator to ensure string interpolation is used."""
220 @functools.wraps(original_make_records)
221 def _wrapper(
222 name: str,
223 level: int | str,
224 fn: str,
225 lno: int,
226 msg: str,
227 args: Any, # noqa: ARG001
228 exc_info: Any,
229 func: Any = None,
230 extra: Any = None,
231 sinfo: Any = None,
232 ) -> typing.Callable:
233 safe_extra = extra or {}
234 try:
235 interpolated_msg = msg.format(**safe_extra)
236 except (KeyError, ValueError, IndexError):
237 interpolated_msg = msg
238 return original_make_records(name, level, fn, lno, interpolated_msg, (), exc_info, func, extra, sinfo)
240 return _wrapper
243def _patch_structlog_call_information(logger: logging.Logger) -> None:
244 # structlog patches the findCaller to hide itself from the traceback.
245 # We need to patch their patch to hide `haystack.logging` from the traceback.
246 try:
247 from structlog._frames import _find_first_app_frame_and_name, _format_stack
248 from structlog.stdlib import _FixedFindCallerLogger
250 if not isinstance(logger, _FixedFindCallerLogger):
251 return
253 # Copied from structlog's `_FixedFindCallerLogger.findCaller`, adding `haystack.logging` to the ignored
254 # frames. We don't forward `stacklevel` to `_find_first_app_frame_and_name` (added in structlog 25.5.0):
255 # structlog is optional and may be older.
256 def findCaller(stack_info: bool = False, stacklevel: int = 1) -> tuple[str, int, str, str | None]: # noqa: ARG001
257 f, _name = _find_first_app_frame_and_name(["logging", "haystack.logging"])
258 sinfo = _format_stack(f) if stack_info else None
259 return f.f_code.co_filename, f.f_lineno, f.f_code.co_name, sinfo
261 logger.findCaller = findCaller # type: ignore
262 except ImportError:
263 pass
266def getLogger(name: str) -> PatchedLogger:
267 """
268 Get the Haystack logger, a patched version of the one from the standard library.
270 We patch the default logger methods to make sure that they are only called with keyword arguments.
271 We enforce keyword-arguments because
272 - it brings in consistency
273 - it makes structure logging effective, not just an available feature
274 """
275 logger = logging.getLogger(name)
276 if getattr(logger, _PATCHED_MARKER, False):
277 # Already patched: `logging.getLogger` returned the same singleton, so re-patching would stack the wrappers
278 # and interpolate the message more than once.
279 return typing.cast(PatchedLogger, logger)
281 logger.debug = patch_log_method_to_kwargs_only(logger.debug) # type: ignore
282 logger.info = patch_log_method_to_kwargs_only(logger.info) # type: ignore
283 logger.warn = patch_log_method_to_kwargs_only(logger.warn) # type: ignore
284 logger.warning = patch_log_method_to_kwargs_only(logger.warning) # type: ignore
285 logger.error = patch_log_method_to_kwargs_only(logger.error) # type: ignore
286 logger.critical = patch_log_method_to_kwargs_only(logger.critical) # type: ignore
287 logger.exception = patch_log_method_to_kwargs_only(logger.exception, default_exc_info=True) # type: ignore
288 logger.fatal = patch_log_method_to_kwargs_only(logger.fatal) # type: ignore
289 logger.log = patch_log_with_level_method_to_kwargs_only(logger.log) # type: ignore
291 _patch_structlog_call_information(logger)
293 # We also patch the `makeRecord` method to use keyword string interpolation
294 logger.makeRecord = patch_make_records_to_use_kwarg_string_interpolation(logger.makeRecord) # type: ignore
296 setattr(logger, _PATCHED_MARKER, True)
298 return typing.cast(PatchedLogger, logger)
301def add_line_and_file(_: "WrappedLogger", __: str, event_dict: "EventDict") -> "EventDict":
302 """Add line and file to log entries."""
303 stdlib_record = event_dict.get("_record")
304 if not stdlib_record:
305 return event_dict
307 event_dict["lineno"] = stdlib_record.lineno
308 event_dict["module"] = stdlib_record.name
310 return event_dict
313def correlate_logs_with_traces(_: "WrappedLogger", __: str, event_dict: "EventDict") -> "EventDict":
314 """
315 Add correlation data for logs.
317 This is useful if you want to correlate logs with traces.
318 """
319 import haystack.tracing.tracer # to avoid circular imports
321 if not haystack.tracing.is_tracing_enabled():
322 return event_dict
324 current_span = haystack.tracing.tracer.current_span()
325 if current_span:
326 event_dict.update(current_span.get_correlation_data_for_logs())
328 return event_dict
331def bound_event_dict_values(_: "WrappedLogger", __: str, event_dict: "EventDict") -> "EventDict":
332 """
333 Keep individual log values from growing without bound.
335 Exceptions are rendered with `str` rather than `repr`, because some carry their whole input in their
336 `repr`: `UnicodeDecodeError` keeps the entire buffer it failed to decode, so logging one raised while
337 decoding a large file would otherwise emit that whole file as a single log line.
338 """
339 for key, value in list(event_dict.items()):
340 if key == "exc_info": # `ExceptionRenderer` runs after this processor and needs it untouched
341 continue
342 if isinstance(value, BaseException):
343 value = f"{type(value).__name__}: {value}"
344 elif not isinstance(value, (str, int, float, bool, list, dict, type(None))):
345 value = repr(value) # what the renderer would do anyway, but here the result can be bounded
346 if isinstance(value, str) and len(value) > MAX_LOG_VALUE_LENGTH:
347 value = f"{value[:MAX_LOG_VALUE_LENGTH]}... [truncated, {len(value)} chars]"
348 event_dict[key] = value
349 return event_dict
352def configure_logging(
353 use_json: bool | None = None,
354 logger_name: str | Sequence[str] = ("haystack", "haystack_integrations", "haystack_experimental"),
355 propagate: bool = True,
356 configure_structlog: bool = True,
357) -> None:
358 """
359 Configure logging for Haystack.
361 - If `structlog` is not installed, we keep everything as it is. The user is responsible for configuring logging
362 themselves.
363 - If `structlog` is installed, we configure it to format log entries including its key-value data. To disable this
364 behavior set the environment variable `HAYSTACK_LOGGING_IGNORE_STRUCTLOG` to `true`.
365 - If `structlog` is installed, you can JSON format all logs. Enable this by
366 - setting the `use_json` parameter to `True` when calling this function
367 - setting the environment variable `HAYSTACK_LOGGING_USE_JSON` to `true`
369 :param use_json: Whether to format logs as JSON. If `None`, we try to guess based on the environment.
370 :param logger_name:
371 The name (or names) of the logger our formatting handler is attached to. Defaults to Haystack's own
372 namespaces (`"haystack"`, `"haystack_integrations"` and `"haystack_experimental"`), so that we only touch
373 Haystack's own loggers and leave the logging configuration of the host application and any other libraries
374 running in the same process untouched. Pass an empty string (`""`) to attach the handler to the root logger
375 instead - this restores the legacy behavior of formatting *every* log record in the process.
376 :param propagate:
377 Whether the configured loggers should propagate their records to ancestor loggers (ultimately the root
378 logger). The default (`True`) keeps records flowing to handlers configured by the host application and to
379 capturing tools such as `pytest`'s `caplog`. Set it to `False` to make Haystack fully own the output of its
380 own logs - this avoids duplicate log lines when the host application also configures the root logger. It has
381 no effect when `logger_name=""` (the root logger has no ancestors).
382 :param configure_structlog:
383 Whether to configure the process-global `structlog` (thereby taking over any configuration set up by someone
384 else). The default (`True`) is what an explicit call should do. Pass `False` (as the import-time call in
385 `haystack/__init__.py` does) to leave the global `structlog` configuration untouched and only install our own
386 scoped handler so Haystack's own logs are formatted. This keeps merely importing Haystack from reconfiguring
387 `structlog` for the host application's own native `structlog` loggers.
388 """
389 try:
390 import structlog
391 from structlog.processors import ExceptionRenderer
392 from structlog.tracebacks import ExceptionDictTransformer
394 except ImportError:
395 # structlog is not installed - fall back to standard logging
396 return
398 if os.getenv(HAYSTACK_LOGGING_IGNORE_STRUCTLOG_ENV_VAR, "false").lower() == "true":
399 # If the user wants to ignore structlog, we don't configure it and fall back to standard logging
400 return
402 # We roughly follow the structlog documentation here:
403 # https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging
404 # This means that we use structlog to format the log entries for entries emitted via `logging` and `structlog`.
406 if use_json is None: # explicit parameter takes precedence over everything else
407 use_json_env_var = os.getenv(HAYSTACK_LOGGING_USE_JSON_ENV_VAR)
408 if use_json_env_var is None:
409 # We try to guess if we are in an interactive terminal or not
410 interactive_terminal = (
411 sys.stderr.isatty() or hasattr(builtins, "__IPYTHON__") or haystack.utils.jupyter.is_in_jupyter()
412 )
413 use_json = not interactive_terminal
414 else:
415 # User gave us an explicit value via environment variable
416 use_json = use_json_env_var.lower() == "true"
418 shared_processors: list[Processor] = [
419 # Add the log level to the event_dict for structlog to use
420 structlog.stdlib.add_log_level,
421 # Adds the current timestamp in ISO format to logs
422 structlog.processors.TimeStamper(fmt="iso"),
423 structlog.contextvars.merge_contextvars,
424 add_line_and_file,
425 ]
427 if use_json:
428 # We only need that in sophisticated production setups where we want to correlate logs with traces
429 shared_processors.append(correlate_logs_with_traces)
431 # `structlog.configure` is process-global: it affects every native structlog logger, not just Haystack's. We only
432 # configure it when explicitly asked (`configure_structlog`).
433 if configure_structlog:
434 structlog.configure(
435 # `filter_by_level` reads the effective level from the underlying stdlib logger on *every* call, so
436 # changes to the log level made after `configure_logging` runs (e.g. by the host app) are respected.
437 processors=[
438 structlog.stdlib.filter_by_level,
439 *shared_processors,
440 structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
441 ],
442 logger_factory=structlog.stdlib.LoggerFactory(ignore_frame_names=["haystack.logging"]),
443 cache_logger_on_first_use=True,
444 wrapper_class=structlog.stdlib.BoundLogger,
445 )
447 renderers: list[Processor]
448 if use_json:
449 renderers = [
450 ExceptionRenderer(
451 # don't show locals in production logs - this can be quite sensitive information
452 ExceptionDictTransformer(show_locals=False)
453 ),
454 structlog.processors.JSONRenderer(),
455 ]
456 else:
457 renderers = [structlog.dev.ConsoleRenderer()]
459 formatter = structlog.stdlib.ProcessorFormatter(
460 # These run ONLY on `logging` entries that do NOT originate within
461 # structlog.
462 foreign_pre_chain=shared_processors
463 + [
464 # Add the information from the `logging` `extras` to the event dictionary
465 structlog.stdlib.ExtraAdder()
466 ],
467 # These run on ALL entries after the pre_chain is done.
468 processors=[
469 # Remove _record & _from_structlog. to avoid that this metadata is added to the final log record
470 structlog.stdlib.ProcessorFormatter.remove_processors_meta,
471 # Bound every value before it reaches a renderer, for both the JSON and the console output
472 bound_event_dict_values,
473 *renderers,
474 ],
475 )
477 handler = logging.StreamHandler()
478 handler.name = _HANDLER_NAME
479 # Use OUR `ProcessorFormatter` to format all `logging` entries.
480 handler.setFormatter(formatter)
482 # Attach the handler to the target logger(s) - Haystack's own namespaces by default (see `logger_name`).
483 logger_names = [logger_name] if isinstance(logger_name, str) else list(logger_name)
485 # Remove our handler from every logger that carries it before re-installing: keeps re-configuration idempotent and
486 # prevents double emission when the target changes (e.g. switching to the root logger via `logger_name=""`).
487 existing_loggers = [logging.getLogger(), *logging.Logger.manager.loggerDict.values()]
488 for existing_logger in existing_loggers:
489 if isinstance(existing_logger, logging.Logger) and any(
490 _is_haystack_logging_handler(h) for h in existing_logger.handlers
491 ):
492 existing_logger.handlers = [h for h in existing_logger.handlers if not _is_haystack_logging_handler(h)]
494 for name in logger_names:
495 target_logger = logging.getLogger(name)
496 target_logger.handlers = [handler, *target_logger.handlers]
497 target_logger.propagate = propagate