logging error with RotatingFileHandler

Discussion in 'Python' started by flupke, Jun 25, 2006.

  1. flupke

    flupke Guest

    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
     
    flupke, Jun 25, 2006
    #1
    1. Advertising

  2. flupke

    Vinay Sajip Guest

    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
     
    Vinay Sajip, Jun 27, 2006
    #2
    1. Advertising

  3. flupke

    flupke Guest

    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
     
    flupke, Jun 28, 2006
    #3
  4. flupke

    Vinay Sajip Guest

    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
     
    Vinay Sajip, Jun 29, 2006
    #4
  5. small inaccuracy in the logging module documentation (Python LibraryReference)

    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
     
    =?windows-1250?Q?Petr_Jake=9A?=, Jun 29, 2006
    #5
  6. flupke

    flupke Guest

    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, Jun 30, 2006
    #6
  7. flupke

    flupke Guest

    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
     
    flupke, Jun 30, 2006
    #7
  8. flupke

    Vinay Sajip Guest

    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
     
    Vinay Sajip, Jul 2, 2006
    #8
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Rob Cranfill
    Replies:
    12
    Views:
    7,047
    Vinay Sajip
    Mar 20, 2005
  2. Roopesh

    RotatingFileHandler Error

    Roopesh, Dec 29, 2006, in forum: Python
    Replies:
    0
    Views:
    595
    Roopesh
    Dec 29, 2006
  3. Replies:
    4
    Views:
    486
    Vinay Sajip
    May 10, 2007
  4. Gabriel Genellina

    Re: RotatingFileHandler - ShouldRollover error

    Gabriel Genellina, Apr 20, 2008, in forum: Python
    Replies:
    0
    Views:
    450
    Gabriel Genellina
    Apr 20, 2008
  5. jordilin
    Replies:
    2
    Views:
    1,201
    Vinay Sajip
    Dec 22, 2009
Loading...

Share This Page