none
WdfRequestComplete で DRIVER_IRQL_NOT_LESS_OR_EQUAL RRS feed

  • Domanda

  • 現在お客様のところのWindows 10 KMDFドライバーで発生しているBSODエラーについてです。

    タイマー処理ルーチン内のタイムアウトエラー処理で、WdfRequestCompleteするところで、DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)が発生しています。WdfRequestComplete はIRQL "<=DISPATCH_LEVEL"で、実際に実行中のタイマールーチンは「CURRENT_IRQL: 2」なので問題なさそうなのです。なぜこのようなエラーが発生するのか、どなたか考えられる原因がわかりましたらアドバイス頂けないでしょうか。以下にminidump(一部)を載せますので、よろしくお願いします。

    DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)
    An attempt was made to access a pageable (or completely invalid) address at an
    interrupt request level (IRQL) that is too high.  This is usually
    caused by drivers using improper addresses.
    If kernel debugger is available get stack backtrace.
    Arguments:
    Arg1: 0000000000000038, memory referenced
    Arg2: 0000000000000002, IRQL
    Arg3: 0000000000000001, value 0 = read operation, 1 = write operation
    Arg4: fffff8059d6f2cc5, address which referenced memory
    
    Debugging Details:
    ------------------
    
    
    KEY_VALUES_STRING: 1
    
    
    STACKHASH_ANALYSIS: 1
    
    TIMELINE_ANALYSIS: 1
    
    
    DUMP_CLASS: 1
    
    DUMP_QUALIFIER: 400
    
    BUILD_VERSION_STRING:  17134.1.amd64fre.rs4_release.180410-1804
    
    SYSTEM_MANUFACTURER:  Dell Inc.
    
    SYSTEM_PRODUCT_NAME:  Precision Tower 5810
    
    SYSTEM_SKU:  0617
    
    BIOS_VENDOR:  Dell Inc.
    
    BIOS_VERSION:  A27
    
    BIOS_DATE:  06/25/2018
    
    BASEBOARD_MANUFACTURER:  Dell Inc.
    
    BASEBOARD_PRODUCT:  0HHV7N
    
    BASEBOARD_VERSION:  A00
    
    DUMP_TYPE:  2
    
    BUGCHECK_P1: 38
    
    BUGCHECK_P2: 2
    
    BUGCHECK_P3: 1
    
    BUGCHECK_P4: fffff8059d6f2cc5
    
    WRITE_ADDRESS: fffff802ae4f4388: Unable to get MiVisibleState
    Unable to get NonPagedPoolStart
    Unable to get NonPagedPoolEnd
    Unable to get PagedPoolStart
    Unable to get PagedPoolEnd
     0000000000000038 
    
    CURRENT_IRQL:  2
    
    FAULTING_IP: 
    Wdf01000!imp_WdfRequestCompleteWithInformation+65 [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 571]
    fffff805`9d6f2cc5 48897838        mov     qword ptr [rax+38h],rdi
    
    CPU_COUNT: 4
    
    CPU_MHZ: aea
    
    CPU_VENDOR:  GenuineIntel
    
    CPU_FAMILY: 6
    
    CPU_MODEL: 3f
    
    CPU_STEPPING: 2
    
    CPU_MICROCODE: 6,3f,2,0 (F,M,S,R)  SIG: 3D'00000000 (cache) 3D'00000000 (init)
    
    BLACKBOXBSD: 1 (!blackboxbsd)
    
    
    BLACKBOXPNP: 1 (!blackboxpnp)
    
    
    CUSTOMER_CRASH_COUNT:  1
    
    DEFAULT_BUCKET_ID:  WIN8_DRIVER_FAULT
    
    BUGCHECK_STR:  AV
    
    PROCESS_NAME:  System
    
    ANALYSIS_SESSION_HOST:  RIE
    
    ANALYSIS_SESSION_TIME:  02-15-2019 15:07:17.0479
    
    ANALYSIS_VERSION: 10.0.17763.1 amd64fre
    
    TRAP_FRAME:  fffff802b046a520 -- (.trap 0xfffff802b046a520)
    NOTE: The trap frame does not contain all registers.
    Some register values may be zeroed or incorrect.
    rax=0000000000000000 rbx=0000000000000000 rcx=ffffdf0616459840
    rdx=000020f9dd6f6208 rsi=0000000000000000 rdi=0000000000000000
    rip=fffff8059d6f2cc5 rsp=fffff802b046a6b0 rbp=0000000000000000
     r8=0000000000000102  r9=0000000000000000 r10=fffff802ae01de10
    r11=0000000000000001 r12=0000000000000000 r13=0000000000000000
    r14=0000000000000000 r15=0000000000000000
    iopl=0         nv up ei pl zr na po nc
    Wdf01000!FxIrp::SetInformation+0xf [inlined in Wdf01000!imp_WdfRequestCompleteWithInformation+0x65]:
    fffff805`9d6f2cc5 48897838        mov     qword ptr [rax+38h],rdi ds:00000000`00000038=????????????????
    Resetting default scope
    
    LAST_CONTROL_TRANSFER:  from fffff802ae261269 to fffff802ae250690
    
    STACK_TEXT:  
    fffff802`b046a3d8 fffff802`ae261269 : 00000000`0000000a 00000000`00000038 00000000`00000002 00000000`00000001 : nt!KeBugCheckEx
    fffff802`b046a3e0 fffff802`ae25dee5 : ffffdf06`1d97e1b0 ffffdf06`1d97e040 ffffdf06`1d97e040 fffff802`ae0e5313 : nt!KiBugCheckDispatch+0x69
    fffff802`b046a520 fffff805`9d6f2cc5 : ffffdf06`15d25218 00000000`c007000b 00000000`00000000 00000000`00000000 : nt!KiPageFault+0x425
    fffff802`b046a6b0 fffff805`a0d795a7 : 00000000`00000102 ffffdf06`22909df0 00000000`00000000 fffff805`a0d801c8 : Wdf01000!imp_WdfRequestCompleteWithInformation+0x65 [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 571] 
    fffff802`b046a720 fffff805`a0d7da52 : 000020f9`dd6f6208 00000000`00000000 ffffdf06`16474c68 ffffdf06`16474a60 : MTXP2!IfbXpTimeout+0x2af [c:\vs15\mtxp\driver\isr.c @ 4232] 
    fffff802`b046a7d0 fffff805`9d70286a : 000020f9`e9b8b4d8 ffffdf06`16474c68 00000000`00000000 fffff802`ae1cca72 : MTXP2!MtxpEvtTimerFunc+0xa2 [c:\vs15\mtxp\driver\queue.c @ 921] 
    fffff802`b046a810 fffff802`ae1cae5f : ffffdf06`16474b20 fffff805`9d6c1a02 fffff805`9d6c1ab0 fffff802`b046ab20 : Wdf01000!FxTimer::_FxTimerExtCallbackThunk+0x40dba [minkernel\wdf\framework\shared\core\fxtimer.cpp @ 440] 
    fffff802`b046a860 fffff802`ae1ca856 : fffff802`b046a9b8 ffffdf06`16474a78 00000000`00000002 fffff802`ae45c4f8 : nt!KiExpireTimer2+0x31f
    fffff802`b046a980 fffff802`ae183e4f : 00000000`0000000e 00000000`00000000 00000001`13587f91 00000000`00000019 : nt!KiTimer2Expiration+0x166
    fffff802`b046aa50 fffff802`ae253dca : 00000000`00000000 fffff802`adeef180 00000000`001a6560 fffff802`ae511400 : nt!KiRetireDpcList+0x6af
    fffff802`b046ac60 00000000`00000000 : fffff802`b046b000 fffff802`b0465000 00000000`00000000 00000000`00000000 : nt!KiIdleLoop+0x5a
    
    
    THREAD_SHA1_HASH_MOD_FUNC:  1acc0bbb7a5ecc0c21bc880e4e3f7715f4e27d69
    
    THREAD_SHA1_HASH_MOD_FUNC_OFFSET:  b30d5ceb470ffaa41e97f907744762f8ddcca92d
    
    THREAD_SHA1_HASH_MOD:  56e95eb53854150f2552555584aaa6bc02fffe5c
    
    FOLLOWUP_IP: 
    MTXP2!IfbXpTimeout+2af [c:\vs15\mtxp\driver\isr.c @ 4232]
    fffff805`a0d795a7 4d897750        mov     qword ptr [r15+50h],r14
    
    FAULT_INSTR_CODE:  5077894d
    
    FAULTING_SOURCE_LINE:  c:\vs15\mtxp\driver\isr.c
    
    FAULTING_SOURCE_FILE:  c:\vs15\mtxp\driver\isr.c
    
    FAULTING_SOURCE_LINE_NUMBER:  4232
    
    FAULTING_SOURCE_CODE:  
      4228: 		//							 IFBXP_IO_INCREMENT);
      4229: 
      4230: 		WdfRequestCompleteWithInformation(request, STATUS_TIMEOUT, 0L);
      4231: 
    > 4232: 		pExtension->CurrentRequest = NULL;
      4233: 
      4234: 		Trace(DBG_INTERRUPT, LV_INFO,
      4235: 			"<-- IfbXpTimeout status %!STATUS!", STATUS_TIMEOUT);
      4236: 
      4237: 		foundTimeout = TRUE;
    
    

    venerdì 15 febbraio 2019 08:18
    Moderatore

