Bugcheck 0x24 FileObject->PrivateCacheMap NULL

NTFSD
1

Hello,

There are xp sp2 laptops that crash with bugcheck 0x24. The details follow:

The crash occurs in CcCopyRead because FileObject->PrivateCacheMap for a FileObject 0x897b67a8 is NULL.
The cache manager is not expecting FileObject->PrivateCacheMap to be NULL when in CcCopyRead.

NTFS_FILE_SYSTEM (24)
If you see NtfsExceptionFilter on the stack then the 2nd and 3rd
parameters are the exception record and context record. Do a .cxr
on the 3rd parameter and then kb to obtain a more informative stack
trace.
Arguments:
Arg1: 001902fe
Arg2: a73c1714
Arg3: a73c1410
Arg4: 8056804d

Debugging Details:

EXCEPTION_RECORD: a73c1714 -- (.exr 0xffffffffa73c1714)
ExceptionAddress: 8056804d (nt!CcCopyRead+0x00000047)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000000
Parameter[1]: 00000002
Attempt to read from address 00000002

CONTEXT: a73c1410 -- (.cxr 0xffffffffa73c1410)
eax=897b67a8 ebx=89251aa0 ecx=00000001 edx=89176148 esi=00000000 edi=00000000
eip=8056804d esp=a73c17dc ebp=a73c1858 iopl=0 nv up ei pl zr na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010246
nt!CcCopyRead+0x47:
8056804d f6460202 test byte ptr [esi+2],2 ds:0023:00000002=?? <-- esi is assigned FO->PrivateCacheObject
Resetting default scope

PROCESS_NAME: OUTLOOK.EXE

LAST_CONTROL_TRANSFER: from b9dd2ad5 to 8056804d

STACK_TEXT:
a73c1858 b9dd2ad5 897b67a8 a73c18a0 00000001 nt!CcCopyRead+0x47
a73c188c b9dbf20b 89795630 89033f90 e3d19d90 Ntfs!NtfsPrepareToShrinkFileSize+0xa3
a73c1970 b9dbeb6b 89795630 89033f90 8915d008 Ntfs!NtfsSetEndOfFileInfo+0x144
a73c19e0 b9d96698 89795630 8915d008 8915d008 Ntfs!NtfsCommonSetInformation+0x477
a73c1a48 804ef163 89c23020 8915d008 8915d174 Ntfs!NtfsFsdSetInformation+0xa3
a73c1a58 b9e6bf45 8915d174 8a3722f0 8915d008 nt!IopfCallDriver+0x31
a73c1a6c 804ef163 89c247d0 e28dc668 00000000 sr!SrSetInformation+0x179
a73c1a7c b9e3f4fa 8923e7f8 a73c1ae4 89033f90 nt!IopfCallDriver+0x31
WARNING: Stack unwind information not available. Following frames may be wrong.
a73c1aac b9e3b244 89c24718 89909008 89033f90 ProtectF+0x84fa <- This driver holds the original IRP 89909008 and creates a new, similar IRP 8915d008 and passes down the same device stack
a73c1b20 b9e3b4d8 89c24968 89909008 8979c320 ProtectF+0x4244
a73c1b48 804ef163 89c24968 8979c320 89909008 ProtectF+0x44d8
a73c1b58 b9c8f24b 89b2ab50 89909008 1ef58ae5 nt!IopfCallDriver+0x31
a73c1b6c b9c948d1 89b2aa98 89909008 1ef58a41 MNUMON+0x124b
a73c1bc8 804ef163 89b2aa98 89909008 89913d38 MNUMON+0x68d1
a73c1ca4 8057a3cf a73c1d64 13b1fca4 b9d06f24 nt!IopfCallDriver+0x31
a73c1d2c b9d06f5c 0000060c 13b1fcac 13b1fcbc nt!NtSetInformationFile+0x523
a73c1d48 805409ac 0000060c 13b1fcac 13b1fcbc SafeCgx+0x1df5c
a73c1d48 7c90eb94 0000060c 13b1fcac 13b1fcbc nt!KiFastCallEntry+0xfc
13b1fc84 7c90e5e5 7c83209d 0000060c 13b1fcac ntdll!KiFastSystemCallRet
13b1fc88 7c83209d 0000060c 13b1fcac 13b1fcbc ntdll!NtSetInformationFile+0xc
13b1fccc 35ccaeb4 0000060c 13b1ff1c 07662310 kernel32!SetEndOfFile+0x62
13b1fcec 35d3c1ec 0000060c 09534400 00000000 MSPST32!MSProviderInit+0x194f1
13b1fd90 00000000 00000e13 00000400 00000400 MSPST32!OSTServiceEntry+0x1994e

