This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging: Improve error handing in RotatingFileHandler.doRollover()
Type: behavior Stage:
Components: Library (Lib) Versions: Python 3.2, Python 3.3, Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: vinay.sajip, vstinner
Priority: normal Keywords: patch

Created on 2010-03-01 11:01 by vstinner, last changed 2022-04-11 14:56 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
logging_rotate.patch vstinner, 2010-03-01 11:01
Messages (4)
msg100252 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2010-03-01 11:01
My server is running as root and is writing logs into /var/log/nucentral.log. I tried to run it under a different user ("nucentral"), and I changed /var/log/nucentral.log file permissions.

I'm using:
   MAX_LOG_FILESIZE = 5 * 1024 * 1024
   MAX_LOG_FILES = 10   # including .log, so last file prefix is .log.9

   handler = RotatingFileHandler('/var/log/nucentral.log', 'a',
      maxBytes=MAX_LOG_FILESIZE, backupCount=(MAX_LOG_FILES - 1),
      encoding='utf8')

The problems start at the next rollover: the user is not allowed to write into /var/log, and so rename /var/log/nucentral.log to /var/log/nucentral.log.1 (and /var/log/nucentral.log.2 to /var/log/nucentral.log.3) fails. We have here a new problem: doRollover() starts by closing the log file and then rename files. If rename fails, the stream is closed and no new stream is opened. But my server catchs any exception and write them into /var/log/nucentral.log. The rename exception will be written... in the log file, but writing in a closed file raise a new exception! The log system is completly broken and go into an evil recursion loop :-)

I can fix my code responsible to log any exception to avoid the recursion, and avoid the directory permission by writing into /var/log/nucentral/. But there is still the problem of closing the stream before renaming the log files.

I propose to close the stream *after* renaming old log files. Attached patch closes the stream just before reopening it. It works correctly on Linux.

I don't know if it's possible on Windows to rename a file which is currently open :-/ Anyway, the goal is to ensure that the stream is open when exiting the doRollover() function. Another idea would be to use the following pattern:
  stream.close()
  try:
     ...
  except:
     self.stream = self._open()
     raise
  else:
     self._mode = 'w'
     self.stream = self._open()
msg100253 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2010-03-01 11:09
I forgot something: to avoid trying to file rotation at each log message, the rotation should be disabled at the first error. For RotatingFileHandler, it can be something like:
 try:
  ...
 except:
  self.maxBytes=0
  raise

For TimedRotatingFileHandler, a flag (new attribute) would be required.

I'm not sure that disabling the rotation if the first rotation failure is a good idea, but most the time if the logging system is broken, the application starts to fail randomly :-/ Anyway, the first rotation exception is still raised and so would be catched by something :-)
msg100256 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-03-01 15:34
Hi Victor,

A couple of points:

1. On Windows, you can't rename files which are open, so the strategy of closing after renaming doesn't work.

2. Using the alternative strategy (on failure, open the file with the current mode, else open with 'w') - if the exception is re-raised in doRollover, the message about to be logged is not logged (because doRollover is called before logging the message). So, nothing gets written to the log file: each attempt to emit() fails because of the exception in doRollover.

If, on the other hand, the exception is not re-raised, then the write of the logged message proceeds as expected, but the log file then grows without limit - definitely a Bad Thing as it could then interfere with normal program operation (e.g. when the disk fills up).

So, I think the better solution is for the user who has this kind of problem to subclass the handler (as it cannot do what it's meant to do, for reasons beyond its control) and to override handleError and attempt recovery based on the circumstances of the exception (for example in your case, switch the handler's base file name to some writable location).

I'm also not sure if disabling rotation on error is useful or not: the conditions causing the error might be removed externally (e.g. write protection reinstated, file locks released).

I'm not sure why, on logging errors, you would find that your application starts to fail randomly: I've tried to ensure that logging problems interfere with application operation as little as possible. Of course external factors might be affecting both application operation and logging operation, correlation != causation :-)

What do you think?
msg101229 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-03-17 15:08
Closing, as no feedback received. Please feel free to reopen when you have the answer to my question!
History
Date User Action Args
2022-04-11 14:56:58adminsetgithub: 52282
2010-03-17 15:08:57vinay.sajipsetstatus: pending -> closed
resolution: not a bug
messages: + msg101229
2010-03-01 15:34:35vinay.sajipsetstatus: open -> pending
assignee: vinay.sajip
messages: + msg100256
2010-03-01 11:39:13r.david.murraysetpriority: normal
nosy: + vinay.sajip
type: behavior
2010-03-01 11:09:35vstinnersetmessages: + msg100253
2010-03-01 11:01:59vstinnercreate