logging.shutdown() ValueError: I/O operation on closed file

[j vickroy]

Hello,

I'm trying to understand the behavior of the Python 2.3 logging module (MS
Windows 2k) with regard to RotatingFileHandler. The following script
illustrates a puzzling problem. What is wrong with this script?

Thanks,

-- jv

BEGIN FILE _________________________________________
'''
This script terminates as follows:

Traceback (most recent call last):
File "D:\$PROJECTS\experimental\Py Logging\t_xb.py", line 63, in ?
shutdown()
File "C:\Python23\lib\logging\__init__.py", line 1195, in shutdown
h.flush()
File "C:\Python23\lib\logging\__init__.py", line 661, in flush
self.stream.flush()
ValueError: I/O operation on closed file

What is wrong with it?
'''

from logging import getLogger, Formatter, shutdown, DEBUG, INFO, WARNING,
ERROR, CRITICAL
from logging.handlers import RotatingFileHandler

def logger_for(component):
'''
RETURNS a logger for the specified component.

SIDE-EFFECTS
(re)assigns the logger handler
'''

global handler

logger = getLogger(component)

if handler:
handler.flush()
handler.close()
logger.removeHandler(handler)

# In normal, operational mode, the following parameters:
filename = '%s.log'%component
mode = 'a'
maxBytes = 100
backupCount = 5
# would be user-configurable "on the fly" hence the reason for this
function.

handler = RotatingFileHandler(filename, mode, maxBytes, backupCount)

handler.setLevel(DEBUG)

logger.addHandler(handler)

return logger

handler = None

for i in range(20):
log = logger_for('supplier')
log.error('testing Python logging module')

shutdown()
END FILE _________________________________________

[Peter Otten]

j vickroy wrote:

> I'm trying to understand the behavior of the Python 2.3 logging module (MS
> Windows 2k) with regard to RotatingFileHandler. The following script
> illustrates a puzzling problem. What is wrong with this script?

> if handler:
> handler.flush()
> handler.close()
> logger.removeHandler(handler)

The handler is stored in the logging._handlers dictionary in order to close
it when shutdown() is called. But you already did close it manually.
I think you have three options to fix your script.

(1) Don't call shutdown() at all and manually close the last handler
instead.

(2) Change the above to

if handler:
logger.removeHandler(handler)
handler.flush()
handler.close()
del logging._handlers[handler]

so that shutdown() cannot touch closed handlers, or

(3) don't close handlers manually

if handler:
logger.removeHandler(handler)

so that shutdown() gets a still open handler as expected. I would go with
the latter, as it does not rely on implementation details.

(all untested, use at your own risk)

Peter

[j vickroy]

Here is the result of not closing a handler manually -- Peter's suggestion
(3)

Traceback (most recent call last):
File

"C:\Python23\lib\site-packages\Pythonwin\pywin\framework\scriptutils.py",
line 310, in RunScript
exec codeObject in __main__.__dict__
File "E:\$PROJECTS\experimental\Py Logging\t_xc.py", line 61, in ?

log.error('testing Python logging module')

File "C:\Python23\lib\logging\__init__.py", line 923, in error
apply(self._log, (ERROR, msg, args), kwargs)
File "C:\Python23\lib\logging\__init__.py", line 994, in _log
self.handle(record)
File "C:\Python23\lib\logging\__init__.py", line 1004, in handle
self.callHandlers(record)
File "C:\Python23\lib\logging\__init__.py", line 1037, in callHandlers
hdlr.handle(record)
File "C:\Python23\lib\logging\__init__.py", line 592, in handle
self.emit(record)
File "C:\Python23\lib\logging\handlers.py", line 105, in emit
self.doRollover()
File "C:\Python23\lib\logging\handlers.py", line 90, in doRollover
os.rename(self.baseFilename, dfn)
OSError: [Errno 13] Permission denied

and here is the script that generated the above behavior:

begin -------------------------------------------------

from logging import getLogger, Formatter, shutdown, DEBUG, INFO, WARNING,
ERROR, CRITICAL
from logging.handlers import RotatingFileHandler

def logger_for(component):
'''
RETURNS a logger for the specified component.

SIDE-EFFECTS
(re)assigns the logger handler
'''

global handler

logger = getLogger(component)

if handler:
## handler.flush()
## handler.close()
logger.removeHandler(handler)

# In normal, operational mode, the following parameters:
filename = '%s.log'%component
mode = 'a'
maxBytes = 100
backupCount = 5
# would be user-configurable "on the fly" hence the reason for this
function.

handler = RotatingFileHandler(filename, mode, maxBytes, backupCount)

handler.setLevel(DEBUG)

logger.addHandler(handler)

return logger

handler = None

for i in range(20):
log = logger_for('supplier')
log.error('testing Python logging module')

shutdown()
end -----------------------------------------

[j vickroy]

As a follow-up question, why is a handle object not removed from
logging._handlers when its (i.e., handle) close() procedure is applied?

That behavior appears to be responsible for the logging.shutdown() failure.

"j vickroy" <jim.v...@noaa.gov> wrote in message
news:bp0vaq$7lc$1...@boulder.noaa.gov...

[Peter Otten]

j vickroy wrote:

Works here. Consider switching to an OS where you can rename an open file...
Well, you read my discalimer :-)

Peter

[Peter Otten]

j vickroy wrote:

> As a follow-up question, why is a handle object not removed from
> logging._handlers when its (i.e., handle) close() procedure is applied?
>
> That behavior appears to be responsible for the logging.shutdown()
> failure.

Seems that the author did not consider the use case of consecutively using
different handlers operating on the same file set - I've not yet made up my
mind, if you are misusing the logging system or if that's a bug.

Anyway, as of 2.3.2 the package has still __status__ = "beta", so patches
might be welcome.

Peter