1: kd> !fileobj 0x897b67a8

$PrepareToShrinkFileSize

Device Object: 0x8a3f4c08 \Driver\Ftdisk
Vpb: 0x8a37a280
Access: Read Write Delete

Flags: 0x40100
Stream File
Handle Created

FsContext: 0xe3d19d90 FsContext2: 0x00000000
CurrentByteOffset: 0
Cache Data:
Section Object Pointers: 897b55dc
Shared Cache Map: 89176148 File Offset: 0
Vacb: 8a3df330
Your data is at: d6f80000

This FileObject is the Scb->FileObject for the actual FileObject 89033f90.
Scb->FileObject is created for a stream internal to NTFS.

1: kd> !fileobj 89033f90

\Documents and Settings\t053559\Local Settings\Application Data\Microsoft\Outlook\t053559.ost

LockOperation Set Device Object: 0x8a3f4c08 \Driver\Ftdisk
Vpb: 0x8a37a280
Access: Read Write SharedRead

Flags: 0x40042
Synchronous IO
Cache Supported
Handle Created

File Object is currently busy and has 0 waiters.

FsContext: 0xe3d19d90 FsContext2: 0xe3d19ee8
Private Cache Map: 0x89b9fad8
CurrentByteOffset: 9534400
Cache Data:
Section Object Pointers: 897b55dc
Shared Cache Map: 89176148 File Offset: 9534400
Vacb: 8a3de070
Your data is at: cd5f4400

There is another FileObject 0x898c4978 for the same file, for which a cleanup is seen complete:

1: kd> !fileobj 0x898c4978

\Documents and Settings\t053559\Local Settings\Application Data\Microsoft\Outlook\t053559.ost

Device Object: 0x8a3f4c08 \Driver\Ftdisk
Vpb: 0x8a37a280
Access: Read SharedRead SharedWrite

Flags: 0x44042
Synchronous IO
Cache Supported
Cleanup Complete
Handle Created

FsContext: 0xe3d19d90 FsContext2: 0xe12ef4a0
CurrentByteOffset: 7fe4400
Cache Data:
Section Object Pointers: 897b55dc
Shared Cache Map: 89176148 File Offset: 7fe4400
Vacb: 8a3e0458
Your data is at: d6ae4400

These 3 FOs share the SharedCacheMap 89176148 (OpenCount set to 1)

The FO 0x898c4978 has PrivateCacheMap set to NULL (I believe it is because a cleanup has been called on it)
The FO 0x89033f90 has PrivateCacheMap set to 0x89b9fad8
The FO 0x897b67a8 has PrivateCacheMap set to NULL (The cache manager did not expect this)

NtfsCreateInternalAttributeStream is responsible for initialization of the internal stream.
The internal stream FileObjects are cleaned up by calling NtfsDeleteInternalAttributeStream, which I think has not been called for the FO 0x897b67a8

The PrivateCacheMap structure has a field FileObject. Thinking that if there was indeed a PrivateCacheMap allocated when in NtfsCreateInternalAttributeStream and that if it is still safely lying around somewhere in the dump, the dump was searched for references to the dword 0x897b67a8.
There were no references that could point to the culprit

I need help in understanding how the PrivateCacheMap got set to NULL. Any pointers on how to proceed
will be highly appreciated as answers to these question too:
Can the filter drivers be responsible? Is it possible for them to manipulate caching that the OS does?

There is a post on the forum.microsoft.com, where a possible cause has been discussed.
http://forums.microsoft.com/MSDN-CHT/ShowPost.aspx?PostID=3929289&SiteID=14&mode=1
The post is in Chinese. An English translation is not very helpful.

Thanks for your time and help,
Amol

2

