Python 3.6 logging thread name regression with concurrent.future threads

[desbma]

BPO	29212
Nosy	@gpshead, @brianquinlan, @methane, @desbma
PRs	bpo-29212: Fix the ugly repr() ThreadPoolExecutor thread name. #2315 [3.6] bpo-29212: Fix the ugly repr() ThreadPoolExecutor thread name #3276
Files	test.py: Program to reproduce issue issue29212_1.patch: First patch

^{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/gpshead'
closed_at = <Date 2017-09-06.20:41:33.631>
created_at = <Date 2017-01-09.05:16:03.048>
labels = ['3.7', 'type-bug', 'library']
title = 'Python 3.6 logging thread name regression with concurrent.future threads'
updated_at = <Date 2017-09-06.20:41:33.630>
user = 'https://github.com/desbma'

bugs.python.org fields:

activity = <Date 2017-09-06.20:41:33.630>
actor = 'gregory.p.smith'
assignee = 'gregory.p.smith'
closed = True
closed_date = <Date 2017-09-06.20:41:33.631>
closer = 'gregory.p.smith'
components = ['Library (Lib)']
creation = <Date 2017-01-09.05:16:03.048>
creator = 'desbma'
dependencies = []
files = ['46222', '46224']
hgrepos = []
issue_num = 29212
keywords = ['patch']
message_count = 16.0
messages = ['285021', '285025', '285028', '285339', '286033', '286035', '286080', '286081', '287417', '296555', '296568', '296582', '296616', '296617', '301174', '301201']
nosy_count = 4.0
nosy_names = ['gregory.p.smith', 'bquinlan', 'methane', 'desbma']
pr_nums = ['2315', '3276']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue29212'
versions = ['Python 3.6', 'Python 3.7']

[desbma]

Logging statement using 'threadName' from concurrent.futures threads produce the wrong output with Python 3.6.

The attached program with Python 3.5.X outputs:
MainThread From main thread
Thread-1 From worker thread

But with 3.6, it outputs:
MainThread From main thread
<concurrent.futures.thread.ThreadPoolExecutor object at 0x7f96711ac278>_0 From worker thread

[desbma]

The bug seem to have been introduced by https://hg.python.org/cpython/rev/1002a1bdc5b1

[desbma]

Here is a patch that restores the previous behavior and update test to catch bogus naming.

[desbma]

Thoughts anyone?

This is a minor bug, but for a common use case (easy to hit), and the fix is trivial.

[desbma]

Ping

[methane]

I don't think this is a regression, bug, bogos naming.

I agree that "<concurrent.futures.thread.ThreadPoolExecutor object at 0x7f96711ac278>_0" is ugly.
But the name describes what is the thread, than "Thread-1".

How about giving default thread_name_prefix less ugly?
e.g. "ThreadPoolExecutor-worker".

[desbma]

I don't think using repr(self) as a fallback was intentional, that is why I wrote regression, but I may be wrong.

I agree that the previous default 'Thread-x' gives little information, but only the user can give a relevant name to describe what a thread is doing.
Using a new default like "ThreadPoolExecutor-worker_x" would give more information but at the same time it leaks internal information about how the thread was created in the code (which is not relevant when using the logging module), not about what it's doing.

Anyway as long as that repr string is replaced, I am happy :)

[methane]

OK. I'll wait for another opinions.

[desbma]

Ping, so that this has a chance for the 3.6.1 release.

[desbma]

Ping.

I think any change, included Inada Naoki's idea above is better that the current behavior that pollutes the logging module output.

Unfortunately I cannot rely on the 3.6 new thread_name_prefix argument for portability reasons, and have to manually patch my Python 3.6.x installs just to fix this.

[gpshead]

agreed the repr(self) name being surfaced is a regression even if technically "correct".

your patch makes sense, but i think a nicer variant of it will be to name the thread ("Executor_" + str(num_threads)) when no thread_name_prefix is supplied.