Logging - Inconsistent behaviour when handling unicode

[jonathan-lp]

BPO	37111
Nosy	@pfmoore, @vsajip, @tjguk, @methane, @zware, @zooba
PRs	bpo-37111: Added encoding keyword parameter to basicConfig. #13932 bpo-37111: Add 'encoding' and 'errors' parameters to logging.basicCon… #14008
Files	my_log.log: File that won't take the unicode

^{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 2019-06-17.16:43:59.796>
created_at = <Date 2019-05-31.09:57:34.129>
labels = ['type-feature', '3.9', 'OS-windows']
title = 'Logging - Inconsistent behaviour when handling unicode'
updated_at = <Date 2019-06-17.16:43:59.608>
user = 'https://bugs.python.org/jonathan-lp'

bugs.python.org fields:

activity = <Date 2019-06-17.16:43:59.608>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2019-06-17.16:43:59.796>
closer = 'vinay.sajip'
components = ['Windows']
creation = <Date 2019-05-31.09:57:34.129>
creator = 'jonathan-lp'
dependencies = []
files = ['48380']
hgrepos = []
issue_num = 37111
keywords = ['patch']
message_count = 20.0
messages = ['344053', '344059', '344060', '344081', '344106', '344110', '344113', '344164', '344198', '344203', '344204', '344208', '344212', '344456', '345319', '345413', '345430', '345432', '345523', '345877']
nosy_count = 8.0
nosy_names = ['paul.moore', 'vinay.sajip', 'tim.golden', 'methane', 'SilentGhost', 'zach.ware', 'steve.dower', 'jonathan-lp']
pr_nums = ['13932', '14008']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue37111'
versions = ['Python 3.9']

[jonathan-lp]

Python is inconsistent in how it handles errors that have some unicode characters. It works to screen but fails to log

This works:

>>> import logging
>>> logging.error('จุด1')
ERROR:root:จุด1

The following breaks:

>>> import logging
>>> logging.basicConfig(filename='c:\\my_log.log')
>>> logging.error('จุด1')

This raises a unicode error:
UnicodeEncodeError: 'charmap' codec can't encode characters in position 11-13: character maps to <undefined>

Python 3.6.3

Given that the file created by the logger is utf-8, it's unclear why it doesn't work.

I found a workaround by using a Handler, but surely the loggers should all work the same way so that people don't get unpleasant surprises that even more painful to debug when things only break in certain logging modes?

[SilentGhost]

Given that the file created by the logger is utf-8

I don't think this is true. Default file handler created using filename argument is opened with encoding None (meaning that it relies on system-default encoding, which is on Windows is not utf-8). And it also explains why your work-around works, provided you've opened file handler with explicit utf-8 encoding.

[jonathan-lp]

It definitely claims to be "utf-8" in NotePad++. I've attached it if you want to double-check.

(Windows 7)

[vsajip]

Given that the file created by the logger is utf-8, it's unclear why it doesn't work ... I found a workaround by using a Handler

Loggers don't create files - handlers do. The file that you attached seems to be just a text file containing ASCII text. Any ASCII is also utf-8, so Notepad++'s assertion doesn't mean anything in this situation.

so that people don't get unpleasant surprises that even more painful to debug when things only break in certain logging modes?

People have been using logging, on Windows, without problems, for years, often using utf-8 to encode their log files. Perhaps you need to read the documentation and look at examples more carefully - I'm not intending to be rude, but say that because using a handler isn't some kind of workaround, and you thinking that it was indicates that you're not sufficiently familiar with the documentation.

I'd suggest posting questions on Stack Overflow or the python-list mailing list, to establish whether there really seems to be a Python bug, before actually logging a Python issue. I appreciate that you're trying to improve Python.

[jonathan-lp]

Thank you for your comments but this wasn't a question and I maintain this is a bug, or at least undesirable behaviour. I'd consider it a bug in my own software.

Reasoning:

• It's an inconsistent default with the logging to screen. This causes more complexity for users when their bug is intermittent.
• Despite your assertion, it's not documented anywhere on the logging docs (I did check before creating this bug when trying to figure out what's going on) - The word "utf" or "unicode" doesn't appear on the logging page, or any of the two tutorials, or the logging.handlers page. There's something in the cookbook but that's about BOM's.
• Much of the world's native characters won't log to ASCII

Per this page: https://docs.python.org/3/howto/unicode.html
"UTF-8 is one of the most commonly used encodings, and Python often defaults to using it."

