classification
Title: Bad interaction between test_logging and test_concurrent_futures
Type: behavior Stage:
Components: Library (Lib), Tests Versions: Python 3.2
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: bquinlan Nosy List: bquinlan, brian.curtin, eric.araujo, georg.brandl, lukasz.langa, ncoghlan, pitrou, r.david.murray, vinay.sajip
Priority: deferred blocker Keywords: buildbot, patch

Created on 2010-12-04 13:51 by pitrou, last changed 2010-12-28 21:15 by bquinlan. This issue is now closed.

Files
File name Uploaded Description Edit
logging.patch bquinlan, 2010-12-05 18:16 Removes handler from futures logger
logging.patch bquinlan, 2010-12-24 20:20
Messages (19)
msg123352 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-12-04 13:51
See this buildbot log:
http://www.python.org/dev/buildbot/all/builders/AMD64%20Windows%20Server%202008%203.x/builds/198/steps/test/logs/stdio

======================================================================
FAIL: test_done_callback_raises (test.test_concurrent_futures.FutureTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\buildslave-py3k\3.x.curtin-win2008-amd64\build\lib\test\test_concurrent_futures.py", line 646, in test_done_callback_raises
    self.assertIn('Exception: doh!', logging_stream.getvalue())
AssertionError: 'Exception: doh!' not found in ''

----------------------------------------------------------------------
msg123387 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-12-04 19:28
Same one under Ubuntu:
http://www.python.org/dev/buildbot/all/builders/PPC64%20Ubuntu%203.x/builds/265/steps/test/logs/stdio
msg123392 - (view) Author: Łukasz Langa (lukasz.langa) * (Python committer) Date: 2010-12-04 19:47
Possibly related: issue #10517.
msg123399 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-12-04 20:27
Minimal command line for reproducing:

./python -m test -uall test_pydoc test_logging test_concurrent_futures
[1/3] test_pydoc
[46429 refs]
[46430 refs]
[46430 refs]
[46429 refs]
[46430 refs]
[46425 refs]
[46425 refs]
[2/3] test_logging
[3/3] test_concurrent_futures
test test_concurrent_futures failed -- Traceback (most recent call last):
  File "/home/antoine/py3k/debug/Lib/test/test_concurrent_futures.py", line 646, in test_done_callback_raises
    self.assertIn('Exception: doh!', logging_stream.getvalue())
AssertionError: 'Exception: doh!' not found in ''


And the culprint seems to be r86962:

user:        nick.coghlan
date:        Fri Dec 03 10:29:11 2010 +0100
summary:     [svn r86962] Improve Pydoc interactive browsing (#2001).  Patch by Ron Adam.
msg123413 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2010-12-05 08:18
This is unrelated to issue 10517 (based on Dave Malcolm's initial investigation, that looks like it may be a genuine problem in multiprocessing)

Instead, this relates to a problem in concurrent.futures where it installs a logging *handler* as a side effect of import. IMO, this is itself a bug in the concurrent.futures package - the standard library shouldn't be installing logging handlers implicitly, but only when explicitly asked to do so, or when absolutely necessary (multiprocessing is an example of a package that walks this line appropriately).

The reason the test_pydoc, test_logging, test_concurrent_futures sequence causes an error is as follows:

1. test_pydoc walks the entire package hierarchy when testing its ability to generate the HTML for the search page.
2. this implicitly imports concurrent.futures, since it is implemented as a package that imports names from submodules in __init__.py
3. this means the c.f handler is already registered in logging when test_logging is run
4. as test_logging assumes it has full control over the logging state, the c.f handler is not left in the same state as it started in
5. test_concurrent_futures then fails, as it assumes the state of the handler has not changed since it was created as a side-effect of the package import

Quite a trip down the rabbit hole to figure that one out :)

Handing back to Brian to fix the underlying problem (i.e. the implicit installation of the logging handler by concurrent.futures).

Georg FYI as to why the py3k buildbots will sometimes go red if the randomised execution happens to run these 3 tests in this particular order (and my apologies for checking in the regrtest.py changes during the release freeze).
msg123419 - (view) Author: Georg Brandl (georg.brandl) * (Python committer) Date: 2010-12-05 12:12
What a nice mess :)  Raising priority so that this doesn't get overlooked.
msg123432 - (view) Author: Brian Quinlan (bquinlan) (Python committer) Date: 2010-12-05 18:16
I've attached a patch that removes the code that installs a handler to the futures logger.

I'm not sure if this is the correct approach though - it means that "impossible" errors will only be reported to the user through a message like "no handler installed for logger". Maybe it is OK because this logging really shouldn't happen.

Thoughts?
msg123451 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2010-12-06 04:05
For 3.2, writing such errors directly to stderr would be fine (we already do that in other places via PyErr_WriteUnraisable)

The test could then be modified to use test.support.captured_output to temporarily replace stderr and look at the output.

The problem of avoiding interfering with application level handlers while having unraisable errors visible by default is probably the biggest reason past attempts to get the standard library using the logging module internally haven't gained much traction :P
msg123505 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-12-06 21:12
> The problem of avoiding interfering with application level handlers
> while having unraisable errors visible by default is probably the
> biggest reason past attempts to get the standard library using the
> logging module internally haven't gained much traction :P

Isn't it a problem that the logging module should be designed to make
easy to fix or work around?
msg123506 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2010-12-06 22:23
Wow, I didn't realize that's how logging worked.  My understanding was a module should just get a logger and log messages, and if the application didn't do any setup beforehand, the first logging call would cause messages to be written to stdout (or stderr) in a default format.  In fact, I thought that I had observed that behavior in the past, but I just tested it and you are right, it complains about not having a handler.  

This definitely seems like a logging bug to me.  IMO the only thing a module should need to do is call getlogger with its qualified name and log messages.
msg123507 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-12-06 22:30
> Wow, I didn't realize that's how logging worked.  My understanding was
> a module should just get a logger and log messages, and if the
> application didn't do any setup beforehand, the first logging call
> would cause messages to be written to stdout (or stderr) in a default
> format.  In fact, I thought that I had observed that behavior in the
> past,

So have I. Did something change?

And does test_logging really have to change the whole logging setup,
rather than only what it needs to check for? Or can't it restore stuff
afterwards?
msg123512 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2010-12-07 01:33
Actually, I take it back. The default state of logging appears to do the right thing with no special handler installed - both the .critical() and .exception() messages are written out to stderr by default, so the futures tests pass even after Brian's patch is applied.

So I think removing the handler installation code is the right thing to do, even if (as it turns out) it doesn't fix the test failure.

I also thought of a more minimal way to reproduce the test failure that makes it clear pydoc isn't really involved:

  ./python -m test test_concurrent_futures test_logging test_concurrent_futures

The first execution of the test will pass, the second will fail (both with and without Brian's patch to remove the handler installation).

Adding Vinay to the nosy list - I suspect Antoine is right that the logging tests are leaving existing loggers in a slightly unhealthy state. A better save/restore in regrtest.py might be a place to start, but I don't know the internals of the logging package well enough to improve on what I already added.
msg123542 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-12-07 11:40
I will take a look at test_logging tidying up after itself, though the intention is to leave things as they were found (this is done in setUp/tearDown, and if it doesn't tidy up properly, that would be a bug).

As already explained in logging's documentation, there is no problem with just getting a logger and logging to it, BUT the top-level logger in any library package (and that includes stdlib, too) should have a NullHandler instance added to avoid the "no handlers could be found for logger XXX" message. This latter, one-off message is only there to guard against mis-configuration.

Re. Nick's comments about using logging in the stdlib - I'm not sure the reason he states is the reason for lack of traction, I think it's more to do with inertia. I will post separately on python-dev about use of logging in the stdlib itself, to see what specific obstacles stdlib maintainers see in the use of logging in their own modules.
msg123543 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2010-12-07 12:12
Yeah, I think that comment was just a mistaken impression on my part.

Definitely something odd going on with the test interaction though.
msg123727 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-12-10 11:58
I've added the logging code to implement and use a logger of last resort as discussed on the thread for http://bit.ly/last-resort-handler into the py3k branch, r87157. Gist of differences is available at https://gist.github.com/736120 - so Brian could remove the STDERR_HANDLER from his code. The futures test code can set sys.stderr to an io.StringIO instance during the test; the last resort handler checks for the sys.stderr value when emitting a record, not when the handler is created.
msg123728 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-12-10 12:00
s/logger of last resort/handler of last resort/
msg124606 - (view) Author: Brian Quinlan (bquinlan) (Python committer) Date: 2010-12-24 20:20
Sorry for being AWOL for so long. Attached is a patch that doesn't install a handler and checks stderr for the exception output. Unfortunately, it looks like the logging tests are still messing things up:

./python.exe -m test test_concurrent_futures test_concurrent_futures
[1/2] test_concurrent_futures
[2/2] test_concurrent_futures
All 2 tests OK.

% ./python.exe -m test test_concurrent_futures test_logging test_concurrent_futures
[1/3] test_concurrent_futures
[2/3] test_logging
[3/3] test_concurrent_futures
test test_concurrent_futures failed -- Traceback (most recent call last):
  File "/home/bquinlan/shared/py3k/Lib/test/test_concurrent_futures.py", line 642, in test_done_callback_raises
    self.assertIn('Exception: doh!', stderr.getvalue())
AssertionError: 'Exception: doh!' not found in ''

2 tests OK.
1 test failed:
    test_concurrent_futures
msg124708 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-12-27 14:37
The reason for the bad interaction is that some of the tests in test_logging disable all existing loggers (due to the configuration tests - disabling of existing loggers is explicitly tested for), but as a side effect this also disabled the concurrent.futures logger.

I've made a change to test_logging which preserves the disabled state of all existing loggers across tests, and now all is well when testing

regrtest.py test_concurrent_futures test_logging test_concurrent_futures

after applying Brian's patch of 24 Dec 2010.

The change has been checked into py3k (r87513). However, this raises the wider issue of other loggers in stdlib and the effect on them of logging configuration calls. I'll raise this on python-dev for discussion.
msg124818 - (view) Author: Brian Quinlan (bquinlan) (Python committer) Date: 2010-12-28 21:15
Fixed in r87556.
History
Date User Action Args
2010-12-28 21:15:11bquinlansetstatus: open -> closed

messages: + msg124818
resolution: fixed
nosy: georg.brandl, vinay.sajip, bquinlan, ncoghlan, pitrou, eric.araujo, r.david.murray, brian.curtin, lukasz.langa
2010-12-27 14:37:53vinay.sajipsetnosy: georg.brandl, vinay.sajip, bquinlan, ncoghlan, pitrou, eric.araujo, r.david.murray, brian.curtin, lukasz.langa
messages: + msg124708
2010-12-24 20:20:31bquinlansetfiles: + logging.patch
nosy: georg.brandl, vinay.sajip, bquinlan, ncoghlan, pitrou, eric.araujo, r.david.murray, brian.curtin, lukasz.langa
messages: + msg124606
2010-12-10 12:00:19vinay.sajipsetmessages: + msg123728
2010-12-10 11:58:41vinay.sajipsetmessages: + msg123727
2010-12-07 20:42:59eric.araujosetnosy: + eric.araujo
2010-12-07 12:12:24ncoghlansetmessages: + msg123543
2010-12-07 11:40:22vinay.sajipsetmessages: + msg123542
2010-12-07 01:34:17ncoghlansettitle: test_concurrent_futures implicitly installs a logging handler on import -> Bad interaction between test_logging and test_concurrent_futures
2010-12-07 01:33:34ncoghlansetnosy: + vinay.sajip
messages: + msg123512
2010-12-06 22:30:26pitrousetmessages: + msg123507
2010-12-06 22:23:45r.david.murraysetnosy: + r.david.murray
messages: + msg123506
2010-12-06 21:12:01pitrousetmessages: + msg123505
2010-12-06 04:05:34ncoghlansetmessages: + msg123451
2010-12-05 18:16:03bquinlansetfiles: + logging.patch
keywords: + patch
messages: + msg123432
2010-12-05 12:12:19georg.brandlsetpriority: normal -> deferred blocker

messages: + msg123419
2010-12-05 08:18:34ncoghlansetnosy: + georg.brandl
title: test_concurrent_futures failure -> test_concurrent_futures implicitly installs a logging handler on import
messages: + msg123413

assignee: ncoghlan -> bquinlan
keywords: + buildbot
2010-12-04 20:27:23pitrousetassignee: bquinlan -> ncoghlan

messages: + msg123399
nosy: + ncoghlan
2010-12-04 19:47:36lukasz.langasetnosy: + lukasz.langa
messages: + msg123392
2010-12-04 19:28:46pitrousetmessages: + msg123387
title: test_concurrent_futures failure under Windows Server 2008 -> test_concurrent_futures failure
2010-12-04 13:51:11pitroucreate