troushoo

強制終了できないプロセスの原因を、ダンプ / カーネルデバッグで調査 (ドライバーでデッドロック)

強制終了できないプロセスの原因調査の方法を紹介します。

強制終了できないプロセスとは
管理者権限を持つタスクマネージャーでプロセスを強制終了させようとしても、「アクセスが拒否されました。」と表示され、強制終了させることができないプロセスがあります。



以下、強制終了できないプロセスの原因の調査方法例を紹介します。

強制終了できないプロセスの原因調査の方法
1. プロセスを強制終了できない状態でダンプをとるか、カーネルデバッガーをアタッチします。

2. 強制終了できないプロセスのコールスタックを「!process 0 1f <強制終了できないプロセス名>」で見てみます。
すると、「nt!ExAcquireFastMutex」で Fast Mutex のシグナルを 10:43:234 待っているスレッドがいました。

0: kd> !process 0 1f notmyfault.exe
PROCESS ffff8301ee78a080
    SessionId: 1  Cid: 0d54    Peb: 007b1000  ParentCid: 0d5c
    DirBase: 110fd000  ObjectTable: ffffaf022bafe240  HandleCount: <Data Not Accessible>
    Image: NotMyfault.exe
    VadRoot ffff8301ec391ca0 Vads 106 Clone 0 Private 583. Modified 1354. Locked 0.
    DeviceMap ffffaf02366661f0
    Token                             ffffaf023757e060
    ElapsedTime                       00:10:50.397
    UserTime                          00:00:00.000
    KernelTime                        00:00:00.000
    QuotaPoolUsage[PagedPool]         253240
    QuotaPoolUsage[NonPagedPool]      14664
    Working Set Sizes (now,min,max)  (5, 50, 345) (20KB, 200KB, 1380KB)
    PeakWorkingSetSize                3915
    VirtualSize                       127 Mb
    PeakVirtualSize                   176 Mb
    PageFaultCount                    5459
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      728
    Job                               ffff8301ee780060

        THREAD ffff8301eea4f080  Cid 0d54.0d4c  Teb: 00000000007b2000 Win32Thread: ffff8301eb83dcf0 WAIT: (WrFastMutex) KernelMode Non-Alertable
            fffff80cfd8e3198  SynchronizationEvent
        IRP List:
            ffff8301ec67f150: (0006,0118) Flags: 00060000  Mdl: 00000000
        Not impersonating
        DeviceMap                 ffffaf02366661f0
        Owning Process            ffff8301ee78a080       Image:         NotMyfault.exe
        Attached Process          N/A            Image:         N/A
        Wait Start TickCount      3135           Ticks: 41167 (0:00:10:43.234)
        Context Switch Count      920            IdealProcessor: 1            
        UserTime                  00:00:00.031
        KernelTime                00:00:00.046
        Win32 Start Address 0x00007ff77ca32f98
        Stack Init ffffe3802d33ffd0 Current ffffe3802d33f5b0
        Base ffffe3802d340000 Limit ffffe3802d33a000 Call 0000000000000000
        Priority 12 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
*** ERROR: Module load completed but symbols could not be loaded for myfault.sys
        Child-SP          RetAddr           Call Site
        ffffe380`2d33f5f0 fffff800`b8aeff5c nt!KiSwapContext+0x76
        ffffe380`2d33f730 fffff800`b8aef9ff nt!KiSwapThread+0x17c
        ffffe380`2d33f7e0 fffff800`b8af17c7 nt!KiCommitThreadWait+0x14f
        ffffe380`2d33f880 fffff800`b8b07251 nt!KeWaitForSingleObject+0x377
        ffffe380`2d33f930 fffff800`b8ae72a8 nt!ExpAcquireFastMutexContended+0x79
        ffffe380`2d33f970 fffff80c`fd8e148c nt!ExAcquireFastMutex+0x138
        ffffe380`2d33f9b0 fffff80c`fd8e1727 myfault+0x148c
        ffffe380`2d33fb00 fffff800`b8f18cd0 myfault+0x1727
        ffffe380`2d33fb60 fffff800`b8f17bb4 nt!IopSynchronousServiceTail+0x1a0
        ffffe380`2d33fc20 fffff800`b8f17536 nt!IopXxxControlFile+0x674
        ffffe380`2d33fd60 fffff800`b8bdf393 nt!NtDeviceIoControlFile+0x56
        ffffe380`2d33fdd0 00007ffc`b28f61b4 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffe380`2d33fe40)
        00000000`004fede8 00000000`00000000 0x00007ffc`b28f61b4