PrivateCacheMap is set up when you enable cached I/O on the file
(CcInitializeCacheMap) which must be done before doing a CcCopyRead or
CcCopyWrite against the file. Typically, this is deferred to the point
of first I/O. When the user is done using the file (IRP_MJ_CLEANUP)
these are torn down (CcUninitializeCacheMap) because the cache is no
longer needed - remember, between CLEANUP and CLOSE, only paging I/O
operations are permissible. A side effect of this is that the
PrivateCacheMap field is set when you initialize and torn down (set to
NULL) when you uninitialized.

If you have two file objects with a NULL private cache map, it means
they have either never been used for cached I/O or they've been cleaned
up. In either case, using them for cached operations is not going to
work. Filter drivers can definitely cause problems like this; in the
post you provided I see that someone was trying to "force a cache
flush," something that just cannot be done from a filter on Windows
(well, unless you count forcing a reboot.)

If a filter driver were to tear down the cache map, it might lead to
this sort of behavior. The stack provided is already highly suspect,
since it shows a system call hooking driver of some sort, which is never
necessary for legitimate software. There are three differently named
drivers involved here, and you might also find this is a functional
interference problem (where they work independently but not together)
because one or more are implementing complex functionality and/or are
violating the rules.

While you have a nice write-up, it follows your analysis too closely and
omits useful information (like the output from !irp.) Is it possible
that this started as one type of IRP and turned into something else?
Was a file object switched? It's tough to look at the broad space of
"what might have happened here" without information available to prune
that space down in size.

With a crash dump it's likely that we could determine more, but with the
information provided it's just speculation at this point.

Tony
OSR

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@yahoo.com
Sent: Friday, September 26, 2008 9:01 AM
To: ntfsd redirect
Subject: [ntfsd] Bugcheck 0x24 FileObject->PrivateCacheMap NULL

Hello,

There are xp sp2 laptops that crash with bugcheck 0x24. The details
follow:

The crash occurs in CcCopyRead because FileObject->PrivateCacheMap for a
FileObject 0x897b67a8 is NULL.
The cache manager is not expecting FileObject->PrivateCacheMap to be
NULL when in CcCopyRead.

NTFS_FILE_SYSTEM (24)
If you see NtfsExceptionFilter on the stack then the 2nd and 3rd
parameters are the exception record and context record. Do a .cxr
on the 3rd parameter and then kb to obtain a more informative stack
trace.
Arguments:
Arg1: 001902fe
Arg2: a73c1714
Arg3: a73c1410
Arg4: 8056804d

Debugging Details:

EXCEPTION_RECORD: a73c1714 -- (.exr 0xffffffffa73c1714)
ExceptionAddress: 8056804d (nt!CcCopyRead+0x00000047)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000000
Parameter[1]: 00000002
Attempt to read from address 00000002

CONTEXT: a73c1410 -- (.cxr 0xffffffffa73c1410)
eax=897b67a8 ebx=89251aa0 ecx=00000001 edx=89176148 esi=00000000
edi=00000000
eip=8056804d esp=a73c17dc ebp=a73c1858 iopl=0 nv up ei pl zr na
pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010246
nt!CcCopyRead+0x47:
8056804d f6460202 test byte ptr [esi+2],2
ds:0023:00000002=?? <-- esi is assigned FO->PrivateCacheObject
Resetting default scope

PROCESS_NAME: OUTLOOK.EXE

LAST_CONTROL_TRANSFER: from b9dd2ad5 to 8056804d

