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?

Insist

Answer 1

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

Pleat

While I can't confirm this, it makes perfect sense. I suspected that early on but eliminated it due to the access showing that it was coming from my EXE and not a virus scanner. I wasn't aware that the virus scanner could inject itself in my process. – Insist

also note, thats a POS virus scanner if it needs to read the file 11 times. – Insist

How does the virus scanner's read originate from ConsoleApplication1.vshost.exe though? – Springtime

Any process with sufficient permissions can inject code into another process's address space and execute it. Look up CreateRemoteThread in MSDN for a good example of one way this can be done. – Pleat

It performed 11 read operations on the file.. This doesn't say it read the file 11 times. (It could be the first 11 bytes; one after another) – Cleodell