WinDbg で時間を巻き戻すデバッグ TTD を試してみた

ホーム
blog, WinDbg, Winデバッグ
WinDbg で時間を巻き戻すデバッグ TTD を試してみた

2018.05.12

WinDbg で時間を巻き戻すデバッグ TTD を試してみた

時間を巻き戻す魔法のツール TTD

みなさん、Visual Studio や、デバッガで、アプリケーションをデバッグする際に、プログラムをステップ実行したり、ブレークポイントで止めながら原因追及することが、あると思いますが、そのとき、時間を戻してみたいと思ったことありませんか？？

たとえば、ある変数におかしな値がはいっているけど、これは一体いつ入れたものなんだろう？？・・・、とか言うときですね。

今までなかなか、そういうことができなかったのですが、今回紹介するツールを利用すれば時間を巻き戻すことができるのです！

そう・・・Time Travel Debugging (以後、TTD) ならね・・・。

これから、TTD を使って、魔法のようにメモリアクセス違反を解析する例を紹介します。

TTD の導入

TTD は、Windows のストアアプリケーションとして、以下より入手することができます。

https://www.microsoft.com/en-us/store/p/windbg/9pgjgd53tn86

※ TTD は現在 Windows 10 でしか利用できません。

ハードコアデバッギング２０１７

TTD は、WinDbg というデバッガの機能のひとつとなります。

WinDbg については、2017 年の Microsoft の技術イベント de:code にて、ハードコアデバッギングというセッションがあり、使い方などを簡単に説明しています。
ハードコアデバッギングについては、セッションの動画、スライドなどが以下のサイトに公開されているので、知らない人は是非見てみてください！
日本最高峰のデバッギングスキルを惜しげもなく公開しているので、デバッギングマニアは必見ですよ！！

https://sway.com/vANWDJTgImr8wqg0?ref=Link&loc=play

今回は、上記のセッションで、早川さんが利用したメモリアクセス違反の事例について TTD を利用して解決していきたいと思います。
サンプルアプリケーションなども上記サイトにあるので、皆さんも是非やってみてください
（ただし、このサンプルアプリ、チャットボットを利用しており、別途用意する必要があったりします・・・）

TTD によるダンプ採取

WinDbg Preview をインストールしたら、管理者権限で実行します。

WinDbg が起動したら、ファイルタブより実行するアプリケーションを指定します。

すると、指定したアプリケーションが実行されるので、ハードコアデバッギングで発生させたアプリケーションクラッシュ（メモリアクセス違反）を起こします。

無事（？）アプリケーションがクラッシュしたので、プログラムの終了を選択します。

これで、TTD のダンプファイル取得は完了です。
指定したダンプファイルの出力先に拡張子 (run) でファイルが出力されているはずです。

通常のダンプファイルは採取した瞬間のメモリ状況のみを保存するため、時間を巻き戻したり、進めたりすることはできません。
しかし、TTD のダンプファイルは特殊なダンプファイルで、アプリケーションが実行されているときのメモリ状況をビデオのように時系列で保存されます。

なんとなく、以下のようなイメージで捉えていればＯＫかなと思います。

通常のダンプファイル：カメラで撮影
TTD のダンプファイル：ビデオで撮影

TTD のダンプファイルを開く

WinDbg のファイルタブより、先ほど取得した TTD のダンプファイルを開きます。

TTD を使ってLet’s デバッギング！！

それでは、実際に採取した TTD のダンプファイルを解析してみましょう！！

まず、読み込むと以下のように、アプリケーションを起動した瞬間となります。

(1908.3af8): Break instruction exception - code 80000003 (first/second chance not available)
Time Travel Position: 26:0
eax=14a97c40 ebx=005a0000 ecx=76f58e9f edx=5fe84afc esi=5fe8137c edi=003a2000
eip=76f58e9f esp=0057f8f8 ebp=0057fb50 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00200202
ntdll!LdrpInitializeProcess+0x1daa:
76f58e9f 83bdbcfeffff00  cmp     dword ptr [ebp-144h],0 ss:002b:0057fa0c=00000000

0:000> !index
Successfully created the index in 0ms.

通常の WinDbg を利用したデバッグと一緒で、まずは g コマンドを利用して、プログラムを進めます。
そうすると、特にブレークポイントなどを貼っているわけではないので、自動的に Exception が発生することまで進みます。

