Issue 1277903: logging module broken for multiple threads? (original) (raw)
Created on 2005-09-01 04:49 by alengarbage, last changed 2022-04-11 14:56 by admin. This issue is now closed.
Messages (7)
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.
Author: Raymond Hettinger (rhettinger) * 
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).
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.
Author: Lenny G. Arbage (alengarbage)
Date: 2005-09-01 16:04
Logged In: YES user_id=1338323
file attached
Author: Lenny G. Arbage (alengarbage)
Date: 2005-09-01 16:04
Logged In: YES user_id=1338323
file attached
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?
Author: Vinay Sajip (vinay.sajip) *
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".