Understanding Pool Corruption Part 3 – Special Pool for Double Frees
In Part 1 and Part 2 of this series we discussed pool corruption and how special pool can be used to identify the cause of such corruption. In today’s article we will use special pool to catch a double free of pool memory.
A double free of pool will cause a system to blue screen, however the resulting crash may vary. In the most obvious scenario a driver that frees a pool allocation twice will cause the system to immediately crash with a stop code of C2 BAD_POOL_CALLER, and the first parameter will be 7 to indicate “Attempt to free pool which was already freed”. If you experience such a crash, enabling special pool should be high on your list of troubleshooting steps.
BAD_POOL_CALLER (c2)
The current thread is making a bad pool request. Typically this is at a bad IRQL level or double freeing the same allocation, etc.
Arguments:
Arg1: 0000000000000007, Attempt to free pool which was already freed
Arg2: 00000000000011c1, (reserved)
Arg3: 0000000004810007, Memory contents of the pool block
Arg4: fffffa8001b10800, Address of the block of pool being deallocated
A less obvious crash would be if the pool has been reallocated. As we showed in Part 2, pool is structured so that multiple drivers share a page. When DriverA calls ExFreePool to free its pool block the block is made available for other drivers. If memory manager gives this memory to DriverF, and then DriverA frees it a second time, a crash may occur in DriverF when the pool allocation no longer contains the expected data. Such a problem may be difficult for the developer of DriverF to identify without special pool.
Special pool will place each driver’s allocation in a separate page of memory (as discussed in Part 2). When a driver frees a pool block in special pool the whole page will be freed, and any access to a free page will cause an immediate bugcheck. Additionally, special pool will place this page on the tail of the list of pages to be used again. This increases the likelihood that the page will still be free when it is freed a second time, decreasing the likelihood of the DriverA/DriverF scenario shown above.
To demonstrate this failure we will once again use the Sysinternals tool NotMyFault. Choose the “Double free” option and click “Crash”. Most likely you will get the stop C2 bugcheck mentioned above. Enable special pool and reboot to get a more informative error.
verifier /flags 1 /driver myfault.sys
Choosing the “Double free” option with special pool enabled resulted in the following crash. The bugcheck code PAGE_FAULT_IN_NONPAGED_AREA means some driver tried to access memory that was not valid. This invalid memory was the freed special pool page.
PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by try-except,
it must be protected by a Probe. Typically the address is just plain bad or it
is pointing at freed memory.
Arguments:
Arg1: fffff9800a7fe7f0, memory referenced.
Arg2: 0000000000000000, value 0 = read operation, 1 = write operation.
Arg3: fffff80060263888, If non-zero, the instruction address which referenced the bad memory address.
Arg4: 0000000000000002, (reserved)
Looking at the call stack we can see myfault.sys was freeing pool and ExFreePoolSanityChecks took a page fault that lead to the crash.
kd> kn
# Child-SP RetAddr Call Site
00 fffff880`0419fe28 fffff800`5fd7e28a nt!DbgBreakPointWithStatus
01 fffff880`0419fe30 fffff800`5fd7d8de nt!KiBugCheckDebugBreak+0x12
02 fffff880`0419fe90 fffff800`5fc5b544 nt!KeBugCheck2+0x79f
03 fffff880`041a05b0 fffff800`5fd1c5bc nt!KeBugCheckEx+0x104
04 fffff880`041a05f0 fffff800`5fc95acb nt! ?? ::FNODOBFM::`string'+0x33e2a
05 fffff880`041a0690 fffff800`5fc58eee nt!MmAccessFault+0x55b
06 fffff880`041a07d0 fffff800`60263888 nt!KiPageFault+0x16e
07 fffff880`041a0960 fffff800`6024258c nt!ExFreePoolSanityChecks+0xe8
08 fffff880`041a09a0 fffff880`04c9b5d9 nt!VerifierExFreePoolWithTag+0x3c
09 fffff880`041a09d0 fffff880`04c9b727 myfault!MyfaultDeviceControl+0x2fd
0a fffff880`041a0b20 fffff800`60241a4a myfault!MyfaultDispatch+0xb7
0b fffff880`041a0b80 fffff800`600306c7 nt!IovCallDriver+0xba
0c fffff880`041a0bd0 fffff800`600458a6 nt!IopXxxControlFile+0x7e5
0d fffff880`041a0d60 fffff800`5fc5a453 nt!NtDeviceIoControlFile+0x56
0e fffff880`041a0dd0 000007fd`ea212c5a nt!KiSystemServiceCopyEnd+0x13
Using the address from the bugcheck code, we can verify that the memory is in fact not valid:
kd> dd fffff9800a7fe7f0
fffff980`0a7fe7f0 ???????? ???????? ???????? ????????
fffff980`0a7fe800 ???????? ???????? ???????? ????????
fffff980`0a7fe810 ???????? ???????? ???????? ????????
fffff980`0a7fe820 ???????? ???????? ???????? ????????
fffff980`0a7fe830 ???????? ???????? ???????? ????????
fffff980`0a7fe840 ???????? ???????? ???????? ????????
fffff980`0a7fe850 ???????? ???????? ???????? ????????
fffff980`0a7fe860 ???????? ???????? ???????? ????????
kd> !pte fffff9800a7fe7f0
VA fffff9800a7fe7f0
PXE at FFFFF6FB7DBEDF98 PPE at FFFFF6FB7DBF3000 PDE at FFFFF6FB7E600298 PTE at FFFFF6FCC0053FF0
contains 0000000002A91863 contains 0000000002A10863 contains 0000000000000000
pfn 2a91 ---DA--KWEV pfn 2a10 ---DA--KWEV not valid
So far we have enough evidence to prove that myfault.sys was freeing invalid memory, but how to we know this memory is being freed twice? If there was a double free we need to determine if the first or second call to ExFreePool was incorrect. To this so we need to determine what code freed the memory first.
Driver Verifier special pool keeps track of the last 0x10000 calls to allocate and free pool. You can dump this database with the !verifier 80 command. To limit the data output you can also pass this command the address of the memory you suspect was double freed.
Don’t assume the address in the bugcheck code is the address being freed, go get the address from the function that called VerifierExFreePoolWithTag.
In the above call stack the call below VerifierExFreePoolWithTag is frame 9 (start counting with 0, or use kn).
kd> .frame /r 9
09 fffff880`041a09d0 fffff880`04c9b727 myfault+0x15d9
rax=0000000000000000 rbx=fffff9800a7fe800 rcx=fffff9800a7fe800
rdx=fffffa8001a37fa0 rsi=fffffa80035975e0 rdi=fffffa8003597610
rip=fffff88004c9b5d9 rsp=fffff880041a09d0 rbp=fffffa80034568d0
r8=fffff9800a7fe801 r9=fffff9800a7fe7f0 r10=fffff9800a7fe800
r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
r14=fffff800600306c7 r15=fffffa8004381b80
iopl=0 nv up ei ng nz na po nc
cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b efl=00000286
myfault+0x15d9:
fffff880`04c9b5d9 eb7a jmp myfault+0x1655 (fffff880`04c9b655)
On x64 systems the first parameter is passed in rcx. The below assembly shows that rcx originated from rbx.
kd> ub fffff880`04c9b5d9
myfault+0x15ba:
fffff880`04c9b5ba ff15a80a0000 call qword ptr [myfault+0x2068 (fffff880`04c9c068)]
fffff880`04c9b5c0 33d2 xor edx,edx
fffff880`04c9b5c2 488bc8 mov rcx,rax
fffff880`04c9b5c5 488bd8 mov rbx,rax
fffff880`04c9b5c8 ff154a0a0000 call qword ptr [myfault+0x2018 (fffff880`04c9c018)]
fffff880`04c9b5ce 33d2 xor edx,edx
fffff880`04c9b5d0 488bcb mov rcx,rbx
fffff880`04c9b5d3 ff153f0a0000 call qword ptr [myfault+0x2018 (fffff880`04c9c018)]
Run !verifier 80 using the address from rbx:
kd> !verifier 80 fffff9800a7fe800
Log of recent kernel pool Allocate and Free operations:
There are up to 0x10000 entries in the log.
Parsing 0x0000000000010000 log entries, searching for address 0xfffff9800a7fe800.
======================================================================
Pool block fffff9800a7fe800, Size 0000000000000800, Thread fffffa80046ce4c0
fffff80060251a32 nt!VfFreePoolNotification+0x4a
fffff8005fe736c9 nt!ExFreePool+0x595
fffff80060242597 nt!VerifierExFreePoolWithTag+0x47
fffff88004c9b5ce myfault!MyfaultDeviceControl+0x2f2
fffff88004c9b727 myfault!MyfaultDispatch+0xb7
fffff80060241a4a nt!IovCallDriver+0xba
fffff800600306c7 nt!IopXxxControlFile+0x7e5
fffff800600458a6 nt!NtDeviceIoControlFile+0x56
fffff8005fc5a453 nt!KiSystemServiceCopyEnd+0x13
======================================================================
Pool block fffff9800a7fe800, Size 0000000000000800, Thread fffffa80046ce4c0
fffff80060242a5d nt!VeAllocatePoolWithTagPriority+0x2d1
fffff8006024b20e nt!XdvExAllocatePoolInternal+0x12
fffff80060242f69 nt!VerifierExAllocatePool+0x61
fffff88004c9b5c0 myfault!MyfaultDeviceControl+0x2e4
fffff88004c9b727 myfault!MyfaultDispatch+0xb7
fffff80060241a4a nt!IovCallDriver+0xba
fffff800600306c7 nt!IopXxxControlFile+0x7e5
fffff800600458a6 nt!NtDeviceIoControlFile+0x56
fffff8005fc5a453 nt!KiSystemServiceCopyEnd+0x13
The above output shows the pool block being allocated by myfault.sys and then freed by myfault.sys. If we combine this information with the call stack leading up to our bugcheck we can conclude that the pool was freed once in MyfaultDeviceControl at offset 0x2f2, then freed again in MyfaultDeviceControl at offset 0x2fd.
Now we know which driver is causing the problem, and if this is our driver we know which area of the code to investigate.
Comments
- Anonymous
October 23, 2014
I have a problem with a BSOD code PAGE_FAULT_IN_NONPAGED_AREA (50),I suspect it case by a minifilter driver,but I have not find the real reason yet. minidump file upload on: pan.baidu.com/.../1dDGOLSt Could you give me some suggest? [Unfortunately we are not able to provide 1:1 support through this blog. A stop 50 could be caused by many different failures. This article contains steps to obtain self-help to debug your crash.]