0:000> g
ModLoad: 70510000 70586000   C:\WINDOWS\SYSTEM32\webio.dll
ModLoad: 70460000 704b5000   C:\WINDOWS\system32\mswsock.dll
ModLoad: 72d10000 72d40000   C:\WINDOWS\SYSTEM32\IPHLPAPI.DLL
ModLoad: 75c40000 75c47000   C:\WINDOWS\System32\NSI.dll
ModLoad: 6f8a0000 6f8a8000   C:\WINDOWS\SYSTEM32\WINNSI.DLL
ModLoad: 6f950000 6f9e4000   C:\WINDOWS\SYSTEM32\DNSAPI.dll
ModLoad: 6f940000 6f948000   C:\Windows\System32\rasadhlp.dll
ModLoad: 6aa60000 6aaae000   C:\WINDOWS\System32\fwpuclnt.dll
ModLoad: 6a330000 6a398000   C:\WINDOWS\System32\schannel.dll
ModLoad: 69c50000 69c7c000   C:\WINDOWS\SYSTEM32\NTASN1.dll
ModLoad: 69c80000 69ca0000   C:\WINDOWS\SYSTEM32\ncrypt.dll
ModLoad: 69ca0000 69cb0000   C:\WINDOWS\SYSTEM32\mskeyprotect.dll
ModLoad: 69c30000 69c4b000   C:\WINDOWS\system32\ncryptsslp.dll
(1908.1c7c): Access violation - code c0000005 (first/second chance not available)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
Time Travel Position: 17683:0
*** WARNING: Unable to verify checksum for BotClient.exe
eax=1e53f418 ebx=1e53f520 ecx=5a5a5a5a edx=00000001 esi=1de146e8 edi=1de146f0
eip=00e2a06d esp=1e53f40c ebp=1e53f424 iopl=0         nv up ei pl nz na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000206
BotClient!std::default_delete<web::json::details::_Value>::operator()+0x7 [inlined in BotClient!std::vector<web::json::value,std::allocator<web::json::value> >::_Destroy+0x3d]:
00e2a06d 8b01            mov     eax,dword ptr [ecx]  ds:002b:5a5a5a5a=????????

上記のハイライトの箇所を見ると、アクセス違反 (例外コード : c0000005) が出ているのが確認できますね。
では、アクセス違反が発生している実効命令を、インストラクションポインタレジスタ (eip) より確認してみます。

0:008> ub eip L20
BotClient!Concurrency::details::_Task_impl<web::json::value>::`scalar deleting destructor'+0xcd:
00e2a01d cc              int     3
00e2a01e cc              int     3
00e2a01f cc              int     3
BotClient!std::vector<std::shared_ptr<Concurrency::details::_Task_impl<bool> >,std::allocator<std::shared_ptr<Concurrency::details::_Task_impl<bool> > > >::_Xlength [c:\program files (x86)\microsoft visual studio\2017\community\vc\tools\msvc\14.14.26428\include\vector @ 2024]:
00e2a020 688039e400      push    offset BotClient!`string' (00e43980)
00e2a025 ff152c31e400    call    dword ptr [BotClient!_imp_?_Xlength_errorstdYAXPBDZ (00e4312c)]
00e2a02b cc              int     3
00e2a02c cc              int     3
00e2a02d cc              int     3
00e2a02e cc              int     3
00e2a02f cc              int     3
BotClient!std::vector<web::json::value,std::allocator<web::json::value> >::_Destroy [c:\program files (x86)\microsoft visual studio\2017\community\vc\tools\msvc\14.14.26428\include\vector @ 1947]:
00e2a030 55              push    ebp
00e2a031 8bec            mov     ebp,esp
00e2a033 6aff            push    0FFFFFFFFh
00e2a035 681000e400      push    offset BotClient!memmove+0xe7 (00e40010)
00e2a03a 64a100000000    mov     eax,dword ptr fs:[00000000h]
00e2a040 50              push    eax
00e2a041 56              push    esi
00e2a042 57              push    edi
00e2a043 a108f0e400      mov     eax,dword ptr [BotClient!__security_cookie (00e4f008)]
00e2a048 33c5            xor     eax,ebp
00e2a04a 50              push    eax
00e2a04b 8d45f4          lea     eax,[ebp-0Ch]
00e2a04e 64a300000000    mov     dword ptr fs:[00000000h],eax
00e2a054 8b7508          mov     esi,dword ptr [ebp+8]
00e2a057 8b7d0c          mov     edi,dword ptr [ebp+0Ch]
00e2a05a 3bf7            cmp     esi,edi
00e2a05c 7424            je      BotClient!std::vector<web::json::value,std::allocator<web::json::value> >::_Destroy+0x52 (00e2a082)
00e2a05e 6690            xchg    ax,ax
00e2a060 8b0e            mov     ecx,dword ptr [esi]
00e2a062 85c9            test    ecx,ecx
00e2a064 7415            je      BotClient!std::vector<web::json::value,std::allocator<web::json::value> >::_Destroy+0x4b (00e2a07b)
00e2a066 c745fc00000000  mov     dword ptr [ebp-4],0

