PagingIO read before PagingIO Write cause data corruption

Gavin_Ye · August 9, 2010, 2:45pm

Hi,

I am working on a encryption driver which is using mini-filter.
It encrypts in NonchaedIO or PagingIO PreWrite, and decrypts in NonchaedIO or PagingIO PostRead.

When I run a test case, I got corrupted data.
Generally, what happens is:

File is created, and data is written to the file (not paging IO)
Application try to read the data, and a Paging IO Read is issued in this process.
Cache Manager flush data to disk (Paging IO Write) – this happens after 6 minutes.

Since #1 only change end of file without flush data to disk, so #2 actually
read ZERO from disk instead of encrypted data. And then the ZERO data is decrypted by our driver, so application get wrong data.

It’s weird, I don’t know why it happens.
My question is:

Is it a windows problem?
Is there any workaround?

Following is detail information.

The test steps are:

Create C:\src and copy test files to it (100+ all kinds of files).
Create E:\enc.
Reboot. Login.
Run the test script enctest.bat.
This batch file keeps doing:
a. Copy file from c:\src to e:\enc (then the files in e:\enc should be encrypted)
b. run fc.exe to compare c:\src and e:\enc
c. If files are identical, go to #a. Otherwise stop.

When this problem happens, I notice the PagingIO Read get empty data (the read buffer is
filled with 0x0) from disk instead of encrypted data. Then our driver try to decrypt it,
and get wrong data.
So I run the test again with ProcMonitor running, and here is the result:

cmd.exe IRP_MJ_CREATE E:\enc\avg8info.id SUCCESS
Desired Access: Generic Write, Read Data/List Directory, Read Attributes, Delete,
Disposition: OverwriteIf,
Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File,
Attributes: A, ShareMode: None, AllocationSize: 0, OpenResult: Created

cmd.exe IRP_MJ_QUERY_VOLUME_INFORMATION E:\enc\avg8info.id SUCCESS
Type: QueryAttributeInformationVolume,
FileSystemAttributes: Case Preserved, Case Sensitive, Unicode, ACLs,
Compression, Named Streams, EFS, Object IDs,
Reparse Points, Sparse Files, Quotas, Transactions, 0x3c00000
MaximumComponentNameLength: 255,
FileSystemName: NTFS

cmd.exe FASTIO_QUERY_INFORMATION E:\enc\avg8info.id SUCCESS
Type: QueryBasicInformationFile,
CreationTime: 8/8/2010 1:51:22 PM,
LastAccessTime: 8/8/2010 1:51:22 PM,
LastWriteTime: 8/8/2010 1:51:22 PM,
ChangeTime: 8/8/2010 1:51:22 PM,
FileAttributes: A

cmd.exe IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
Type: SetEndOfFileInformationFile,
EndOfFile: 92

1:51:22.2261035 PM
cmd.exe IRP_MJ_WRITE E:\enc\avg8info.id SUCCESS
Offset: 0,
Length: 92,
Priority: Normal

1:51:22.2262274 PM
cmd.exe IRP_MJ_READ E:\enc\avg8info.id SUCCESS
Offset: 0,
Length: 92, I/O
Flags: Non-cached, Paging I/O, Synchronous Paging I/O,
Priority: Normal

cmd.exe IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
Type: SetBasicInformationFile,
CreationTime: 0,
LastAccessTime: 0,
LastWriteTime: 8/8/2010 12:17:17 PM,
ChangeTime: 8/8/2010 12:17:17 PM,
FileAttributes: n/a

cmd.exe IRP_MJ_CLEANUP E:\enc\avg8info.id SUCCESS

cmd.exe FASTIO_NETWORK_QUERY_OPEN E:\enc\avg8info.id SUCCESS
CreationTime: 8/8/2010 1:51:22 PM,
LastAccessTime: 8/8/2010 1:51:22 PM,
LastWriteTime: 8/8/2010 12:17:17 PM,
ChangeTime: 8/8/2010 12:17:17 PM,
AllocationSize: 96, EndOfFile: 92, FileAttributes: A

cmd.exe IRP_MJ_CREATE E:\enc\avg8info.id 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

System FASTIO_ACQUIRE_FOR_CC_FLUSH E:\enc\avg8info.id SUCCESS

1:57:03.2788028 PM
System IRP_MJ_WRITE E:\enc\avg8info.id SUCCESS
Offset: 0,
Length: 4,096,
I/O Flags: Non-cached,
Paging I/O, Synchronous Paging I/O,
Priority: Normal

System FASTIO_RELEASE_FOR_CC_FLUSH E:\enc\avg8info.id SUCCESS
cmd.exe IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
Type: SetBasicInformationFile,
CreationTime: 0,
LastAccessTime: 0, LastWriteTime: 0, ChangeTime: 0,
FileAttributes: AN

cmd.exe IRP_MJ_CLEANUP E:\enc\avg8info.id SUCCESS

cmd.exe IRP_MJ_CLOSE E:\enc\avg8info.id SUCCESS

System IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
Type: SetEndOfFileInformationFile,
EndOfFile: 92

System FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION E:\enc\avg8info.id SUCCESS
SyncType: SyncTypeOther

System FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION E:\enc\avg8info.id SUCCESS

System IRP_MJ_CLOSE E:\enc\avg8info.id SUCCESS

cmd.exe IRP_MJ_WRITE (at 1:51:22.226 PM) is not a PagingIO, so only end of file is set, but data on disk is all ZER.
But cmd.exe IRP_MJ_READ (at 1:51:22.226 PM) is not a PagingIO, and it get ZERO data.
System IRP_MJ_WRITE (at1:57:03.278 PM) is too late – 6 minutes later!

Scott_Noone_OSR · August 10, 2010, 11:10am

wrote in message news:xxxxx@ntfsd…
> Generally, what happens is:
> 1. File is created, and data is written to the file (not paging IO)
> 2. Application try to read the data, and a Paging IO Read is issued in
> this process.

Normally you shouldn’t see the read for the cached region go through to the
disk if it’s a cached I/O, it should be satisfied from the cache (and if
it’s a non-cached I/O then the file system will do a cache flush before the
non-cached read to try to guarantee coherency).

> My question is:
> 1. Is it a windows problem?

Does this happen without your filter involved? If not, then you need to do
some investigation. Get logs in the working and non-working case. Does this
happen on FAT? If so, build your own copy of FAT from the WDK and instrument
it (I recently had to add in memory write logging to FAT with a debugger
extension to extract the data in order to track down a similar issue because
DbgPrints caused the problem to go away). The issues that can arise with
encryption filters are so vast, complex, and implementation specific that
you’re going to have to get good at tracking these types of bugs down.

Good luck!

-scott

–
Scott Noone
Consulting Associate
OSR Open Systems Resources, Inc.
http://www.osronline.com

wrote in message news:xxxxx@ntfsd…
> Hi,
>
> I am working on a encryption driver which is using mini-filter.
> It encrypts in NonchaedIO or PagingIO PreWrite, and decrypts in NonchaedIO
> or PagingIO PostRead.
>
>
> When I run a test case, I got corrupted data.
> Generally, what happens is:
> 1. File is created, and data is written to the file (not paging IO)
> 2. Application try to read the data, and a Paging IO Read is issued in
> this process.
> 3. Cache Manager flush data to disk (Paging IO Write) – this happens
> after 6 minutes.
>
> Since #1 only change end of file without flush data to disk, so #2
> actually
> read ZERO from disk instead of encrypted data. And then the ZERO data is
> decrypted by our driver, so application get wrong data.
>
> It’s weird, I don’t know why it happens.
> My question is:
> 1. Is it a windows problem?
> 2. Is there any workaround?
>
>
>
> Following is detail information.
>
> The test steps are:
> 1. Create C:\src and copy test files to it (100+ all kinds of files).
> 3. Create E:\enc.
> 4. Reboot. Login.
> 5. Run the test script enctest.bat.
> This batch file keeps doing:
> a. Copy file from c:\src to e:\enc (then the files in e:\enc should be
> encrypted)
> b. run fc.exe to compare c:\src and e:\enc
> c. If files are identical, go to #a. Otherwise stop.
>
>
> When this problem happens, I notice the PagingIO Read get empty data (the
> read buffer is
> filled with 0x0) from disk instead of encrypted data. Then our driver try
> to decrypt it,
> and get wrong data.
> So I run the test again with ProcMonitor running, and here is the result:
>
> cmd.exe IRP_MJ_CREATE E:\enc\avg8info.id SUCCESS
> Desired Access: Generic Write, Read Data/List Directory, Read
> Attributes, Delete,
> Disposition: OverwriteIf,
> Options: Sequential Access, Synchronous IO Non-Alert,
> Non-Directory File,
> Attributes: A, ShareMode: None, AllocationSize: 0, OpenResult:
> Created
>
> cmd.exe IRP_MJ_QUERY_VOLUME_INFORMATION E:\enc\avg8info.id SUCCESS
> Type: QueryAttributeInformationVolume,
> FileSystemAttributes: Case Preserved, Case Sensitive, Unicode,
> ACLs,
> Compression, Named Streams, EFS, Object
> IDs,
> Reparse Points, Sparse Files, Quotas,
> Transactions, 0x3c00000
> MaximumComponentNameLength: 255,
> FileSystemName: NTFS
>
> cmd.exe FASTIO_QUERY_INFORMATION E:\enc\avg8info.id SUCCESS
> Type: QueryBasicInformationFile,
> CreationTime: 8/8/2010 1:51:22 PM,
> LastAccessTime: 8/8/2010 1:51:22 PM,
> LastWriteTime: 8/8/2010 1:51:22 PM,
> ChangeTime: 8/8/2010 1:51:22 PM,
> FileAttributes: A
>
> cmd.exe IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
> Type: SetEndOfFileInformationFile,
> EndOfFile: 92
>
> 1:51:22.2261035 PM
> cmd.exe IRP_MJ_WRITE E:\enc\avg8info.id SUCCESS
> Offset: 0,
> Length: 92,
> Priority: Normal
>
> 1:51:22.2262274 PM
> cmd.exe IRP_MJ_READ E:\enc\avg8info.id SUCCESS
> Offset: 0,
> Length: 92, I/O
> Flags: Non-cached, Paging I/O, Synchronous Paging I/O,
> Priority: Normal
>
> cmd.exe IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
> Type: SetBasicInformationFile,
> CreationTime: 0,
> LastAccessTime: 0,
> LastWriteTime: 8/8/2010 12:17:17 PM,
> ChangeTime: 8/8/2010 12:17:17 PM,
> FileAttributes: n/a
>
> cmd.exe IRP_MJ_CLEANUP E:\enc\avg8info.id SUCCESS
>
> cmd.exe FASTIO_NETWORK_QUERY_OPEN E:\enc\avg8info.id SUCCESS
> CreationTime: 8/8/2010 1:51:22 PM,
> LastAccessTime: 8/8/2010 1:51:22 PM,
> LastWriteTime: 8/8/2010 12:17:17 PM,
> ChangeTime: 8/8/2010 12:17:17 PM,
> AllocationSize: 96, EndOfFile: 92, FileAttributes: A
>
> cmd.exe IRP_MJ_CREATE E:\enc\avg8info.id 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
>
> System FASTIO_ACQUIRE_FOR_CC_FLUSH E:\enc\avg8info.id SUCCESS
>
> 1:57:03.2788028 PM
> System IRP_MJ_WRITE E:\enc\avg8info.id SUCCESS
> Offset: 0,
> Length: 4,096,
> I/O Flags: Non-cached,
> Paging I/O, Synchronous Paging I/O,
> Priority: Normal
>
> System FASTIO_RELEASE_FOR_CC_FLUSH E:\enc\avg8info.id SUCCESS
> cmd.exe IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
> Type: SetBasicInformationFile,
> CreationTime: 0,
> LastAccessTime: 0, LastWriteTime: 0, ChangeTime: 0,
> FileAttributes: AN
>
> cmd.exe IRP_MJ_CLEANUP E:\enc\avg8info.id SUCCESS
>
> cmd.exe IRP_MJ_CLOSE E:\enc\avg8info.id SUCCESS
>
> System IRP_MJ_SET_INFORMATION E:\enc\avg8info.id SUCCESS
> Type: SetEndOfFileInformationFile,
> EndOfFile: 92
>
> System FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION E:\enc\avg8info.id
> SUCCESS
> SyncType: SyncTypeOther
>
> System FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION E:\enc\avg8info.id
> SUCCESS
>
> System IRP_MJ_CLOSE E:\enc\avg8info.id SUCCESS
>
>
> cmd.exe IRP_MJ_WRITE (at 1:51:22.226 PM) is not a PagingIO, so only end of
> file is set, but data on disk is all ZER.
> But cmd.exe IRP_MJ_READ (at 1:51:22.226 PM) is not a PagingIO, and it get
> ZERO data.
> System IRP_MJ_WRITE (at1:57:03.278 PM) is too late – 6 minutes later!
>

