logging error with RotatingFileHandler

[flupke]

Hi,
i'm getting errors with the log module concerning RotatingFileHandler.
I'm using Python 2.4.3 on Windows XP SP2. This used to work in previous
python versions but since i upgraded to 2.4.3 i get these errors:

Traceback (most recent call last):
File "C:\Python24\lib\logging\handlers.py", line 71, in emit
if self.shouldRollover(record):
File "C:\Python24\lib\logging\handlers.py", line 150, in shouldRollover
self.stream.seek(0, 2) #due to non-posix-compliant Windows feature
ValueError: I/O operation on closed file
2006-06-25 10:35:07,171 INFO firebird 210 Starting up the database
Traceback (most recent call last):
File "C:\Python24\lib\logging\handlers.py", line 72, in emit
self.doRollover()
File "C:\Python24\lib\logging\handlers.py", line 134, in doRollover
self.handleError(record)
NameError: global name 'record' is not defined

I use the logging module by loading a config file:
import logging
import logging.config
LOGFILE = r"logconf.ini"
Then in the init function of the class
# load logger
logging.config.fileConfig(LOGFILE)
self.log = logging.getLogger('stats')

If i have a main class and a class deriving from it, i let the main
class instantiate the class by issueing the commands like above and then
get automatically get access to it in the deriving classes.

If i remove the logfile, it all works until it has to rollover.

My config.ini file contains this info:

[loggers]
keys=root,stats,database

[handlers]
keys=hand01,hand02

[formatters]
keys=form01,form02

[logger_root]
level=NOTSET
handlers=hand01
qualname=(root) # note - this is used in non-root loggers
propagate=1 # note - this is used in non-root loggers
channel=
parent=

[logger_stats]
level=DEBUG
propagate=0
qualname=stats
handlers=hand01,hand02
channel=log02
parent=(root)