*ログは抜粋です。


3. Fast Mutex の状態を調べるため、Mex のコマンド「!wrfastmutex」を実行します。
すると、スレッド ffff8301eea4f080 が、Fast Mutex のシグナル化を待っており (WrFastMutex)、その Fast Mutext を持っているスレッド (Owning Thread) は ffff8301eea4f080、すなわち自分自身ということがわかります。
0: kd> !wrfastmutex

Process        PID Thread            Id CSwitches User Kernel State         Time Reason      Waiting On                      Wait Function
============== === ================ === ========= ==== ====== ======= ========== =========== =============================== ===========================
NotMyfault.exe d54 ffff8301eea4f080 d4c       920 31ms   47ms Waiting 10m:43.234 WrFastMutex Owning Thread: ffff8301eea4f080 nt!ExAcquireFastMutex+0x138
Count: 1

*ログは抜粋です。

よって、自分自身でデッドロックしており処理が進まなかった、ということがわかり、これが、プロセスを強制終了できなかった理由です。

今回用いたプログラム
今回使用した nomyfault.exe は、Microsoft が公開しているドライバーのバグを紹介するためのツール NotMyFault です。
今回は、nomyfault.exe の「Deadlock」を実行し、完全ダンプを取得しました。


NotMyFault はソースコードも公開されていたので、ソースコードを見てみます。
(最新版の NotMyFault は、ソースコードは公開されておりませんでしたが、以前はダウンロードした NotMyFault の中にソースも含まれておりました。)
結果、すでに Fast Mutex を持っている状態で Fast Mutex の取得を試みているためにデッドロックが発生するコードになっていたことがわかります。

//----------------------------------------------------------------------
//
// DeadLock
//
// Try to grab a fast mutext when we already own it so that there's a 
// deadlock. This can be debugged with CrashOnCtrlScroll and then using
// the !thread 0 7 NotMyfault.exe debugger command to look at the thread
// stack. 
//
//----------------------------------------------------------------------
FAST_MUTEX     Fmutex1;
FAST_MUTEX     Fmutex2;
 
VOID
DeadLock(
    VOID 
    )
{
    ExInitializeFastMutex( &Fmutex1 );
    ExInitializeFastMutex( &Fmutex2 );
 
    ExAcquireFastMutex( &Fmutex1 );
    ExAcquireFastMutex( &Fmutex2 );
 
    //
    // Driver Verifier expects that Fmutex2 is released before Fmutex1.
    // The lock hierarchy is not respected as Fmutex2 was acquired last.
    //
    ExReleaseFastMutex( &Fmutex1 );
 
    ExAcquireFastMutex( &Fmutex2 );
}

補足
Mex を使用しないでデバッグすることも可能です。
1. 強制終了できないプロセスのコールスタックを「!process 0 1f notmyfault.exe」で見てみます。
すると、スレッドは SynchronizationEvent を待っていることがわかります。

