hynek
PositionalArgumentsFormatter raises TypeError when postional argument is not a formatting tuple
When a structlog BouldLogger user incorrectly uses a postional argument that is not a formatting tuple, the PositionalArgumentsFormatter raises a TypeError.
The documentation states that this "must contain a tuple that is used for formatting".
What I want to point out is that this behavior is different than the stdlib when that method is misused. When the stdlib method is misused it catches the exception and prints a stacktrace, but it does not result in an uncaught exception. e.g.
import logging
logging.basicConfig()
logging.getLogger('stdlib').warning('Info message', 'x')
Results in:
--- Logging error ---
Traceback (most recent call last):
File "/Users/rbever/.pyenv/versions/3.7.6/lib/python3.7/logging/__init__.py", line 1025, in emit
msg = self.format(record)
File "/Users/rbever/.pyenv/versions/3.7.6/lib/python3.7/logging/__init__.py", line 869, in format
return fmt.format(record)
File "/Users/rbever/.pyenv/versions/3.7.6/lib/python3.7/logging/__init__.py", line 608, in format
record.message = record.getMessage()
File "/Users/rbever/.pyenv/versions/3.7.6/lib/python3.7/logging/__init__.py", line 369, in getMessage
msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
File "scratch.py", line 4, in <module>
logging.getLogger('stdlib').warning('Info message', 'x')
Message: 'Info message'
Arguments: ('x',)
Process finished with exit code 0
PositionalArgumentsFormatter does result in an uncaught exception e.g.
import structlog
structlog.configure(
processors=[
structlog.stdlib.PositionalArgumentsFormatter(),
structlog.dev.ConsoleRenderer(),
],
context_class=dict,
logger_factory=structlog.stdlib.LoggerFactory(),
wrapper_class=structlog.stdlib.BoundLogger,
cache_logger_on_first_use=True,
)
structlog.get_logger('structlog').warning('Info message', 'x')
Results in:
Traceback (most recent call last):
File "/Users/rbever/git/sfprime/nde-node-service/scratch.py", line 17, in <module>
structlog.get_logger('structlog').warning('Info message', 'x')
File "/Users/rbever/.pyenv/versions/nde-node-service/lib/python3.7/site-packages/structlog/stdlib.py", line 80, in warning
return self._proxy_to_logger("warning", event, *args, **kw)
File "/Users/rbever/.pyenv/versions/nde-node-service/lib/python3.7/site-packages/structlog/stdlib.py", line 124, in _proxy_to_logger
method_name, event=event, **event_kw
File "/Users/rbever/.pyenv/versions/nde-node-service/lib/python3.7/site-packages/structlog/_base.py", line 189, in _proxy_to_logger
args, kw = self._process_event(method_name, event, event_kw)
File "/Users/rbever/.pyenv/versions/nde-node-service/lib/python3.7/site-packages/structlog/_base.py", line 149, in _process_event
event_dict = proc(self._logger, method_name, event_dict)
File "/Users/rbever/.pyenv/versions/nde-node-service/lib/python3.7/site-packages/structlog/stdlib.py", line 328, in __call__
event_dict["event"] = event_dict["event"] % args
TypeError: not all arguments converted during string formatting
Process finished with exit code 1
Which is an uncaught error.
Ideally logging even when misused in this manner wouldn't cause Runtime errors.
Well, I'm a bit conflicted on this one. Sure logging does it, but there's the zen of Python that errors shouldn't pass silently and what logging is doing here is masking an error that can lead to data loss in production because nobody reads warnings.
What exactly is motivation to allow for bugs here? Just because it's logging?
I do agree that is masking an error and potentially losing logs in production but, while migrating from logging to structlog, these errors which were silent can now break the code - in perfect world everything would be unit tested, agree.
Perhaps a optional flag similar to the logging.raiseExceptions could be used.
But… isn’t that a feature that you’re finding those bugs now? You’re basically asking me to tape over an engine warning light.