2

Trying figure out how to actually use the processor. What I want to do is add a custom dictionary to log messages as per the example under Debug in the standard Python logging library (https://docs.python.org/3/library/logging.html).

It doesn't work, whether I put an extra in or not.

Python 3.9.2 (default, Feb 28 2021, 17:03:44)
[GCC 10.2.1 20210110] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import structlog
>>> from structlog import stdlib,processors
>>> import logging, sys
>>> logging.basicConfig(stream=sys.stdout)
>>> structlog.configure(logger_factory=stdlib.LoggerFactory(), processors=[stdlib.add_log_level, stdlib.add_logger_name, stdlib.filter_by_level, stdlib.PositionalArgumentsFormatter(), processors.TimeStamper(fmt="iso"), structlog.processors.JSONRenderer(), structlog.stdlib.ExtraAdder(),],)
>>> log = structlog.get_logger(__name__)
>>> type(log)
<class 'structlog._config.BoundLoggerLazyProxy'> # looks like we got a logger

# with an extra:

>>> log.error("Log message example", extra={'a':'b'})
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.9/dist-packages/structlog/_log_levels.py", line 124, in meth
    return self._proxy_to_logger(name, event, **kw)
  File "/usr/local/lib/python3.9/dist-packages/structlog/_base.py", line 203, in _proxy_to_logger
    args, kw = self._process_event(method_name, event, event_kw)
  File "/usr/local/lib/python3.9/dist-packages/structlog/_base.py", line 160, in _process_event
    event_dict = proc(self._logger, method_name, event_dict)
  File "/usr/local/lib/python3.9/dist-packages/structlog/stdlib.py", line 708, in __call__
    record: Optional[logging.LogRecord] = event_dict.get("_record")
AttributeError: 'str' object has no attribute 'get'

# without an extra

>>> log.error("Log message example")
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/local/lib/python3.9/dist-packages/structlog/_log_levels.py", line 124, in meth
    return self._proxy_to_logger(name, event, **kw)
  File "/usr/local/lib/python3.9/dist-packages/structlog/_base.py", line 203, in _proxy_to_logger
    args, kw = self._process_event(method_name, event, event_kw)
  File "/usr/local/lib/python3.9/dist-packages/structlog/_base.py", line 160, in _process_event
    event_dict = proc(self._logger, method_name, event_dict)
  File "/usr/local/lib/python3.9/dist-packages/structlog/stdlib.py", line 708, in __call__
    record: Optional[logging.LogRecord] = event_dict.get("_record")
AttributeError: 'str' object has no attribute 'get'

The configuration seems easy enough if I want to allow anything. Actually using this processor in a log message stumps me.

Any help appreciated.

coyot
  • 418
  • 1
  • 3
  • 12
  • A further test shows that if I remove the processor, it works except that the dict is a value of the extra key instead of the dict keys being surfaced as a top level keys. `INFO:v1:{"extra": {"a": "b"}, "event": "Log message example", "level": "info", "logger": "conductor.v1routes", "timestamp": "2022-05-06T18:31:05.484096Z", "module": "thread", "process": 1, "lineno": 58, "process_name": "MainProcess", "thread": 140150516976440, "filename": "thread.py", "pathname": "/usr/local/lib/python3.10/concurrent/futures/thread.py", "func_name": "run", "thread_name": "asyncio_0"}` – coyot May 06 '22 at 18:36

1 Answers1

3

JSONRenderer renders the event dict and therefore returns a string (or if you use orjson: bytes). You must move ExtraAdder before it, where the event is still a dict.

hynek
  • 3,647
  • 1
  • 18
  • 26
  • Thanks. I kind of suspected there might be an ordering issue. – coyot May 09 '22 at 16:17
  • However, it doesn't seem to do anything once it works. Repeating the example from the OP but putting ExtraAdder first, I get: `>>> log.error("Log message example", extra={'a':'b'})` `ERROR:__main__:{"extra": {"a": "b"}, "event": "Log message example", "level": "error", "logger": "__main__", "timestamp": "2022-05-09T16:35:47.100513Z"` Which is the same as if I had left the processor out, so I am not sure of the value add here. What I was hoping for is that it would make "a" a key at the top level. – coyot May 09 '22 at 16:38
  • Trying without the `extra=` gets an error `>>> log.error("Log message example", {'a':'b'}) Traceback (most recent call last): File "", line 1, in TypeError: meth() takes 2 positional arguments but 3 were given` – coyot May 09 '22 at 16:55
  • 1
    I think you're somewhat confused about what's going on here. If you pass `extra` as a keyword argument to a structlog logger, it's just that. Nothing needs to be extracted. So what you want here is `log.error("message example", a="b")` – hynek May 11 '22 at 05:31
  • Perfect, thanks. I suggest clarifying this in the docs, as this is different than how extra handling works in the standard logging library. e.g., from the example at the above linked stdlib page, ```FORMAT = '%(asctime)s %(clientip)-15s %(user)-8s %(message)s' logging.basicConfig(format=FORMAT) d = {'clientip': '192.168.0.1', 'user': 'fbloggs'} logger = logging.getLogger('tcpserver') logger.warning('Protocol problem: %s', 'connection reset', extra=d)``` I'm thinking of writing my own processor based on your ExtraAdder that behaves like stdlib extra logging. Would you accept a patch? – coyot May 12 '22 at 16:13
  • structlog generally works the way I like it to work which is often differnt from stdlib. :) My focus is to let everyone tailor their own favorite experience. So the answer is probably no, but feel free to publish it and add to . – hynek May 13 '22 at 05:24
  • One last comment on this, I promise. It turns out that an extension isn't necessary. One just needs to unpack the dictionary before sending it to structlog, e.g., something like `foo = {'a':'b'}` and then `log.error("message example", **foo)`. A trick worth documenting, I think. – coyot May 16 '22 at 17:24