0: kd> !process 0 1f notmyfault.exe
PROCESS ffff8301ee78a080
    SessionId: 1  Cid: 0d54    Peb: 007b1000  ParentCid: 0d5c
    DirBase: 110fd000  ObjectTable: ffffaf022bafe240  HandleCount: <Data Not Accessible>
    Image: NotMyfault.exe
    VadRoot ffff8301ec391ca0 Vads 106 Clone 0 Private 583. Modified 1354. Locked 0.
    DeviceMap ffffaf02366661f0
    Token                             ffffaf023757e060
    ElapsedTime                       00:10:50.397
    UserTime                          00:00:00.000
    KernelTime                        00:00:00.000
    QuotaPoolUsage[PagedPool]         253240
    QuotaPoolUsage[NonPagedPool]      14664
    Working Set Sizes (now,min,max)  (5, 50, 345) (20KB, 200KB, 1380KB)
    PeakWorkingSetSize                3915
    VirtualSize                       127 Mb
    PeakVirtualSize                   176 Mb
    PageFaultCount                    5459
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      728
    Job                               ffff8301ee780060

        THREAD ffff8301eea4f080  Cid 0d54.0d4c  Teb: 00000000007b2000 Win32Thread: ffff8301eb83dcf0 WAIT: (WrFastMutex) KernelMode Non-Alertable
            fffff80cfd8e3198  SynchronizationEvent
        IRP List:
            ffff8301ec67f150: (0006,0118) Flags: 00060000  Mdl: 00000000
        Not impersonating
        DeviceMap                 ffffaf02366661f0
        Owning Process            ffff8301ee78a080       Image:         NotMyfault.exe
        Attached Process          N/A            Image:         N/A
        Wait Start TickCount      3135           Ticks: 41167 (0:00:10:43.234)
        Context Switch Count      920            IdealProcessor: 1            
        UserTime                  00:00:00.031
        KernelTime                00:00:00.046
        Win32 Start Address 0x00007ff77ca32f98
        Stack Init ffffe3802d33ffd0 Current ffffe3802d33f5b0
        Base ffffe3802d340000 Limit ffffe3802d33a000 Call 0000000000000000
        Priority 12 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
*** ERROR: Module load completed but symbols could not be loaded for myfault.sys
        Child-SP          RetAddr           Call Site
        ffffe380`2d33f5f0 fffff800`b8aeff5c nt!KiSwapContext+0x76
        ffffe380`2d33f730 fffff800`b8aef9ff nt!KiSwapThread+0x17c
        ffffe380`2d33f7e0 fffff800`b8af17c7 nt!KiCommitThreadWait+0x14f
        ffffe380`2d33f880 fffff800`b8b07251 nt!KeWaitForSingleObject+0x377
        ffffe380`2d33f930 fffff800`b8ae72a8 nt!ExpAcquireFastMutexContended+0x79
        ffffe380`2d33f970 fffff80c`fd8e148c nt!ExAcquireFastMutex+0x138
        ffffe380`2d33f9b0 fffff80c`fd8e1727 myfault+0x148c
        ffffe380`2d33fb00 fffff800`b8f18cd0 myfault+0x1727
        ffffe380`2d33fb60 fffff800`b8f17bb4 nt!IopSynchronousServiceTail+0x1a0
        ffffe380`2d33fc20 fffff800`b8f17536 nt!IopXxxControlFile+0x674
        ffffe380`2d33fd60 fffff800`b8bdf393 nt!NtDeviceIoControlFile+0x56
        ffffe380`2d33fdd0 00007ffc`b28f61b4 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffe380`2d33fe40)
        00000000`004fede8 00000000`00000000 0x00007ffc`b28f61b4

*ログは抜粋です。


