File: getting-started.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 (256 lines) | stat: -rw-r--r-- 10,469 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
# Getting Started

(install)=

## Installation

You can install *structlog* from [PyPI](https://pypi.org/project/structlog/) using *pip*:

```console
$ python -m pip install structlog
```

If you want pretty exceptions in development (you know you do!), additionally install either [Rich] or [*better-exceptions*].
Try both to find out which one you like better -- the screenshot in the README and docs homepage is rendered by Rich.

On **Windows**, you also have to install [Colorama](https://pypi.org/project/colorama/) if you want colorful output beside exceptions.


## Your first log entry

A lot of effort went into making *structlog* accessible without reading pages of documentation.
As a result, the simplest possible usage looks like this:

```{doctest}
>>> import structlog
>>> log = structlog.get_logger()
>>> log.info("hello, %s!", "world", key="value!", more_than_strings=[1, 2, 3])  # doctest: +SKIP
2022-10-07 10:41:29 [info     ] hello, world!   key=value! more_than_strings=[1, 2, 3]
```

Here, *structlog* takes advantage of its default settings:

- Output is sent to **[standard out](https://en.wikipedia.org/wiki/Standard_out#Standard_output_.28stdout.29)** instead of doing nothing.
- It **imitates** standard library {mod}`logging`'s **log level names** for familiarity.
  By default, no level-based filtering is done, but it comes with a **very fast [filtering machinery](filtering)**.
- Like in `logging`, positional arguments are [**interpolated into the message string using %**](https://docs.python.org/3/library/stdtypes.html#old-string-formatting).
  That might look dated, but it's *much* faster than using {any}`str.format` and allows *structlog* to be used as drop-in replacement for {mod}`logging`.
  If you *know* that the log entry is *always* gonna be logged out, just use [f-strings](https://docs.python.org/3/tutorial/inputoutput.html#formatted-string-literals) which are the fastest.
- All keywords are formatted using {class}`structlog.dev.ConsoleRenderer`.
  That in turn uses {func}`repr` to serialize **any value to a string**.
- It's rendered in nice **{doc}`colors <console-output>`**.
- If you have [Rich] or [*better-exceptions*] installed, **exceptions** will be rendered in **colors** and with additional **helpful information**.

Please note that even in most complex logging setups the example would still look just like that thanks to {doc}`configuration`.
Using the defaults, as above, is equivalent to:

```python
import logging
import structlog

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.processors.add_log_level,
        structlog.processors.StackInfoRenderer(),
        structlog.dev.set_exc_info,
        structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S", utc=False),
        structlog.dev.ConsoleRenderer()
    ],
    wrapper_class=structlog.make_filtering_bound_logger(logging.NOTSET),
    context_class=dict,
    logger_factory=structlog.PrintLoggerFactory(),
    cache_logger_on_first_use=False
)
log = structlog.get_logger()
```

:::{note}
- {func}`structlog.stdlib.recreate_defaults()` allows you to switch *structlog* to using standard library's `logging` module for output for better interoperability with just one function call.
- {func}`~structlog.make_filtering_bound_logger()` (re-)uses {any}`logging`'s log levels, but doesn't use `logging` at all.
  The exposed API is {class}`~structlog.typing.FilteringBoundLogger`.
- For brevity and to enable doctests, all further examples in *structlog*'s documentation use the more simplistic {class}`~structlog.processors.KeyValueRenderer()` without timestamps.
:::

There you go, structured logging!


However, this alone wouldn't warrant its own package.
After all, there's even a [recipe] on structured logging for the standard library.
So let's go a step further.

(building-ctx)=

## Building a context

Imagine a hypothetical web application that wants to log out all relevant data with just the APIs that we've introduced so far:

```python
def view(request):
    user_agent = request.get("HTTP_USER_AGENT", "UNKNOWN")
    peer_ip = request.client_addr
    if something:
        log.info("something", user_agent=user_agent, peer_ip=peer_ip)
        return "something"
    elif something_else:
        log.info("something_else", user_agent=user_agent, peer_ip=peer_ip)
        return "something_else"
    else:
        log.info("else", user_agent=user_agent, peer_ip=peer_ip)
        return "else"
```

The calls themselves are nice and straight to the point, however you're repeating yourself all over the place.
It's easy to forget to add a key-value pair in one of the incantations.

At this point, you'll be tempted to write a closure like:

```python
def log_closure(event):
    log.info(event, user_agent=user_agent, peer_ip=peer_ip)
```

inside of the view.
Problem solved?
Not quite.
What if the parameters are introduced step by step?
And do you really want to have a logging closure in each of your views?

Let's have a look at a better approach:

```python
def view(request):
    log = log.bind(
        user_agent=request.get("HTTP_USER_AGENT", "UNKNOWN"),
        peer_ip=request.client_addr,
    )

    if foo := request.get("foo"):
        log = log.bind(foo=foo)

    if something:
        log.info("something")
        return "something"
    elif something_else:
        log.info("something_else")
        return "something_else"
    else:
        log.info("else")
        return "else"

```

Suddenly your logger becomes your closure!

---

To *structlog*, a log entry is just a dictionary called *event dict\[ionary\]*:

- You can pre-build a part of the dictionary step by step.
  These pre-saved values are called the *context*.
- As soon as an *event* happens -- which are the `kwargs` of the log call -- it is merged together with the *context* to an *event dict* and logged out.
- Each logger with its context is *immutable*.
  You manipulate the context by creating new loggers using `bind()` and `unbind()`.

The last point is very clean and easy to reason about, but sometimes it's useful to store _some_ data globally.

In our example above the peer IP comes to mind.
There's no point in extracting it in every view!
For that, *structlog* gives you thread-local context storage based on the {mod}`contextvars` module:

```pycon
>>> structlog.contextvars.bind_contextvars(peer_ip="1.2.3.4")
>>> structlog.get_logger().info("something")
2022-10-10 10:18:05 [info     ] something    peer_ip=1.2.3.4
```

See {doc}`contextvars` for more information and a more complete example.


## Manipulating log entries in flight

Now that your log events are dictionaries, it's also much easier to manipulate them than if they were plain strings.

To facilitate that, *structlog* has the concept of {doc}`processor chains <processors>`.
A processor is a function that receives the event dictionary along with two other arguments and returns a new event dictionary that may or may not differ from the one it got passed.
The next processor in the chain receives that returned dictionary instead of the original one.

Let's assume you wanted to add a timestamp to every event dict.
The processor would look like this:

```{doctest}
>>> import datetime
>>> def timestamper(_, __, event_dict):
...     event_dict["time"] = datetime.datetime.now().isoformat()
...     return event_dict
```

Plain Python, plain dictionaries.
Now you have to tell *structlog* about your processor by {doc}`configuring <configuration>` it:

```{doctest}
>>> structlog.configure(processors=[timestamper, structlog.processors.KeyValueRenderer()])
>>> structlog.get_logger().info("hi")  # doctest: +SKIP
event='hi' time='2018-01-21T09:37:36.976816'
```


## Rendering

Finally you want to have control over the actual format of your log entries.

As you may have noticed in the previous section, renderers are just processors too.
The type of the return value that is required from the renderer depends on the input that the *logger* that is wrapped by *structlog* needs.
While usually it's a string or bytes, there's no rule saying it _has_ to be a string!

So assuming you want to follow [best practices](logging-best-practices.md) and render your event dictionary to JSON that is picked up by a log aggregation system like ELK or Graylog, *structlog* comes with batteries included -- you just have to tell it to use its {class}`~structlog.processors.JSONRenderer`:

```{doctest}
>>> structlog.configure(processors=[structlog.processors.JSONRenderer()])
>>> structlog.get_logger().info("hi")
{"event": "hi"}
```


## *structlog* and standard library's `logging`

While *structlog*'s loggers are very fast and sufficient for the majority of our users, you're not bound to them.
Instead, it's been designed from day one to wrap your *existing* loggers and **add** *structure* and *incremental context building* to them.

The most prominent example of such an "existing logger" is certainly the logging module in the standard library.
To make this common case as simple as possible, *structlog* comes with [some tools](standard-library.md) to help you.

As noted before, the fastest way to transform *structlog* into a `logging`-friendly package is calling {func}`structlog.stdlib.recreate_defaults()`.


## asyncio

The default *bound logger* that you get back from {func}`structlog.get_logger()` and standard library's {class}`structlog.stdlib.BoundLogger` don't have just the familiar log methods like `debug()` or `info()`, but also their async cousins, that simply prefix the name with an a:

```pycon
>>> import asyncio
>>> logger = structlog.get_logger()
>>> async def f():
...     await logger.ainfo("async hi!")
...
>>> logger.info("Loop isn't running yet, but we can log!")
2023-04-06 07:25:48 [info     ] Loop isn't running yet, but we can log!
>>> asyncio.run(f())
2023-04-06 07:26:08 [info     ] async hi!
```

You can use the sync and async logging methods interchangeably within the same application.


## Liked what you saw?

Now you're all set for the rest of the user's guide and can start reading about [bound loggers](bound-loggers.md) -- the heart of *structlog*.

```{include} ../README.md
:start-after: <!-- begin tutorials -->
:end-before: <!-- end tutorials -->
```

[*better-exceptions*]: https://github.com/qix-/better-exceptions
[recipe]: https://docs.python.org/3/howto/logging-cookbook.html#implementing-structured-logging
[Rich]: https://github.com/Textualize/rich