People have been using logging, on Windows, without problems, for years, often using utf-8 to encode their log files.
I'm afraid this line of reasoning is suffering from selection bias, cherry picking, confirmation bias, and probably some others too. Clearly people have had problems before because it was from one of those folks I took the solution.

Doing something as basic as logging unicode shouldn't require knowledge of "handlers" - that's failing "simple is better than complex".

[vsajip]

Doing something as basic as logging unicode shouldn't require knowledge of "handlers" - that's failing "simple is better than complex".

I reiterate my statement that it appears that you aren't sufficiently familiar with how logging is designed to work. Logging is more complex than print() or open() because it has to work flexibly in lots of different scenarios. Handlers are part of this, as are Formatters and Filters.

See my 2009 blog post

https://plumberjack.blogspot.com/2009/09/python-logging-101.html

for more information for why logging is designed the way it is.

If you want to configure a stream with utf-8 encoding, without explicitly using handlers, this is easily doable, as follows:

C:\Users\Vinay> \python37\python
Python 3.7.3 (v3.7.3:ef4ec6ed12, Mar 25 2019, 22:22:05) [MSC v.1916 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging
>>> logging.basicConfig(stream=open(r'c:\temp\my_log.log', 'w', encoding='utf-8'))
>>> logging.error('จุด1')
>>> ^Z

and, lo and behold, the file c:\temp\my_log.log contains

ERROR:root:จุด1

The use of the stream keyword parameter is clearly documented at

https://docs.python.org/3/library/logging.html#logging.basicConfig

Did you look at the basicConfig documentation before raising this issue?

[jonathan-lp]

Did you look at the basicConfig documentation before raising this issue?

This seems like an attempt at victim blaming. But yes, I did. In fact, this is now the third time I've looked at that page - once before raising this issue, once before my previous reply, and now. I note that your example and nothing like your example is anywhere on that page. The word "encoding" doesn't appear anywhere on the page either. Sure "stream" is on there, but then you need to know about streams and make the association with logging which I apparently don't. You have to remember not everyone has your level of proficiency in the language. In fact, most Python users don't.

Lets put this another way - is there a reason NOT to have Unicode logging as the default? Clearly Unicode was important enough for Guido-et-al to decide to throw Python 2 under the bus.
I've listed the advantages of changing it, what are the disadvantages?

[vsajip]

This seems like an attempt at victim blaming.

Er, no, it was a straight question about whether you'd read the documentation.

I'm afraid this line of reasoning is suffering from selection bias, cherry picking, confirmation bias, and probably some others too.

Er, no, it was stating that lots of people have successfully used logging on Windows with utf-8, as a way of justifying my opinion that there's no deficiency here that needs addressing.

Sure "stream" is on there, but then you need to know about streams and make the association with logging which I apparently don't. You have to remember not everyone has your level of proficiency in the language. In fact, most Python users don't.

Sure, and that's fine. Experienced developers learn stuff every day too. But responding to issues takes time (notice how many people will have been notified about this issue from the "nosy list" above; each would have to spend at least some time looking at it), so raising issues should be done only after exhausting other resources to make sure that the problem isn't in one's own level of knowledge or understanding, but an actual problem with the software. This is why I earlier suggested Stack Overflow and python-list as useful resources for improving one's knowledge and understanding.

Lets put this another way - is there a reason NOT to have Unicode logging as the default?

I have no idea what you mean by this. As my example illustrated, it's quite easy to log Unicode in log files.

A simple Internet search for "basicConfig encoding" yields for me as the second result this Stack Overflow question

https://stackoverflow.com/questions/21402530

for which the accepted answer is a slight variation on what I suggested earlier.

[jonathan-lp]

I have no idea what you mean by this.

I don't see how I can be clearer. What are the reasons for NOT implementing logging to file be unicode as a default? Logging to screen is unicode as a default. What are the reasons for not wanting consistency?

A simple Internet search for "basicConfig encoding" yields for me as the second result this Stack Overflow question

Indeed, and it was from that question I got my solution in fact. The problem was the 30-60 minutes I wasted before that trying to figure out why my program was crashing and why it was only crashing *sometimes*. I'd written the logging part of the program a year ago and not really touched it since, so the logging module being a possible culprit was not even in my mind when the program crashed.

As my example illustrated, it's quite easy to log Unicode in log files.

Yes, things are easy when you know it's necessary. It's the process of discovery that's an unnecessary waste of people's time. That's why I raised this and that's why I would consider this a bug in my own software. It's inconsistent, it invites problems, and it wastes peoples time.

[vsajip]

Learning is not a waste of time. You're entitled to your opinion, but this is not a bug in logging. We'll have to agree to disagree.

[jonathan-lp]

Learning is not a waste of time. You're entitled to your opinion, but this is not a bug in logging. We'll have to agree to disagree.

I agree and value learning a great deal. However learning should happen on your own time, NOT when a program crashes randomly and tries taking you down the rabbit hole. I like learning but not about unrelated things when I'm trying to do useful work.

Fine, if you don't consider this a bug, consider it a feature request. "User would like Python logging of Unicode characters to be consistent" is not an unreasonable request.

[vsajip]

Different people have different ideas of what a default should be. You can pretty much guarantee that whatever a default is, someone will think it should be something else. The basicConfig functionality has been around in its present form since 2003, and people in general haven't had a problem with the current defaults. There is no case for changing a default unless there is a consensus among lots of people that a default needs changing.

[pfmoore]

User would like Python logging of Unicode characters to be consistent

It is consistent. The encoding of

    logging.basicConfig(filename='c:\\my_log.log')

is consistent with the encoding of

    open('c:\\my_log.log')

Both use the system default encoding, which is not UTF-8. There is some discussion going on right now, as to whether it *should* be, but it isn't, and I wouldn't consider changing the behaviour of loging *without* changing the behaviour of open() to be consistent.

Logging to the console is consistent with the standard IO streams, and it was PEP-528 (https://www.python.org/dev/peps/pep-0528/) that made that change - before that, the standard IO streams, and logging to the console, used the console codepage.

So, while I agree that the behaviour takes a bit of work to understand, it's not (IMO) inconsistent, nor is it (IMO) a bug.

[zooba]

I agree with Paul. Consistency with open() is the most important aspect here, and when we investigated changing that to UTF-8 it was decided to be too disruptive.

That said, I'm not opposed to adding encoding/errors to basicConfig if someone wants to do that (and the logging specialists are okay with it).

[methane]

Hmm,, about encoding, I agree that default encoding of open() should be used.
If we change it, encoding of log files are changed unexpectedly after upgrading Python.

On the other hand, couldn't we use different default error handler?
"replace" or "backslashescape" seems better default error handler for the logging.
Is this change affects too many users?

[vsajip]

On the other hand, couldn't we use different default error handler?
"replace" or "backslashescape" seems better default error handler for the logging.

I've left it as is using the same rationale as I guess open() has at the moment - "Errors should never pass silently. Unless explicitly silenced".

[methane]

I've left it as is using the same rationale as I guess open() has at the moment - "Errors should never pass silently. Unless explicitly silenced".

But open() is general purpose, and logging is for logging.

Note that stderr uses 'backslashreplace', even when PYTHONIOENCODING=ascii:strict is used.

And if we don't log something due to encoding error, doesn't it mean "errors may ignored completely silently by default"?
What logging does when UnicodeEncodeError is happened?

[methane]

What logging does when UnicodeEncodeError is happened?

Hm, it seems logging does best job, show enough information to stderr.

But sometime, Python is embedded in web servers and there is no stderr. pythonw.exe may not have stderr too....

I still feel backslashreplace is better default error handler. But it's not strong opinion and it shouldn't block this issue. Go ahead.

$ cat x.py
import logging

logging.basicConfig(filename="mylog.txt")
msg = "hello, はろー"
logging.error(msg)

$ LC_ALL=en_US.US-ASCII python3 x.py
--- Logging error 

---

Traceback (most recent call last):
  File "/usr/local/Cellar/python/3.7.3/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/__init__.py", line 1037, in emit
    stream.write(msg + self.terminator)
UnicodeEncodeError: 'ascii' codec can't encode characters in position 18-20: ordinal not in range(128)
Call stack:
  File "x.py", line 5, in <module>
    logging.error(msg)
Message: 'hello, \u306f\u308d\u30fc'
Arguments: ()

[zooba]

I think Vinay gets to make the call, but I also agree that some sort of error handling by default makes sense for logging. Especially now that it's (about to be) easier to override the default.

FWIW, I'd leave the default arguments as None and just coerce it as late as possible, before TextIOWrapper does it.

[vsajip]

New changeset ca7b504 by Vinay Sajip in branch 'master':
bpo-37111: Add 'encoding' and 'errors' parameters to logging.basicCon… (GH-14008)
ca7b504