2. この SynchronizationEvent のアドレスを「dt nt!_DISPATCHER_HEADER fffff80cfd8e3198」で見てみると、このオブジェクトを待っているスレッド情報のリスト (WaitListHead) が確認できます。
ここでは、 0xffff8301`eea4f1c0 だけです。

0: kd> dt nt!_DISPATCHER_HEADER fffff80cfd8e3198 
   +0x000 Lock             : 0n393217
   +0x000 LockNV           : 0n393217
   +0x000 Type             : 0x1 ''
   +0x001 Signalling       : 0 ''
   +0x002 Size             : 0x6 ''
   +0x003 Reserved1        : 0 ''
   +0x000 TimerType        : 0x1 ''
   +0x001 TimerControlFlags : 0 ''
   +0x001 Absolute         : 0y0
   +0x001 Wake             : 0y0
   +0x001 EncodedTolerableDelay : 0y000000 (0)
   +0x002 Hand             : 0x6 ''
   +0x003 TimerMiscFlags   : 0 ''
   +0x003 Index            : 0y000000 (0)
   +0x003 Inserted         : 0y0
   +0x003 Expired          : 0y0
   +0x000 Timer2Type       : 0x1 ''
   +0x001 Timer2Flags      : 0 ''
   +0x001 Timer2Inserted   : 0y0
   +0x001 Timer2Expiring   : 0y0
   +0x001 Timer2CancelPending : 0y0
   +0x001 Timer2SetPending : 0y0
   +0x001 Timer2Running    : 0y0
   +0x001 Timer2Disabled   : 0y0
   +0x001 Timer2ReservedFlags : 0y00
   +0x002 Timer2Reserved1  : 0x6 ''
   +0x003 Timer2Reserved2  : 0 ''
   +0x000 QueueType        : 0x1 ''
   +0x001 QueueControlFlags : 0 ''
   +0x001 Abandoned        : 0y0
   +0x001 DisableIncrement : 0y0
   +0x001 QueueReservedControlFlags : 0y000000 (0)
   +0x002 QueueSize        : 0x6 ''
   +0x003 QueueReserved    : 0 ''
   +0x000 ThreadType       : 0x1 ''
   +0x001 ThreadReserved   : 0 ''
   +0x002 ThreadControlFlags : 0x6 ''
   +0x002 CycleProfiling   : 0y0
   +0x002 CounterProfiling : 0y1
   +0x002 GroupScheduling  : 0y1
   +0x002 AffinitySet      : 0y0
   +0x002 Tagged           : 0y0
   +0x002 EnergyProfiling  : 0y0
   +0x002 ThreadReservedControlFlags : 0y00
   +0x003 DebugActive      : 0 ''
   +0x003 ActiveDR7        : 0y0
   +0x003 Instrumented     : 0y0
   +0x003 Minimal          : 0y0
   +0x003 Reserved4        : 0y000
   +0x003 UmsScheduled     : 0y0
   +0x003 UmsPrimary       : 0y0
   +0x000 MutantType       : 0x1 ''
   +0x001 MutantSize       : 0 ''
   +0x002 DpcActive        : 0x6 ''
   +0x003 MutantReserved   : 0 ''
   +0x004 SignalState      : 0n0
   +0x008 WaitListHead     : _LIST_ENTRY [ 0xffff8301`eea4f1c0 - 0xffff8301`eea4f1c0 ]


3. 2 で確認したスレッド情報のアドレス 0xffff8301`eea4f1c0  を「dt nt!_KWAIT_BLOCK 0xffff8301`eea4f1c0 」で見てみると、実際にそのオブジェクトを待っていたスレッド (Thread) がわかります。
ここでは、0xffff8301`eea4f080 であり、これは、SynchronizationEvent を待っているスレッドでもあり、スレッド自身でデッドロックになっていたことがわかります。

0: kd> dt nt!_KWAIT_BLOCK 0xffff8301`eea4f1c0
   +0x000 WaitListEntry    : _LIST_ENTRY [ 0xfffff80c`fd8e31a0 - 0xfffff80c`fd8e31a0 ]
   +0x010 WaitType         : 0x1 ''
   +0x011 BlockState       : 0x4 ''
   +0x012 WaitKey          : 0
   +0x014 SpareLong        : 0n920
   +0x018 Thread           : 0xffff8301`eea4f080 _KTHREAD
   +0x018 NotificationQueue : 0xffff8301`eea4f080 _KQUEUE
   +0x020 Object           : 0xfffff80c`fd8e3198 Void
   +0x028 SparePtr         : (null)




参考記事
Work Queues and Dispatcher Headers (英語)

関連記事
強制終了できないプロセスの原因を、ダンプ / カーネルデバッグで調査
一般公開されたWinDBG のデバッガーエクステンション MEX
  1. 2017/01/29(日) 23:56:29|
  2. WinDbg
  3. | トラックバック:0
  4. | コメント:0
<<ソース解析時に便利な Visual Studio 2017 の新機能 - フォルダーを開く、すべての参照を検索、すべてに移動 | ホーム | リバース実行を用いた gdb によるデバッグ>>

コメント

コメントの投稿


管理者にだけ表示を許可する

トラックバック

トラックバック URL
http://troushoo.blog.fc2.com/tb.php/330-e9719dcf
この記事にトラックバックする(FC2ブログユーザー)

スポンサーリンク

最新記事

月別アーカイブ

カテゴリ

ツール (92)
ネットワーク (76)
Visual Studio (56)
SOS・Psscor2/Psscor4 (25)
WinDbg (25)
Linux (24)
Azure (17)
Tips (20)
英語 (1)
About Me (1)
未分類 (0)

全記事表示リンク

全ての記事を表示する

検索フォーム

RSSリンクの表示

リンク

このブログをリンクに追加する