[logger_database]
level=DEBUG
propagate=0
qualname=database
handlers=hand01,hand02
channel=log03
parent=(root2

[handler_hand01]
class=StreamHandler
level=DEBUG
formatter=form01
args=(sys.stdout,)
stream=sys.stdout

[handler_hand02]
class=handlers.RotatingFileHandler
level=NOTSET
formatter=form01
filename=stats.log
mode=a
maxsize=500000
backcount=9
args=('stats.log', 'a', 900000, 5)

[formatter_form01]
format=%(asctime)s %(levelname)s %(module)s %(lineno)d %(message)s
datefmt=

[formatter_form02]
format=%(asctime)s %(levelname)s %(module)s %(lineno)d %(message)s
datefmt=

Any idea on why this suddenly doesn't work anymore?
Thanks

[Vinay Sajip]

flupke wrote:

File "C:\Python24\lib\logging\handlers.py", line 134, in doRollover
self.handleError(record)
NameError: global name 'record' is not defined

There's a bug in doRollover's exception handling, which is masking the
true error - which is most probably an exception being thrown in
os.rename.

I'll look at fixing this bug asap. Most likely, it'll be done by let
the exception propagate up from doRollover to its caller.

Regards,

Vinay Sajip

[flupke]

Vinay Sajip wrote:

flupke wrote:

File "C:\Python24\lib\logging\handlers.py", line 134, in doRollover
self.handleError(record)
NameError: global name 'record' is not defined

There's a bug in doRollover's exception handling, which is masking the
true error - which is most probably an exception being thrown in
os.rename.

I'll look at fixing this bug asap. Most likely, it'll be done by let
the exception propagate up from doRollover to its caller.

Regards,

Vinay Sajip

OK Vinjay,

thanks for the info.
If this bug is fixed, where will i find a fixed version and how do i
install it?
Also, more important to me, what am i doing wrong to get this error
message in the first place?

I could reproduce the error with this program:

import logging
import logging.config

LOGFILE = r"logconf.ini"
logging.config.fileConfig(LOGFILE)

class TypeA(object):
def __init__(self):
#logging.config.fileConfig(LOGFILE)
self.log = logging.getLogger('logfile')
self.dolog("Starting the program")

def dolog(self,text):
self.log.debug(text)

class TypeB(TypeA):
def __init__(self):
super(TypeB,self).__init__()
# put this line in comment to prevent the error
logging.config.fileConfig(LOGFILE)
#self.log = logging.getLogger('logfile')
self.log.debug("Starting class B")

for nr_of_lognr in range(0,2000):
b = TypeB()
b.dolog("This is a test to see if logging works and more
specifically the RotatingFileHandler functionallity")

It seemed as if the "logging.config.fileConfig(LOGFILE)" line in Type B
is to blame. I changed the code of my big program to reflect this change
yet i still get this error.

I didn't get this with an earlier version of python.

Regards,
Benedict

[Vinay Sajip]

flupke wrote:

If this bug is fixed, where will i find a fixed version and how do i
install it?
Also, more important to me, what am i doing wrong to get this error
message in the first place?

You're not doing anything particularly wrong, though it's not exactly
good practice to call fileConfig lots of times. (It's really meant for
one-off configuration, not incremental configuration.)

I get an error with just the following script typed in at the
interactive prompt:

import logging.config
logging.config.fileConfig("logconf.ini")
logging.config.fileConfig("logconf.ini")

So, I will investigate, and when I check in a fix to the Python
Subversion repository, I will post a message to this thread.

Regards,

Vinay Sajip

[Petr Jakeš]

Hi,

I have found some inaccuracy in the Python Library Reference
6.29.5.4 TimedRotatingFileHandler
(http://docs.python.org/lib/node349.html)

1)
it is not really obvious from the documentation the "when" value has
to be in the format "w0", "w1" ... "w6" if "Type of interval" is
defined as a "week day"

2)
next the documentation says:
"If backupCount is non-zero, the system will save old log files by
appending the extensions ".1", ".2" etc., to the filename"

This is not really true, in this case.
The extension is (depending on the "when" value): "timestamp" or
"date+hour+minutes" or "date+hours" or "date".

Regards
Petr Jakes

[flupke]

Vinay Sajip schreef:

flupke wrote:

If this bug is fixed, where will i find a fixed version and how do i
install it?
Also, more important to me, what am i doing wrong to get this error
message in the first place?

You're not doing anything particularly wrong, though it's not exactly
good practice to call fileConfig lots of times. (It's really meant for
one-off configuration, not incremental configuration.)

I get an error with just the following script typed in at the
interactive prompt:

import logging.config
logging.config.fileConfig("logconf.ini")
logging.config.fileConfig("logconf.ini")

So, I will investigate, and when I check in a fix to the Python
Subversion repository, I will post a message to this thread.

Regards,

Vinay Sajip

Hi Vinay,

thanks for the info.

I tried to change the handlers.py file.
First, i changed some code in doRollover.

if os.path.exists(dfn):
os.remove(dfn)
try:
#os.rename(self.baseFilename, dfn)

-> The rename fails for some reason.

I tried with the move function of shutil
shutil.move(self.baseFilename, dfn)

This partially works: the file is now rotated but i still get an error:
The error that i get is this:
Error [Errno 13] Permission denied: 'E:\\python\\proj1\\src\\proj1.log'
Traceback (most recent call last):
File "C:\Python24\lib\logging\handlers.py", line 72, in emit
self.doRollover()
File "C:\Python24\lib\logging\handlers.py", line 141, in doRollover
self.handleError(record)
NameError: global name 'record' is not defined

The last part of the error shows that the part where the exception is
caugth is also not working correctly as the "record" isn't know.

When i close my program, i get this error as well:

Error in atexit._run_exitfuncs:
Traceback (most recent call last):
File "C:\Python24\lib\atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "C:\Python24\lib\logging\__init__.py", line 1333, in shutdown
h.close()
File "C:\Python24\lib\logging\__init__.py", line 772, in close
StreamHandler.close(self)
File "C:\Python24\lib\logging\__init__.py", line 674, in close
del _handlers[self]
KeyError: <logging.handlers.RotatingFileHandler instance at 0x01E098A0>
Error in sys.exitfunc:
Traceback (most recent call last):
File "C:\Python24\lib\atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "C:\Python24\lib\logging\__init__.py", line 1333, in shutdown
h.close()
File "C:\Python24\lib\logging\__init__.py", line 772, in close
StreamHandler.close(self)
File "C:\Python24\lib\logging\__init__.py", line 674, in close
del _handlers[self]
KeyError: <logging.handlers.RotatingFileHandler instance at 0x01E098A0>

Regards
Benedict

[flupke]

flupke schreef:
<snip>

Hi Vinay,

thanks for the info.

I tried to change the handlers.py file.
First, i changed some code in doRollover.

if os.path.exists(dfn):
os.remove(dfn)
try:
#os.rename(self.baseFilename, dfn)

-> The rename fails for some reason.

I tried with the move function of shutil
shutil.move(self.baseFilename, dfn)

This partially works: the file is now rotated but i still get an error:
The error that i get is this:
Error [Errno 13] Permission denied: 'E:\\python\\proj1\\src\\proj1.log'
Traceback (most recent call last):
File "C:\Python24\lib\logging\handlers.py", line 72, in emit
self.doRollover()
File "C:\Python24\lib\logging\handlers.py", line 141, in doRollover
self.handleError(record)
NameError: global name 'record' is not defined

The last part of the error shows that the part where the exception is
caugth is also not working correctly as the "record" isn't know.

When i close my program, i get this error as well:

Error in atexit._run_exitfuncs:
Traceback (most recent call last):
File "C:\Python24\lib\atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "C:\Python24\lib\logging\__init__.py", line 1333, in shutdown
h.close()
File "C:\Python24\lib\logging\__init__.py", line 772, in close
StreamHandler.close(self)
File "C:\Python24\lib\logging\__init__.py", line 674, in close
del _handlers[self]
KeyError: <logging.handlers.RotatingFileHandler instance at 0x01E098A0>
Error in sys.exitfunc:
Traceback (most recent call last):
File "C:\Python24\lib\atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "C:\Python24\lib\logging\__init__.py", line 1333, in shutdown
h.close()
File "C:\Python24\lib\logging\__init__.py", line 772, in close
StreamHandler.close(self)
File "C:\Python24\lib\logging\__init__.py", line 674, in close
del _handlers[self]
KeyError: <logging.handlers.RotatingFileHandler instance at 0x01E098A0>

Regards
Benedict

I was able to solve the errors (i think):

1. in the function doRollover of the class RotatingFileHandler

if os.path.exists(dfn):
os.remove(dfn)
try:
os.rename(self.baseFilename, dfn)

I added this instead of the rename function:
import shutil
shutil.copy(self.baseFilename, dfn)

If this code works ok, then the "import shutil" should be placed at the
top of the file for performance reasons.
The logic of the copy is that a few statements later, the self.stream
var is set to a new file again so it doesn't need to be deleted. At
least it seems to work here. I will need to test further.
Weird thing is, the stream is closed and yet you get this error when you
use rename:
[Errno 13] Permission denied

2. in the same function, when an error occurred, the record var wasn't
found.
This can be solved by changing the code of emit in BaseRotatingHandler.
Change this:
if self.shouldRollover(record):
self.doRollover()
by:
if self.shouldRollover(record):
self.doRollover(record)

3. The last error (error when closing the program) can be solved by
editing the __init__.py, close(self) function.
Change this:
_acquireLock()
try: #unlikely to raise an exception, but you never know...
del _handlers[self]
_handlerList.remove(self)
finally:
_releaseLock()

by:
_acquireLock()
try: #unlikely to raise an exception, but you never know...
#del _handlers[self]
if ( _handlers.has_key(self) ): del _handlers[self]
#if ( self in _handlerList ): _handlerList.remove(self)
_handlerList.remove(self)
finally:
_releaseLock()

It might even be better to change the _handlerList.remove(self)
statement by this statement:
if ( self in _handlerList ): _handlerList.remove(self)

Regards,
Benedict Verheyen

[Vinay Sajip]

flupke wrote:

-The rename fails for some reason.

I would dig a little deeper to find out what the reason is. After all,
on the face of it, there's no obvious reason it should fail. The
"permission denied" indicates perhaps that some other process or thread
is keeping that file open?

I've fixed (AFAICT) both the crash at shutdown and the buggy exception
handling, in the Python subversion repository. You can download the
latest from here and try it.

http://svn.python.org/view/python/trunk/Lib/logging/

Regards,

Vinay Sajip