[ python-Bugs-1516995 ] test_logging fails with reference count-checking enabled

[SourceForge.net]

Bugs item #1516995, was opened at 2006-07-04 10:34
Message generated for change (Comment added) made by collinwinter
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1516995&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.5
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Collin Winter (collinwinter)
Assigned to: Vinay Sajip (vsajip)
Summary: test_logging fails with reference count-checking enabled

Initial Comment:
When running from the following, test_logging fails:
./python Lib/test/regrtest.py -R :: test_logging.

Here's the traceback:

test test_logging crashed -- <type
'exceptions.KeyError'>: <logging.StreamHandler instance
at 0xb7aaebcc>
Traceback (most recent call last):
  File "Lib/test/regrtest.py", line 554, in runtest_inner
    dash_R(the_module, test, indirect_test, huntrleaks)
  File "Lib/test/regrtest.py", line 673, in dash_R
    run_the_test()
  File "Lib/test/regrtest.py", line 660, in run_the_test
    indirect_test()
  File
"/home/collin/src/python/Lib/test/test_support.py",
line 299, in inner
    return func(*args, **kwds)
  File
"/home/collin/src/python/Lib/test/test_logging.py",
line 677, in test_main
    test_main_inner()
  File
"/home/collin/src/python/Lib/test/test_logging.py",
line 640, in test_main_inner
    globals()['test%d' % t]()
  File
"/home/collin/src/python/Lib/test/test_logging.py",
line 347, in test2
    sh.close()
  File
"/home/collin/src/python/Lib/logging/__init__.py", line
687, in close
    del _handlers[self]
KeyError: <logging.StreamHandler instance at 0xb7aaebcc>




This problem does not occur when run without reference
count-checking.

System info:
Python SVN r47224
Linux 2.6.13
x86

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

>Comment By: Collin Winter (collinwinter)
Date: 2007-03-11 00:53

Message:
Logged In: YES 
user_id=1344176
Originator: YES

Adding those lines does indeed suppress the exception. I'm not convinced
it eliminates the problem, though, since adding "t = 2" after "for t in
range(1,6):" in test_main_inner() will still cause test2() to raise
KeyError() (with the same traceback as before), even with your patch. I've
tried this same approach for all tests (0-5) and test2() is the only one to
exhibit this behaviour. That said, I'm very happy to have test_logging not
fail under "regrtest -R" anymore : )

I would apply your solution to both trunk/ and release25-maint/, if only
to keep the number of buildbot false alarms to a minimum.

Thanks, Vinay!

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

Comment By: Vinay Sajip (vsajip)
Date: 2007-03-10 19:58

Message:
Logged In: YES 
user_id=308438
Originator: NO

Thanks for the info. test2() is a little sensitive because it makes
assumptions about the state of handlers attached to the root logger.
test4() and test5() do some slightly dodgy manipulation of the internal
handler list maintained by the module. I played around with the assumption
that test5() is the culprit (as it's the last test run), and found that
adding the lines

        hdlr = logging.getLogger().handlers[0]
        logging.getLogger().handlers.remove(hdlr)

in test5(), just after the line

        os.remove(fn)

causes the error not to occur, and the test passes successfully. Please
try this on your system and re-run the tests, and if you can confirm that
this change works for you, I can check it in. (I propose to only check it
into trunk, and not into release25-maint or other branches - what do you
think?)

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

Comment By: Collin Winter (collinwinter)
Date: 2007-03-10 15:36

Message:
Logged In: YES 
user_id=1344176
Originator: YES

Vinay: I've been able to gather a little more information.

The problem occurs during the second run-through of the test suite; that
is, it runs once, then "-R ::" kicks in and starts to run the test again,
which is when the exception occurs. From what I can tell from poking around
test2(), something is removing the "sh" handler from logging._handlers
prematurely (its id() matches that displayed in the KeyError traceback).

More poking around: "-R ::" doesn't really enter into it. Modifying
test_main_inner() to run test2() more than once (in isolation or after
other tests) will trigger this, too. On the second run, sh.close() raises a
KeyError.

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

Comment By: Vinay Sajip (vsajip)
Date: 2007-03-10 12:25

Message:
Logged In: YES 
user_id=308438
Originator: NO

Hi Collin,

I'm sorry to be so slow on this. For various reasons, I don't have a debug
build of Python 2.5 :-(, without which the -R option is not available to
me. Also, of course, it's not a bug in logging itself, more in the test
case.

If you have time, I would appreciate some help on this: I would
temporarily modify test_logging to print out the StreamHandlers created
either explicity in test_logging.py or via the calls to fileConfig(), to
see which StreamHandler is not being released. TIA...

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

Comment By: Collin Winter (collinwinter)
Date: 2007-03-09 15:42

Message:
Logged In: YES 
user_id=1344176
Originator: YES

Still present as of 54248. Vinay, do you have any insights on this?

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

Comment By: Collin Winter (collinwinter)
Date: 2006-09-01 00:03

Message:
Logged In: YES 
user_id=1344176

This issue is still present as of r51654.

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

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