logging UnicodeDecodeError from undecodable strftime output

[mdickinson]

BPO	35427
Nosy	@vsajip, @mdickinson, @iritkatriel

^{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 = None
closed_at = <Date 2021-05-28.18:46:48.749>
created_at = <Date 2018-12-06.16:39:34.623>
labels = ['type-bug', 'library']
title = 'logging UnicodeDecodeError from undecodable strftime output'
updated_at = <Date 2021-05-28.18:46:48.748>
user = 'https://github.com/mdickinson'

bugs.python.org fields:

activity = <Date 2021-05-28.18:46:48.748>
actor = 'mark.dickinson'
assignee = 'none'
closed = True
closed_date = <Date 2021-05-28.18:46:48.749>
closer = 'mark.dickinson'
components = ['Library (Lib)']
creation = <Date 2018-12-06.16:39:34.623>
creator = 'mark.dickinson'
dependencies = []
files = []
hgrepos = []
issue_num = 35427
keywords = []
message_count = 4.0
messages = ['331238', '331239', '394674', '394677']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'mark.dickinson', 'iritkatriel']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue35427'
versions = ['Python 2.7']

[mdickinson]

We're seeing UnicodeDecodeErrors on Windows / Python 2.7 when using logging on a Japanese customer machine. The cause turns out to be in the log record formatting, where unicode fields are combined with non-decodable bytestrings coming from strftime.

More details: we were using the following formatter:

_LOG_FORMATTER = logging.Formatter(
    "%(asctime)s %(levelname)s:%(name)s:%(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S%Z",
)

In the logging internals, that datefmt gets passed to time.strftime, which on the machine in question produced a non-ASCII bytestring (i.e., type str). When combined with other Unicode strings in the log record, this gave the UnicodeDecodeError.

I'm unfortunately failing to reproduce this directly on my own macOS / UK locale machine, but it's documented that time.strftime returns a value encoded according to the current locale. In this particular case, the output we were getting from the time.strftime call looked like:

"2018-12-06T23:57:14\x93\x8c\x8b\x9e (\x95W\x8f\x80\x8e\x9e)"

which assuming an encoding of cp932 decodes to something plausible:

>>> s.decode("cp932")
u'2018-12-06T23:57:14\u6771\u4eac (\u6a19\u6e96\u6642)'
>>> print(s.decode("cp932"))
2018-12-06T23:57:14東京 (標準時)

It looks as though the logging module should be explicitly decoding the strftime output before doing formatting, using for example what's recommended in the strftime documentation [1]:

strftime(<myformat>).decode(locale.getlocale()[1])

Code links: this is the line that's producing non-decodable bytes:

cpython/Lib/logging/__init__.py

Line 425 in 49cedc5

s = time.strftime(datefmt, ct)

... and this is the formatting operation that then ends up raising UnicodeDecodeError as a result of those:

cpython/Lib/logging/__init__.py

Line 469 in 49cedc5

s = self._fmt % record.__dict__

This isn't an issue on Python 3, and I was unable to reproduce it on my non-Windows machine; that particular form of strftime output may well be specific to Windows (or possibly even specific to Japanese flavours of Windows).

[1] https://docs.python.org/2/library/time.html#time.strftime

[mdickinson]

Here's a bug report from someone else running into the same issue on Scrapy; looks like they worked around the issue by simply removing the timezone information from the datefmt (which is what we ended up doing, too):

scrapy/scrapy#1270

[iritkatriel]

Since this is not relevant to python 3, I think this issue can be closed.

[mdickinson]

Agreed. Thank you!