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]

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.

 

[Peter Otten]

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

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

Peter

 

[Peter Otten]

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