locked
Bluescreen on Windows 8.1 when enabling traces with tracelog for a wfp driver RRS feed

  • Question

  • Whenever i test my wfp driver on Windows 8.1 i get a bluescreen when i use tracelog.exe acticates WPP trace messages. Using Windows 7 or Windows 8 everything works fine.

    BugCheck Analysis results in BAD_POOL_CALLER for netio.sys:

    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: 00000007, Attempt to free pool which was already freed
    Arg2: 00001205, (reserved)
    Arg3: 00090009, Memory contents of the pool block
    Arg4: 840b2b14, Address of the block of pool being deallocated


    Since my driver is not directly involved, i tested with enabling "special pool" via "verifier /flags 1 /driver netio.sys".

    From result of memory-dump analyze i believe that both calls of ExFreePoolWithTag are not originated by my wfp driver so i have no idea how to handle this bluescreen. To make it again clear: the bluescreen happens only when i activate trace messages in my driver with tracelog.exe and only on Windows 8.1.

    Here is the output of the kernel debugger from the memory dump with "special pool" activated:

    Microsoft (R) Windows Debugger Version 6.3.9600.16384 X86
    Copyright (c) Microsoft Corporation. All rights reserved.
    
    TIG\jens (npipe WinIDE_01CF0D40EFA2B216) connected at Thu Jan 09 14:44:36 2014
    
    Microsoft (R) Windows Debugger Version 6.3.9600.16384 X86
    Copyright (c) Microsoft Corporation. All rights reserved.
    
    
    Loading Dump File [C:\Work\Jens\temp\MEMORY.DMP]
    Kernel Bitmap Dump File: Only kernel address space is available
    
    Symbol search path is: C:\Work\Jens\projects\SVN\develop\trunk\products\MOBILEmanager\client\wfpfilter\project\x64\Win8Debug;C:\Work\Jens\temp;http://msdl.microsoft.com/download/symbols;srv*
    Executable search path is: 
    Windows 8 Kernel Version 9600 MP (2 procs) Free x64
    Product: WinNt, suite: TerminalServer SingleUserTS
    Built by: 9600.16452.amd64fre.winblue_gdr.131030-1505
    Machine Name:
    Kernel base = 0xfffff803`9ae81000 PsLoadedModuleList = 0xfffff803`9b145990
    Debug session time: Thu Jan  9 14:08:59.933 2014 (UTC + 1:00)
    System Uptime: 0 days 0:02:50.811
    Loading Kernel Symbols
    ...............................................................
    ................................................................
    ..................
    Loading User Symbols
    Loading unloaded module list
    ......
    *******************************************************************************
    *                                                                             *
    *                        Bugcheck Analysis                                    *
    *                                                                             *
    *******************************************************************************
    
    Use !analyze -v to get detailed debugging information.
    
    BugCheck C4, {16, 1de8, ffffe00002ad77f8, 0}
    
    Probably caused by : NETIO.SYS ( NETIO! ?? ::FNODOBFM::`string'+797c )
    
    Followup: MachineOwner
    ---------
    
    nt!KeBugCheckEx:
    fffff803`9afceca0 48894c2408      mov     qword ptr [rsp+8],rcx ss:0018:ffffd000`25a16120=00000000000000c4
    0: kd> !analyze -v
    *******************************************************************************
    *                                                                             *
    *                        Bugcheck Analysis                                    *
    *                                                                             *
    *******************************************************************************
    
    DRIVER_VERIFIER_DETECTED_VIOLATION (c4)
    A device driver attempting to corrupt the system has been caught.  This is
    because the driver was specified in the registry as being suspect (by the
    administrator) and the kernel has enabled substantial checking of this driver.
    If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA will
    be among the most commonly seen crashes.
    Arguments:
    Arg1: 0000000000000016, the pool the caller is trying to free is a bad address.
    Arg2: 0000000000001de8, line number
    Arg3: ffffe00002ad77f8, pool address
    Arg4: 0000000000000000, 0
    
    Debugging Details:
    ------------------
    
    Page e31f not present in the dump file. Type ".hh dbgerr004" for details
    
    BUGCHECK_STR:  0xc4_16
    
    POOL_ADDRESS:  ffffe00002ad77f8 Nonpaged pool
    
    DEFAULT_BUCKET_ID:  WIN8_DRIVER_FAULT
    
    PROCESS_NAME:  svchost.exe
    
    CURRENT_IRQL:  2
    
    ANALYSIS_VERSION: 6.3.9600.16384 (debuggers(dbg).130821-1623) x86fre
    
    LAST_CONTROL_TRANSFER:  from fffff8039b503d6f to fffff8039afceca0
    
    STACK_TEXT:  
    ffffd000`25a16118 fffff803`9b503d6f : 00000000`000000c4 00000000`00000016 00000000`00001de8 ffffe000`02ad77f8 : nt!KeBugCheckEx
    ffffd000`25a16120 fffff803`9b4e311d : ffffe000`02ad77f8 ffffe000`02165068 00000000`00000001 00000000`00000001 : nt!ExFreePoolSanityChecks+0xe3
    ffffd000`25a16160 fffff800`00f8ef67 : ffffe000`0261fb50 ffffe000`0211c610 00000000`00000003 00000000`00000010 : nt!VerifierExFreePoolWithTag+0x39
    ffffd000`25a16190 fffff800`01118de5 : 00000000`00000003 00000000`00000000 ffff3ef0`ff4d3734 00000000`00000000 : NETIO! ?? ::FNODOBFM::`string'+0x797c
    ffffd000`25a161e0 fffff800`00f5a224 : 00000000`00000000 00000000`00000001 00000000`00000000 fffff800`00000008 : tcpip!UdpSendMessagesDatagramsComplete+0xfcc85
    ffffd000`25a16240 fffff800`0101ac8c : 00000000`ffffffff ffffe000`0211c600 00000000`00000000 ffffe000`0261f9f0 : NETIO!NetioDereferenceNetBufferListChain+0xe4
    ffffd000`25a16300 fffff800`010bf8f9 : 00000000`00000001 00000000`00000000 ffffe000`0261f9f0 ffffd000`25a16490 : tcpip!IppCompleteAndFreePacketList+0xf8
    ffffd000`25a16390 fffff800`0106fc54 : fffff800`011d7370 00000000`00000000 ffffd000`25a165e0 ffffe000`02163040 : tcpip!IppFragmentPackets+0x4ccc9
    ffffd000`25a164e0 fffff800`0102f475 : fffff800`011d7370 ffffe000`02023900 ffffd000`00000000 00000000`00000000 : tcpip!IppDispatchSendPacketHelper+0x94
    ffffd000`25a16670 fffff800`0106eb02 : 00000000`00000000 00000000`00000017 ffffd000`25a16b80 ffffcf80`003fea58 : tcpip!IppPacketizeDatagrams+0x2d5
    ffffd000`25a16810 fffff800`010295f2 : 00000000`00000000 ffffe000`02024504 fffff800`011d7370 ffffe000`02a3bd70 : tcpip!IppSendDatagramsCommon+0x4a2
    ffffd000`25a169f0 fffff800`0101bd2e : 00000000`00000000 00000000`000068e3 00000000`0000760e 00000000`0000080a : tcpip!IpNlpSendDatagrams+0x42
    ffffd000`25a16a30 fffff800`0107733a : ffffe000`025de0a0 00000000`00000002 ffffe000`01dfcb28 fffff800`011d7370 : tcpip!UdpSendMessagesOnPathCreation+0x42e
    ffffd000`25a16e50 fffff800`0101c154 : 00000000`0000000d fffff803`9af589c4 ffffe000`0273e880 ffffe000`00401318 : tcpip!UdpSendMessages+0x1da
    ffffd000`25a17280 fffff803`9af393f9 : 00000000`00000070 fffff803`9b4f1de3 00000000`00000007 00000000`00000000 : tcpip!UdpTlProviderSendMessagesCalloutRoutine+0x15
    ffffd000`25a172b0 fffff800`0101b7ac : fffff800`0101c140 ffffd000`25a17430 ffffe000`0296b600 00000000`00000000 : nt!KeExpandKernelStackAndCalloutInternal+0xe9
    ffffd000`25a17400 fffff800`00847629 : ffffe000`01dfc2f0 ffffd000`25a17cc0 ffffe000`01dfc2f0 ffffe000`01dfc2f0 : tcpip!UdpTlProviderSendMessages+0x6c
    ffffd000`25a17480 fffff800`0082f0ca : ffffe000`0296b6b0 ffffd000`25a17a48 ffffe000`02a3db70 fffff803`9aeb836d : afd!AfdFastDatagramSend+0x579
    ffffd000`25a17640 fffff803`9b22bf97 : ffffe000`02a3db70 00000000`00000000 00000000`00000000 ffffc000`01132150 : afd!AfdFastIoDeviceControl+0x10bb
    ffffd000`25a179b0 fffff803`9b22cd7a : e00002af`5700ffef 0000000c`001f0003 00000000`00000000 00000000`00000000 : nt!IopXxxControlFile+0x3f7
    ffffd000`25a17b60 fffff803`9afda4b3 : 00000000`00000000 ffffd000`25a17c18 00000000`00000001 00000000`00000000 : nt!NtDeviceIoControlFile+0x56
    ffffd000`25a17bd0 00007ffd`610b65ea : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiSystemServiceCopyEnd+0x13
    00000062`049bef48 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : 0x00007ffd`610b65ea
    
    
    STACK_COMMAND:  kb
    
    FOLLOWUP_IP: 
    NETIO! ?? ::FNODOBFM::`string'+797c
    fffff800`00f8ef67 90              nop
    
    SYMBOL_STACK_INDEX:  3
    
    SYMBOL_NAME:  NETIO! ?? ::FNODOBFM::`string'+797c
    
    FOLLOWUP_NAME:  MachineOwner
    
    MODULE_NAME: NETIO
    
    IMAGE_NAME:  NETIO.SYS
    
    DEBUG_FLR_IMAGE_TIMESTAMP:  5215f7e4
    
    BUCKET_ID_FUNC_OFFSET:  797c
    
    FAILURE_BUCKET_ID:  0xc4_16_VRF_NETIO!_??_::FNODOBFM::_string_
    
    BUCKET_ID:  0xc4_16_VRF_NETIO!_??_::FNODOBFM::_string_
    
    ANALYSIS_SOURCE:  KM
    
    FAILURE_ID_HASH_STRING:  km:0xc4_16_vrf_netio!_??_::fnodobfm::_string_
    
    FAILURE_ID_HASH:  {69495d91-9145-9351-7e9d-27859f7bb550}
    
    Followup: MachineOwner
    ---------
    
    0: kd> kn
     # Child-SP          RetAddr           Call Site
    00 ffffd000`25a16118 fffff803`9b503d6f nt!KeBugCheckEx
    01 ffffd000`25a16120 fffff803`9b4e311d nt!ExFreePoolSanityChecks+0xe3
    02 ffffd000`25a16160 fffff800`00f8ef67 nt!VerifierExFreePoolWithTag+0x39
    03 ffffd000`25a16190 fffff800`01118de5 NETIO! ?? ::FNODOBFM::`string'+0x797c
    04 ffffd000`25a161e0 fffff800`00f5a224 tcpip!UdpSendMessagesDatagramsComplete+0xfcc85
    05 ffffd000`25a16240 fffff800`0101ac8c NETIO!NetioDereferenceNetBufferListChain+0xe4
    06 ffffd000`25a16300 fffff800`010bf8f9 tcpip!IppCompleteAndFreePacketList+0xf8
    07 ffffd000`25a16390 fffff800`0106fc54 tcpip!IppFragmentPackets+0x4ccc9
    08 ffffd000`25a164e0 fffff800`0102f475 tcpip!IppDispatchSendPacketHelper+0x94
    09 ffffd000`25a16670 fffff800`0106eb02 tcpip!IppPacketizeDatagrams+0x2d5
    0a ffffd000`25a16810 fffff800`010295f2 tcpip!IppSendDatagramsCommon+0x4a2
    0b ffffd000`25a169f0 fffff800`0101bd2e tcpip!IpNlpSendDatagrams+0x42
    0c ffffd000`25a16a30 fffff800`0107733a tcpip!UdpSendMessagesOnPathCreation+0x42e
    0d ffffd000`25a16e50 fffff800`0101c154 tcpip!UdpSendMessages+0x1da
    0e ffffd000`25a17280 fffff803`9af393f9 tcpip!UdpTlProviderSendMessagesCalloutRoutine+0x15
    0f ffffd000`25a172b0 fffff800`0101b7ac nt!KeExpandKernelStackAndCalloutInternal+0xe9
    10 ffffd000`25a17400 fffff800`00847629 tcpip!UdpTlProviderSendMessages+0x6c
    11 ffffd000`25a17480 fffff800`0082f0ca afd!AfdFastDatagramSend+0x579
    12 ffffd000`25a17640 fffff803`9b22bf97 afd!AfdFastIoDeviceControl+0x10bb
    13 ffffd000`25a179b0 fffff803`9b22cd7a nt!IopXxxControlFile+0x3f7
    14 ffffd000`25a17b60 fffff803`9afda4b3 nt!NtDeviceIoControlFile+0x56
    15 ffffd000`25a17bd0 00007ffd`610b65ea nt!KiSystemServiceCopyEnd+0x13
    16 00000062`049bef48 00000000`00000000 0x00007ffd`610b65ea
    0: kd> .frame /r 2
    02 ffffd000`25a16160 fffff800`00f8ef67 nt!VerifierExFreePoolWithTag+0x39
    rax=0000000000000000 rbx=ffffe00002ad77f8 rcx=00000000000000c4
    rdx=0000000000000016 rsi=0000000000000000 rdi=0000000000000000
    rip=fffff8039b4e311d rsp=ffffd00025a16160 rbp=ffffe0000261fc00
     r8=0000000000001de8  r9=ffffe00002ad77f8 r10=fffff78000000008
    r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
    r14=0000000000000000 r15=0000000000000000
    iopl=0         nv up ei pl zr na po nc
    cs=0010  ss=0018  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
    nt!VerifierExFreePoolWithTag+0x39:
    fffff803`9b4e311d 8bd7            mov     edx,edi
    0: kd> ub fffff80000f8ef67
    NETIO! ?? ::FNODOBFM::`string'+0x795f:
    fffff800`00f8ef4a 488bd7          mov     rdx,rdi
    fffff800`00f8ef4d 488bcb          mov     rcx,rbx
    fffff800`00f8ef50 ff1572250200    call    qword ptr [NETIO!_imp_ExpInterlockedPushEntrySList (fffff800`00fb14c8)]
    fffff800`00f8ef56 90              nop
    fffff800`00f8ef57 e97d91fdff      jmp     NETIO!NetioFreeMdl+0xa9 (fffff800`00f680d9)
    fffff800`00f8ef5c 33d2            xor     edx,edx
    fffff800`00f8ef5e 488bcf          mov     rcx,rdi
    fffff800`00f8ef61 ff1569250200    call    qword ptr [NETIO!_imp_ExFreePoolWithTag (fffff800`00fb14d0)]
    0: kd> !verifier 80 ffffe00002ad77f8
    
    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 0xffffe00002ad77f8.
    
    
    ======================================================================
    Pool block ffffe00002ad77f0, Size 0000000000000060, Thread ffffe000011715c0
    fffff8039b4f1bea nt!VfFreePoolNotification+0x4a
    fffff8039b11343a nt!ExFreePoolWithTag+0x116a
    fffff8039b2afb1b nt!IopFreeMiniCompletionPacket+0x7f
    fffff8039af68a57 nt!ExpWorkerFactoryCompletionPacketRoutine+0xcb
    fffff8039b2afabe nt!IopFreeMiniCompletionPacket+0x22
    fffff8039b28386f nt!IopFreeCompletionListPackets+0x2b
    fffff8039af130cc nt!IopDeleteIoCompletionInternal+0x7c
    fffff8039b283ac8 nt!IopCloseIoCompletion+0x18
    fffff8039b22f461 nt!NtClose+0x1d1
    fffff8039afda4b3 nt!KiSystemServiceCopyEnd+0x13
    
    Finished parsing all pool tracking information.

    The memory-dump file is available on request.

    Thanks four help, Jens

    Thursday, January 9, 2014 2:23 PM

