haystack

1
import builtins
2
import json
3
import logging
4
import os
5
import sys
6
from datetime import datetime, timezone
7
from pathlib import Path
8
from test.tracing.utils import SpyingTracer
9
from unittest.mock import ANY
10

11
import pytest
12
from _pytest.capture import CaptureFixture
13
from _pytest.logging import LogCaptureFixture
14
from _pytest.monkeypatch import MonkeyPatch
15

16
import haystack.utils.jupyter
17
from haystack import logging as haystack_logging
18

19

20
@pytest.fixture(autouse=True)
21
def reset_logging_config() -> None:
22
    old_handlers = logging.root.handlers.copy()
23
    yield
24
    # Reset the logging configuration after each test to avoid impacting other tests
25
    logging.root.handlers = old_handlers
26

27

28
class TestSkipLoggingConfiguration:
29
    def test_skip_logging_configuration(
30
        self, monkeypatch: MonkeyPatch, capfd: CaptureFixture, caplog: LogCaptureFixture
31
    ) -> None:
32
        monkeypatch.setenv("HAYSTACK_LOGGING_IGNORE_STRUCTLOG", "true")
33
        haystack_logging.configure_logging()
34

35
        logger = logging.getLogger(__name__)
36
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
37

38
        # the pytest fixture caplog only captures logs being rendered from the stdlib logging module
39
        assert caplog.messages == ["Hello, structured logging!"]
40

41
        # Nothing should be captured by capfd since structlog is not configured
42
        assert capfd.readouterr().err == ""
43

44

45
class TestStructuredLoggingConsoleRendering:
46
    def test_log_filtering_when_using_debug(self, capfd: CaptureFixture) -> None:
47
        haystack_logging.configure_logging(use_json=False)
48

49
        logger = logging.getLogger(__name__)
