This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging module broken for multiple threads?
Type: Stage:
Components: None Versions: Python 2.4
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: alengarbage, alenlpeacock, rhettinger, vinay.sajip
Priority: normal Keywords:

Created on 2005-09-01 04:49 by alengarbage, last changed 2022-04-11 14:56 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
logtest.py alengarbage, 2005-09-01 16:04 Minimal program that exhibits behavior
logtest3.py alengarbage, 2005-09-01 22:29 even more minimal example
Messages (7)
msg26166 - (view) Author: Lenny G. Arbage (alengarbage) Date: 2005-09-01 04:49
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.
msg26167 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2005-09-01 12:54
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).
msg26168 - (view) Author: Alen Peacock (alenlpeacock) Date: 2005-09-01 16:00
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.
msg26169 - (view) Author: Lenny G. Arbage (alengarbage) Date: 2005-09-01 16:04
Logged In: YES 
user_id=1338323

file attached
msg26170 - (view) Author: Lenny G. Arbage (alengarbage) Date: 2005-09-01 16:04
Logged In: YES 
user_id=1338323

file attached
msg26171 - (view) Author: Lenny G. Arbage (alengarbage) Date: 2005-09-01 22:29
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?
msg26172 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2005-09-02 10:05
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".
History
Date User Action Args
2022-04-11 14:56:12adminsetgithub: 42329
2005-09-01 04:49:27alengarbagecreate