Issue with RotatingFileHandler logging handler on Windows

[mramahi77]

BPO	4749
Nosy	@vsajip
Files	rothandlerbug.py: Sample file. Please run several times loggertest.zip: script and configuration file unnamed logthred.py: Script that reproduces logging failure with multiple threads. unnamed unnamed logthred-windows.zip logthread-ubuntu.zip revised-logthred.py python-logging-capture.log: Filemon log during test run with logging script. thredio.py: Script which behaves like revised-logthred.py but doesn't use logging python-io-capture.log: Filemon log during test run with non-logging script. subprclg.py: Using subprocess.Popen instead of os.system - still fails. NTSafeLogging.py: NT RotatingFileHandler that ensures log file handles cannot be inherited

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2009-06-09.23:37:10.558>
created_at = <Date 2008-12-26.12:46:45.328>
labels = ['invalid', 'type-bug', 'library']
title = 'Issue with RotatingFileHandler logging handler on Windows'
updated_at = <Date 2013-08-14.20:15:09.636>
user = 'https://bugs.python.org/mramahi77'

bugs.python.org fields:

activity = <Date 2013-08-14.20:15:09.636>
actor = 'piotr.dobrogost'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2009-06-09.23:37:10.558>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2008-12-26.12:46:45.328>
creator = 'mramahi77'
dependencies = []
files = ['12449', '13315', '14219', '14226', '14227', '14228', '14229', '14230', '14241', '14247', '14248', '14249', '14260', '14420']
hgrepos = []
issue_num = 4749
keywords = []
message_count = 48.0
messages = ['78293', '78562', '78619', '80287', '83512', '83666', '83682', '88206', '88218', '88219', '89028', '89031', '89049', '89091', '89092', '89093', '89095', '89103', '89109', '89110', '89113', '89114', '89122', '89124', '89126', '89127', '89128', '89150', '89151', '89155', '89172', '89174', '89180', '89184', '89201', '89210', '89212', '89215', '89218', '89264', '89265', '89994', '101778', '101819', '101822', '101823', '101827', '163403']
nosy_count = 12.0
nosy_names = ['vinay.sajip', 'ggenellina', 'fossilet', 'mramahi77', 'lowell87', 'neyro', 'rcronk', 'Frans', 'eantelman', 'jpfarias', 'piotr.dobrogost', 'Thom.Nichols']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = None
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue4749'
versions = ['Python 2.6']

[mramahi77]

It seems that RotatingFileHandler is experiencing an issue when
attempting to rotate log files under Windows. The following errors are
received:

Traceback (most recent call last):
  File "C:\Python25\lib\logging\handlers.py", line 73, in emit
    if self.shouldRollover(record):
  File "C:\Python25\lib\logging\handlers.py", line 147, in 
shouldRollover
    self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
ValueError: I/O operation on closed file
Traceback (most recent call last):
  File "C:\Python25\lib\logging\handlers.py", line 73, in emit
    if self.shouldRollover(record):

I tried the code on Python 2.5.2 and 2.5.4 under Windows XP SP 2, with
the same results. To reproduce run the attached scripts few times. The
first time the handlers attempt to rotate the log files the error
message above is received.

In addition to crashing the application, log files are getting lost as
a result, which is a serious issue.

I have seen few complaints about this issue, but tickets were closed
without a real resolution to the issue (unless I missed something)

[lowell87]

I've ran into the same problem before. I've found that due to
differences between the way Unix and Windows handles files (inodes vs
file handles), this problem is more apparent on Windows, but it isn't
handled 100% correctly on Unix systems either.

I think the root of the problem is that there is nothing in the code to
handle multiple concurrent processes writing to a single log file; and
I'm not sure there is a simple fix for this. I tried several easy
solutions to this problem by retrying failed file renames and re-opening
closed files, but I ultimately discovered all all such approaches are
inadequate and can actually result in losing old log files too (in the
worse-case scenario).

I final got frustrated enough to just take the time to write my own. It
is based on the built-in one and aims to be a "drop-in" replacement. I
use file locking to safely write to a single log file from multiple
python processes concurrently. If you would like to give it a try, it
is located here:
http://pypi.python.org/pypi/ConcurrentLogHandler

I agree that it would be nice for the built in logging handlers to do
this for you, but in the mean time this may be option for you.

[vsajip]

Can you (Mohammad) say which specific tickets raised the same issue? I
downloaded and ran your script (Windows XP Pro, ActivePython 2.5.2.2)
and had no problems. I created a .bat file with 100 invocations of the
.py file.

Lowell Alleman refers to concurrent use of a single log file by multiple
processes - this is not supported as there is no cross-platform method
of handling multiple process contention for a file. Lowell's handler
uses a portalocker module which is for NT or posix only - if this works
for you, then great.

The preferred way of dealing with logging to a single file from multiple
processes is to use a SocketHandler from the processes, and a separate
socket receiver application which receives the events and logs to file.
An example is in the docs:

http://docs.python.org/library/logging.html#sending-and-receiving-logging-events-across-a-network

I'll change the status of this issue to Pending while I wait for info on
other tickets about this - but multiple process support for any logging
to file (whether rotating or not) is not supported and won't be until
there is a cross-platform mechanism for file locking in the stdlib.

N.B. re your script - logging.shutdown() need not be called by your
script, as logging registers an atexit handler to do this automatically.

[vsajip]

Closed, as no further feedback received.

[neyro]

I have the same problem with a program I'm writing.
The attached script is made using parts of it's code.
The logger is set up using a configuration file.

By the way, the error is:

Traceback (most recent call last):
  File "C:\Python26\lib\logging\handlers.py", line 74, in emit
    if self.shouldRollover(record):
  File "C:\Python26\lib\logging\handlers.py", line 146, in shouldRollover
    self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
ValueError: I/O operation on closed file

[vsajip]

Neyro, your problem is caused by having two handlers (a FileHandler and
a RotatingFileHandler) pointing to the same file. Because of this,
rollover fails (the file is still open because there is a handle open
to it from the FileHandler).

If you remove the FileHandler from the config file and re-run, things
appear to work as expected.

[neyro]

@vsajip

thank you very much for correcting me.
I always thought that since I was not using that FileHandler it didn't
count, as if the handler was not created.
Now I see that there are no reasons for the config loader to ignore it,
especially since it is declared in the [handlers] section.

Thanks again.

[rcronk]

I have had this problem with 2.6.1 on windows from multiple _threads_
instead of multiple processes. Is that not supported either? If not,
what is the workaround for logging from multiple threads? Shouldn't it
be easy to use a semaphore within the logging code to make it thread
safe at least? I have had this problem on multiple PC's with multiple
versions of python, and multiple versions of windows.

[vsajip]

This exact problem? Single process, multiple threads, one single handler
for a given file? Can you post an example which demonstrates your issue?

Multiple threads *are* supported by the logging package, as mentioned in
the documentation. If you can post a an example here, I'll take a look
at it.

[rcronk]

I will go through the code and make sure I am not mistaken, but I do
believe I have a single process, multiple threads, and only one handler
for this file and I'm getting the same types of error messages shown on
this page. I'm probably doing something wrong. I'll post what I find
soon.

[Frans]

I ran into the same problem with RotatingFileHandler from a
multithreaded daemon under Ubuntu. I Googled around and found the
ConcurrentLogHandler on pypi
(http://pypi.python.org/pypi/ConcurrentLogHandler). It solved the problem.