アクセス違反が発生しているところ (ハイライトしているところ) では、esi が指すアドレス値が ecx にコピーされていることがわかります。
esi が怪しいので、確認してみます。

0:008> r esi
esi=1de146e8
0:008> dd 1de146e8
1de146e8  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a
1de146f8  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a
1de14708  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a
1de14718  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a
1de14728  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a
1de14738  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a
1de14748  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a
1de14758  5a5a5a5a 5a5a5a5a 5a5a5a5a 5a5a5a5a

上記を見ると、esi が指す値周辺が 0x5a にて埋め尽くされていることがわかります。
実際、このヒープが何らかの要因によって、破壊されていることを、de:code のハードコアデバッギングセッションではさらに確認するのですが、ここでは割愛します。

ハードコアデバッギングセッションの以下の画像を見ていただければわかるのですが、メモリアクセス違反は大きく分けて二つのパターンあって、大半の場合は、バッファーオーバーランなどによって、発生した瞬間では、原因の特定に至らない場合が多いです（今回のこのバグも難易度が高いものになってます）。

というわけで、ヒープが破壊された瞬間を見つけるためにも、ここより前の時点で、esi のアドレスに書き込んだ処理を調べる必要があります。
ハードコアデバッギングセッションでは、ここから gflags を利用して、再度アプリケーションを実行させることになるのですが・・・

ここからが、TTD の本領発揮です！！

そして、時は巻き戻る！！

まずは、esi のアドレス (1de146e8) に書き込まれたタイミングで ba コマンドにてブレークさせるように指定します。

0:008> ba w4 1de146e8

これで、準備は完了です！！
それでは、時を巻き戻す魔法のコマンド g- を使用します！！！！

0:008> g-
Breakpoint 0 hit
Time Travel Position: 17678:10B
eax=5a5a5a5a ebx=0057f954 ecx=000000bc edx=000003f2 esi=1e53f474 edi=1de146ec
eip=585ddcbc esp=1e53f414 ebp=1e53f430 iopl=0         nv up ei pl nz na po cy
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000203
VCRUNTIME140!memset+0x3c:
585ddcbc f3aa            rep stos byte ptr es:[edi]

というわけで、破壊されたメモリに書き込みが行われたところで、無事ブレークしました！
上記ハイライトされた Time Travel Position は、今どの時系列にいるかを示す値となります。この値を利用して時をジャンプしたりすることもできます。
それでは、ここでスタックを確認してみましょう。

0:008> k
 # ChildEBP RetAddr  
