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)

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.

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.

Closed, as no further feedback received.

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

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.

@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.

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.

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.

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.

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.

ConcurrentLogHandler is for multiple *processes* writing to the same
file, not multiple threads in a single process. Python logging does not
support multiple processes writing to the same file because there is no
portable IPC locking across all platforms supported by Python.
ConcurrentLogHandler uses portalocker to achieve interprocess
synchronization, and there is no equivalent mechanism which is part of
the Python stdlib. AFAIK portalocker works on Windows and Linux - I'm
not sure about other platforms.

Python logging *does* support multiple threads in a single process
writing to the same file, which is why I asked Robert if it was
definitely a single-process environment he was working in.

Hi Vinay,

Thanks for your info. I have just shared my experience. I ran into a problem
(apperently, there is one)  and found a work-around that fits my needs.
If I find the real fix, I will surely follow up on it.

Regards,

Frans

2009/6/7 Vinay Sajip <report@bugs.python.org>

>
> Vinay Sajip <vinay_sajip@yahoo.co.uk> added the comment:
>
> ConcurrentLogHandler is for multiple *processes* writing to the same
> file, not multiple threads in a single process. Python logging does not
> support multiple processes writing to the same file because there is no
> portable IPC locking across all platforms supported by Python.
> ConcurrentLogHandler uses portalocker to achieve interprocess
> synchronization, and there is no equivalent mechanism which is part of
> the Python stdlib. AFAIK portalocker works on Windows and Linux - I'm
> not sure about other platforms.
>
> Python logging *does* support multiple threads in a single process
> writing to the same file, which is why I asked Robert if it was
> definitely a single-process environment he was working in.
>
> ----------
>
> _______________________________________
> Python tracker <report@bugs.python.org>
> <http://bugs.python.org/issue4749>
> _______________________________________
>

I have a small script that reproduces the problem.  I couldn't 
reproduce it until I added some os.system() calls in the threads that 
were logging.  Here's the output using python 2.6.1:


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


Here is the script - let me know if I'm doing things incorrectly:

import os, threading, logging, logging.handlers