Risposte

  • Arguments:
    Arg1: 0000000000000038, memory referenced
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    Arg2: 0000000000000002, IRQL
    ^^^^^^^^^^^^^^^^^^^^
    Arg3: 0000000000000001, value 0 = read operation, 1 = write operation
    Arg4: fffff8059d6f2cc5, address which referenced memory
    
    STACK_TEXT:  
    fffff802`b046a3d8 fffff802`ae261269 : 00000000`0000000a 00000000`00000038 00000000`00000002 00000000`00000001 : nt!KeBugCheckEx
    fffff802`b046a3e0 fffff802`ae25dee5 : ffffdf06`1d97e1b0 ffffdf06`1d97e040 ffffdf06`1d97e040 fffff802`ae0e5313 : nt!KiBugCheckDispatch+0x69
    fffff802`b046a520 fffff805`9d6f2cc5 : ffffdf06`15d25218 00000000`c007000b 00000000`00000000 00000000`00000000 : nt!KiPageFault+0x425
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    fffff802`b046a6b0 fffff805`a0d795a7 : 00000000`00000102 ffffdf06`22909df0 00000000`00000000 fffff805`a0d801c8 : Wdf01000!imp_WdfRequestCompleteWithInformation+0x65 [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 571] 
    fffff802`b046a720 fffff805`a0d7da52 : 000020f9`dd6f6208 00000000`00000000 ffffdf06`16474c68 ffffdf06`16474a60 : MTXP2!IfbXpTimeout+0x2af [c:\vs15\mtxp\driver\isr.c @ 4232] 
    fffff802`b046a7d0 fffff805`9d70286a : 000020f9`e9b8b4d8 ffffdf06`16474c68 00000000`00000000 fffff802`ae1cca72 : MTXP2!MtxpEvtTimerFunc+0xa2 [c:\vs15\mtxp\driver\queue.c @ 921] 
    fffff802`b046a810 fffff802`ae1cae5f : ffffdf06`16474b20 fffff805`9d6c1a02 fffff805`9d6c1ab0 fffff802`b046ab20 : Wdf01000!FxTimer::_FxTimerExtCallbackThunk+0x40dba [minkernel\wdf\framework\shared\core\fxtimer.cpp @ 440] 
    fffff802`b046a860 fffff802`ae1ca856 : fffff802`b046a9b8 ffffdf06`16474a78 00000000`00000002 fffff802`ae45c4f8 : nt!KiExpireTimer2+0x31f
    fffff802`b046a980 fffff802`ae183e4f : 00000000`0000000e 00000000`00000000 00000001`13587f91 00000000`00000019 : nt!KiTimer2Expiration+0x166
    fffff802`b046aa50 fffff802`ae253dca : 00000000`00000000 fffff802`adeef180 00000000`001a6560 fffff802`ae511400 : nt!KiRetireDpcList+0x6af
    fffff802`b046ac60 00000000`00000000 : fffff802`b046b000 fffff802`b0465000 00000000`00000000 00000000`00000000 : nt!KiIdleLoop+0x5a
    
    典型的なメモリ破壊です。
    だれかがカーネル モード空間内のどっかのメモリを壊して、"0000000000000038" に書き換えた。
    で、"0000000000000038" の仮想アドレス空間は物理メモリ上にマップされていないから、NT カーネルはその壊れたアドレスが pagefile.sys に Pageout しているんだと思い込んで Page Fault を発生させ、Pagein をさせようとした。
    しかし NT カーネル アーキテクチャの大原則として、Page Fault は PASSIVE_LEVEL 以外で発生させてはいけないから、DISPATCH_LEVEL に引き上げられら Completion Routine 内で Page Fault が発生するのは規則違反。
    なので DRIVER_IRQL_NOT_LESS_OR_EQUAL で BSOD ということだと思います。
    なんのデバイスかは知りませんが、毎回同一デバイス スタック内で落ちるのであれば、そのデバイス スタックを構成するドライバのどれかがバグっているいるんだと思います。
    逆に、全くことなるデバイス スタック内で落ちるのであれば、そのシステムにインストールされている他の 3rd ベンダー製ドライバの可能性も考えられる。
    毎回 MTXP2 モジュールが介在してる状態で落ちるのなら、このモジュールの可能性が高いと思うので、"Driver Verifier" でチェックすれば簡単に見つかると思います。

    venerdì 15 febbraio 2019 09:11

