logging.shutdow n() 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 RotatingFileHan dler. 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\e xperimental\Py Logging\t_xb.py ", line 63, in ?
shutdown()
File "C:\Python23\li b\logging\__ini t__.py", line 1195, in shutdown
h.flush()
File "C:\Python23\li b\logging\__ini t__.py", line 661, in flush
self.stream.flu sh()
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.handler s import RotatingFileHan dler

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

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

global handler

logger = getLogger(compo nent)

if handler:
handler.flush()
handler.close()
logger.removeHa ndler(handler)

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

handler = RotatingFileHan dler(filename, mode, maxBytes, backupCount)

handler.setLeve l(DEBUG)

logger.addHandl er(handler)

return logger

handler = None

for i in range(20):
log = logger_for('sup plier')
log.error('test ing 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 RotatingFileHan dler. The following script
illustrates a puzzling problem. What is wrong with this script? if handler:
handler.flush()
handler.close()
logger.removeHa ndler(handler)

The handler is stored in the logging._handle rs 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.removeHa ndler(handler)
handler.flush()
handler.close()
del logging._handle rs[handler]

so that shutdown() cannot touch closed handlers, or

(3) don't close handlers manually

if handler:
logger.removeHa ndler(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\li b\site-packages\Python win\pywin\frame work\scriptutil s.py",
line 310, in RunScript
exec codeObject in __main__.__dict __
File "E:\$PROJECTS\e xperimental\Py Logging\t_xc.py ", line 61, in ?
log.error('test ing Python logging module')
File "C:\Python23\li b\logging\__ini t__.py", line 923, in error
apply(self._log , (ERROR, msg, args), kwargs)
File "C:\Python23\li b\logging\__ini t__.py", line 994, in _log
self.handle(rec ord)
File "C:\Python23\li b\logging\__ini t__.py", line 1004, in handle
self.callHandle rs(record)
File "C:\Python23\li b\logging\__ini t__.py", line 1037, in callHandlers
hdlr.handle(rec ord)
File "C:\Python23\li b\logging\__ini t__.py", line 592, in handle
self.emit(recor d)
File "C:\Python23\li b\logging\handl ers.py", line 105, in emit
self.doRollover ()
File "C:\Python23\li b\logging\handl ers.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.handler s import RotatingFileHan dler

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

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

global handler

logger = getLogger(compo nent)

if handler:
## handler.flush()
## handler.close()
logger.removeHa ndler(handler)

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

handler = RotatingFileHan dler(filename, mode, maxBytes, backupCount)

handler.setLeve l(DEBUG)

logger.addHandl er(handler)

return logger

handler = None

for i in range(20):
log = logger_for('sup plier')
log.error('test ing Python logging module')

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

[j vickroy]

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

That behavior appears to be responsible for the logging.shutdow n() failure.
"j vickroy" <ji*********@no aa.gov> wrote in message
news:bp******** **@boulder.noaa .gov...

Hello,

I'm trying to understand the behavior of the Python 2.3 logging module (MS
Windows 2k) with regard to RotatingFileHan dler. 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\e xperimental\Py Logging\t_xb.py ", line 63, in ?
shutdown()
File "C:\Python23\li b\logging\__ini t__.py", line 1195, in shutdown
h.flush()
File "C:\Python23\li b\logging\__ini t__.py", line 661, in flush
self.stream.flu sh()
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.handler s import RotatingFileHan dler

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

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

global handler

logger = getLogger(compo nent)

if handler:
handler.flush()
handler.close()
logger.removeHa ndler(handler)

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

handler = RotatingFileHan dler(filename, mode, maxBytes, backupCount)

handler.setLeve l(DEBUG)

logger.addHandl er(handler)

return logger

handler = None

for i in range(20):
log = logger_for('sup plier')
log.error('test ing Python logging module')

shutdown()
END FILE _______________ _______________ ___________

[Peter Otten]

j vickroy wrote:

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

Traceback (most recent call last):
File
"C:\Python23\li b\site-packages\Python win\pywin\frame work\scriptutil s.py",
line 310, in RunScript
exec codeObject in __main__.__dict __
File "E:\$PROJECTS\e xperimental\Py Logging\t_xc.py ", line 61, in ?
log.error('test ing Python logging module')
File "C:\Python23\li b\logging\__ini t__.py", line 923, in error
apply(self._log , (ERROR, msg, args), kwargs)
File "C:\Python23\li b\logging\__ini t__.py", line 994, in _log
self.handle(rec ord)
File "C:\Python23\li b\logging\__ini t__.py", line 1004, in handle
self.callHandle rs(record)
File "C:\Python23\li b\logging\__ini t__.py", line 1037, in callHandlers
hdlr.handle(rec ord)
File "C:\Python23\li b\logging\__ini t__.py", line 592, in handle
self.emit(recor d)
File "C:\Python23\li b\logging\handl ers.py", line 105, in emit
self.doRollover ()
File "C:\Python23\li b\logging\handl ers.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]

j vickroy wrote:

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

That behavior appears to be responsible for the logging.shutdow n()
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