PositionalArgumentsFormatter raises TypeError when postional argument is not a formatting tuple

[ryan-bever]

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.

[nel-iprv]

Hi,
Nothing happened regarding to this?

[hynek]

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?

[nel-iprv]

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.

[hynek]

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.

[ruslaniv]

Wait a minute, i'm completely lost!
I thought this is exactly how I could use the logger by passing positional arguments, it is actually in the documentation:

log.info("hello, %s!", "world", key="value!", more_than_strings=[1, 2, 3])  

although I do get exactly the same error, when I'm trying to use logger this way:

logger = structlog.get_logger(__name__)
logger.error("Update ticker", ticker.name)

logger.error("Update ticker", ticker.name)
  File ".../site-packages/structlog/_native.py", line 136, in meth
    return self._proxy_to_logger(name, event % args, **kw)
                                       ~~~~~~^~~~~~
TypeError: not all arguments converted during string formatting

What is going on here?

[hynek]

There's a %s in the example and none in yours.