Tutte le risposte

  • Arguments:
    Arg1: 0000000000000038, memory referenced
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    Arg2: 0000000000000002, IRQL
    ^^^^^^^^^^^^^^^^^^^^
    Arg3: 0000000000000001, value 0 = read operation, 1 = write operation
    Arg4: fffff8059d6f2cc5, address which referenced memory
    
    STACK_TEXT:  
    fffff802`b046a3d8 fffff802`ae261269 : 00000000`0000000a 00000000`00000038 00000000`00000002 00000000`00000001 : nt!KeBugCheckEx
    fffff802`b046a3e0 fffff802`ae25dee5 : ffffdf06`1d97e1b0 ffffdf06`1d97e040 ffffdf06`1d97e040 fffff802`ae0e5313 : nt!KiBugCheckDispatch+0x69
    fffff802`b046a520 fffff805`9d6f2cc5 : ffffdf06`15d25218 00000000`c007000b 00000000`00000000 00000000`00000000 : nt!KiPageFault+0x425
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    fffff802`b046a6b0 fffff805`a0d795a7 : 00000000`00000102 ffffdf06`22909df0 00000000`00000000 fffff805`a0d801c8 : Wdf01000!imp_WdfRequestCompleteWithInformation+0x65 [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 571] 
    fffff802`b046a720 fffff805`a0d7da52 : 000020f9`dd6f6208 00000000`00000000 ffffdf06`16474c68 ffffdf06`16474a60 : MTXP2!IfbXpTimeout+0x2af [c:\vs15\mtxp\driver\isr.c @ 4232] 
    fffff802`b046a7d0 fffff805`9d70286a : 000020f9`e9b8b4d8 ffffdf06`16474c68 00000000`00000000 fffff802`ae1cca72 : MTXP2!MtxpEvtTimerFunc+0xa2 [c:\vs15\mtxp\driver\queue.c @ 921] 
    fffff802`b046a810 fffff802`ae1cae5f : ffffdf06`16474b20 fffff805`9d6c1a02 fffff805`9d6c1ab0 fffff802`b046ab20 : Wdf01000!FxTimer::_FxTimerExtCallbackThunk+0x40dba [minkernel\wdf\framework\shared\core\fxtimer.cpp @ 440] 
    fffff802`b046a860 fffff802`ae1ca856 : fffff802`b046a9b8 ffffdf06`16474a78 00000000`00000002 fffff802`ae45c4f8 : nt!KiExpireTimer2+0x31f
    fffff802`b046a980 fffff802`ae183e4f : 00000000`0000000e 00000000`00000000 00000001`13587f91 00000000`00000019 : nt!KiTimer2Expiration+0x166
    fffff802`b046aa50 fffff802`ae253dca : 00000000`00000000 fffff802`adeef180 00000000`001a6560 fffff802`ae511400 : nt!KiRetireDpcList+0x6af
    fffff802`b046ac60 00000000`00000000 : fffff802`b046b000 fffff802`b0465000 00000000`00000000 00000000`00000000 : nt!KiIdleLoop+0x5a
    
    典型的なメモリ破壊です。
    だれかがカーネル モード空間内のどっかのメモリを壊して、"0000000000000038" に書き換えた。
    で、"0000000000000038" の仮想アドレス空間は物理メモリ上にマップされていないから、NT カーネルはその壊れたアドレスが pagefile.sys に Pageout しているんだと思い込んで Page Fault を発生させ、Pagein をさせようとした。
    しかし NT カーネル アーキテクチャの大原則として、Page Fault は PASSIVE_LEVEL 以外で発生させてはいけないから、DISPATCH_LEVEL に引き上げられら Completion Routine 内で Page Fault が発生するのは規則違反。
    なので DRIVER_IRQL_NOT_LESS_OR_EQUAL で BSOD ということだと思います。
    なんのデバイスかは知りませんが、毎回同一デバイス スタック内で落ちるのであれば、そのデバイス スタックを構成するドライバのどれかがバグっているいるんだと思います。
    逆に、全くことなるデバイス スタック内で落ちるのであれば、そのシステムにインストールされている他の 3rd ベンダー製ドライバの可能性も考えられる。
    毎回 MTXP2 モジュールが介在してる状態で落ちるのなら、このモジュールの可能性が高いと思うので、"Driver Verifier" でチェックすれば簡単に見つかると思います。

    venerdì 15 febbraio 2019 09:11
  • 早々に丁寧な回答頂き、ありがとうございます。良くわかりました。ほかのMiniDumpも調べていますが、どうもドライバーの作りが悪く排他制御がうまく動作していない様子です。

    補足しますとデバイスはPCIで、現象発生は数か所のマシンで1時間から2時間に1回程度のランダム、BSOD発生のモジュールは毎回同じMTXP2ですが、ドライバーのコード中では比較的様々な場所で発生しています。実機が手元に無く、また"Driver Verifier"の実機操作もできない状況なので現在、排他制御の検証コードをドライバーに作っています。結果がわかりましたらここで報告致します。ありがとうございました。

    venerdì 15 febbraio 2019 12:57
    Moderatore
  • 既に複数のダンプファイルが採取されているのであれば、それらに共通点がないか再検証されることをお勧めします。
    今回提示されているダンプでは、DeviceExtension 構造体のメンバー参照時に BSOD に陥っているようですが、他のダンプでも同様のタイミングで起きているのであれば、メモリ破壊以外に以下の可能性も考えられます。

    ☆ DeviceExtension を持たない DeviceObject  (i.g.] Control Device Object) へのリクエストを、Functional  Device Object へのリクエストとして処理した。
    ☆ Remove 関連の PnP IRP の実装上の不備。

    BSOD 発生時に、アクセスしようとしている場所、あるいは処理しようとしているリクエスト (IRP) 等に共通点があるのであれば、それが問題箇所を特定するための重要なヒントになります。
    sabato 16 febbraio 2019 11:38
  • お馬鹿様、回答とアドバイスを頂き、ありがとうございます。

    発生原因がどうにも不明なので、アドバイスに従って手元にシミュレーション環境を構築してDriver Verifierを入れて動かしたところ、あっさりとDRIVER_PAGE_FAULT_IN_FREED_SPECIAL_POOL

    というBSODが出ました。これは元のWindows 2000時代のコードが実行している「Start IO」の動作が、Windows 10 1803頃から親IRPを実行中にも、IRPを解放する頻度が増えたのが原因と推定して、「Start IO」だった処理をDispatchルーチンに移動したところ、発生頻度が減りました。コードはWDM WDF混在だったのがKMDF統一になってスッキリしましたが、まだ別のエラーが出る場合があるので、引き続き調査中です。

    現在は、比較的シンプルなPCIドライバーとなりました。Control Device Objectは使っていませんし、Remove 関連の PnP IRPも動作の機会がありません。この件は一旦クローズさせていただきます。ありがとうございました。

    lunedì 18 febbraio 2019 05:38
    Moderatore
  • > これは元のWindows 2000時代のコードが実行している「Start IO」の動作が、
    > Windows 10 1803頃から親IRPを実行中にも、
    > IRPを解放する頻度が増えたのが原因と推定して、

    手元にある Driver Framework の Source Code を基に、BSOD 発生箇所 (Wdf01000!imp_WdfRequestCompleteWithInformation+0x65) で止めてみたところ、下記場所でした。

    -------------------------------
    
     # Child-SP          RetAddr           : Args to Child                                                           : Call Site
    00 (Inline Function) --------`-------- : --------`-------- --------`-------- --------`-------- --------`-------- : Wdf01000!FxIrp::SetInformation (Inline Function @ fffff80b`f10a6420) [minkernel\wdf\framework\shared\inc\private\km\fxirpkm.hpp @ 467] 
    01 (Inline Function) --------`-------- : --------`-------- --------`-------- --------`-------- --------`-------- : Wdf01000!FxRequest::CompleteWithInformation (Inline Function @ fffff80b`f10a6420) [minkernel\wdf\framework\shared\inc\private\common\fxrequest.hpp @ 819] 
    02 ffffc68b`d4fc4880 fffff807`25976bd4 : 00000000`00000000 ffffca88`d7710d30 00003577`288ef2c8 ffffca88`d71c0b20 : Wdf01000!imp_WdfRequestCompleteWithInformation+0x60 [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 571] 
    03 ffffc68b`d4fc48e0 fffff807`25989685 : 00000000`00000001 00000000`00000028 ffffc68b`fffffffe ffffca88`d7710d30 : cdrom!RequestCompletion+0x1c0
    04 ffffc68b`d4fc49a0 fffff807`25988a61 : ffffca88`d726ae40 ffffc68b`d4fc4ac0 ffffca88`d71c0b20 00000000`00000000 : cdrom!RequestProcessSerializedIoctl+0xab1
    05 ffffc68b`d4fc4a50 fffff80b`f10b412a : ffffca88`d3f20080 ffffc68b`d4fc4a80 fffff807`23177240 00000000`00000000 : cdrom!IoctlWorkItemRoutine+0x71
    06 ffffc68b`d4fc4a80 fffff80b`f10b3fb9 : ffff8d00`c2a67100 ffffca88`d726ae40 ffffca88`d7702300 fffff807`22cceca9 : Wdf01000!FxWorkItem::WorkItemHandler+0x7e [minkernel\wdf\framework\shared\core\fxworkitem.cpp @ 374] 
    07 ffffc68b`d4fc4ac0 fffff807`22c88f7c : ffffca88`d3cc0880 ffffca88`00000000 ffffca88`d3f20080 00000000`00000000 : Wdf01000!FxWorkItem::WorkItemThunk+0x29 [minkernel\wdf\framework\shared\core\fxworkitem.cpp @ 439] 
    08 ffffc68b`d4fc4b00 fffff807`22cce1ea : ffffca88`d328b9a0 ffffca88`d7702300 fffff807`22c88e50 00000000`00000000 : nt!IopProcessWorkItem+0x12c
    09 ffffc68b`d4fc4b70 fffff807`22ca0bc5 : ffffca88`d7702300 ffffca88`d3297040 ffffca88`d7702300 000024a5`b19bbfff : nt!ExpWorkerThread+0x16a
    0a ffffc68b`d4fc4c10 fffff807`22dd489c : fffff807`21ca7180 ffffca88`d7702300 fffff807`22ca0b70 00000000`00000000 : nt!PspSystemThreadStartup+0x55
    0b ffffc68b`d4fc4c60 00000000`00000000 : ffffc68b`d4fc5000 ffffc68b`d4fbf000 00000000`00000000 00000000`00000000 : nt!KiStartSystemThread+0x1c
    
    -------------------------------
    
    Wdf01000!FxIrp::SetInformation [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 571] [inlined in Wdf01000!imp_WdfRequestCompleteWithInformation+0x60 [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 571]]:
    fffff80b`f10a6420 488b8398000000  mov     rax,qword ptr [rbx+98h]
    fffff80b`f10a6427 48897838        mov     qword ptr [rax+38h],rdi
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    fffff80b`f10a642b 488b7b60        mov     rdi,qword ptr [rbx+60h]
    fffff80b`f10a642f 488b4b10        mov     rcx,qword ptr [rbx+10h]
    fffff80b`f10a6433 4038a944010000  cmp     byte ptr [rcx+144h],bpl
    fffff80b`f10a643a 0f8509e40100    jne     Wdf01000!imp_WdfRequestCompleteWithInformation+0x1e489 (fffff80b`f10c4849)
    fffff80b`f10a6440 4885ff          test    rdi,rdi
    fffff80b`f10a6443 742c            je      Wdf01000!imp_WdfRequestCompleteWithInformation+0xb1 (fffff80b`f10a6471)
    
    -------------------------------
    
    __inline
    VOID
    FxIrp::SetInformation(
        ULONG_PTR Information
        )
    {
        m_Irp->IoStatus.Information = Information;
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    }
    
    -------------------------------
    
    Local var @ 0xffffc68bd4fc48e8 Type FxRequest*
    0xffffca88`d7710d30 
       +0x098 m_Irp  : 
          +0x000 m_Irp  : 0xffffca88`d71178a0 _IRP
       +0x0d0 m_IrpCompletionReferenceCount : 0n0
       +0x0d5 m_IrpAllocation : 0 ''
       +0x0dc m_IrpReferenceCount : 0n0
       +0x0e0 m_IrpQueue : 
    
    -------------------------------
    なので提示されているダンプので BSOD は、IRP の二重解放が原因のようです。




    • Modificato お馬鹿 martedì 19 febbraio 2019 01:43
    martedì 19 febbraio 2019 01:42
  • お馬鹿様

    わざわざ調べて頂いてありがとうございます。ご指摘の場所のコードには何回もぶち当たっています。様々なエラーが出る中で、前述の通りStart IOを使わないようにして頻度を減らすことには成功したのですが、それでも各所のWdfRequestComplete直前のタイミングで、 まれにm_Irpがゼロになり、0x38にResult(information)を書き込むとことでBSODという現象が発生しています。根本原因は治っていない訳です。現在は該当ルーチンに入った時に、処理を進める前に、Requestの値を調べてゼロなら抜けるという消極的なBSOD回避策を試しています。

    WDFで完了処理していないのに、Requestが無くなる(ゼロになる)というケースは考えられないと思うのですが、いかがでしょう。

    domenica 24 febbraio 2019 13:48
    Moderatore
  • > 様々なエラーが出る中で、
    > 前述の通りStart IOを使わないようにして頻度を減らすことには成功したのですが、
    > それでも各所のWdfRequestComplete直前のタイミングで、
    > まれにm_Irpがゼロになり、
    > 0x38にResult(information)を書き込むとことでBSODという現象が発生しています。

    先に返信でも触れましたが、WDFREQUEST ハンドルから算出される FxRequest クラス m_Irp メンバーに NULL がセットされるということは、WDF (Framework Driver) 側が既にその IRP に対して完了ルーチンでの処理を実施した後の状態であると考えられるため、少なくとも WDF 側はそのリクエスト (IRP) は完了していると認識しているはずです。
    (デバッガで Wdf01000!imp_WdfRequestCompleteWithInformation ルーチンからの挙動をトレースしていけば確認できますが、Wdf01000!FxRequest::CompleteInternal メソッド内での処理が完了した時点で、FxRequest クラス m_Irp メンバーには NULL がセットされます。)
    その状態で再度完了ルーチンでの処理を実施しようとした。。。つまり IRP の二重解放処理をしようとしたので、今回の BSOD が発生しているのだと思います。
    ですので本質的な問題は、FxRequest クラス m_Irp メンバーに NULL がセットされていることではなく、そのような IRP の二重解放の状況に陥ってしまうことだと思います。
    つまり、ご自身が作成された KMDF 側では「WDFで完了処理していない」と思っていても、WDF 側は IRP を完了していると認識している、この IRP の状態に対する認識の不一致が根本的な原因だと思います。

    この問題は、不特定の IRP に対して起きるのでしょうか?
    特定の IRP に対して子 IRP を生成させている場合、親子関係にある IRP の同期処理 (整合性) に不備があると、今回のような問題が発生する可能性が考えられると思います。

    P.S.
    これ↓に該当している可能性はないのでしょうか?
    ------------------------------------------------
    Synchronizing Cancel and Completion Code
    https://docs.microsoft.com/en-us/windows-hardware/drivers/wdf/synchronizing-cancel-and-completion-code
    ------------------------------------------------

    • Modificato お馬鹿 lunedì 25 febbraio 2019 08:56 追記
    lunedì 25 febbraio 2019 03:56
  • ご指摘頂き、ありがとうございます。

    Cancel関係は使ってないのです。気になることは、元々はWDM+WinDKでDPCだったIsrのコードを私が、WdfInterruptQueueWorkItemForIsr に書き換えた事による影響ぐらいですが、それもStartIOを止めてから、通常運用では問題無く動作する様になりました。お客様先の実機でテスト用のアプリを動作させた場合、ごくまれにRequestがゼロになる現象が発生していたのですが、それもさらに「Requestの値を調べてゼロなら抜ける」という処理で発生しなくなりました。

    Cancelが無く、Completeもしてないのに、どこでRequestがゼロになる場合が発生するのかはいまだに不明なのですが、取りあえずは再現が難しくなってしまったので、このまま様子を見ています。

    giovedì 7 marzo 2019 09:19
    Moderatore
  • 釈迦に説法なのかもしれませんが。。。
    この BSOD が毎回 "Wdf01000!imp_WdfRequestCompleteWithInformation+0x65" で発生するのであれば、IRP の二重解放が原因だと思います。
    つまり、問題は「割込み処理」ではなく「I/O リクエスト処理」にあると考えます。
    私が実際にデバッグした訳ではないので断言はできませんが、経験上、IRP の二重解放は大抵の場合ドライバ内での実装ロジック上の不備で発生するので、特定の IRP でのみ発生するのがほとんどです。
    なので、その原因となる IRP さえ特定できれば、確認すべき実装個所も特定できると思っています。

    もし私がこの BSOD を調べるとしたら、Dispatch Routine に入ってきた IRP と Completion Routine が呼びだれた IRP の情報をログに吐かせ、そのログと BSOD 発生時のダンプを照合することで、どの IRP で二重解放が発生しているのかを確認する。。。という調査を実施すると思います。
    venerdì 8 marzo 2019 01:52
  • お馬鹿様

    気にかけて頂きまして、ありがとうございます。

    本日、久しぶりにエンドユーザーのところから送られて来たダンプを調べたところ、IRP が消える(ゼロ)になる場所が、ioControlのDispatchルーチンに入った直後だったり、該当ドライバーに入る前だったりしているのです。以前から特定の場所では発生していないのは何となく感じていたのですが、決定的な状況です。モグラ叩き的な対策をした結果、頻度は減ったのですがとんでもない所にモグラが出るようになったという事です。

    ご参考までにドライバーに入る前というのは、KMDFの Irp ハンドラ

    https://github.com/Microsoft/Windows-Driver-Frameworks/blob/master/src/framework/shared/irphandlers/io/fxioqueue.cpp

    の3238行目のpIrpがゼロなのです。

    3236:    hRequest = pRequest->GetHandle();
    3237:
    3238:    UCHAR majorFunction = pIrp->GetMajorFunction();

    根拠はありませんが、ハードウェアがらみの問題ではないかと思っています。

    mercoledì 13 marzo 2019 12:34
    Moderatore
  • > の3238行目のpIrpがゼロなのです。

    そこで「pIrpがゼロ」になるということは、FxRequest クラス m_Irp メンバーに NULL がセットされてしまっているということですから、IRP の二重解放かメモリ破壊かのいずれかが起きたと考えるのが妥当だと思います。
    ただ、BSOD 発生時の状況が毎回 m_Irp メンバーの NULL に起因しているのであれば、メモリ破壊の可能性は極めて低いと思います。
    (そんな器用にピンポイントで、しかも狙い撃ちしたかのような m_Irp メンバーの破壊を、不定期に起こせるとは思えません。)
    また該当ドライバが m_Irp メンバーを NULL にセットする必要性も無いと思うので、繰り返しになりますが、個人的には IRP の二重解放が原因だと思います。

    ioControlのDispatchルーチンに入った直後だったり」ということは、今回の BSOD は特定の (もしかしたら特定かつ複数の) IOCTL コードでのみ発生しているのかもしれません。
    複数のダンプ ファイルがあるなら、そこからオリジナルの IRP 特定し、処理しようとしていた IOCTL コードも割り出せるのでは?
    試しに手元の VMWare 環境で該当箇所に Breakpoint を張り止めてみたところ、以下のような感じで確認できました。

    0: kd> k
     # Child-SP          RetAddr           Call Site
    00 (Inline Function) --------`-------- Wdf01000!FxIrp::GetMajorFunction [minkernel\wdf\framework\shared\inc\private\km\fxirpkm.hpp @ 263] 
    01 fffff806`7666b0e0 fffff80e`38c29297 Wdf01000!FxIoQueue::DispatchRequestToDriver+0xb0 [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 3238] 
    02 fffff806`7666b180 fffff80e`38c281f5 Wdf01000!FxIoQueue::DispatchEvents+0x617 [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 3125] 
    03 (Inline Function) --------`-------- Wdf01000!FxIoQueue::QueueRequestFromForward+0x285 [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 2493] 
    04 fffff806`7666b260 fffff80e`38c2ab0f Wdf01000!FxPkgIo::EnqueueRequest+0x375 [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 697] 
    05 fffff806`7666b310 fffff806`76a9292b Wdf01000!imp_WdfDeviceEnqueueRequest+0xbf [minkernel\wdf\framework\shared\core\fxdeviceapi.cpp @ 2074] 
    06 fffff806`7666b370 fffff806`76a9201f cdrom!RequestDispatchSpecialIoctls+0x283
    07 fffff806`7666b410 fffff80e`38c2763b cdrom!DeviceEvtIoInCallerContext+0x2bf
    08 (Inline Function) --------`-------- Wdf01000!FxIoInCallerContext::Invoke+0x19 [minkernel\wdf\framework\shared\inc\private\common\fxdevicecallbacks.hpp @ 55] 
    09 (Inline Function) --------`-------- Wdf01000!FxPkgIo::DispathToInCallerContextCallback+0xbc [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 1748] 
    0a (Inline Function) --------`-------- Wdf01000!FxPkgIo::DispatchStep2+0x61b [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 459] 
    0b fffff806`7666b5a0 fffff80e`38c26f8d Wdf01000!FxPkgIo::DispatchStep1+0x69b [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 324] 
    0c fffff806`7666b660 fffff80e`38c21b73 Wdf01000!FxPkgIo::Dispatch+0x5d [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 119] 
    0d (Inline Function) --------`-------- Wdf01000!DispatchWorker+0x9e [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1572] 
    0e (Inline Function) --------`-------- Wdf01000!FxDevice::Dispatch+0xbc [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1586] 
    0f fffff806`7666b6c0 fffff806`73f540d9 Wdf01000!FxDevice::DispatchWithLock+0x113 [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1430] 
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    10 fffff806`7666b720 fffff806`76a97bcf nt!IofCallDriver+0x59
    11 fffff806`7666b760 fffff806`76a9e32f cdrom!RequestHandleEventNotification+0x177
    12 fffff806`7666b7d0 fffff80e`38c22e0e cdrom!DeviceMainTimerTickHandler+0x5f
    13 (Inline Function) --------`-------- Wdf01000!FxTimer::TimerHandler+0x8c [minkernel\wdf\framework\shared\core\fxtimer.cpp @ 343] 
    14 fffff806`7666b800 fffff806`73fc9190 Wdf01000!FxTimer::_FxTimerExtCallbackThunk+0xbe [minkernel\wdf\framework\shared\core\fxtimer.cpp @ 440] 
    15 fffff806`7666b850 fffff806`73fc8b97 nt!KiExpireTimer2+0x340
    16 fffff806`7666b980 fffff806`73f5478d nt!KiTimer2Expiration+0x257
    17 fffff806`7666ba50 fffff806`74052e5a nt!KiRetireDpcList+0x68d
    18 fffff806`7666bc60 00000000`00000000 nt!KiIdleLoop+0x5a
    
    0: kd> .frame 0f
    0f fffff806`7666b6c0 fffff806`73f540d9 Wdf01000!FxDevice::DispatchWithLock+0x113 [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1430] 
    
    0: kd> dv /V
    <unavailable>     <unavailable>        DeviceObject = <value unavailable>
    @rbx              @rbx                          Irp = 0xffffce8d`ac23d8a0
                                                           ^^^^^^^^^^^^^^^^^
    @esi              @esi                       status = 0n336
    
    0: kd> !irp 0xffffce8d`ac23d8a0
    Irp is active with 4 stacks 2 is current (= 0xffffce8dac23d9b8)
     No Mdl: No System Buffer: Thread 00000000:  Irp stack trace.  
         cmd  flg cl Device   File     Completion-Context
     [N/A(0), N/A(0)]
                0  0 00000000 00000000 00000000-00000000    
    
    			Args: 00000000 00000000 00000000 00000000
    >[IRP_MJ_DEVICE_CONTROL(e), N/A(0)]
                2 e1 ffffce8da8daadc0 00000000 00000000-00000000    pending
    	       \Driver\cdrom
    			Args: fffff80676a9e420 fffff80676a9e420 0x7c0c8 fffff80676a9e420
     [IRP_MJ_DEVICE_CONTROL(e), N/A(0)]
                2 e0 ffffce8da8daadc0 00000000 fffff80676a9e3d0-ffffce8dac1bbb20 Success Error Cancel 
    	       \Driver\cdrom	cdrom!RequestMcnSyncIrpCompletion
    			Args: fffff80676a9e420 fffff80676a9e420 0x7c0c8 fffff80676a9e420
     [IRP_MJ_CREATE(0), N/A(0)]
                0  0 ffffce8da8daadc0 00000000 00000000-00000000    
    	       \Driver\cdrom
    			Args: 00000000 00000000 00000000 00000000
    
    0: kd> dt nt!_IRP 0xffffce8d`ac23d8a0 Tail.Overlay.Cu*
       +0x078 Tail            : 
          +0x000 Overlay         : 
             +0x040 CurrentStackLocation : 0xffffce8d`ac23d9b8 _IO_STACK_LOCATION
    
    0: kd> dt nt!_IO_STACK_LOCATION 0xffffce8d`ac23d9b8 Parameters.DeviceIoControl.
       +0x008 Parameters                  : 
          +0x000 DeviceIoControl             : 
             +0x000 OutputBufferLength          : 0x76a9e420
             +0x008 InputBufferLength           : 0x76a9e420
             +0x010 IoControlCode               : 0x7c0c8
             ^^^^^^^^^^^^^^^^^^^^^^^^^^
             +0x018 Type3InputBuffer            : 0xfffff806`76a9e420 Void
    
    #define IOCTL_DISK_UPDATE_DRIVE_SIZE        CTL_CODE(IOCTL_DISK_BASE, 0x0032, METHOD_BUFFERED, FILE_READ_ACCESS | FILE_WRITE_ACCESS)
    

    上記例では、IoControlCode が 0x7c0c8 ですので、このスレッドでは IOCTL_DISK_UPDATE_DRIVE_SIZE コードを処理中であることが分かります。
    カーネル ダンプだと、記録される情報が限定的になってしまうためここまで確認できるかどうかはわかりませんが、「完全メモリ ダンプ」を採取すれば、きちんとここまで確認できると思います。

    蛇足ですが。。。
    現状までの話を聞く限り、BSOD は必ず IRP が NULL になることに起因して発生しているということなので、個人的には「ハードウェアがらみの問題」ということは無いと思います。
    (IRP は PC 側からのリクエストで発生するのだから、それをハードウェア側の挙動で NULL にすることなど不可能だと思っています。)

    giovedì 14 marzo 2019 06:54
  • お馬鹿様、この問題は結局のところ、次の2点の方策で解決しましたで、ご報告させていただきます。
    以前試していた、他のモグラ叩き的な処理は全て外しました。

    1. EvtInterruptWorkItem を EvtInterruptDpc に変更

    この処理で、発生頻度が約半分程度になり5~10時間に1回程度から、1~2日で1回程度になりました。

    2. Dispatch Routine での Work Item処理の廃止

    この処理で、実験環境で1週間以上連続運転しても発生しなくなりました。

    WDFのWork Item関連のコードは見ていましたが、結局のところカーネルのWork Itemのソースコードは公開されていないのと、最終修正の直前状態では、再現までかなりの時間がかかる様になったで、真の原因は不明のままです。

    lunedì 8 luglio 2019 11:46
    Moderatore
  • > 真の原因は不明のままです。

    Driver Verifier のチェックでも検出できなかったのでしょうか?
    martedì 9 luglio 2019 02:39
  • > Driver Verifier のチェックでも検出できなかったのでしょうか?

    はい。ご指摘頂いた2月頃からDriver Verifier 対応のためにコードをかなりいじってました。
    結果Request(IRP)が空になるエラーの発生頻度が減って、前記2点の対策をする前までは、Driver Verifier の有無、設定のいかんにかかわらず、数時間ぐらい経ってRequest(IRP)が空になり、それに起因するBSOD発生という状況でした。

    テストなので、IoCcontrolを20個ぐらいに絞り、発生頻度を上げるために、アプリ呼び出しをマルチスレッドで繰り返して回しいましたが、発生するIoControlや場所は不定でした。

    その後、対策が思いつかないので前記1.を試して発生頻度が減ったので、前記2.を試したところ、うまくいったという事です。

    martedì 9 luglio 2019 13:32
    Moderatore
  • > 1. EvtInterruptWorkItem を EvtInterruptDpc に変更
    > この処理で、発生頻度が約半分程度になり5~10時間に1回程度から、1~2日で1回程度になりました。

    上記変更により発生頻度が下がったということは、Hardware Interrupt による ISR 以降の DPC 処理で IRQL に起因する問題があった、ということだと思いますが、そこらへんの確認はされたのでしょうか?
    通常、IRP は PASSIVE_LEVEL で処理されるのに対し、ISR は DIRQL、DPC は DISPATCH_LEVEL で実行されるので、DPC 処理は IRP 処理よりも優先されます。
    上記変更により発生頻度が下がったということは、本来 IRP 処理よりも優先されるべき DPC 処理が「逆転」してしまっている状況が発生していたのでは?
    つまりドライバの実装として、IRP と Hardware Interrupt の処理において、その優先順位に矛盾が発生するロジックになっていたのだと思います。
    (私が自分でデバッグしたわけではないので、単なる「空想」ですが。)
    mercoledì 10 luglio 2019 00:07
  • そこらへんの確認は基本的な事ですので、何回もしていました。ですので、Dispatch Routine で Work Itemを止めたらピタリと止まったことと合わせて、真相は謎のままです。
    venerdì 19 luglio 2019 14:33
    Moderatore