Writing to a FileStream behaves strangely, as observed by process monitor

Question

I'm using FileStream to write to a file, and watching the underlying system calls using Process Monitor. I'm having trouble with some file locking issues in a production deployment, so I'm looking at the details closely.

This sample code:

        using (FileStream fs = new FileStream("c:\\temp\\test.txt", FileMode.Create, FileAccess.Write, FileShare.Read))
        {
            fs.Write(new byte[] { 1, 2, 3, 4, 5 }, 0, 5);
            fs.Close();
        }

Causes the following systems calls:

9:27:09.4561092 AM  ConsoleApplication1.vshost.exe 2320 CreateFile C:\temp\test.txt SUCCESS Desired Access: Generic Read/Write, Disposition: OverwriteIf, Options: Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: 0, OpenResult: Overwritten
9:27:12.2217409 AM  ConsoleApplication1.vshost.exe 2320 WriteFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2219901 AM  ConsoleApplication1.vshost.exe 2320 CloseFile C:\temp\test.txt SUCCESS 
9:27:12.2234484 AM  ConsoleApplication1.vshost.exe 2320 CreateFile C:\temp\test.txt SUCCESS Desired Access: Generic Read, Write Attributes, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Complete If Oplocked, Random Access, Attributes: N, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
9:27:12.2248664 AM  ConsoleApplication1.vshost.exe 2320 QueryBasicInformationFile C:\temp\test.txt SUCCESS CreationTime: 10/29/2008 9:04:14 AM, LastAccessTime: 10/29/2008 9:27:12 AM, LastWriteTime: 10/29/2008 9:27:12 AM, ChangeTime: 10/29/2008 9:27:12 AM, FileAttributes: A
9:27:12.2250075 AM  ConsoleApplication1.vshost.exe 2320 SetBasicInformationFile C:\temp\test.txt SUCCESS CreationTime: -1, LastAccessTime: -1, LastWriteTime: -1, ChangeTime: -1, FileAttributes: n/a
9:27:12.2255889 AM  ConsoleApplication1.vshost.exe 2320 QueryStandardInformationFile C:\temp\test.txt SUCCESS AllocationSize: 8, EndOfFile: 5, NumberOfLinks: 1, DeletePending: False, Directory: False
9:27:12.2257571 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2259825 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2261588 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2265161 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 2
9:27:12.2268237 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2271332 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2272841 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2274779 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2276249 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2278766 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2282577 AM  ConsoleApplication1.vshost.exe 2320 ReadFile C:\temp\test.txt SUCCESS Offset: 0, Length: 5
9:27:12.2284476 AM  ConsoleApplication1.vshost.exe 2320 QueryFileInternalInformationFile C:\temp\test.txt SUCCESS IndexNumber: 0x2d000000016b88
9:27:12.2286183 AM  ConsoleApplication1.vshost.exe 2320 CloseFile C:\temp\test.txt SUCCESS 
9:27:12.2288759 AM  ConsoleApplication1.vshost.exe 2320 CreateFile C:\temp\test.txt SUCCESS Desired Access: Read Attributes, Write Attributes, Disposition: Open, Options: , Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
9:27:12.2305722 AM  ConsoleApplication1.vshost.exe 2320 QueryBasicInformationFile C:\temp\test.txt SUCCESS CreationTime: 10/29/2008 9:04:14 AM, LastAccessTime: 10/29/2008 9:27:12 AM, LastWriteTime: 10/29/2008 9:27:12 AM, ChangeTime: 10/29/2008 9:27:12 AM, FileAttributes: A
9:27:12.2307379 AM  ConsoleApplication1.vshost.exe 2320 CloseFile C:\temp\test.txt SUCCESS

The first three IO calls are expected (create, write, close), but the the process goes on to read the file a dozen more times and repeatedly open and close it.

I've now observed this behavior on Win XP SP2, and Win 2003 x64. However, my Windows Vista machine at home behaves as expected (just the first three lines).

Any clues on why this is happening on non-Vista runtimes?

Answer 1

One possibility is that you have a virus scanner installed that injects itself into each running process?