STACK_TEXT:
a73c1858 b9dd2ad5 897b67a8 a73c18a0 00000001 nt!CcCopyRead+0x47
a73c188c b9dbf20b 89795630 89033f90 e3d19d90
Ntfs!NtfsPrepareToShrinkFileSize+0xa3
a73c1970 b9dbeb6b 89795630 89033f90 8915d008
Ntfs!NtfsSetEndOfFileInfo+0x144
a73c19e0 b9d96698 89795630 8915d008 8915d008
Ntfs!NtfsCommonSetInformation+0x477
a73c1a48 804ef163 89c23020 8915d008 8915d174
Ntfs!NtfsFsdSetInformation+0xa3
a73c1a58 b9e6bf45 8915d174 8a3722f0 8915d008 nt!IopfCallDriver+0x31
a73c1a6c 804ef163 89c247d0 e28dc668 00000000 sr!SrSetInformation+0x179
a73c1a7c b9e3f4fa 8923e7f8 a73c1ae4 89033f90 nt!IopfCallDriver+0x31
WARNING: Stack unwind information not available. Following frames may be
wrong.
a73c1aac b9e3b244 89c24718 89909008 89033f90 ProtectF+0x84fa <- This
driver holds the original IRP 89909008 and creates a new, similar IRP
8915d008 and passes down the same device stack
a73c1b20 b9e3b4d8 89c24968 89909008 8979c320 ProtectF+0x4244
a73c1b48 804ef163 89c24968 8979c320 89909008 ProtectF+0x44d8
a73c1b58 b9c8f24b 89b2ab50 89909008 1ef58ae5 nt!IopfCallDriver+0x31
a73c1b6c b9c948d1 89b2aa98 89909008 1ef58a41 MNUMON+0x124b
a73c1bc8 804ef163 89b2aa98 89909008 89913d38 MNUMON+0x68d1
a73c1ca4 8057a3cf a73c1d64 13b1fca4 b9d06f24 nt!IopfCallDriver+0x31
a73c1d2c b9d06f5c 0000060c 13b1fcac 13b1fcbc
nt!NtSetInformationFile+0x523
a73c1d48 805409ac 0000060c 13b1fcac 13b1fcbc SafeCgx+0x1df5c
a73c1d48 7c90eb94 0000060c 13b1fcac 13b1fcbc nt!KiFastCallEntry+0xfc
13b1fc84 7c90e5e5 7c83209d 0000060c 13b1fcac ntdll!KiFastSystemCallRet
13b1fc88 7c83209d 0000060c 13b1fcac 13b1fcbc
ntdll!NtSetInformationFile+0xc
13b1fccc 35ccaeb4 0000060c 13b1ff1c 07662310 kernel32!SetEndOfFile+0x62
13b1fcec 35d3c1ec 0000060c 09534400 00000000
MSPST32!MSProviderInit+0x194f1
13b1fd90 00000000 00000e13 00000400 00000400
MSPST32!OSTServiceEntry+0x1994e

1: kd> !fileobj 0x897b67a8

$PrepareToShrinkFileSize

Device Object: 0x8a3f4c08 \Driver\Ftdisk
Vpb: 0x8a37a280
Access: Read Write Delete

Flags: 0x40100
Stream File
Handle Created

FsContext: 0xe3d19d90 FsContext2: 0x00000000
CurrentByteOffset: 0
Cache Data:
Section Object Pointers: 897b55dc
Shared Cache Map: 89176148 File Offset: 0
Vacb: 8a3df330
Your data is at: d6f80000

This FileObject is the Scb->FileObject for the actual FileObject
89033f90.
Scb->FileObject is created for a stream internal to NTFS.

1: kd> !fileobj 89033f90

\Documents and Settings\t053559\Local Settings\Application
Data\Microsoft\Outlook\t053559.ost

LockOperation Set Device Object: 0x8a3f4c08 \Driver\Ftdisk
Vpb: 0x8a37a280
Access: Read Write SharedRead

Flags: 0x40042
Synchronous IO
Cache Supported
Handle Created

File Object is currently busy and has 0 waiters.

FsContext: 0xe3d19d90 FsContext2: 0xe3d19ee8
Private Cache Map: 0x89b9fad8
CurrentByteOffset: 9534400
Cache Data:
Section Object Pointers: 897b55dc
Shared Cache Map: 89176148 File Offset: 9534400
Vacb: 8a3de070
Your data is at: cd5f4400

There is another FileObject 0x898c4978 for the same file, for which a
cleanup is seen complete:

1: kd> !fileobj 0x898c4978

\Documents and Settings\t053559\Local Settings\Application
Data\Microsoft\Outlook\t053559.ost

Device Object: 0x8a3f4c08 \Driver\Ftdisk
Vpb: 0x8a37a280
Access: Read SharedRead SharedWrite

Flags: 0x44042
Synchronous IO
Cache Supported
Cleanup Complete
Handle Created

FsContext: 0xe3d19d90 FsContext2: 0xe12ef4a0
CurrentByteOffset: 7fe4400
Cache Data:
Section Object Pointers: 897b55dc
Shared Cache Map: 89176148 File Offset: 7fe4400
Vacb: 8a3e0458
Your data is at: d6ae4400

These 3 FOs share the SharedCacheMap 89176148 (OpenCount set to 1)

