The logging module has a bug that tries to call `flush' on a closed 
file handle (sys.std[out|err] to be specific). This bug was introduced 
by ConsoleHandler as defined in http://code.activestate.com/
recipes/576819/

The fix is simple: change definition of StreamHandler.flush in logging/
__init__.py to:

  def flush(self):
      if self.stream and hasattr(self.stream, 'flush') and not 
self.stream.closed:
          logging.StreamHandler.flush()

BTW, this only happens when running the tests via py.test - http://
pytest.org ... perhaps threading/multiprocess issue.

Can you submit a short script which demonstrates the bug? Your fix is
unfortunately not suitable to use as-is, since the StreamHandler
operates on file-like objects, and these are not guaranteed to have the
"closed" attribute.

I have attached a script that repros this bug. Run it using py.test 
(instructions inside the file).

Workaround is by uncommenting the last few lines ('flush' method).

Note: It appears that py.test assigns a temporary file to sys.std[out|
err].

Perhaps it's a py.test issue. Have you tried with unittest and nose?
Remember, py.test has had little love for a while and so perhaps has a
few rougher edges (though I hear in the blogosphere that the project may
be rejuvenated shortly).

Perhaps there is an issue with py.test.

My understanding is that: if the logging module is designed to let 
users implement their own custom handlers (like I did with 
ConsoleHandler), is it not expected that they may do whatever they want 
with it including closing the file (in this case - sys.stdout is a 
temporary file that is obviously closed at one stage)? Shouldn't the 
logging module be reliable in such cases?

I will point holger (author of py.test) to this issue in case if he has 
any comments.

Anyways, this is a very low-prio bug for me .. especially when there is 
a workaround.

> Shouldn't the logging module be reliable in such cases?

It tries to be, but it's neither omnipotent nor omniscient. It doesn't 
expect streams which it's using to be closed out from under it.

See my comments about your ConsoleHandler recipe(s) on issue6345. Sorry 
if it seems I'm trying to rain on your parade - I'm just calling it as 
I see it.

I think the issue is unrelated to py.test - it just presents a use case
as it wants to run 1000's of tests and capture stdout/stderr per each
test function, cannot guess about a test's logging-usage yet wants to
minimize memory/resource usage and close any temporary files it opens.  

Anyway, a standalone minimal example involving the issue is this:

import logging
import StringIO
stream = StringIO.StringIO()
logging.basicConfig(stream=stream)
stream.close() # to free memory/release resources

At exit logging's shutdown() will try to flush/close resulting in an
exception.  Is it a problem to have the logging module be a bit more
defensive and only try a flush/close if the stream isn't already closed?

> Is it a problem to have the logging module be a bit more defensive and
> only try a flush/close if the stream isn't already closed?

Not particularly, but it would be better if the following approach were
taken:

import logging
import StringIO
stream = StringIO.StringIO()
h = logging.StreamHandler(stream)
r = logging.getLogger()
r.addHandler(h)
#Do your testing work
r.removeHandler(h)
h.close() # closes underlying stream, also removes logging refs to h

It should be understood that if a stream is passed to a StreamHandler,
the ownership of that stream is passed as well, so closing the handler
rather than the underlying stream is the right thing to do. ISTM this is
good practice in general and not exclusive to logging.

To recap the use case: stdout is redirected during a test function run
which might trigger arbitrary usage of logging-functionality.  Not
closing the temporary file would mean that there could be as many open
files as there are test functions - or one needs to rely on garbage
collection for closing the resource - this is generally considered bad
practise.  So I consider it best practise to do resource cleanup
immediately and close the temp file.  

Note that the test tool *does not touch the logging module at all*, and
it has no way to mandate the usage of the logging module like you suggest.

On Thu, 09 Jul 2009 06:48:28 -0700, Vinay Sajip <report@bugs.python.org>  
wrote:

> It should be understood that if a stream is passed to a StreamHandler,
> the ownership of that stream is passed as well, so closing the handler
> rather than the underlying stream is the right thing to do. ISTM this is
> good practice in general and not exclusive to logging.

However, sys.stdout|err can be assigned to some thing else (eg: py.test  
assigning it to an open file object) .. in which case it is legitimate to  
handle (close) such objects (handles) by who created it (py.test).

> However, sys.stdout|err can be assigned to some thing else
> (eg: py.test assigning it to an open file object) .. in which case it 
> is legitimate to handle (close) such objects (handles) by who
> created it (py.test).

@Sridhar: I disagree. Creation is not ownership. Clearly ownership is
*initially* with the creator, but when a stream is used to initialise a
StreamHandler, ownership of the stream passes to the StreamHandler.

@Holger: I am not asking that py.test be specially modified to cater for
use of a logging module it knows nothing about. But your example showed
logging calls; I indicated what changes were needed to that sample to
interoperate with logging. So if that was a part of the test cases, then
the design of test cases which use logging (and not py.test itself, if
it doesn't invoke logging directly) needs to consider the interaction
between each test case, logging and py.test. And it is not solely the
responsibility of py.test to minimise resource usage during test runs;
part of this is also the responsibility of the test case design, which
surely is why test frameworks have the concepts of setUp and tearDown.

Your example calls logging.basicConfig passing a stream, and the stream
is then immediately closed. If the test case had involved threads which
did logging, for example, how could you guarantee that a call on the
stream (other than flush) would never happen after the call to close the
stream? Would I then have to ensure not only that flush was defensively
programmed, but write as well? It seems like a can of worms to me,
because of the propensity of this kind of approach to mask logic errors.
I'm not saying you never have to resort to defensive programming - just
that errors shouldn't pass silently where this is avoidable. The design
of StreamHandler is predicated on it owning the stream (for example, it
takes care to serialise access to the stream with locks, to allow
thread-safe operation). This would be pointless if other code could
arbitrarily operate on the stream without worrying about thread-safety.

I also pointed out numerous flaws in Sridhar's reasoning both in this
issue and in issue6435 (not py.test related) and in my view, he needs to
look more closely at the logging package and the included functionality,
and if necessary the core's regression test module, test_logging.py, to
see what sorts of issues crop up. For example, I pointed out in msg90148
that file-like objects are not guaranteed to have a "closed" attribute,
to which he has not responded. I would appeal for more attention to detail.

And just in case it may seem otherwise, I'll state explicitly that I am
not trying to be difficult. Similar issues have arisen during the
initial development of test_logging.py. 

I will update the documentation for StreamHandler, FileHandler etc. to
highlight the issue of ownership of the stream, as perhaps it's not
clear enough. Sorry if this post seems a little long-winded.

On Thu, 09 Jul 2009 16:43:49 -0700, Vinay Sajip <report@bugs.python.org>
wrote:

> Vinay Sajip <vinay_sajip@yahoo.co.uk> added the comment:
>
>> However, sys.stdout|err can be assigned to some thing else
>> (eg: py.test assigning it to an open file object) .. in which case it
>> is legitimate to handle (close) such objects (handles) by who
>> created it (py.test).
> @Sridhar: I disagree. Creation is not ownership. Clearly ownership is
> *initially* with the creator, but when a stream is used to initialise a
> StreamHandler, ownership of the stream passes to the StreamHandler.

Are you suggesting that the ownership of `sys.stderr` belongs to the
logging module once logging.basicConfig (that initializes a StreamHandler
with stderr) is called? That no other module/library is to close
sys.stderr even though they created it (sys.__stderr__ being the backup)?

StreamHandler can take ownership of an arbitrary stream (say, created by
the caller) passed to it, but assuming ownership of a standard stream,
that are free to be overridden by a library (such as py.test), is rather
bizarre.

> I pointed out in msg90148
> that file-like objects are not guaranteed to have a "closed" attribute,
> to which he has not responded.

If this bug is acknowledged as a problem, then coming up with a fix is a  
different issue. I don't know how to detect whether a stream is closed or  
not .. especially when you say that not all file-like objects have a  
'closed' attribute (BTW, which doesn't?), but this is the only solution I  
know currently:

     ...
     # some streams, such as sys.stdout|err, cannot be owned by  
StreamHandler
     # they might have been closed by whoever customized it.
     closed = hasattr(self.stream, 'closed') and self.stream.closed
     if self.stream and hasattr(self.stream, 'flush') and not closed:
         self.stream.flush()
     ...

-srid

> Are you suggesting that the ownership of `sys.stderr` belongs to the
> logging module once logging.basicConfig (that initializes a 
> StreamHandler with stderr) is called?
> That no other module/library is to close sys.stderr even though they
> created it (sys.__stderr__ being the backup)?

> StreamHandler can take ownership of an arbitrary stream (say, created
> by the caller) passed to it, but assuming ownership of a
> standard stream, that are free to be overridden by a library (such as
> py.test), is rather bizarre.

Actually, it's not bizarre at all. Are you saying it's OK for multiple
threads in a program to write to sys.stderr, whenever they want, without
restriction, even if the end result is end-user visible output which is
gibberish (for example data from two logical streams interspersed
randomly)? Just because it's a "standard" stream? 

Also, perhaps you haven't noticed that StreamHandler has no way of
knowing whether the stream it was passed was a standard stream or not.
Logging may make certain hasattr-type checks e.g. for presence of
"flush" or "close", but it can't expect to not have ownership of the
stream, even for a standard stream.

I advise you to do the following: refactor your test cases to include
the explicit handler-adding code in your setup (instead of basicConfig),
and the handler-removing and closing code in your teardown.

def setUp(self):
  self.hdlr = logging.StreamHandler(stream)
  someLogger.addHandler(h)

def tearDown(self):
    someLogger.removeHandler(self.hdlr)
    self.hdlr.close()

where I have given someLogger module scope in the above snippet, you may
of course make it a testcase attribute too. I've used a unittest-style
of setUp/tearDown, I assume py.test is similar.

No changes to py.test are required. What happens if you do this?

Actually py.test catches stdout separately for setup and for the test
code.  Moreover, functional or integration test code (py.test is not
only for unittests) can easily trigger some implicit logging-module
usage which cannot eaysily be factored into a testcase-setup method, i
am afraid.