Answers

  • From the dump, you are retreating the NBL too far, and not returning it to the original offset. When you retreat, the NDIS allocator allocates a new MDL.  When NetIO goes to free this MDL it bugchecks.  For any NBLs that you do not own, you must return them to the original state.  In this case you should call NdisAdvanceNetBufferListDataStart setting the DataOffsetDelta parameter to the same size you used to the NdisRetreatNetBufferListDataStart and setting the FreeMdl parameter to TRUE.  This will return the NBL to the original state.

    Hope this helps,


    Dusty Harper [MSFT]
    Microsoft Corporation
    ------------------------------------------------------------
    This posting is provided "AS IS", with NO warranties and confers NO rights
    ------------------------------------------------------------

    Saturday, February 1, 2014 2:02 AM
    Moderator

All replies

  • Please send me a link to the memory dump: DHarper @AT@ Microsoft .DOT. com.

    Thanks,


    Dusty Harper [MSFT]
    Microsoft Corporation
    ------------------------------------------------------------
    This posting is provided "AS IS", with NO warranties and confers NO rights
    ------------------------------------------------------------

    Thursday, January 9, 2014 8:26 PM
    Moderator
  • From the dump, you are retreating the NBL too far, and not returning it to the original offset. When you retreat, the NDIS allocator allocates a new MDL.  When NetIO goes to free this MDL it bugchecks.  For any NBLs that you do not own, you must return them to the original state.  In this case you should call NdisAdvanceNetBufferListDataStart setting the DataOffsetDelta parameter to the same size you used to the NdisRetreatNetBufferListDataStart and setting the FreeMdl parameter to TRUE.  This will return the NBL to the original state.

    Hope this helps,


    Dusty Harper [MSFT]
    Microsoft Corporation
    ------------------------------------------------------------
    This posting is provided "AS IS", with NO warranties and confers NO rights
    ------------------------------------------------------------

    Saturday, February 1, 2014 2:02 AM
    Moderator