50
        logger.debug("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
51

52
        # Use `capfd` to capture the output of the final structlog rendering result
53
        output = capfd.readouterr().err
54
        assert output == ""
55

56
    def test_log_filtering_when_using_debug_and_log_level_is_debug(self, capfd: CaptureFixture) -> None:
57
        haystack_logging.configure_logging(use_json=False)
58

59
        logger = logging.getLogger(__name__)
60
        logger.setLevel(logging.DEBUG)
61

62
        logger.debug("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
63

64
        # Use `capfd` to capture the output of the final structlog rendering result
65
        output = capfd.readouterr().err
66
        assert "Hello, structured logging" in output
67
        assert "{" not in output, "Seems JSON rendering is enabled when it should not be"
68

69
    def test_console_rendered_structured_log_even_if_no_tty_but_python_config(
70
        self, capfd: CaptureFixture, monkeypatch: MonkeyPatch
71
    ) -> None:
72
        monkeypatch.setattr(sys.stderr, "isatty", lambda: False)
73

74
        haystack_logging.configure_logging(use_json=False)
75

76
        logger = logging.getLogger(__name__)
77
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
78

79
        # Use `capfd` to capture the output of the final structlog rendering result
80
        output = capfd.readouterr().err
81

82
        assert "Hello, structured logging!" in output
83
        assert "{" not in output, "Seems JSON rendering is enabled when it should not be"
84

85
    def test_console_rendered_structured_log_if_in_ipython(
86
        self, capfd: CaptureFixture, monkeypatch: MonkeyPatch
87
    ) -> None:
88
        monkeypatch.setattr(builtins, "__IPYTHON__", "true", raising=False)
89

90
        haystack_logging.configure_logging()
91

92
        logger = logging.getLogger(__name__)
93
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
94

95
        # Use `capfd` to capture the output of the final structlog rendering result
96
        output = capfd.readouterr().err
97

98
        assert "Hello, structured logging!" in output
99
        assert "{" not in output, "Seems JSON rendering is enabled when it should not be"
100

101
    def test_console_rendered_structured_log_even_in_jupyter(
102
        self, capfd: CaptureFixture, monkeypatch: MonkeyPatch
103
    ) -> None:
104
        monkeypatch.setattr(haystack.utils.jupyter, haystack.utils.jupyter.is_in_jupyter.__name__, lambda: True)
105

106
        haystack_logging.configure_logging()
107

108
        logger = logging.getLogger(__name__)
109
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
110

111
        # Use `capfd` to capture the output of the final structlog rendering result
112
        output = capfd.readouterr().err
113

114
        assert "Hello, structured logging!" in output
115
        assert "{" not in output, "Seems JSON rendering is enabled when it should not be"
116

117
    def test_console_rendered_structured_log_even_if_no_tty_but_forced_through_env(
118
        self, capfd: CaptureFixture, monkeypatch: MonkeyPatch
119
    ) -> None:
120
        monkeypatch.setenv("HAYSTACK_LOGGING_USE_JSON", "false")
121

122
        haystack_logging.configure_logging()
123

124
        logger = logging.getLogger(__name__)
125
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
126

127
        # Use `capfd` to capture the output of the final structlog rendering result
128
        output = capfd.readouterr().err
129

130
        assert "Hello, structured logging!" in output
131
        assert "{" not in output, "Seems JSON rendering is enabled when it should not be"
132

133
    def test_console_rendered_structured_log(self, capfd: CaptureFixture) -> None:
134
        haystack_logging.configure_logging()
135

136
        logger = logging.getLogger(__name__)
137
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
138

139
        # Use `capfd` to capture the output of the final structlog rendering result
140
        output = capfd.readouterr().err
141

142
        # Only check for the minute to be a bit more robust
143
        today = datetime.now(tz=timezone.utc).isoformat(timespec="minutes").replace("+00:00", "")
144
        assert today in output
145

146
        log_level = "warning"
147
        assert log_level in output
148

149
        assert "Hello, structured logging!" in output
150

151
        assert "key1" in output
152
        assert "value1" in output
153

154
    def test_logging_exceptions(self, capfd: CaptureFixture) -> None:
155
        haystack_logging.configure_logging()
156

157
        logger = logging.getLogger(__name__)
158

159
        def function_that_raises_and_adds_to_stack_trace():
160
            raise ValueError("This is an error")
161

162
        try:
163
            function_that_raises_and_adds_to_stack_trace()
164
        except ValueError:
165
            logger.exception("An error happened")
166

167
        # Use `capfd` to capture the output of the final structlog rendering result
168
        output = capfd.readouterr().err
169

170
        assert "An error happened" in output
171

172

173
class TestStructuredLoggingJSONRendering:
174
    def test_logging_as_json_if_not_atty(self, capfd: CaptureFixture, monkeypatch: MonkeyPatch) -> None:
175
        monkeypatch.setattr(sys.stderr, "isatty", lambda: False)
176
        haystack_logging.configure_logging()
177

178
        logger = logging.getLogger(__name__)
179
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
180

181
        # Use `capfd` to capture the output of the final structlog rendering result
182
        output = capfd.readouterr().err
183
        parsed_output = json.loads(output)  # should not raise an error
184

185
        assert parsed_output == {
186
            "event": "Hello, structured logging!",
187
            "key1": "value1",
188
            "key2": "value2",
189
            "level": "warning",
190
            "timestamp": ANY,
191
            "lineno": ANY,
192
            "module": "test.test_logging",
193
        }
194

195
    def test_logging_as_json(self, capfd: CaptureFixture) -> None:
196
        haystack_logging.configure_logging(use_json=True)
197

198
        logger = logging.getLogger(__name__)
199
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
200

201
        # Use `capfd` to capture the output of the final structlog rendering result
202
        output = capfd.readouterr().err
203
        parsed_output = json.loads(output)  # should not raise an error
204

205
        assert parsed_output == {
206
            "event": "Hello, structured logging!",
207
            "key1": "value1",
208
            "key2": "value2",
209
            "level": "warning",
210
            "timestamp": ANY,
211
            "lineno": ANY,
212
            "module": "test.test_logging",
213
        }
214

215
    def test_logging_as_json_enabling_via_env(self, capfd: CaptureFixture, monkeypatch: MonkeyPatch) -> None:
216
        monkeypatch.setenv("HAYSTACK_LOGGING_USE_JSON", "true")
217
        haystack_logging.configure_logging()
218

219
        logger = logging.getLogger(__name__)
220
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
221

222
        # Use `capfd` to capture the output of the final structlog rendering result
223
        output = capfd.readouterr().err
224
        parsed_output = json.loads(output)  # should not raise an error
225

226
        assert parsed_output == {
227
            "event": "Hello, structured logging!",
228
            "key1": "value1",
229
            "key2": "value2",
230
            "level": "warning",
231
            "timestamp": ANY,
232
            "lineno": ANY,
233
            "module": "test.test_logging",
234
        }
235

236
    def test_logging_exceptions_json(self, capfd: CaptureFixture) -> None:
237
        haystack_logging.configure_logging(use_json=True)
238

239
        logger = logging.getLogger(__name__)
240

241
        def function_that_raises_and_adds_to_stack_trace():
242
            my_local_variable = "my_local_variable"  # noqa: F841
243
            raise ValueError("This is an error")
244

245
        try:
246
            function_that_raises_and_adds_to_stack_trace()
247
        except ValueError:
248
            logger.exception("An error happened ")
249

250
        # Use `capfd` to capture the output of the final structlog rendering result
251
        output = capfd.readouterr().err
252
        parsed_output = json.loads(output)
253
        assert parsed_output == {
254
            "event": "An error happened ",
255
            "level": "error",
256
            "timestamp": ANY,
257
            "lineno": ANY,
258
            "module": "test.test_logging",
259
            "exception": [
260
                {
261
                    "exc_type": "ValueError",
262
                    "exc_value": "This is an error",
263
                    "syntax_error": None,
264
                    "is_cause": False,
265
                    "frames": [
266
                        {
267
                            "filename": str(Path.cwd() / "test" / "test_logging.py"),
268
                            "lineno": ANY,  # otherwise the test breaks if you add a line :-)
269
                            "name": "test_logging_exceptions_json",
270
                            "line": "",
271
                            "locals": None,
272
                        },
273
                        {
274
                            "filename": str(Path.cwd() / "test" / "test_logging.py"),
275
                            "lineno": ANY,  # otherwise the test breaks if you add a line :-)
276
                            "name": "function_that_raises_and_adds_to_stack_trace",
277
                            "line": "",
278
                            "locals": None,
279
                        },
280
                    ],
281
                }
282
            ],
283
        }
284

285

286
class TestLogTraceCorrelation:
287
    def test_trace_log_correlation_python_logs_with_console_rendering(
288
        self, spying_tracer: SpyingTracer, capfd: CaptureFixture
289
    ) -> None:
290
        haystack_logging.configure_logging(use_json=False)
291

292
        with spying_tracer.trace("test-operation"):
293
            logger = logging.getLogger(__name__)
294
            logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
295

296
        output = capfd.readouterr().err
297
        assert "trace_id" not in output
298

299
    def test_trace_log_correlation_python_logs(self, spying_tracer: SpyingTracer, capfd: CaptureFixture) -> None:
300
        haystack_logging.configure_logging(use_json=True)
301

302
        with spying_tracer.trace("test-operation") as span:
303
            logger = logging.getLogger(__name__)
304
            logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
305

306
        output = capfd.readouterr().err
307
        parsed_output = json.loads(output)
308

309
        assert parsed_output == {
310
            "event": "Hello, structured logging!",
311
            "key1": "value1",
312
            "key2": "value2",
313
            "level": "warning",
314
            "timestamp": ANY,
315
            "trace_id": span.trace_id,
316
            "span_id": span.span_id,
317
            "lineno": ANY,
318
            "module": "test.test_logging",
319
        }
320

321
    def test_trace_log_correlation_no_span(self, spying_tracer: SpyingTracer, capfd: CaptureFixture) -> None:
322
        haystack_logging.configure_logging(use_json=True)
323

324
        logger = logging.getLogger(__name__)
325

326
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
327

328
        output = capfd.readouterr().err
329
        parsed_output = json.loads(output)
330

331
        assert parsed_output == {
332
            "event": "Hello, structured logging!",
333
            "key1": "value1",
334
            "key2": "value2",
335
            "level": "warning",
336
            "timestamp": ANY,
337
            "lineno": ANY,
338
            "module": "test.test_logging",
339
        }
340

341
    def test_trace_log_correlation_no_tracer(self, capfd: CaptureFixture) -> None:
342
        haystack_logging.configure_logging(use_json=True)
343

344
        logger = logging.getLogger(__name__)
345

346
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
347

348
        output = capfd.readouterr().err
349
        parsed_output = json.loads(output)
350

351
        assert parsed_output == {
352
            "event": "Hello, structured logging!",
353
            "key1": "value1",
354
            "key2": "value2",
355
            "level": "warning",
356
            "timestamp": ANY,
357
            "lineno": ANY,
358
            "module": "test.test_logging",
359
        }
360

361

362
class TestCompositeLogger:
363
    def test_correct_stack_level_with_stdlib_rendering(
364
        self, monkeypatch: MonkeyPatch, capfd: CaptureFixture, caplog: LogCaptureFixture
365
    ) -> None:
366
        monkeypatch.setenv("HAYSTACK_LOGGING_IGNORE_STRUCTLOG", "true")
367
        haystack_logging.configure_logging()
368

369
        logger = logging.getLogger(__name__)
370
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
371

372
        # the pytest fixture caplog only captures logs being rendered from the stdlib logging module
373
        assert caplog.messages == ["Hello, structured logging!"]
374
        assert caplog.records[0].name == "test.test_logging"
375
        assert caplog.records[0].lineno == 370
376

377
        # Nothing should be captured by capfd since structlog is not configured
378
        assert capfd.readouterr().err == ""
379

380
    def test_correct_stack_level_with_consoler_rendering(self, capfd: CaptureFixture) -> None:
381
        haystack_logging.configure_logging(use_json=False)
382

383
        logger = haystack_logging.getLogger(__name__)
384
        logger.warning("Hello, structured logging!", extra={"key1": "value1", "key2": "value2"})
385

386
        output = capfd.readouterr().err
387
        assert "test.test_logging" in output
388
        assert "384" in output
389

390
    @pytest.mark.parametrize(
391
        "method, expected_level",
392
        [
393
            ("debug", "debug"),
394
            ("info", "info"),
395
            ("warning", "warning"),
396
            ("error", "error"),
397
            ("fatal", "critical"),
398
            ("exception", "error"),
399
            ("critical", "critical"),
400
        ],
401
    )
402
    def test_various_levels(self, capfd: LogCaptureFixture, method: str, expected_level: str) -> None:
403
        haystack_logging.configure_logging(use_json=True)
404

405
        logger = haystack_logging.getLogger(__name__)
406

407
        logger.setLevel(logging.DEBUG)
408

409
        getattr(logger, method)("Hello, structured {key}!", key="logging", key1="value1", key2="value2")
410

411
        output = capfd.readouterr().err
412
        parsed_output = json.loads(output)  # should not raise an error
413

414
        assert parsed_output == {
415
            "event": "Hello, structured logging!",
416
            "key": "logging",
417
            "key1": "value1",
418
            "key2": "value2",
419
            "level": expected_level,
420
            "timestamp": ANY,
421
            "lineno": ANY,
422
            "module": "test.test_logging",
423
        }
424

425
    def test_log(self, capfd: LogCaptureFixture) -> None:
426
        haystack_logging.configure_logging(use_json=True)
427

428
        logger = haystack_logging.getLogger(__name__)
429
        logger.setLevel(logging.DEBUG)
430

431
        logger.log(logging.DEBUG, "Hello, structured '{key}'!", key="logging", key1="value1", key2="value2")
432

433
        output = capfd.readouterr().err
434
        parsed_output = json.loads(output)
435

436
        assert parsed_output == {
437
            "event": "Hello, structured 'logging'!",
438
            "key": "logging",
439
            "key1": "value1",
440
            "key2": "value2",
441
            "level": "debug",
442
            "timestamp": ANY,
443
            "lineno": ANY,
444
            "module": "test.test_logging",
445
        }
446

447
    def test_log_with_string_cast(self, capfd: LogCaptureFixture) -> None:
448
        haystack_logging.configure_logging(use_json=True)
449

450
        logger = haystack_logging.getLogger(__name__)
451
        logger.setLevel(logging.DEBUG)
452

453
        logger.log(logging.DEBUG, "Hello, structured '{key}'!", key=LogCaptureFixture, key1="value1", key2="value2")
454

455
        output = capfd.readouterr().err
456
        parsed_output = json.loads(output)
457

458
        assert parsed_output == {
459
            "event": "Hello, structured '<class '_pytest.logging.LogCaptureFixture'>'!",
460
            "key": "<class '_pytest.logging.LogCaptureFixture'>",
461
            "key1": "value1",
462
            "key2": "value2",
463
            "level": "debug",
464
            "timestamp": ANY,
465
            "lineno": ANY,
466
            "module": "test.test_logging",
467
        }
468

469
    @pytest.mark.parametrize(
470
        "method, expected_level",
471
        [
472
            ("debug", "debug"),
473
            ("info", "info"),
474
            ("warning", "warning"),
475
            ("error", "error"),
476
            ("fatal", "critical"),
477
            ("exception", "exception"),
478
            ("critical", "critical"),
479
        ],
480
    )
481
    def test_haystack_logger_with_positional_args(self, method: str, expected_level: str) -> None:
482
        haystack_logging.configure_logging(use_json=True)
483

484
        logger = haystack_logging.getLogger(__name__)
485
        logger.setLevel(logging.DEBUG)
486

487
        with pytest.raises(TypeError):
488
            getattr(logger, method)("Hello, structured logging %s!", "logging")
489

490
    @pytest.mark.parametrize(
491
        "method, expected_level",
492
        [
493
            ("debug", "debug"),
494
            ("info", "info"),
495
            ("warning", "warning"),
496
            ("error", "error"),
497
            ("fatal", "critical"),
498
            ("exception", "exception"),
499
            ("critical", "critical"),
500
        ],
501
    )
502
    def test_haystack_logger_with_old_interpolation(self, method: str, expected_level: str) -> None:
503
        haystack_logging.configure_logging(use_json=True)
504

505
        logger = haystack_logging.getLogger(__name__)
506
        logger.setLevel(logging.DEBUG)
507

508
        # does not raise - hence we need to check this separately
509
        getattr(logger, method)("Hello, structured logging %s!", key="logging")
510

511
    def test_that_haystack_logger_is_used(self) -> None:
512
        """Forces the usage of the Haystack logger instead of the standard library logger."""
513
        allowed_list = [Path("haystack") / "logging.py"]
514
        for root, dirs, files in os.walk("haystack"):
515
            for file in files:
516
                path = Path(root) / file
517

518
                if not path.suffix.endswith(".py"):
519
                    continue
520

521
                if path in allowed_list:
522
                    continue
523

524
                content = path.read_text(encoding="utf-8")
525

526
                # that looks like somebody is using our standard logger
527
                if " logging.getLogger" in content:
528
                    haystack_logger_in_content = " haystack import logging" in content or ", logging" in content
529
                    assert haystack_logger_in_content, (
530
                        f"{path} doesn't use the Haystack logger. Please use the Haystack logger instead of the "
531
                        f"standard library logger and add plenty of keyword arguments."
532
                    )
533