[New-bugs-announce] [issue33369] Removing Popen log files in threads is racy on Windows

[Peter Boström]

New submission from Peter Boström <peterbostrom at gmail.com>:

OS: Windows 10, version 1607 (OS Build 14393.2189)
Python --version: Python 2.7.3

Removing logfiles files just after Popen().wait() outside an open() block is racy on Windows. This seems to require multiple parallel workers to pull off, not sure where the synchronization issue lies (interpreter or os).

This report is spun off from the following pull request where we ran into the issue (we always log to log files instead of memory pipes but sometimes discard them after the worker has finished): https://github.com/google/gtest-parallel/pull/59#issuecomment-369551914

Attaching repro script, in it essentially all workers do this:

  command = ['ping', '-n', '1', '127.0.0.1']
  with open(file_name, 'w') as file_obj:
    task = subprocess.Popen(command, stdout=file_obj, stderr=file_obj)
    task.wait()

  print 'Removing %s\n' % file_name
  os.remove(file_name)

Here os.remove() fails fairly often with an exception even though there should be no handles left to the file: WindowsError: [Error 32] The process cannot access the file because it is being used by another process: '25436.log'

Run (this seems to repro pretty reliably, more than half of the time on my machine):

C:\src>del *.log

C:\src>python racy_windows.py
Logging to 24788.log
Logging to 1052.log


Logging to 32320.log
Logging to 29316.log


Removing 1052.log

Exception in thread Thread-2:
Traceback (most recent call last):
  File "C:\python_27_amd64\files\lib\threading.py", line 551, in __bootstrap_inner
    self.run()
  File "C:\python_27_amd64\files\lib\threading.py", line 504, in run
    self.__target(*self.__args, **self.__kwargs)
  File "racy_windows.py", line 19, in __call__
    os.remove(file_name)
WindowsError: [Error 32] The process cannot access the file because it is being used by another process: '1052.log'

Removing 24788.log

Exception in thread Thread-1:
Traceback (most recent call last):
  File "C:\python_27_amd64\files\lib\threading.py", line 551, in __bootstrap_inner
    self.run()
  File "C:\python_27_amd64\files\lib\threading.py", line 504, in run
    self.__target(*self.__args, **self.__kwargs)
  File "racy_windows.py", line 19, in __call__
    os.remove(file_name)
WindowsError: [Error 32] The process cannot access the file because it is being used by another process: '24788.log'

Removing 29316.log
Removing 32320.log

----------
components: Windows
files: racy_windows.py
messages: 315822
nosy: paul.moore, pbos, steve.dower, tim.golden, zach.ware
priority: normal
severity: normal
status: open
title: Removing Popen log files in threads is racy on Windows
type: behavior
versions: Python 2.7
Added file: https://bugs.python.org/file47552/racy_windows.py

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue33369>
_______________________________________