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: python logger RotatingFileHandler can't wrap log file and blows with traceback
Type: behavior Stage: resolved
Components: Library (Lib), Windows Versions: Python 3.3
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: bialix, paul.moore, r.david.murray, steve.dower, tim.golden, vinay.sajip, zach.ware
Priority: normal Keywords:

Created on 2015-09-15 08:57 by bialix, last changed 2022-04-11 14:58 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
test-issue25121.py bialix, 2015-09-15 14:59
Messages (9)
msg250747 - (view) Author: Alexander Belchenko (bialix) Date: 2015-09-15 08:57
We're using standard logging library for logs. On machine of my colleague there is constantly traceback like this:

[11:21:29] <altuhkov> PermissionError: [WinError 32] The process cannot access the file because it is
being used by another process: 'C:\\Users\\Andrew\\Desktop\\server\\logs\\2015-0
9-09_10-44-03\\2015-09-09_10-44-04-middleman-684.log.1'
Logged from file middleman.py, line 379
Traceback (most recent call last):
  File "c:\python33\lib\logging\handlers.py", line 73, in emit
    self.doRollover()
  File "c:\python33\lib\logging\handlers.py", line 176, in doRollover
    self.rotate(self.baseFilename, dfn)
  File "c:\python33\lib\logging\handlers.py", line 116, in rotate
    os.rename(source, dest)

middleman.py, line 379 is simple call to logger.debug:

    self.logger.debug('node %s is already processing, packet %s postponed', node_id, packet_no) 

It's strange that another log file with different basename in the same logs directory is wrapping without problems.

Anyway, my complain is about traceback. I don't think it's good behavior that my application crashes because logging library can't wrap file. The problem for me - I have no idea how to catch and ignore such problem, because it's in the logging internals.
msg250749 - (view) Author: Alexander Belchenko (bialix) Date: 2015-09-15 09:04
PermissionError mentions file name "C:\\Users\\Andrew\\Desktop\\server\\logs\\2015-0
9-09_10-44-03\\2015-09-09_10-44-04-middleman-684.log.1" - but this file does not exist in log directory. There is only "C:\\Users\\Andrew\\Desktop\\server\\logs\\2015-0
9-09_10-44-03\\2015-09-09_10-44-04-middleman-684.log" so I think it's about unable to rename.

Python 3.3.5 64 bits
Windows 7 64 bits.
msg250767 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-09-15 13:27
Are you using a rotating file handler for the logger?  You should take a look at some of the other issues in this tracker about RotatingFileHandler and Windows.

I will be interested in Vinay's answer to your question about the exception being allowed to bubble up.  I suspect it has to do with the fact that you would be completely losing your logging data if it were ignored.
msg250769 - (view) Author: Alexander Belchenko (bialix) Date: 2015-09-15 13:30
Yes. it's rotating file handler.

I'll try to recreate this issue with simpler test application, so I can provide something as example.
msg250771 - (view) Author: Alexander Belchenko (bialix) Date: 2015-09-15 14:15
I have suspicion about this issue.

In my application tornado framework is used. I setup logger for my own code, but use the same logger for tornado, so all messages from tornado itself go into the same log file.

As I said earlier it's strange but one log file works as expected. This log file is not used by tornado.
msg250772 - (view) Author: Alexander Belchenko (bialix) Date: 2015-09-15 14:28
Update to previous comment. I use the same settings for tornado logger (e.g. filename).

    logger = logging.getLogger('tornado')
    setup_logger(logger, log_config)

So I have 2 loggers in one application which are trying to write to the same file. I guess it's out of supported use cases?
msg250773 - (view) Author: Alexander Belchenko (bialix) Date: 2015-09-15 14:31
According to documentation on RotateFileHandler

"When this file is filled, it is closed and renamed to app.log.1, and if files app.log.1, app.log.2, etc. exist, then they are renamed to app.log.2, app.log.3 etc. respectively."

But we have 2 loggers which holds open file inside the same process. And while one handler is trying to close and rename file, another handler (tornado, which writes something to log only when there are errors actually) is holding file open.
msg250776 - (view) Author: Alexander Belchenko (bialix) Date: 2015-09-15 14:59
Based on my last assumption I'm able to reproduce this issue with simple test attached. If I comment out the line

  setup_logger(loggerB)

The everything works OK.

Once this line in - it's traceback.

I guess it's fair to say the bug in my code and one never should use this approach. On Linux it never traceback but I think it may have other unvisible issues.

I expect you mark this as "won't fix" but maybe you want to look at it.
msg250795 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-09-15 18:54
Vinay has closed other issues reporting this two-open-files problem in the past (which was why i recommended you read through some of them :).  Windows causes problems when there are two open file handles and a rename is attempted, so no, that is not a supported configuration for the logging module.

So I'm going to close it as not a bug.  If you can propose a way to make things work better, by all means open an enhancement issue.
History
Date User Action Args
2022-04-11 14:58:21adminsetgithub: 69308
2015-09-15 18:54:13r.david.murraysetstatus: open -> closed
type: crash -> behavior
messages: + msg250795

resolution: not a bug
stage: resolved
2015-09-15 14:59:10bialixsetfiles: + test-issue25121.py

messages: + msg250776
2015-09-15 14:31:53bialixsetmessages: + msg250773
2015-09-15 14:28:19bialixsetmessages: + msg250772
2015-09-15 14:15:42bialixsetmessages: + msg250771
2015-09-15 13:33:25bialixsettitle: python logger can't wrap log file and blows with traceback -> python logger RotatingFileHandler can't wrap log file and blows with traceback
2015-09-15 13:30:22bialixsetmessages: + msg250769
2015-09-15 13:27:38r.david.murraysetnosy: + r.david.murray, vinay.sajip
messages: + msg250767
2015-09-15 09:04:45bialixsetmessages: + msg250749
2015-09-15 08:57:34bialixcreate