The FO 0x898c4978 has PrivateCacheMap set to NULL (I believe it is
because a cleanup has been called on it)
The FO 0x89033f90 has PrivateCacheMap set to 0x89b9fad8
The FO 0x897b67a8 has PrivateCacheMap set to NULL (The cache manager did
not expect this)

NtfsCreateInternalAttributeStream is responsible for initialization of
the internal stream.
The internal stream FileObjects are cleaned up by calling
NtfsDeleteInternalAttributeStream, which I think has not been called for
the FO 0x897b67a8

The PrivateCacheMap structure has a field FileObject. Thinking that if
there was indeed a PrivateCacheMap allocated when in
NtfsCreateInternalAttributeStream and that if it is still safely lying
around somewhere in the dump, the dump was searched for references to
the dword 0x897b67a8.
There were no references that could point to the culprit

I need help in understanding how the PrivateCacheMap got set to NULL.
Any pointers on how to proceed
will be highly appreciated as answers to these question too:
Can the filter drivers be responsible? Is it possible for them to
manipulate caching that the OS does?

There is a post on the forum.microsoft.com, where a possible cause has
been discussed.
http://forums.microsoft.com/MSDN-CHT/ShowPost.aspx?PostID=3929289&SiteID
=14&mode=1
The post is in Chinese. An English translation is not very helpful.

Thanks for your time and help,
Amol

NTFSD is sponsored by OSR

For our schedule debugging and file system seminars
(including our new fs mini-filter seminar) visit:

You are currently subscribed to ntfsd as: xxxxx@osr.com
To unsubscribe send a blank email to xxxxx@lists.osr.com

3

Thanks a bunch Tony, for the explanation.
It did help in moving forward.

Yes, there are a lot of filter drivers involved and there is a possibility that all of them may behave correct when independent but may cause problems when together.Yes, one of them has a hook into the system call table!

A filter driver calling into cache manager, as you said, can cause such problems, I looked into the import table of ProtectF from within the dump and saw 12 cachemanager calls including CcUninitializeCacheMap, CcPurgeCacheSection and CcFlushCache.

I learnt that the Cc calls are available to the file system drivers and not to the file system filter drivers. This is a piece of information that I did not know before. That Chinese post would have been useful, if I knew about the Cc calls.

ProtectF calling these functions must be causing the state of the cachemaps to change without the knowledge of Ntfs. I believe that the FO 0x897b67a8 must have had its PrivateCacheMap cleared that way.

The irps that we see on the stack have similar parameters - specifically, the same FO and the same Major,Minor functions. ProtectF holds the original IRP and sends a new, similar IRP down the stack. The IRPs are as follows:

The original IRP

1: kd> !irp 89909008
Irp is active with 11 stacks 11 is current (= 0x899091e0)
No Mdl: System buffer=8923e7f0: Thread 89251aa0: Irp stack trace.
cmd flg cl Device File Completion-Context
. . .
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[6, 0] 0 0 89c24968 89033f90 00000000-00000000
\FileSystem\ProtectF
Args: 00000008 00000014 00000000 00000000

The FO 89033f90 is one of the 3 FOs involved.

The new IRP created by the filter driver ProtectF
1: kd> !irp 8915d008
Irp is active with 8 stacks 8 is current (= 0x8915d174)
No Mdl: System buffer=89aa5468: Thread 89251aa0: Irp stack trace.
cmd flg cl Device File Completion-Context
. . .
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[6, 0] 0 e0 89c23020 89033f90 b9e3ed76-00000000 Success Error Cancel
\FileSystem\Ntfs ProtectF
Args: 00000008 00000014 00000000 00000000

The stacksize allocated for this IRP is 8. It is 11 for the original IRP. That’s OK as the new IRP is not travelling all the way from the top of the stack, but just from the place where the original IRP should’ve gone next. the FO is 89033f90 again.

This is the file system device stack:
1: kd> !devstack 89c23020
!DevObj !DrvObj !DevExt ObjectName
89555df0 \Driver\mfehidk 89555ea8
89b2aa98 \FileSystem\MNUMON 89b2ab50
89c24968 \FileSystem\ProtectF 89c24a20
89c24718 \FileSystem\sr 89c247d0

89c23020 \FileSystem\Ntfs 89c230d8

  • Amol