How to debug filesystem "access denied" errors on win32?

Question

Hi all

I'm having a hell of a time with our build scripts right now: I'm using Waf to drive our build process, and everything works great, except on Windows, where I am getting intermitent errors during builds.

The errors are always basically "access denied" errors of one form or another, relating to temporary files I have created during the build process to enable some tool to run and do it's job. For example, before running NSIS to generate an executable installer, I have to "stage" all the required files to the build directory and run the command from there. Sometimes things work as expected, but other times I get an error reported about one of the files I have copied for example:

File: failed opening file "Platform\\Win32\\lxml-2.2.1-py2.6-win32.egg

I've spent an age trying to work out what the issue is but its really difficult because the issue is intermittent. The last thing I tried is using procmon to monitor filesystem access to try to trace what was causing the access error: I know the file is there so it must be that something has the file open. I'm including the relevant output below because I can't see what is wrong: Python seems to be closing the file before NSIS want's to open it but then NSIS is failing. Can anyone shed any light on this? This issue is not isolated to this situation but also to other cases where I spawn subprocesses to work with files I have copied to build directories...

7:35:15.9704427 PM  python.exe 4968 QueryOpen ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg FAST IO DISALLOWED 
7:35:15.9707497 PM  python.exe 4968 CreateFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
7:35:15.9708634 PM  python.exe 4968 QueryBasicInformationFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS CreationTime: 7/25/2009 7:35:11 PM, LastAccessTime: 7/25/2009 7:35:11 PM, LastWriteTime: 7/25/2009 7:35:11 PM, ChangeTime: 7/25/2009 7:35:11 PM, FileAttributes: A
7:35:15.9709271 PM  python.exe 4968 CloseFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS 
7:35:15.9785180 PM  python.exe 4968 CreateFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS Desired Access: Write Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
7:35:15.9786119 PM  python.exe 4968 SetBasicInformationFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS CreationTime: 1/1/1601 1:00:00 AM, LastAccessTime: 1/1/1601 1:00:00 AM, LastWriteTime: 1/1/1601 1:00:00 AM, ChangeTime: 1/1/1601 1:00:00 AM, FileAttributes: AN
7:35:15.9787155 PM  python.exe 4968 CloseFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS 
7:35:15.9789401 PM  python.exe 4968 QueryOpen ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg FAST IO DISALLOWED 
7:35:15.9790309 PM  python.exe 4968 CreateFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
7:35:15.9790700 PM  python.exe 4968 QueryBasicInformationFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS CreationTime: 7/25/2009 7:35:11 PM, LastAccessTime: 7/25/2009 7:35:11 PM, LastWriteTime: 7/25/2009 7:35:11 PM, ChangeTime: 7/25/2009 7:35:12 PM, FileAttributes: A
7:35:15.9790952 PM  python.exe 4968 CloseFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS 
7:35:15.9792809 PM  python.exe 4968 CreateFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS Desired Access: Write Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
7:35:15.9793270 PM  python.exe 4968 SetBasicInformationFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS CreationTime: 1/1/1601 1:00:00 AM, LastAccessTime: 1/1/1601 1:00:00 AM, LastWriteTime: 1/1/1601 1:00:00 AM, ChangeTime: 1/1/1601 1:00:00 AM, FileAttributes: AN
7:35:15.9794041 PM  python.exe 4968 CloseFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS 
7:35:16.3508170 PM  makensis.exe 3296 CreateFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SHARING VIOLATION Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, AllocationSize: n/a
7:35:16.3557763 PM  python.exe 4968 QueryOpen ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg FAST IO DISALLOWED 
7:35:16.3558928 PM  python.exe 4968 CreateFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
7:35:16.3559461 PM  python.exe 4968 QueryNetworkOpenInformationFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS CreationTime: 7/25/2009 7:35:11 PM, LastAccessTime: 7/25/2009 7:35:11 PM, LastWriteTime: 7/25/2009 7:35:11 PM, ChangeTime: 7/25/2009 7:35:12 PM, AllocationSize: 1/1/1601 1:00:00 AM, EndOfFile: 1/1/1601 1:00:00 AM, FileAttributes: A
7:35:16.3560121 PM  python.exe 4968 CloseFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS 
7:35:16.3562048 PM  python.exe 4968 CreateFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SHARING VIOLATION Desired Access: Read Attributes, Delete, Disposition: Open, Options: Non-Directory File, Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
7:35:21.9320579 PM  python.exe 3160 CloseFile ..\Path\To\Build\lxml-2.2.1-py2.6-win32.egg SUCCESS

Answer 1

In that trace, the file is already there when the trace starts. So something else may have kept it open (e.g. a virus scanner, or the indexing service).