My coworker and I are writing a Python class for the other developers
within our team. This class is supposed to encapsulate several things,
including daemonizing, setting up logging, and spawning a thread to
host an XML-RPC server.
I'm having a real problem with logging.Logger and threading.Thread. In
the main thread, we set up two loggers, each with file handlers. We
then spawn the xml-rpc server thread, and allow the parent thread to
continue. At some point, the stream of the file handlers appears to be
closed from the xml-rpc server's thread, but still open from the POV
of the parent thread?! How is this possible?
Here's the POV from the child thread:
--------------------
/Users/marco/work/cam/services/common/lib/camService.py(226)__run_xr_server()
-> self.loggers['main'].info("ABOUT TO WAIT FOR START")
(Pdb) self._camBaseService__serviceLog._camLog__handlers['file']['main']['handler'].stream
<closed file '/Users/marco/work/cam/services/camd/var/logs/camd-main.log', mode 'a' at 0x142d890>
(Pdb) n
Traceback (most recent call last):
File "/export/crawlspace/cam/python/builds/current/python-2.4-cam/lib/python2.4/logging/handlers.py", line 62, in emit
if self.shouldRollover(record):
File "/export/crawlspace/cam/python/builds/current/python-2.4-cam/lib/python2.4/logging/handlers.py", line 132, in shouldRollover
self.stream.seek(0, 2) #due to non-posix-compliant Windows feature
ValueError: I/O operation on closed file
--------------------
And here's the POV from the parent thread:
--------------------
(Pdb) camd._camBaseService__serviceLog._camLog__handlers['file']['main']['handler'].stream
<open file '/Users/marco/work/cam/services/camd/var/logs/camd-main.log', mode 'a' at 0x142e890>
--------------------
Obviously, these are two different pdb runs, but I've stepped through
the parent very carefully, and stream.close() is NEVER called, either
by the child nor the parent. BUT, while it continues to appear open to
the parent, it clearly IS changed in the child. How is this even
possible?! They're the same file handle!
Here are some code snippets. Unfortunately, we have a considerable
amount of inheritance going on.
From the parent:
--------------------
if __name__ == "__main__":
camd = camBaseService("camd", parsedOptions.configFile, configDef)
if not camd.start():
print "Start failed, exiting..."
sys.exit(1)
camd.loggers['main'].info("Main loop waiting for XML-RPC Server to quit.")
--------------------
Any call to that info() method will continue to work forever.
camBaseService does some initialziation in that camd object:
--------------------
# Flags for communicating to the XRServer thread
self.xrStart = False
self.xrInitialized = False
self.__initialize_logging()
self.loggers['xr-server'] = self.__serviceLog.add_logger('xr-server')
self.loggers['main'] = self.__serviceLog.add_logger('main')
self.xrSvcThread = threading.Thread(target=self.__run_xr_server)
--------------------
camd.start (see __main__, above) spawns the thread, so it runs this
code in the parent thread:
--------------------
self.xrSvcThread.start()
i = 0
while i < 10 and not self.xrInitialized:
if not self.xrInitialized:
i = i + 1
time.sleep(1)
if self.xrInitialized:
self.xrStart = True
return True
--------------------
In the child thread:
--------------------
# some misc configuration goo
self.xrInitialized = True
self.loggers['main'].info("ABOUT TO WAIT FOR START")
--------------------
I've isolated the switch from open to closed (from the POV of the
child ONLY) to that exchange of flags xrInitiated (child says, "I'm
ready to go!") to the parent thread's setting xrStart (ok! go!).
Can anyone PLEASE help me understand what's going on here?
--
__________________________________________________ _____________________
Marco E. Nicosia | http://www.escape.org/~marco/ | ma***@escape.org
