logging module broken for multiple threads?

[alengarbage]

BPO	1277903
Nosy	@rhettinger, @vsajip
Files	logtest.py: Minimal program that exhibits behavior logtest3.py: even more minimal example

^{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 2005-09-02.10:05:43.000>
created_at = <Date 2005-09-01.04:49:27.000>
labels = ['invalid']
title = 'logging module broken for multiple threads?'
updated_at = <Date 2005-09-02.10:05:43.000>
user = 'https://bugs.python.org/alengarbage'

bugs.python.org fields:

activity = <Date 2005-09-02.10:05:43.000>
actor = 'vinay.sajip'
assignee = 'vinay.sajip'
closed = True
closed_date = None
closer = None
components = ['None']
creation = <Date 2005-09-01.04:49:27.000>
creator = 'alengarbage'
dependencies = []
files = ['1764', '1765']
hgrepos = []
issue_num = 1277903
keywords = []
message_count = 7.0
messages = ['26166', '26167', '26168', '26169', '26170', '26171', '26172']
nosy_count = 4.0
nosy_names = ['rhettinger', 'vinay.sajip', 'alengarbage', 'alenlpeacock']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = None
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue1277903'
versions = ['Python 2.4']

[alengarbage]

After upgrading from python 2.2, I noticed that the
logging facility doesn't seem to work in my code anymore.

As far as I can tell, after spending a bit of time
isolating the problem, this is an issue with threading.
In the main thread, logging works without a hitch. In
the secondary thread (which is run via
twisted.reactor), any attempt to write to the log
results in:

Traceback (most recent call last):
  File "/usr/lib/python2.4/logging/__init__.py", line
712, in emit
    self.stream.write(fs % msg)
ValueError: I/O operation on closed file

The code that initializes the logger is as follows:
logger = logging.getLogger('mylogger')
screenhandler = logging.StreamHandler()
screenhandler.setLevel(logging.INFO)
logger.addHandler(self.screenhandler)

    logfile = "/tmp/testlog"
    if os.path.isfile(logfile):
        os.remove(logfile)
    handler = logging.FileHandler(logfile)
    formatter = logging.Formatter('%(asctime)s

%(levelname)s: %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.INFO)

Alone, this works fine. It is only when a the second
thread does a 'logger = logging.getLogger('mylogger')
and subsequently calls 'logger.log()' that the above
error is produced.

[rhettinger]

Logged In: YES
user_id=80475

It looks to me like you've created a race condition that
became evident only when switching Python versions.
Assigning to Vijay so he can give advice on the best way to
code this (most likely by moving resource competing calls to
the main thread).

[alenlpeacock]

Logged In: YES
user_id=1239721

I'm attaching a minimal program that demonstrates the
behavior. You'll need twisted installed to run it. I've
tested on python 2.4.1 and 2.4.14, both produce the error.

[alengarbage]

Logged In: YES
user_id=1338323

file attached

[alengarbage]

Logged In: YES
user_id=1338323

file attached

[alengarbage]

Logged In: YES
user_id=1338323

Here's an even more minimal snippet of code that produces
the error. Nothing but a logger and a thread. No need for
twisted anything. Ignore the previous example.

Does this code do something to abuse the logging facility?

[vsajip]

Logged In: YES
user_id=308438

The problem is occurring because the main thread exits,
which causes shutdown of the logging system via an atexit
hook. If you add either of the following lines at the end of your
__name__ == "__main__" clause:

raw_input("Press a key:")

or

mythread.join()

Then the thread continues to run:

2005-09-02 10:23:37,023 2564 INFO: logging initialized
2005-09-02 10:23:37,023 2564 INFO: initializing MyThread
2005-09-02 10:23:37,023 2564 INFO: test (before starting
thread)
2005-09-02 10:23:37,032 2220 INFO: MyThread starting
2005-09-02 10:23:37,032 2564 INFO: test (after starting
thread)
2005-09-02 10:23:37,032 2220 INFO: MyThread ticking...
2005-09-02 10:23:39,036 2220 INFO: MyThread ticking...
2005-09-02 10:23:41,039 2220 INFO: MyThread ticking...
2005-09-02 10:23:43,042 2220 INFO: MyThread ticking...
2005-09-02 10:23:45,045 2220 INFO: MyThread ticking...
2005-09-02 10:23:47,048 2220 INFO: MyThread ticking...

(I modified the format string to show the thread ID in the
logged message).

Hence, this is not a bug and I am closing this entry
as "Invalid".