Unexpected behaviour with logging.LogRecord "first arg is dict" case

[alanbriolat]

BPO	21172
Nosy	@vsajip, @alanbriolat
Files	logging_format_bug.py: Example of triggering the confusing behaviour

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2014-04-10.06:14:15.255>
created_at = <Date 2014-04-07.17:04:37.576>
labels = ['type-feature', 'library']
title = 'Unexpected behaviour with logging.LogRecord "first arg is dict" case'
updated_at = <Date 2014-04-10.06:14:15.253>
user = 'https://github.com/alanbriolat'

bugs.python.org fields:

activity = <Date 2014-04-10.06:14:15.253>
actor = 'python-dev'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2014-04-10.06:14:15.255>
closer = 'python-dev'
components = ['Library (Lib)']
creation = <Date 2014-04-07.17:04:37.576>
creator = 'alan.briolat'
dependencies = []
files = ['34750']
hgrepos = []
issue_num = 21172
keywords = []
message_count = 6.0
messages = ['215713', '215752', '215754', '215756', '215781', '215867']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'python-dev', 'alan.briolat']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue21172'
versions = ['Python 2.7', 'Python 3.4', 'Python 3.5']

[alanbriolat]

The logging.LogRecord class is more restrictive with its "first arg is dict" case than the formatting operator it uses requires. As far as I can tell, for "%(foo)s" % bar, the minimum contract is that bar.__getitem__("foo") succeeds, not that bar is an instance of dict. However, fulfilling only this minimum contract results in LogRecord raising an exception at the point of applying the string format, which is confusing considering the "same" expression succeeds outside of logging. See the attached file for how 2 "equivalent" expressions behave completely differently.

For resolution, I wonder if checking for "hasattr(..., '__getitem__')" instead of "isinstance(..., dict)" would be sufficient?

[vsajip]

I wouldn't say it is a bug, as it is working as documented - though you might say it is a request for enhancement. The documentation for string formatting at

https://docs.python.org/2/library/stdtypes.html#string-formatting-operations

says that the argument should be a "single mapping object", and, further down the same page at

https://docs.python.org/2/library/stdtypes.html#mapping-types-dict

it's clear that the mapping protocol is more than just __getitem__. Although perhaps currently only __getitem__ is used, who's to say that such will always remain the case?

Removing Python versions 3.2, 3.3 (security fixes only).

[vsajip]

Looking into it further, I see no incidence in logging code of the string "format requires a mapping" or of raising a TypeError with such a message. Can you provide more information? Otherwise I will have to close this issue as invalid.

[alanbriolat]

Because the object in question is not actually a dict, LogRecord is attempting, in this example, "%(bar)s" % (f,) instead of "%(bar)s" % f.

In unicodeobject.c this causes the PyMapping_Check in PyUnicode_Format to fail because it's a tuple (note that PyMapping_Check *only* checks for the __getitem__ attribute), the argument to not be treated as a dict, and consequently ctx.dict = NULL for the format operation.

This condition, combined with still attempting to resolve named values in the format string, causes unicode_format_arg_parse to raise the TypeError("format requires a mapping").

Speaking of documentation, the language of

https://docs.python.org/2/library/logging.html#logging.Logger.debug

strongly suggests that logging.debug(msg, args...) should be considered equivalent to logging.debug(msg % args...), which still means this is still "unexpected" behaviour. The intention is clearly to allow this special case to pass through to the formatting operator unimpeded, however this doesn't happen.

Also, even if "the mapping protocol" should remain the key concept (the behaviour of PyMapping_Check being a happy accident), checking for isinstance(..., dict) is still wrong - it should at least be collections.Mapping to give users a chance to emulate the correct interface.

[vsajip]

Thanks for pinpointing what the issue is.

checking for isinstance(..., dict) is still wrong - it should at least
be collections.Mapping to give users a chance to emulate the correct
interface.

That seems reasonable.

[python-dev]

New changeset d08e3586dde3 by Vinay Sajip in branch '2.7':
Issue bpo-21172: isinstance check relaxed from dict to collections.Mapping.
http://hg.python.org/cpython/rev/d08e3586dde3

New changeset 5e303360db14 by Vinay Sajip in branch '3.4':
Issue bpo-21172: isinstance check relaxed from dict to collections.Mapping.
http://hg.python.org/cpython/rev/5e303360db14

New changeset 8e6b8cfeb172 by Vinay Sajip in branch 'default':
Closes bpo-21172: Merged fix from 3.4.
http://hg.python.org/cpython/rev/8e6b8cfeb172