classification
Title: Unexpected behaviour with logging.LogRecord "first arg is dict" case
Type: enhancement Stage: resolved
Components: Library (Lib) Versions: Python 3.5, Python 3.4, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: alan.briolat, python-dev, vinay.sajip
Priority: normal Keywords:

Created on 2014-04-07 17:04 by alan.briolat, last changed 2014-04-10 06:14 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
logging_format_bug.py alan.briolat, 2014-04-07 17:04 Example of triggering the confusing behaviour
Messages (6)
msg215713 - (view) Author: Alan Briolat (alan.briolat) Date: 2014-04-07 17:04
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?
msg215752 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-04-08 10:56
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).
msg215754 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-04-08 11:40
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.
msg215756 - (view) Author: Alan Briolat (alan.briolat) Date: 2014-04-08 12:19
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.
msg215781 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-04-09 00:07
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.
msg215867 - (view) Author: Roundup Robot (python-dev) Date: 2014-04-10 06:14
New changeset d08e3586dde3 by Vinay Sajip in branch '2.7':
Issue #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 #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 #21172: Merged fix from 3.4.
http://hg.python.org/cpython/rev/8e6b8cfeb172
History
Date User Action Args
2014-04-10 06:14:15python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg215867

resolution: fixed
stage: resolved
2014-04-09 00:07:26vinay.sajipsetresolution: not a bug -> (no value)
messages: + msg215781
2014-04-08 12:19:49alan.briolatsetstatus: pending -> open

messages: + msg215756
2014-04-08 11:40:32vinay.sajipsetstatus: open -> pending
resolution: not a bug
messages: + msg215754
2014-04-08 10:57:18vinay.sajipsettype: behavior -> enhancement
2014-04-08 10:56:57vinay.sajipsetmessages: + msg215752
versions: - Python 3.1, Python 3.2, Python 3.3
2014-04-07 17:25:31benjamin.petersonsetassignee: vinay.sajip

nosy: + vinay.sajip
2014-04-07 17:04:37alan.briolatcreate