00 1e53f410 00e24f66 VCRUNTIME140!memset+0x3c  
01 (Inline) -------- BotClient!Logger::Test+0x1e  
02 (Inline) -------- BotClient!Logger::Flash+0x37  
03 (Inline) -------- BotClient!Logger::FlashAndReallocIfNeeded+0x4b  
04 1e53f430 00e27158 BotClient!Logger::Append+0x76  
05 1e53f520 00e37f9c BotClient!<lambda_920e457775d0ba851ef3a168c853d866>::operator()+0x5f8  
06 (Inline) -------- BotClient!std::_Invoker_functor::_Call+0x35  
07 (Inline) -------- BotClient!std::invoke+0x35  
08 (Inline) -------- BotClient!std::_Invoker_ret<void,1>::_Call+0x35  
09 1e53f53c 00e3c660 BotClient!std::_Func_impl_no_alloc<<lambda_920e457775d0ba851ef3a168c853d866>,void,web::http::http_response>::_Do_call+0x3c  
0a (Inline) -------- BotClient!std::_Func_class<void,web::http::http_response>::operator()+0x1a  
0b (Inline) -------- BotClient!Concurrency::details::_MakeTToUnitFunc::__l2::<lambda_fef69d4e794e2133436026cef66da29e>::operator()+0x3d  
0c (Inline) -------- BotClient!std::_Invoker_functor::_Call+0x58  
0d (Inline) -------- BotClient!std::invoke+0x58  
0e (Inline) -------- BotClient!std::_Invoker_ret<unsigned char,0>::_Call+0x58  
0f 1e53f574 00e34120 BotClient!std::_Func_impl_no_alloc<<lambda_fef69d4e794e2133436026cef66da29e>,unsigned char,web::http::http_response>::_Do_call+0x80  
10 (Inline) -------- BotClient!std::_Func_class<unsigned char,web::http::http_response>::operator()+0x1b  
11 (Inline) -------- BotClient!Concurrency::task<web::http::http_response>::_ContinuationTaskHandle<web::http::http_response,void,std::function<void __cdecl(web::http::http_response)>,std::integral_constant<bool,0>,Concurrency::details::_TypeSelectorNoAsync>::_LogWorkItemAndInvokeUserLambda+0x46  
12 1e53f638 00e32831 BotClient!Concurrency::task<web::http::http_response>::_ContinuationTaskHandle<web::http::http_response,void,std::function<void __cdecl(web::http::http_response)>,std::integral_constant<bool,0>,Concurrency::details::_TypeSelectorNoAsync>::_Continue+0x170  
13 (Inline) -------- BotClient!Concurrency::task<web::http::http_response>::_ContinuationTaskHandle<web::http::http_response,void,std::function<void __cdecl(web::http::http_response)>,std::integral_constant<bool,0>,Concurrency::details::_TypeSelectorNoAsync>::_Perform+0xd  
14 1e53f674 1304ed27 BotClient!Concurrency::details::_PPLTaskHandle<unsigned char,Concurrency::task<web::http::http_response>::_ContinuationTaskHandle<web::http::http_response,void,std::function<void __cdecl(web::http::http_response)>,std::integral_constant<bool,0>,Concurrency::details::_TypeSelectorNoAsync>,Concurrency::details::_ContinuationTaskHandleBase>::invoke+0x101  
WARNING: Stack unwind information not available. Following frames may be wrong.
15 1e53f690 1304eaf8 cpprest140_2_9!web::http::client::http_client::request+0x1a377
16 1e53f6b0 5852c56c cpprest140_2_9!web::http::client::http_client::request+0x1a148
17 1e53f6d4 76ee4dcb MSVCP140!Concurrency::details::`anonymous namespace'::_Task_scheduler_callback+0x5c  
18 1e53f710 76ee3ec3 ntdll!TppWorkpExecuteCallback+0x16b
19 1e53f8fc 757c8674 ntdll!TppWorkerThread+0x623
1a 1e53f910 76f14b47 KERNEL32!BaseThreadInitThunk+0x24
1b 1e53f958 76f14b17 ntdll!__RtlUserThreadStart+0x2f
1c 1e53f968 00000000 ntdll!_RtlUserThreadStart+0x1b

上記のハイライトされた部分を確認すると、BotClient の Logger クラスの Test 関数にて、memset を呼び出したことでメモリが破壊されたことが確認できます。

いかがでしたでしょう？
時間を戻るデバッガの魅力を多少は伝えられたのではないでしょうか？

TTD では、今回利用したコマンド以外にも、ステップレベルの巻き戻しや、特定の時間にジャンプなど様々なコマンドがあります。
コマンドのリファレンスが以下のサイトにあるので、是非色々と試してみてください！！

https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/time-travel-debugging-replay

blog

Hello うしみつ技術部

挨拶始めましての方、始めまして！そうでない方、お久しぶりです。…
blog

デバッギングの考え方と手順

デバッグとは？プログラムを作ると、必ずバグが生まれます！世…

この記事へのコメントはありません。

この記事へのトラックバックはありません。

トラックバック URL

プロフィール

光路郎

人生が迷子系エンジニア。
C#、CLR、XNA、Java、JavaVM、Unityあたりが好物。
Microsoft信者。

Twitter

C#、Javaのデバッグを中心とした技術情報を配信

WinDbg で時間を巻き戻すデバッグ TTD を試してみた

時間を巻き戻す魔法のツール TTD

TTD の導入

ハードコアデバッギング２０１７

TTD によるダンプ採取

TTD のダンプファイルを開く

TTD を使ってLet’s デバッギング！！

そして、時は巻き戻る！！

関連記事

Hello うしみつ技術部

デバッギングの考え方と手順

コメント

プロフィール

光路郎

サイト内検索

メニュー

最近の記事

C#、Javaのデバッグを中心とした技術情報を配信

WinDbg で時間を巻き戻すデバッグ TTD を試してみた

時間を巻き戻す魔法のツール TTD

TTD の導入

ハードコアデバッギング ２０１７

TTD によるダンプ採取

TTD のダンプファイルを開く

TTD を使ってLet’s デバッギング！！

そして、時は巻き戻る！！

関連記事

Hello うしみつ技術部

デバッギングの考え方と手順

コメント

プロフィール

光路郎

サイト内検索

メニュー

最近の記事

ハードコアデバッギング２０１７