class LoggerThread(threading.Thread):
    def __init__(self, numLoops):
	threading.Thread.__init__(self)
	self.numLoops = numLoops


    def run(self):
	for x in range(0, self.numLoops):
	    os.system('cd.>blah.txt')
	    os.system('del blah.txt')
	    logging.debug('This is log message ' + str(x) + ' from ' + 
self.name + ' and I think this should be a little longer, so I\'ll add 
some more data here because perhaps the size of the individual log 
message is a factor.  Who knows for sure until this simple test fails.')


if __name__=="__main__":
    logSize = 2048
    numberOfLogs = 10

    files = logging.handlers.RotatingFileHandler('logthred.log', 'a', 
logSize, numberOfLogs)
    console = logging.StreamHandler()

    # set a format
    fileFormatter = logging.Formatter('%(asctime)s %(levelname)-8s %
(thread)-4s %(message)s')
    consoleFormatter = logging.Formatter('%(asctime)s %(levelname)-8s %
(thread)-4s %(message)s')

    # tell the handler to use this format
    files.setFormatter(fileFormatter)
    console.setFormatter(consoleFormatter)

    # add the handlers to the root logger
    logging.getLogger('').addHandler(files)
    logging.getLogger('').addHandler(console)
    logging.getLogger('').setLevel(logging.DEBUG)

    numThreads = 10
    numLoops = 100

    # Create and execute threads
    for x in range(0, numThreads):
	LoggerThread(numLoops).start()

P.S. The above script and failure is running on winxp sp3.  Also, if 
you comment out the two os.system() calls, it works just fine.  They 
seem like they should be unrelated to the logging though.  You'll also 
see some errors about access to the blah.txt file which makes sense 
since multiple threads are hitting that file at the same time.  I don't 
know if this is about using os.system() itself from multiple threads 
while logging or if it's about having an error condition during the 
os.system() call on top of that.  Anyway, let me know what you think or 
if I've done something wrong, let me know how to fix it and that might 
be good documentation for others running into this problem.  Thanks.

Robert, please provide the Python version and distribution that your are
using.  This should do the trick:

import sys
print sys.version

Hi Robert,

Thanks, I have run the script, both on

=> Windows: '2.5.1 (r251:54863, Apr 18 2007, 08:51:08) [MSC v.1310 32 bit
(Intel)]'
=> And on Ubuntu: '2.5.2 (r252:60911, Oct  5 2008, 19:24:49) \n[GCC 4.3.2]'

In both cases the problem appeared almost immediately. I've zipped the
produced log file, the script used, and the console output (files attached),
so you can see for your self.
Also, on linux the logfile is cluttered with a lot of bianry 0 values. This
is consistent with what I saw with my own script.

Regards,

Frans

2009/6/8 Robert Cronk <report@bugs.python.org>

>
> Robert Cronk <cronk.r@gmail.com> added the comment:
>
> P.S. The above script and failure is running on winxp sp3.  Also, if
> you comment out the two os.system() calls, it works just fine.  They
> seem like they should be unrelated to the logging though.  You'll also
> see some errors about access to the blah.txt file which makes sense
> since multiple threads are hitting that file at the same time.  I don't
> know if this is about using os.system() itself from multiple threads
> while logging or if it's about having an error condition during the
> os.system() call on top of that.  Anyway, let me know what you think or
> if I've done something wrong, let me know how to fix it and that might
> be good documentation for others running into this problem.  Thanks.
>
> ----------
>
> _______________________________________
> Python tracker <report@bugs.python.org>
> <http://bugs.python.org/issue4749>
> _______________________________________
>

>>> import sys
>>> print sys.version
2.6.1 (r261:67517, Dec  4 2008, 16:51:00) [MSC v.1500 32 bit (Intel)]

I have seen this behavior in older versions as well.  Interesting to 
see it fail in linux as well.

I tested this against a number of different python installs that I
have laying around.  Here are the results that I found:

Releases that reproduce this bug:

Python 2.3.5 (#62, Feb  8 2005, 16:23:02) [MSC v.1200 32 bit (Intel)] on win32
Python 2.4.2 (#67, Sep 28 2005, 12:41:11) [MSC v.1310 32 bit (Intel)] on win32
Python 2.4.5 (#2, Jul 31 2008, 18:51:48) [GCC 4.2.3 (Ubuntu
4.2.3-2ubuntu7)] on linux2  (Ubuntu 8.04)
Python 2.4.6 (#2, Mar 19 2009, 10:00:53) [GCC 4.3.3] on linux2 (Ubuntu 9.04)
Python 2.5.2 (r252:60911, Feb 21 2008, 13:11:45) [MSC v.1310 32 bit
(Intel)] on win32

The following release worked fine:
Python 2.5.2 (r252:60911, Jul 31 2008, 17:28:52) [GCC 4.2.3 (Ubuntu
4.2.3-2ubuntu7)] on linux2 (Ubuntu 8.04)
Python 2.5.4 (r254:67916, Apr  4 2009, 17:55:16) [GCC 4.3.3] on linux2
(Ubuntu 9.04)
Python 2.6.2 (release26-maint, Apr 19 2009, 01:56:41) [GCC 4.3.3] on
linux2 (Ubuntu 9.04)

P.S.  Frans - It's good to get these other data points from you.  So 
this is reproducible from another person and on different versions of 
python AND on different platforms!  I wasn't expecting that at all.  
Thanks Frans.

Is there a way we can reopen this bug?  I couldn't find a way to change 
its status now that we seem to have a reproducible case.  Perhaps Vinay 
is authorized to do so.

Thanks Lowell - good information.  You have many more versions of 
Python "laying around" than I do.  ;)

I just upgraded to 2.6.2 windows from python.org and it fails as well:

Python 2.6.2 (r262:71605, Apr 14 2009, 22:40:02) [MSC v.1500 32 bit 
(Intel)] on win32

I hope Vinay can track this down in case it's a race condition that's 
just moving around between versions or track it down to something 
concrete that has actually been purposefully fixed somewhere else that 
fixes this too.  I guess we'll see.

Lowell - what's the difference between my 2.6.2 shown above and yours 
(release26-maint, Apr 19 2009)?  Yours is on ubuntu and mine is on 
windows, but I'm not familiar with the two version types (r262:71605 
vs. release26-maint).  Yours is 5 days newer - is it a patch?  What was 
changed in it that might affect this problem?  Just wondering aloud 
until Vinay can help make sense of all of this.  Thanks everyone.

I did some tests on the zip files which Frans attached to this post. The
reason you are getting errors is at least partly that you are not
following best practices in the test scripts. Specifically, the threads
are making system calls to update and delete blah.txt without handling
contention between them. Also, you are not joining on the created
threads before exiting the main thread, which means that the atexit code
will be invoked while the threads are still running. This is nothing
specifically to do with logging, except that logging registers an atexit
handler to close open files etc. So, you need to join the created threads.

I also found some mixture of tabs and spaces in the scripts Frans attached.

So, you need to test with the modified script which I am attaching here.
This script runs without problems on Ubuntu (Hardy/Python 2.5.2 built
Jul 31 2008 17:28:52 and Jaunty 2.6.2 built on Apr 19 2009 01:56:41).
There is still a problem on Windows, which appears to be related to an
error in os.rename. I am investigating this further to see if it is a
logging bug.

I didn't care about the os.system() call contention because that's what 
caused the logging problem and that blah.txt file contention should not 
cause logging to fail.

I also had the join calls originally but took them out to simplify the 
code since it seemed to run correctly either way - if this were 
production code, I'd have left them in.

The revised script works for me on windows 2.6.2 (the version I 
upgraded to) but I think it just puts locks around the problem and 
masks the true problem out.  It appears something in os.system() is 
crashing logging and that shouldn't happen.  If locks need to be 
placed, they should be placed around the problem within os.system() or 
within logging, if needed.

Please take the locks off the os.system() calls and see why logging is 
failing when those calls are made.  Remember, this is a test script I 
wrote from scratch with the express purpose of making logging fail from 
multiple threads so you could catch it in a debugger or something.  
Changing the script to make it work misses the point.

Whoops, my revised test script still had some tabs. Replacing. Further
information on Windows - you sometimes get error 32 (cannot rename file
because owned by another process) because of anti-virus or Windows
indexing software having the file open. Can you please retry on Windows
but with anti-virus software and Windows indexing temporarily turned off
during the test? (On Windows you'll have to rename "rm" to "del" in the
os.system() call.

On Ubuntu, without the locks around the os.system calls, I was not
getting any errors other than file-not-found errors on blah.txt - which
you would expect if another thread had just deleted the file. You didn't
post the errors which your test script was generating - and I assumed
you may have been referring to the file-not-founds on blah.txt.

You definitely need the join calls, as without them atexit processing in
the main thread will close the handlers when the threads are still
running. This will lead to errors like the ones you saw (I/O operation
on closed file), but this is not a bug - you definitely need to join on
all created threads before exiting the main thread - whether test or
production.

Please post the exact errors you are getting, after removing the locks
around the os.system calls. Delete all logthred.log files before the
test run, and please post the console output as Frans did. As I said in
my earlier comment - ensure that anti-virus, Windows indexing and any
other software which may open files at non-deterministic times is
disabled. If you are seeing a WindowsError with an error code of 32
(this might get lost in all the other output, but it's the first error I
found - the other messages look like they are a consequence of that
initial error).

The last sentence in my last comment got truncated  - it's getting late
here ;-)

I meant to say: If you are seeing a WindowsError with an error code of 32
(this might get lost in all the other output, but it's the first error I
found - the other messages look like they are a consequence of that
initial error), then it looks as if *something* is definitely holding
the file open and that's why logging is failing. We just need to find
out what it is, maybe you can use the Sysinternals tools from Microsoft
(e.g. procexp, handle) to see what's holding the file open.

Thanks Vinay.  I ran the newest revised script with virus protection 
turned off and got the same failures as before (see console output 
below).

If you comment out the os.system() calls, everything works just fine.  
Uncomment them and logging breaks.

The os.system() calls shouldn't break logging, especially since they 
are accessing a completely unrelated file - not the log file.

If you could go back to my original script that fails for you, you 
should be able to chase down why these unrelated os.system() calls are 
breaking logging.  Feel free to add the joins and replace the tabs if 
you want to, but don't put locks around the os.system() calls because 
that just makes the problem go away and leaves us with nothing to do.  
Does that make sense?  Regardless of what the os.system() calls are 
doing, they shouldn't break logging in any way whatsoever.  So if my 
original script breaks for you, please use that broken state to debug 
the problem and find out why an os.system() call is breaking logging.

-----------------------------------

C:\logthred>revised.py
Traceback (most recent call last):
  File "C:\Python26\lib\logging\handlers.py", line 72, in emit
    self.doRollover()
  File "C:\Python26\lib\logging\handlers.py", line 129, in doRollover
    os.rename(self.baseFilename, dfn)
WindowsError: [Error 32] The process cannot access the file because it 
is being
used by another process
2009-06-09 09:54:47,828 DEBUG    3704 This is log message 0 from thread-
00 and I
 think this should be a little longer, so I'll add some more data here 
because p
erhaps the size of the individual log message is a factor.  Who knows 
for sure u
ntil this simple test fails.
Traceback (most recent call last):
  File "C:\Python26\lib\logging\handlers.py", line 71, in emit
    if self.shouldRollover(record):
  File "C:\Python26\lib\logging\handlers.py", line 145, in 
shouldRollover
    self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
ValueError: I/O operation on closed file
2009-06-09 09:54:47,967 DEBUG    9052 This is log message 0 from thread-
01 and I
 think this should be a little longer, so I'll add some more data here 
because p
erhaps the size of the individual log message is a factor.  Who knows 
for sure u
ntil this simple test fails.
Traceback (most recent call last):
  File "C:\Python26\lib\logging\handlers.py", line 71, in emit
    if self.shouldRollover(record):
  File "C:\Python26\lib\logging\handlers.py", line 145, in 
shouldRollover
    self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
ValueError: I/O operation on closed file
2009-06-09 09:54:48,062 DEBUG    7480 This is log message 0 from thread-
02 and I
 think this should be a little longer, so I'll add some more data here 
because p
erhaps the size of the individual log message is a factor.  Who knows 
for sure u
ntil this simple test fails.
Traceback (most recent call last):
  File "C:\Python26\lib\logging\handlers.py", line 71, in emit
    if self.shouldRollover(record):
  File "C:\Python26\lib\logging\handlers.py", line 145, in 
shouldRollover
    self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
ValueError: I/O operation on closed file
.
.
.

Debugging threading problems is never as simple as it seems. I don't
believe logging is breaking because of some interaction with the system
calls - rather, the presence of the system calls is changing the
real-time characteristics of the system and exposing the failure.

This problem is not directly related to logging - for example, see

http://groups.google.com/group/comp.lang.python/browse_thread/thread/98fa9592e7c47130/d5642964c573dfc0#d5642964c573dfc0

I will look to see if I can find what the exact problem is. Did you turn
off Windows search indexing for the volume before running the test, in
addition to turning off the anti-virus? It looks as if something else is
opening the file (which, in our test, will have been very recently
written to when the error occurs) and the suspicion must fall on
anti-virus or search indexing or some other file watching software (e.g.
backup software which is configured to monitor all file changes and
refresh the backup copy in pseudo-real-time).

I'll thoroughly look through every piece of software that's running to 
see if I can turn eveything off that might be causing the problem.

Were you able to reproduce the problem with my original script?  I'm 
sure you have all of your virus/searching/etc. stuff turned off, so if 
it reproduced for you, then those things aren't the problem.

Question: If you take my original script and add joins at the end so 
it's proper and modify nothing else about it, does it show the rollover 
error?

If so, then I think that is where we need to start since you then have 
a simple test that manifests the problem without virus scanners (etc.) 
that might taint the issue.  Then you can chase this without having to 
assume what my system has running on it.

I turned off anti-virus again as well as file indexing and google 
desktop too and still got the errors when I disabled the locks around 
the os.system() calls.

Vinay - when the locks aren't around the os.system() calls, do you get 
the rotating log errors?

I'm still confused at how the os.system calls could be affecting the 
logging at all.  The os.system calls aren't touching the log files.  
Why would it cause them to fail when the os.system calls fail?  It 
seems that when the os.system calls succeed (because of the locks) then 
the logging succeeds but when the os.system calls fail (because the 
locks are disabled), then logging fails.  If, as you suggest, this is a 
race condition that is being exposed by the os.system calls failing 
because they don't have locks around them, then that would be the 
perfect situation (if you can reproduce it) to debug it.

I've just run a test several times - it's your original script with
joins added at the end. I kept the acquire_lock and release_lock calls
but made them only do anything if a constant USE_LOCK was True. I set
this to False, so that no locking is actually occurring.

My earlier tests had run with Windows indexing not turned off properly
(there's an option to turn off for all subfolders which I mistakenly
didn't select, so that I had only turned it off on the root folder).
Now, I've turned off search indexing for the entire volume, as well as
the anti-virus, and re-run the tests. I also found that the TortoiseSVN
Windows shell extension sometimes scans files if you are working inside
a directory which is part of an SVN checkout, so I was careful to work
outside any SVN tree.

I also ran SysInternals filemon. I attach the log: it appears to show
that a SHARING VIOLATION (the WindowsError 32) is occurring specifically
because of interaction with a spawned os.system child process. However,
this does not appear to be logging-specific: my conjecture is that when
the cmd.exe is spawned, it inherits file handles from the parent process
(the Python process which is doing the logging). When cmd.exe exits, it
closes all its open file handles, thereby pulling the rug out from under
the Python process.

To confirm this, I created another script, thredio.py, which does not
use logging but does the equivalent I/O operations (including using a
threading lock around them to serialise access from the threads - but
there is no locking around the os.system() calls).

Guess what - the same error occurs. Here's the extract from the console
output:

Exception in thread Thread-10:
Traceback (most recent call last):
  File "C:\Python\lib\threading.py", line 488, in __bootstrap_inner
    self.run()
  File "C:\temp\thredio.py", line 28, in run
    os.rename('logthred.log', dfn)
WindowsError: [Error 32] The process cannot access the file because it
is being used by another process

So, I submit that this is not a logging issue, and am closing this issue.

Vinay - that's great news!  Are you going to create a new bug for this issue with a proper title?  It would seem to me that the fix for this would be to put locks internal to the os.system() call around where it spawns cmd so multiple spawns don't occur simultaneously.

Is the proper procedure at this point to open a new bug with a more correct title that points back to this bug for reference?  Can you do that Vinay?  I don't know if I have the authority (nor experience with the bug tracking system) to do that.  Thanks.

The problem may occur just because of the way file handles work with
child processes. I'm not sure if it's a bug, or even if it's specific to
Python, so I'm not going to raise another issue. It's worth searching to
see if there's an existing issue about it, though.

Anyone can raise a new bug; you just log in and click on "Create New"
under "Issues" in the menu on the left of the page. I would suggest that
you research the issue first to see if it's previously been raised on
this tracker, or in c.l.py, or on the wider Internet.

I must say that Vinay's findings are most interesting.  Thanks Vinay
for tracking this down!

Just a thought, but has anybody tried this using the subprocess
module?  I've glanced through subprocess.py and it certainly does not
use os.system().  Instead it uses CreateProcess() on windows and
os.execvp*() on all other platforms.  It also appears to go to great
effort to properly deal with file handles, so I'm wondering if that
would resolve this issue.  (The current 2.6 docs, state that the
subprocess "module is preferable" over the os.system() call, and that
"All of the popen*() functions are obsolete. Use the subprocess
module.")

I'm quite curious to see if my ConcurrentLogHandler will fare any
better with this scenario.  I would really like for it to be able to
handle this scenario, since it's design goals are to be resilient to
this type of thing.  But I'm relying on the threading system and locks
too, so it's hard to say what will happen.

Robert, I agree that submitting a new bug on this would be a good idea
if none currently exists.  I also think it would be good to to put a
warning in the docs about this scenario if there is nothing that can
be done to correct the situation.  Even it if is not Python-specific
thing, I think it is good to let people know about gotchas whenever
possible.

I changed the script to use subprocess (attached file) and got the same 
rollover errors as before.  I had to change cd and del to be cd.bat and 
del.bat which contained cd %1 and del %1 respectively since it appears 
subprocess can't run internal commands like cd and del (unless you 
specify shell = True, which I thought might defeat the purpose of the 
test).

I will search around for this bug to see if it's already been entered.  
If the python developers decide not to fix this by wrapping os.system 
(and I guess subprocess.Popen too) with locks to prevent this error, 
then I agree that it should at least be well documented.

You may want to re-test with Popen(..., close_fds=True) with the latest
Python 2.6. From the latest docs:

http://docs.python.org/library/subprocess.html

"If close_fds is true, all file descriptors except 0, 1 and 2 will be
closed before the child process is executed. (Unix only). Or, on
Windows, if close_fds is true then no handles will be inherited by the
child process. Note that on Windows, you cannot set close_fds to true
and also redirect the standard handles by setting stdin, stdout or stderr."

In Python 2.5, you can't use close_fds on Windows. In the 2.5
documentation (ActivePython 2.5.2.2) the above paragraph ends with
"(Unix only)."

I found Issue1425127 which may be a different symptom of this core 
problem.  I suggested that we create a bug that documents the core 
problem here as described by Vinay in msg89174 and links to these two 
bugs (along with any others we find) as examples of the types of 
symptoms that can come from this bug.  At that point, the merits of 
working around this bug in python versus documenting the problem for 
python users to work around it can be discussed and a decision can be 
made.  Thoughts?

One more possibly related bug is issue2320 where subprocesses are 
spawned from multiple threads.  They found an interesting workaround 
that I found seems to help our problem too: "on Windows, if close_fds 
is true then no handles will be inherited by the child process."  So if 
I change the subprocess.Popen lines in my most recently uploaded script 
to:

rc = subprocess.Popen('cd.bat . > blah.txt', close_fds=True).wait()
rc = subprocess.Popen('del.bat blah.txt', close_fds=True).wait()

The rollover logging failure goes away.  Does os.system have a similar 
option?  If not, then that would mean I'd have to convert all os.system 
calls to subprocess.Popen and add the close_fds=True parameter to it.  
The problem with this is that "Note that on Windows, you cannot set 
close_fds to true and also redirect the standard handles by setting 
stdin, stdout or stderr" and I am using both stdin and stdout on my 
main subprocess.Popen call and I have a couple of os.system calls as 
well.  Thoughts?

For anyone who is interested, I did some testing with the
ConcurrentRotatingFileHandler from my ConcurrentLogHandler package (v
0.8.3). I've found that it does not fail when dropped into the
revised-logthred.py script.  However, it does spend most of the time
in what I call "degraded" mode because the file rotation fails--this
means that the log file is constantly opened and closed around each
write() call so that eventually the log file can be successfully
rotated.  This is very inefficient, but the design goal of the
ConcurrentRotatingFileHandler is to never loose log events at all
cost, whereas the RotatingFileHandler is a more general purpose
solution and can therefore adhere to more size-based file rotation,
and yields a better and more consistent performance.

What I found interesting is that the ConcurrentRotatingFileHandler
seems to be behaves the same with or without the thread locking around
the os.system() calls.  This is something that I need to look into
when I have some more time.  (I haven't actually timed or traced
anything yet, so it's hard to say for sure what's really going on; or
if something else was going on during my tests)

Robert, one alternate approach to consider given all the complexities
you have going on (by that I mean, multi-threaded process spawning
programs that you need to have the ability to redirect the
stdin/stdout streams...)  You might want to look into adding one more
process in the equation.  You could have your script start off by
launching a "central logging" socket listener (or use a system wide
listener), and then have that single process handle writing to and
rotating your log files.  Then it's just a mater of redirecting the
logging system to push the events to your logging process.  I know
this might not seem like the most appealing approach, but it may end
up being the one that requires the least amount of modifications to
your existing code... just a thought.  (Vinay, I know you've
recommended this approach before, are there any samples laying around
to help people get started with a simple central logging solution
based on (e.g. built on top of) Python's logging package?)

Lowell, there's a working sample right there in the docs:

I mentioned it in msg78619 in this issue. The link is

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

This should get anyone started for a multiprocess logging requirement.
For a single-process multi-threaded scenario, Python logging should work
out of the box except in scenarios already discussed, where child
processes contend for the files - as per thredio.py - and if one can't
avoid spawning child processes which cause contention, then the socket
logging approach with a separate process can be used.

The really annoying this about handle inheritance is that even if a 
subprocess is never referencing or using logging there can be an open 
file handle conflict due to the default inheratence.

Another tack from modifying Popen, 

I looked at the forking.py of multiprocessing and observed the 
techniques for changing the inheratance attribute of files handles 
using the _subprocess wrapper to the NT DuplicateHandle call.

Then by replacing the _open of the FileHandler to ensure handles are 
open non-inheritable I can ensure that log files are not inherited. 
This preserves the behavior of everything else. 

I attached the NT/Multiprocessing safe version of a RotatingFileHandler 
class

I dont see the resolution for this problem yet... What should I do to not have it happen?

@jpfarias: could you be more specific? Which error(s) do you have? in which scenario?

> From: João Paulo Farias <report@bugs.python.org>

> I dont see the resolution for this problem yet... What should I 
> do to not have it happen?

Don't use RotatingFileHandler in any process which spawns a subprocess. In a multiprocess situation where you want to use rotating log files, have a dedicated subprocess (which does not spawn any children) which listens for logging events on a socket and writes them to the rotated log. Have every other process use SocketHandler to log events to the aforementioned dedicated process. There is an example in the Python documentation of listening for events on a socket.

Ok.. I was hoping for a solution that did not involve running a separate process just for logging.

Gabriel: Yeah, I have a python application that uses threads and spawns processes, even tho the processes it spawns have nothing related to the log file.

Also, I noticed that I get the problem even before spawning any processes.

João Paulo Farias <jpaulofarias@gmail.com> 
added the comment:

> Ok.. I was hoping for a solution that did not involve running a 
> separate process just for logging.

It needn't *just* be for logging - as long as it doesn't spawn any child processes. And the need to run a separate process stems from the fact that there's no reliable cross-platform way (in the Python stdlib) of synchronising access to a resource (such as a file) from multiple processes.

There are other solutions, no doubt, but the separate process will probably be the quickest and easiest to implement.

> Also, I noticed that I get 
> the problem even before spawning any 
> processes.

If you're sure about this, and not running into any of the other gotchas mentioned in the thread, then please post a small script which succinctly demonstrates the problem, and I'll look at it. Numerous people have posted problem scripts in this thread (e.g. Neyro, Robert Cronk, Frans) but the problem has generally turned out to be not related to logging specifically, but more generically handle inheritance, differences/limitations in implementations of subprocess under Windows etc.

I just ran into this issue, clearly it is old and Python 2.6, but I just experienced it in a single-process linux app running on a production embedded system.  

root@at91sam9g20ek:~# python
Python 2.6.5 (r265:79063, Sep 28 2011, 11:52:59) 
[GCC 4.3.3] on linux2

The symptom is the original "ValueError: I/O operation on closed file."  I see one log file that has reached its max size and never rolls over and as a result, the app is unable to log anything. 

Has anyone since experienced related issues that could exhibit this behavior?