Gavin_Ye · August 10, 2010, 6:54pm

Thanks Scott!

I also tried following tests on Windows 7, NTFS drive:

SwapBuffer sample in WDK
No our filter driver

In both tests, Process Monitor shows that Paging Read is still before Paging Write. But the data corruption doesn’t happen because neither of them modifies the data.

In our case (using our driver), although it returns wrong data in the paging read, most of time application still gets correct data. Normally, the compare error happened after the batch file ran an hour or more (but one time I saw it only after 10 minutes).

I haven’t tried it on FAT, so I don’t know if it happens on FAT.

Scott_Noone_OSR · August 11, 2010, 9:41am

wrote in message news:xxxxx@ntfsd…
>In both tests, Process Monitor shows that Paging Read is still before
>Paging Write. But the data corruption doesn’t happen >because neither of
>them modifies the data.

I’m a bit confused now (which admittedly isn’t hard to do :)). If the
application does a cached write and then a read for the same region causes a
paging I/O instead of a cache hit how is it not getting the wrong data? The
“right” data is in the cache at this point so I’d expect to see the cached
I/O serviced directly out of the cache.

-scott

–
Scott Noone
Consulting Associate
OSR Open Systems Resources, Inc.
http://www.osronline.com

wrote in message news:xxxxx@ntfsd…
> Thanks Scott!
>
> I also tried following tests on Windows 7, NTFS drive:
> 1. SwapBuffer sample in WDK
> 2. No our filter driver
>
> In both tests, Process Monitor shows that Paging Read is still before
> Paging Write. But the data corruption doesn’t happen because neither of
> them modifies the data.
>
> In our case (using our driver), although it returns wrong data in the
> paging read, most of time application still gets correct data. Normally,
> the compare error happened after the batch file ran an hour or more (but
> one time I saw it only after 10 minutes).
>
> I haven’t tried it on FAT, so I don’t know if it happens on FAT.
>
>
>