[ python-Bugs-1314519 ] logging run into deadlock in some error handling situation

[SourceForge.net]

Bugs item #1314519, was opened at 2005-10-05 22:56
Message generated for change (Tracker Item Submitted) made by Item Submitter
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1314519&group_id=5470

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: Python Library
Group: Python 2.4
Status: Open
Resolution: None
Priority: 5
Submitted By: Wai Yip Tung (tungwaiyip)
Assigned to: Nobody/Anonymous (nobody)
Summary: logging run into deadlock in some error handling situation

Initial Comment:
I've a daemon that pipe stdout and stderr into logging
in order to capture everything it does. It works fine.
However if there is an error throw inside logging, the
error is sent to stderr that got redirect into logging
again. Its seems some lock is not reentrant and it
causes deadlock.


>>> import logging,sys
>>> # a quick and dirty log file object
... class LogFileObj(object):
...     def __init__(self,log):
...         self.log = log
...     def write(self,str):
...         self.log.warn(str)
...
>>> # create a logger for stderr
... log = logging.getLogger()
>>>
>>> # for the purpose of showing this bug, output to a
StreamHandler based on stdout
... handler = logging.StreamHandler(sys.stdout)
>>> handler.setFormatter(logging.Formatter('%(asctime)s
%(message)s'))
>>> log.addHandler(handler)
>>>
>>> # redirect stderr to a logger
... sys.stderr = LogFileObj(log)
>>>
>>> # it works!
... print >>sys.stderr, 'hello world'
2005-10-05 22:52:32,391 hello world
2005-10-05 22:52:32,391

>>>
>>> # now put sys.stderr aside
... # use the logger as usual
... log.warn('hello world')
2005-10-05 22:52:32,401 hello world
>>>
>>> # this one has an error in the number of arguments
... log.warn('hello world %s', 1, 2)


When the last statement is ran, it goes into a deadlock.

It seems this can be workaround by using
threading.RLock instead of thread's lock.


>>> # workaround the deadlock by using RLock
... import threading
>>> handler.lock = threading.RLock()
>>> log.warn('hello world %s', 1, 2)
2005-10-05 22:47:46,390 Traceback (most recent call last):

2005-10-05 22:47:46,400   File
"C:\Python24\lib\logging\__init__.py", line 706, in emit

2005-10-05 22:47:46,400     msg = self.format(record)

2005-10-05 22:47:46,400   File
"C:\Python24\lib\logging\__init__.py", line 592, in format

2005-10-05 22:47:46,400     return fmt.format(record)

2005-10-05 22:47:46,400   File
"C:\Python24\lib\logging\__init__.py", line 382, in format

2005-10-05 22:47:46,400     record.message =
record.getMessage()

2005-10-05 22:47:46,400   File
"C:\Python24\lib\logging\__init__.py", line 253, in
getMessage

2005-10-05 22:47:46,400     msg = msg % self.args

2005-10-05 22:47:46,400 TypeError: not all arguments
converted during string formatting


I'm not too familiar with the implementation of
logging. Please keep me posted whether this is a
legitimate workaround.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1314519&group_id=5470