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 ''

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

Same one under Ubuntu:
http://www.python.org/dev/buildbot/all/builders/PPC64%20Ubuntu%203.x/builds/265/steps/test/logs/stdio

Possibly related: issue #10517.

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.

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).

What a nice mess :)  Raising priority so that this doesn't get overlooked.

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?

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

> 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?

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.

> 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?

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.

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.

Yeah, I think that comment was just a mistaken impression on my part.

Definitely something odd going on with the test interaction though.

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.

s/logger of last resort/handler of last resort/

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

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.

Fixed in r87556.