logging error with RotatingFileHandler

[flupke]

Hi,


i'm getting errors with the log module concerning RotatingFileHan dler.
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\li b\logging\handl ers.py", line 71, in emit
if self.shouldRoll over(record):
File "C:\Python24\li b\logging\handl ers.py", line 150, in shouldRollover
self.stream.see k(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\li b\logging\handl ers.py", line 72, in emit
self.doRollover ()
File "C:\Python24\li b\logging\handl ers.py", line 134, in doRollover
self.handleErro r(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.in i"
Then in the init function of the class
# load logger
logging.config. fileConfig(LOGF ILE)
self.log = logging.getLogg er('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,han d02

[formatters]
keys=form01,for m02

[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=databa se
handlers=hand01 ,hand02
channel=log03
parent=(root2

[handler_hand01]
class=StreamHan dler
level=DEBUG
formatter=form0 1
args=(sys.stdou t,)
stream=sys.stdo ut

[handler_hand02]
class=handlers. RotatingFileHan dler
level=NOTSET
formatter=form0 1
filename=stats. log
mode=a
maxsize=500000
backcount=9
args=('stats.lo g', 'a', 900000, 5)

[formatter_form0 1]
format=%(asctim e)s %(levelname)s %(module)s %(lineno)d %(message)s
datefmt=

[formatter_form0 2]
format=%(asctim e)s %(levelname)s %(module)s %(lineno)d %(message)s
datefmt=

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

[Vinay Sajip]

Re: logging error with RotatingFileHan dler

flupke wrote:
[color=blue]
> File "C:\Python24\li b\logging\handl ers.py", line 134, in doRollover
> self.handleErro r(record)
> NameError: global name 'record' is not defined[/color]

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]

Re: logging error with RotatingFileHan dler

Vinay Sajip wrote:[color=blue]
> flupke wrote:
>
>[color=green]
>> File "C:\Python24\li b\logging\handl ers.py", line 134, in doRollover
>> self.handleErro r(record)
>>NameError: global name 'record' is not defined[/color]
>
>
> 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
>[/color]

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.in i"
logging.config. fileConfig(LOGF ILE)

class TypeA(object):
def __init__(self):
#logging.config .fileConfig(LOG FILE)
self.log = logging.getLogg er('logfile')
self.dolog("Sta rting the program")

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

class TypeB(TypeA):
def __init__(self):
super(TypeB,sel f).__init__()
# put this line in comment to prevent the error
logging.config. fileConfig(LOGF ILE)
#self.log = logging.getLogg er('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 RotatingFileHan dler functionallity" )

It seemed as if the "logging.config .fileConfig(LOG FILE)" 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]

Re: logging error with RotatingFileHan dler

flupke wrote:
[color=blue]
> 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?[/color]

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("log conf.ini")
logging.config. fileConfig("log conf.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š]

small inaccuracy in the logging module documentation (Python LibraryReferenc e)

Hi,

I have found some inaccuracy in the Python Library Reference
6.29.5.4 TimedRotatingFi leHandler
(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+minu tes" or "date+hours " or "date".

Regards
Petr Jakes

[flupke]

Re: logging error with RotatingFileHan dler

Vinay Sajip schreef:[color=blue]
> flupke wrote:
>[color=green]
>> 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?[/color]
>
> 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("log conf.ini")
> logging.config. fileConfig("log conf.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
>[/color]

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(sel f.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\\pr oj1\\src\\proj1 .log'
Traceback (most recent call last):
File "C:\Python24\li b\logging\handl ers.py", line 72, in emit
self.doRollover ()
File "C:\Python24\li b\logging\handl ers.py", line 141, in doRollover
self.handleErro r(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_exi tfuncs:
Traceback (most recent call last):
File "C:\Python24\li b\atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "C:\Python24\li b\logging\__ini t__.py", line 1333, in shutdown
h.close()
File "C:\Python24\li b\logging\__ini t__.py", line 772, in close
StreamHandler.c lose(self)
File "C:\Python24\li b\logging\__ini t__.py", line 674, in close
del _handlers[self]
KeyError: <logging.handle rs.RotatingFile Handler instance at 0x01E098A0>
Error in sys.exitfunc:
Traceback (most recent call last):
File "C:\Python24\li b\atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "C:\Python24\li b\logging\__ini t__.py", line 1333, in shutdown
h.close()
File "C:\Python24\li b\logging\__ini t__.py", line 772, in close
StreamHandler.c lose(self)
File "C:\Python24\li b\logging\__ini t__.py", line 674, in close
del _handlers[self]
KeyError: <logging.handle rs.RotatingFile Handler instance at 0x01E098A0>

Regards
Benedict

[flupke]

Re: logging error with RotatingFileHan dler

flupke schreef:
<snip>[color=blue]
> 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(sel f.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\\pr oj1\\src\\proj1 .log'
> Traceback (most recent call last):
> File "C:\Python24\li b\logging\handl ers.py", line 72, in emit
> self.doRollover ()
> File "C:\Python24\li b\logging\handl ers.py", line 141, in doRollover
> self.handleErro r(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_exi tfuncs:
> Traceback (most recent call last):
> File "C:\Python24\li b\atexit.py", line 24, in _run_exitfuncs
> func(*targs, **kargs)
> File "C:\Python24\li b\logging\__ini t__.py", line 1333, in shutdown
> h.close()
> File "C:\Python24\li b\logging\__ini t__.py", line 772, in close
> StreamHandler.c lose(self)
> File "C:\Python24\li b\logging\__ini t__.py", line 674, in close
> del _handlers[self]
> KeyError: <logging.handle rs.RotatingFile Handler instance at 0x01E098A0>
> Error in sys.exitfunc:
> Traceback (most recent call last):
> File "C:\Python24\li b\atexit.py", line 24, in _run_exitfuncs
> func(*targs, **kargs)
> File "C:\Python24\li b\logging\__ini t__.py", line 1333, in shutdown
> h.close()
> File "C:\Python24\li b\logging\__ini t__.py", line 772, in close
> StreamHandler.c lose(self)
> File "C:\Python24\li b\logging\__ini t__.py", line 674, in close
> del _handlers[self]
> KeyError: <logging.handle rs.RotatingFile Handler instance at 0x01E098A0>
>
> Regards
> Benedict[/color]

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

1. in the function doRollover of the class RotatingFileHan dler

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(sel f.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 BaseRotatingHan dler.
Change this:
if self.shouldRoll over(record):
self.doRollover ()
by:
if self.shouldRoll over(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.re move(self)
finally:
_releaseLock()

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

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

Regards,
Benedict Verheyen

[Vinay Sajip]

Re: logging error with RotatingFileHan dler


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