File: standard-library.md

package info (click to toggle)
python-structlog 25.4.0-1
  • links: PTS, VCS
  • area: main
  • in suites: forky, sid
  • size: 2,416 kB
  • sloc: python: 8,182; makefile: 138
file content (573 lines) | stat: -rw-r--r-- 22,601 bytes parent folder | download | duplicates (2)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
# Standard Library Logging

Ideally, *structlog* should be able to be used as a drop-in replacement for standard library's {mod}`logging` by wrapping it.
In other words, you should be able to replace your call to {func}`logging.getLogger` by a call to {func}`structlog.get_logger` and things should keep working as before (if *structlog* is configured right, see {ref}`stdlib-config` below).

If you run into incompatibilities, it is a *bug* so please take the time to [report it](https://github.com/hynek/structlog/issues)!
If you're a heavy `logging` user, your [help](https://github.com/hynek/structlog/issues?q=is%3Aopen+is%3Aissue+label%3Astdlib) to ensure a better compatibility would be highly appreciated!

:::{important}
The quickest way to get started with *structlog* and `logging` is {func}`structlog.stdlib.recreate_defaults()`.
It will recreate the default configuration on top of `logging` and optionally configure `logging` for you.
:::


## Just enough `logging`

If you want to use *structlog* with `logging`, you should have at least a fleeting understanding on how the standard library operates because *structlog* will *not* do any magic things in the background for you.
Most importantly you have to *configure* the `logging` system *additionally* to configuring *structlog*.

Usually it is enough to use:

```
import logging
import sys

logging.basicConfig(
    format="%(message)s",
    stream=sys.stdout,
    level=logging.INFO,
)
```

This will send all log messages with the [log level](https://docs.python.org/3/library/logging.html#logging-levels) `logging.INFO` and above (that means that, for example, `logging.debug` calls are ignored) to standard out without any special formatting by the standard library.

If you require more complex behavior, please refer to the standard library's {mod}`logging` documentation.


## Concrete bound logger

*structlog* ships a stdlib-specific [*bound logger*](bound-loggers.md) that  mirrors the log methods of standard library's {any}`logging.Logger` with correct type hints.

If you want to take advantage of said type hints, you have to either annotate the logger coming from {func}`structlog.get_logger`, or use {func}`structlog.stdlib.get_logger()` that has the appropriate type hints.
Please note though, that it will neither configure nor verify your configuration.
It will call `structlog.get_logger()` just like if you would've called it -- the only difference are the type hints.

See also {doc}`typing`.


### `asyncio`

In {mod}`asyncio` applications, you may not want your whole application to block while the processor chain is formatting your log entries.

For that use case *structlog* comes with a set of non-standard methods that will do all processing in a thread pool executor.
They have the same names as the regular methods, except they are prefixed by an `a`.
So instead of `logger.info("event!")` you write `await logger.ainfo("event!)`.
No extra configuration is necessary and you can mix-and-match both types of methods within the same application.

This means an increased computational cost per log entry, but your application will not block because of logging.

```{versionadded} 23.1.0
```

---


*structlog* also comes with {class}`structlog.stdlib.AsyncBoundLogger` that blankly makes all logging methods asynchronous (in other words, you have to use `await log.info()` instead of just `log.info()`).

To use it, {doc}`configure <configuration>` *structlog* to use `AsyncBoundLogger` as `wrapper_class`.

```{versionadded} 20.2.0
```
```{deprecated} 23.1.0
```


## Processors

*structlog* comes with a few standard library-specific processors:

{func}`~structlog.stdlib.render_to_log_args_and_kwargs`:

: Renders the event dictionary into positional and keyword arguments for `logging.Logger` logging methods.
  This is useful if you want to render your log entries entirely within `logging`.

{func}`~structlog.stdlib.render_to_log_kwargs`:

: Same as above, but does not support passing positional arguments from *structlog* loggers to `logging.Logger` logging methods as positional arguments.
  *structlog* positional arguments are still passed to `logging` under `positional_args` key of `extra` keyword argument.

{func}`~structlog.stdlib.filter_by_level`:

: Checks the log entry's log level against the configuration of standard library's logging.
  Log entries below the threshold get silently dropped.
  Put it at the beginning of your processing chain to avoid expensive operations from happening in the first place.

{func}`~structlog.stdlib.add_logger_name`:

: Adds the name of the logger to the event dictionary under the key `logger`.

{func}`~structlog.stdlib.add_log_level`:

: Adds the log level to the event dictionary under the key `level`.

{func}`~structlog.stdlib.add_log_level_number`:

: Adds the log level number to the event dictionary under the key `level_number`.
  Log level numbers map to the log level names.
  The Python stdlib uses them for filtering logic.
  This adds the same numbers so users can leverage similar filtering.
  Compare:

  ```
  level in ("warning", "error", "critical")
  level_number >= 30
  ```

  The mapping of names to numbers is in `structlog.stdlib._NAME_TO_LEVEL`.

{class}`~structlog.stdlib.ExtraAdder`:

: Add extra attributes of `logging.LogRecord` objects to the event dictionary.

This processor can be used for adding data passed in the `extra` parameter of the `logging` module's log methods to the event dictionary.

{func}`~structlog.stdlib.PositionalArgumentsFormatter`:

: This processes and formats positional arguments (if any) passed to log methods in the same way the `logging` module would do, for example, `logger.info("Hello, %s", name)`.

*structlog* also comes with {class}`~structlog.stdlib.ProcessorFormatter` which is a `logging.Formatter` that enables you to format non-*structlog* log entries using *structlog* renderers *and* multiplex *structlog*’s output with different renderers (see [below](processor-formatter) for an example).

(stdlib-config)=

## Suggested configurations

:::{note}
We do appreciate that fully integrating *structlog* with standard library's `logging` is fiddly when done for the first time.

This is the price of flexibility and unfortunately -- given the different needs of our users -- we can't make it any simpler without compromising someone's use-cases.
However, once it is set up, you can rely on not having to ever touch it again.
:::

Depending *where* you'd like to do your formatting, you can take one of four approaches:


### Don't integrate

The most straight-forward option is to configure standard library `logging` close enough to what *structlog* is logging and leaving it at that.

Since these are usually log entries from third parties that don't take advantage of *structlog*'s features, this is surprisingly often a perfectly adequate approach.

For instance, if you log JSON in production, configure `logging` to use [*python-json-logger*] to make it print JSON too, and then tweak the configuration to match their outputs.
You can also use {class}`~structlog.stdlib.ProcessorFormatter` as a formatter for `logging` to get the same output for both *structlog* and `logging` log entries -- see [below](processor-formatter) for an example.

:::{important}
If you want to use same file (for example, `sys.stdout` or `sys.stderr`) for both *structlog* and `logging.StreamHandler` output, you must use {class}`~structlog.WriteLogger` instead of {class}`~structlog.PrintLogger`.

This is because {class}`~structlog.PrintLogger` uses `print(log, file=file, flush=True)` to write log, and `print` writes the `log` message and a newline ("\n") to the stream separately.
This can cause interleaving of log entries from *structlog* and `logging` loggers.
{class}`~structlog.WriteLogger` writes log entries atomically to the file (for example, `file.write(log+"\n")`).
:::


### Rendering within *structlog*

This is the simplest approach where *structlog* does all the heavy lifting and passes a fully-formatted string to `logging`.
Chances are, this is all you need.

```{mermaid}
:align: center

flowchart TD
    User
    structlog
    stdlib[Standard Library
    e.g. logging.StreamHandler]

    User --> |"structlog.get_logger().info('foo')"| structlog
    User --> |"logging.getLogger().info('foo')"| stdlib
    structlog --> |"logging.getLogger().info(#quot;{'event': 'foo'}#quot;)"| stdlib ==> Output

    Output
```

A basic configuration to output structured logs in JSON format looks like this:

```python
import structlog

structlog.configure(
    processors=[
        # If log level is too low, abort pipeline and throw away log entry.
        structlog.stdlib.filter_by_level,
        # Add the name of the logger to event dict.
        structlog.stdlib.add_logger_name,
        # Add log level to event dict.
        structlog.stdlib.add_log_level,
        # Perform %-style formatting.
        structlog.stdlib.PositionalArgumentsFormatter(),
        # Add a timestamp in ISO 8601 format.
        structlog.processors.TimeStamper(fmt="iso"),
        # If the "stack_info" key in the event dict is true, remove it and
        # render the current stack trace in the "stack" key.
        structlog.processors.StackInfoRenderer(),
        # If the "exc_info" key in the event dict is either true or a
        # sys.exc_info() tuple, remove "exc_info" and render the exception
        # with traceback into the "exception" key.
        structlog.processors.format_exc_info,
        # If some value is in bytes, decode it to a Unicode str.
        structlog.processors.UnicodeDecoder(),
        # Add callsite parameters.
        structlog.processors.CallsiteParameterAdder(
            {
                structlog.processors.CallsiteParameter.FILENAME,
                structlog.processors.CallsiteParameter.FUNC_NAME,
                structlog.processors.CallsiteParameter.LINENO,
            }
        ),
        # Render the final event dict as JSON.
        structlog.processors.JSONRenderer()
    ],
    # `wrapper_class` is the bound logger that you get back from
    # get_logger(). This one imitates the API of `logging.Logger`.
    wrapper_class=structlog.stdlib.BoundLogger,
    # `logger_factory` is used to create wrapped loggers that are used for
    # OUTPUT. This one returns a `logging.Logger`. The final value (a JSON
    # string) from the final processor (`JSONRenderer`) will be passed to
    # the method of the same name as that you've called on the bound logger.
    logger_factory=structlog.stdlib.LoggerFactory(),
    # Effectively freeze configuration after creating the first bound
    # logger.
    cache_logger_on_first_use=True,
)
```

To make your program behave like a proper [12 Factor App](https://12factor.net/logs) that outputs only JSON to `stdout`, configure the `logging` module like this:

```
import logging
import sys

logging.basicConfig(
    format="%(message)s",
    stream=sys.stdout,
    level=logging.INFO,
)
```

In this case *only* your own logs are formatted as JSON:

```pycon
>>> structlog.get_logger("test").warning("hello")
{"event": "hello", "logger": "test", "level": "warning", "timestamp": "2017-03-06T07:39:09.518720Z"}

>>> logging.getLogger("test").warning("hello")
hello
```


### Rendering using `logging`-based formatters

You can choose to use *structlog* only for building the event dictionary and leave all formatting -- additionally to the output -- to the standard library.

```{mermaid}
:align: center

flowchart TD
    User
    structlog
    stdlib[Standard Library
    e.g. logging.StreamHandler]

    User --> |"structlog.get_logger().info('foo', bar=42)"| structlog
    User --> |"logging.getLogger().info('foo')"| stdlib
    structlog --> |"logging.getLogger().info('foo', extra={&quot;bar&quot;: 42})"| stdlib ==> Output

    Output
```

```python
import structlog

structlog.configure(
    processors=[
        structlog.stdlib.filter_by_level,
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        # Transform event dict into `logging.Logger` method arguments.
        # "event" becomes "msg" and the rest is passed as a dict in
        # "extra". IMPORTANT: This means that the standard library MUST
        # render "extra" for the context to appear in log entries! See
        # warning below.
        structlog.stdlib.render_to_log_kwargs,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)
```

Now you have the event dict available within each log record.
If you want *all* your log entries (meaning: also those not from your application / *structlog*) to be formatted as JSON, you can use the [*python-json-logger*] library:

```python
import logging
import sys

from pythonjsonlogger import jsonlogger

handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(jsonlogger.JsonFormatter())
root_logger = logging.getLogger()
root_logger.addHandler(handler)
```

Now both *structlog* and `logging` will emit JSON logs:

```pycon
>>> structlog.get_logger("test").warning("hello")
{"message": "hello", "logger": "test", "level": "warning"}

>>> logging.getLogger("test").warning("hello")
{"message": "hello"}
```

:::{warning}
With this approach, it's the standard library `logging` formatter's duty to do something useful with the event dict.
In the above example that's `jsonlogger.JsonFormatter`.

Keep this in mind if you only get the event name without any context, and exceptions are ostensibly swallowed.
:::

(processor-formatter)=

### Rendering using *structlog*-based formatters within `logging`

Finally, the most ambitious approach.
Here, you use *structlog*'s {class}`~structlog.stdlib.ProcessorFormatter` as a {any}`logging.Formatter` for both `logging` as well as *structlog* log entries.

Consequently, the output is the duty of the standard library too.

```{mermaid}
:align: center

flowchart TD
    User
    structlog
    structlog2[structlog]
    stdlib["Standard Library"]

    User --> |"structlog.get_logger().info(#quot;foo#quot;, bar=42)"| structlog
    User --> |"logging.getLogger().info(#quot;foo#quot;)"| stdlib
    structlog --> |"logging.getLogger().info(event_dict, {#quot;extra#quot;: {#quot;_logger#quot;: logger, #quot;_name#quot;: name})"| stdlib

    stdlib --> |"structlog.stdlib.ProcessorFormatter.format(logging.Record)"| structlog2
    structlog2 --> |"Returns a string that is passed into logging handlers.
    This flow is controlled by the logging configuration."| stdlib2

    stdlib2[Standard Library
    e.g. logging.StreamHandler] ==> Output
```

{class}`~structlog.stdlib.ProcessorFormatter` has two parts to its API:

1. On the *structlog* side, the {doc}`processor chain <processors>` must be configured to end with {func}`structlog.stdlib.ProcessorFormatter.wrap_for_formatter` as the renderer.
   It converts the processed event dictionary into something that `ProcessorFormatter` understands.

2. On the `logging` side, you must configure `ProcessorFormatter` as your formatter of choice.
   `logging` then calls `ProcessorFormatter`'s `format()` method.

   For that, `ProcessorFormatter` wraps a processor chain that is responsible for rendering your log entries to strings.

Thus, the simplest possible configuration looks like the following:

```python
import logging
import structlog

structlog.configure(
    processors=[
        # Prepare event dict for `ProcessorFormatter`.
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
)

formatter = structlog.stdlib.ProcessorFormatter(
    processors=[structlog.dev.ConsoleRenderer()],
)

handler = logging.StreamHandler()
# Use OUR `ProcessorFormatter` to format all `logging` entries.
handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(logging.INFO)
```

which will allow both of these to work in other modules:

```pycon
>>> import logging
>>> import structlog

>>> logging.getLogger("stdlog").info("woo")
woo      _from_structlog=False _record=<LogRecord:...>
>>> structlog.get_logger("structlog").info("amazing", events="oh yes")
amazing  _from_structlog=True _record=<LogRecord:...> events=oh yes
```

Of course, you probably want timestamps and log levels in your output.
The `ProcessorFormatter` has a `foreign_pre_chain` argument which is responsible for adding properties to events from the standard library -- in other words, those that do not originate from a *structlog* logger -- and which should in general match the `processors` argument to {func}`structlog.configure` so you get a consistent output.

`_from_structlog` and `_record` allow your processors to determine whether the log entry is coming from *structlog*, and to extract information from `logging.LogRecord`s and add them to the event dictionary.
However, you probably don't want to have them in your log files, thus we've added the `ProcessorFormatter.remove_processors_meta` processor to do so conveniently.

For example, to add timestamps, log levels, and traceback handling to your logs without `_from_structlog` and `_record` noise you should do:

```python
timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
shared_processors = [
    structlog.stdlib.add_log_level,
    timestamper,
]

structlog.configure(
    processors=shared_processors + [
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)

formatter = structlog.stdlib.ProcessorFormatter(
    # These run ONLY on `logging` entries that do NOT originate within
    # structlog.
    foreign_pre_chain=shared_processors,
    # These run on ALL entries after the pre_chain is done.
    processors=[
        # Remove _record & _from_structlog.
        structlog.stdlib.ProcessorFormatter.remove_processors_meta,
        structlog.dev.ConsoleRenderer(),
    ],
)
```

which (given the same `logging.*` calls as in the previous example) will result in:

```pycon
>>> logging.getLogger("stdlog").info("woo")
2021-11-15 11:41:47 [info     ] woo
>>> structlog.get_logger("structlog").info("amazing", events="oh yes")
2021-11-15 11:41:47 [info     ] amazing    events=oh yes
```

This allows you to set up some sophisticated logging configurations.
For example, to use the standard library's `logging.config.dictConfig` to log colored logs to the console and plain logs to a file you could do:

```python
import logging.config
import structlog

timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
pre_chain = [
    # Add the log level and a timestamp to the event_dict if the log entry
    # is not from structlog.
    structlog.stdlib.add_log_level,
    # Add extra attributes of LogRecord objects to the event dictionary
    # so that values passed in the extra parameter of log methods pass
    # through to log output.
    structlog.stdlib.ExtraAdder(),
    timestamper,
]


def extract_from_record(_, __, event_dict):
    """
    Extract thread and process names and add them to the event dict.
    """
    record = event_dict["_record"]
    event_dict["thread_name"] = record.threadName
    event_dict["process_name"] = record.processName
    return event_dict


logging.config.dictConfig(
    {
        "version": 1,
        "disable_existing_loggers": False,
        "formatters": {
            "plain": {
                "()": structlog.stdlib.ProcessorFormatter,
                "processors": [
                    structlog.stdlib.ProcessorFormatter.remove_processors_meta,
                    structlog.dev.ConsoleRenderer(colors=False),
                ],
                "foreign_pre_chain": pre_chain,
            },
            "colored": {
                "()": structlog.stdlib.ProcessorFormatter,
                "processors": [
                    extract_from_record,
                    structlog.stdlib.ProcessorFormatter.remove_processors_meta,
                    structlog.dev.ConsoleRenderer(colors=True),
                ],
                "foreign_pre_chain": pre_chain,
            },
        },
        "handlers": {
            "default": {
                "level": "DEBUG",
                "class": "logging.StreamHandler",
                "formatter": "colored",
            },
            "file": {
                "level": "DEBUG",
                "class": "logging.handlers.WatchedFileHandler",
                "filename": "test.log",
                "formatter": "plain",
            },
        },
        "loggers": {
            "": {
                "handlers": ["default", "file"],
                "level": "DEBUG",
                "propagate": True,
            },
        },
    }
)
structlog.configure(
    processors=[
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        timestamper,
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)
```

This defines two formatters: one plain and one colored.
Both are run for each log entry.
Log entries that do not originate from *structlog*, are additionally pre-processed using a cached `timestamper` and {func}`~structlog.stdlib.add_log_level`.

Additionally, for both `logging` and *structlog* -- but only for the colorful logger -- we also extract some data from {class}`logging.LogRecord`:

```pycon
>>> logging.getLogger().warning("bar")
2021-11-15 13:26:52 [warning  ] bar    process_name=MainProcess thread_name=MainThread

>>> structlog.get_logger("structlog").warning("foo", x=42)
2021-11-15 13:26:52 [warning  ] foo    process_name=MainProcess thread_name=MainThread x=42

>>> pathlib.Path("test.log").read_text()
2021-11-15 13:26:52 [warning  ] bar
2021-11-15 13:26:52 [warning  ] foo    x=42
```

(Sadly, you have to imagine the colors in the first two outputs.)

If you leave `foreign_pre_chain` as `None`, formatting will be left to `logging`.
Meaning: you can define a `format` for {class}`~structlog.stdlib.ProcessorFormatter` too!


[*python-json-logger*]: https://github.com/madzak/python-json-logger