Hatena::ブログ(Diary)

ペンギンの備忘録 Twitter

2017-10-08

[]Time Travel Debugging(3) 17:53 Time Travel Debugging(3)を含むブックマーク Time Travel Debugging(3)のブックマークコメント

D

C++ ConferenceのTTDのセッションの動画。ヒープ破壊のデバッグやエラーコードを追跡するデモ、今後予定されている機能の紹介、がありました。

カーネルレベルのトレースは、ユーザーモードプロセスからのカーネル呼び出しでその先までトレースするという話なのか、リモートマシンや仮想マシンに接続してカーネル全体のトレースができるのか。前者なら個人的には必要ない機能かな。

動画の方は、38:00あたりから今まで見たことないようなデバッグテクニックが使われてるので必見です。関数呼び出しの位置をクエリーするなど、TTDとLINQ、Debugger Object Modelを組み合わせるとここまで強力なことが出来るのかって感じです。Time Travel Debugging = Postmortem Live Debuggingという認識でしたが、この動画を見て覆されました。

今のところ肝心のレコーディングがWindows 10 Aniversary Update以降のしかもストアアプリインストールできないと利用できないということで実務では使えないんだけど、早く他のバージョンのOS向けにTime Travel Recorder的なものがリリースされるといいなぁ。

dx -g @$cursession.TTD.Calls("USER32!SendMessageW").Where(x => x.Parameters[1] == 0x000D)
dx -g @$cursession.TTD.Calls("kernelbase!GetLastError").Where(x => x.ReturnValue != 0)

2017-09-30

[]Time Travel Debugging (2) 23:03 Time Travel Debugging (2)を含むブックマーク Time Travel Debugging (2)のブックマークコメント

Time Travel Debuggingをさらにいろいろ試してみて感じたところ。

  • アプリケーションがクソ遅くなる。運用環境でw3wp.exeとかにアタッチするならリクエストを限定するようにうまく振り分けないと大変なことになる。
  • ログファイルがクソでかくなる。10分ほどアタッチしたままアプリケーションを動かしてたらログファイルが20GBとかアホみたいなサイズになった。バグを再現させるのが苦痛。
  • .timeコマンドでpositionの時点のDebug session timeとSystem Uptimeが確認できる。これはすごくありがたい。
  • "!address -summary"とかが使えない。メモリリークの調査とかでこれは致命的。
  • 例外が発生する処理にブレークポイントを設定するとgで停止するときは例外が発生する命令、g-で停止すると例外発生直後の命令で停止する。
  • "ba w4 0x12345678"とか書いたとき、値を書き換える命令とその直後の命令で2回ブレークしてしまう。これもgとg-でややこしいことになる。
  • .logexts拡張機能は使えなさそう。

メモリリークの調査でよく使うのは、!heap、!address、!handleあたり。だけどどうもTTDだと!heapコマンドしか使えないみたい。!addressコマンドは仕組み的に厳しいことは想像がつくけど、せめて!handleぐらいは使えてほしかった。オプションがあれば良いのだけど。

0:000> !heap -a
Index   Address  Name      Debugging options enabled
  1:   00de0000 
    Segment at 00de0000 to 00edf000 (000ff000 bytes committed)
  2:   01170000 
    Segment at 01170000 to 0117f000 (0000f000 bytes committed)
    Segment at 1d910000 to 1da0f000 (0004a000 bytes committed)
  3:   1cae0000 
    Segment at 1cae0000 to 1caef000 (0000f000 bytes committed)

0:000> !address -summary
The current target does not provide full memory information. No meaningful summary available.
Use !address with no arguments to display the available virtual memory map of the target.

0:000> !handle
ERROR: !handle: extension exception 0x8000ffff.
    "Unable to read handle information"

ちなみにTTDの再生中はsystem statusも"Time Travel Debugging Mode"という値を返すようです。

0:000> ||
.  0 Time Travel Debugging Mode

2017-09-26

[]Time Travel Debugging 01:07 Time Travel Debuggingを含むブックマーク Time Travel Debuggingのブックマークコメント

先日@JamesMcNellisさんのツイートで出てたTime Travel Debuggingが早速公開されたみたいですね。

Time Travel Debugging in WinDbg Preview! – Debugging Tools for Windows

既にドキュメントも(英語だけど)かなり充実してるし素晴らしい。


Time Travel Debugging - Overview | Microsoft Docs

ざっと流し読みすると、Time Travel Debugging(TTD)はプロセスの処理を記録して行ったり来たり出来るツールのようです。巻き戻しができるので、バグの原因を突き止められるまで何度も再現させながらライブデバッグするという苦行から解放されそうです。再現させなおすとアドレスやらなにやら全部変わっちゃうし、そもそも再現させるのがすごく手間だし、間違えてpコマンドで行き過ぎて分からなくなったときには全てを投げ出して家に帰りたくなりますが、そんなこともなくなります。

また、クラッシュダンプと比べると、ダンプはあくまでも問題が起きた瞬間のスナップショットでしかなく問題の原因の処理からずっと離れた時点の情報しか得られないので、TTDは大きな利点があるそうです。

例えばmemcpyとかで配列のサイズを超えて書き込みしてしまって関数のリターンアドレスを上書きしてしまった場合、欲しいのはmemcpyで書き込んだ瞬間の情報ですが、ダンプからはeipがおかしなことになっててkコマンドでもコールスタックが得られないといったことになります。TTDなら処理を巻き戻すことで問題が特定できそうですね。


Time Travel Debugging - Replay a trace | Microsoft Docs

g-、p-、t-といったコマンドがあります。!ttdext.helpコマンドで確認すると、TTD特有のいくつかのコマンドがあるようです。

早速TTDを試してみます。


サンプルプログラム

最適化無効、セキュリティチェックなし(/GS-)でビルド。foo関数バッファオーバーランを起こしてリターンアドレスを書き換えています。当然、すぐクラッシュします。

#include <stdio.h>
#include <string.h>

void foo(char *buf)
{
	strcpy(buf, "abcdefghijklmnopqrstuvwxyz\n");
}

int main()
{
	char buf[8];
	foo(buf);
	printf(buf);
	printf("completed.\n");
	return 0;
}

そういえば、2年以上前にもスタック破壊をライブデバッグする記事書いてましたが、これがTTDで事後デバッグできるようになるわけですね。

スタック破壊の調査 - ペンギンの備忘録


クラッシュダンプ

0:000> k

# ChildEBP RetAddr

00 0133eccc 743c2c23 ntdll!NtWaitForMultipleObjects+0xc

01 0133ee60 743c2b08 KERNELBASE!WaitForMultipleObjectsEx+0x103

02 0133ee7c 7456ef0a KERNELBASE!WaitForMultipleObjects+0x18

03 0133f2f8 7456f19b kernel32!WerpReportFaultInternal+0x58b

04 0133f314 74531609 kernel32!WerpReportFault+0x9d

05 0133f31c 7444a3ff kernel32!BasepReportFault+0x19

06 0133f3b0 775d4af1 KERNELBASE!UnhandledExceptionFilter+0x28f

07 0133fe94 775957fd ntdll!__RtlUserThreadStart+0x3f2f3

08 0133fea4 00000000 ntdll!_RtlUserThreadStart+0x1b

0:000> .ecxr

eax=00000000 ebx=01076000 ecx=74ac2431 edx=74ba8324 esi=74ba9304 edi=01681ee8

eip=706f6e6d esp=0133fdf8 ebp=6c6b6a69 iopl=0 nv up ei pl zr na pe nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246

706f6e6d ?? ???

0:000> k

Stack trace for last set context - .thread/.cxr resets it

# ChildEBP RetAddr

WARNING: Frame IP not in any known module. Following frames may be wrong.

00 0133fdf4 74737271 0x706f6e6d

01 0133fe38 74528744 0x74737271

02 0133fe4c 7759582d kernel32!BaseThreadInitThunk+0x24

03 0133fe94 775957fd ntdll!__RtlUserThreadStart+0x2f

04 0133fea4 00000000 ntdll!_RtlUserThreadStart+0x1b

eipが0x706f6e6dになってます。("ponm"のAsciiコードですね。)

スタックに積まれたリターンアドレスをつぶしてしまってるので、ret命令で不正なアドレスに飛んでしまいこのようになります。あとはデータ実行防止とかのハードウェア例外でクラッシュします。

このダンプだけを見て原因がstrcpyのバッファオーバーランであることを突き止めるのは、少なくとも自分にはかなりきついです。実際のアプリはもっと処理も複雑ですし、壊れ方も複雑なので。

エラーが再現できれば何度かライブデバッグを繰り返して原因は特定できるでしょうけど、再現頻度が低いと地獄です。滅多に起こらないので運用上支障ないので無視してください、仕様です、などの政治的な対処が必要になります。


Time Travel Debugging(TTD)

Time Travel Debugging - Record a trace | Microsoft Docs

とりあえずTTDのレコーディングから始めます。手順は↑のとおりなのだけど、「Record process with Time Travel Debugging」を選択するにはWinDbg Previewを管理者権限で実行する必要があるので要注意。

エラーを再現させてしばらくすると、"Recording"というダイアログが消えて、コンソールにこんな感じのメッセージがでてきます。この時点で、.runファイルと.idxファイルが作成されていました。サイズ的には45MB程度でしたのでダンプファイルと比べるとはるかに小さいです。逆に言うと、メモリの全領域を記録しているわけではなさそうなので、得られない情報もありそうです。

Microsoft (R) Windows Debugger Version 10.0.16365.1002 AMD64

Copyright (c) Microsoft Corporation. All rights reserved.


Loading Dump File [C:\work\StackCorruption101.run]

JavaScript script successfully loaded from 'C:\Program Files\WindowsApps\Microsoft.WinDbg_1.0.13.0_x86__8wekyb3d8bbwe\amd64\TTD\Analyzers\HeapAnalysis.js'

JavaScript script successfully loaded from 'C:\Program Files\WindowsApps\Microsoft.WinDbg_1.0.13.0_x86__8wekyb3d8bbwe\amd64\TTD\Analyzers\TtdAnalyze.js'

Path validation summary

Response Time (ms) Location

Deferred srv*c:\symbols*http://msdl.microsoft.com/download/symbols

Symbol search path is: srv*c:\symbols*http://msdl.microsoft.com/download/symbols

Executable search path is:

ModLoad: 00310000 00316000 C:\repos\Buggy\Cpp\StackCorruption\StackCorruption1\Release\StackCorruption1.exe

ModLoad: 0f3a0000 0f4e1000 C:\ProgramData\Microsoft\Windbg\1-0-13\TTD\wow64\TTDWriter.dll

ModLoad: 0fb70000 0fd09000 C:\ProgramData\Microsoft\Windbg\1-0-13\TTD\wow64\TTDRecordCPU.dll

ModLoad: 5b660000 5b6f3000 C:\WINDOWS\SYSTEM32\apphelp.dll

ModLoad: 73480000 73494000 C:\WINDOWS\SYSTEM32\VCRUNTIME140.dll

ModLoad: 742d0000 74492000 C:\WINDOWS\System32\KERNELBASE.dll

ModLoad: 74510000 745e0000 C:\WINDOWS\System32\KERNEL32.DLL

ModLoad: 74aa0000 74bb8000 C:\WINDOWS\System32\ucrtbase.dll

ModLoad: 77530000 776be000 C:\WINDOWS\SYSTEM32\ntdll.dll

.........

(1b48.25b4): Break instruction exception - code 80000003 (first/second chance not available)

Time Travel Position: E:0

eax=0fbda5b0 ebx=00e05000 ecx=7759f821 edx=0ff34afc esi=0ff3137c edi=00df0000

eip=7759f821 esp=0113f93c ebp=0113fb74 iopl=0 nv up ei pl nz na po nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202

ntdll!LdrpInitializeProcess+0x1bbe:

7759f821 83bdd4feffff00 cmp dword ptr [ebp-12Ch],0 ss:002b:0113fa48=00000000

0:000> !index

Indexed 1/1 keyframes

Successfully created the index in 67ms.

ちゃんとgコマンドで実行し、kコマンドでコールスタックを見ることができます。"Time Travel Position: 47:0"と出ていますが、これは!ttコマンドで指定するときに使う位置情報のようです。

0:000> g

(1b48.25b4): 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: 47:0

eax=00000000 ebx=00e05000 ecx=74ac2431 edx=74ba8324 esi=74ba9304 edi=00461ed8

eip=706f6e6d esp=0113fe0c ebp=6c6b6a69 iopl=0 nv up ei pl zr na pe nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246

706f6e6d ?? ???

0:000> k

# ChildEBP RetAddr

WARNING: Frame IP not in any known module. Following frames may be wrong.

00 0113fe08 74737271 0x706f6e6d

01 0113fe4c 74528744 0x74737271

02 0113fe60 7759582d KERNEL32!BaseThreadInitThunk+0x24

03 0113fea8 775957fd ntdll!__RtlUserThreadStart+0x2f

04 0113feb8 00000000 ntdll!_RtlUserThreadStart+0x1b

さらにgコマンドを実行すると、"TTD: End of trace reached."と出ます。最後に達しましたよ、ということでしょう。

0:000> g

TTD: End of trace reached.

(1b48.25b4): Break instruction exception - code 80000003 (first/second chance not available)

Time Travel Position: 8AA:0

eax=0007002c ebx=00000000 ecx=00000000 edx=775b6180 esi=775d4b07 edi=00000000

eip=6a267000 esp=0113fe5c ebp=0113fea8 iopl=0 nv up ei pl zr na pe nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246

6a267000 ea0970266a3300 jmp 0033:6A267009

とりあえずAVが発生したところ(47:0)に戻します。

0:000> !tt 47:0

Setting position: 47:0

(1b48.25b4): Break instruction exception - code 80000003 (first/second chance not available)

Time Travel Position: 47:0

eax=00000000 ebx=00e05000 ecx=74ac2431 edx=74ba8324 esi=74ba9304 edi=00461ed8

eip=706f6e6d esp=0113fe0c ebp=6c6b6a69 iopl=0 nv up ei pl zr na pe nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246

706f6e6d ?? ???

ここから2回、t-コマンドでトレースバックします。とりあえずret命令のところまで戻ることができました。素晴らしい。ソースウィンドウも、しっかりreturn 0;の次の行を指してます。

0:000> t-

Time Travel Position: 46:31

eax=00000000 ebx=00e05000 ecx=74ac2431 edx=74ba8324 esi=74ba9304 edi=00461ed8

eip=706f6e6d esp=0113fe0c ebp=6c6b6a69 iopl=0 nv up ei pl zr na pe nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246

706f6e6d ?? ???

0:000> t-

WARNING: Unable to verify checksum for StackCorruption1.exe

Time Travel Position: 46:30

eax=00000000 ebx=00e05000 ecx=74ac2431 edx=74ba8324 esi=74ba9304 edi=00461ed8

eip=003110d0 esp=0113fe08 ebp=6c6b6a69 iopl=0 nv up ei pl zr na pe nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246

StackCorruption1!main+0x30:

003110d0 c3 ret

0:000> k

# ChildEBP RetAddr

00 0113fe4c 74528744 StackCorruption1!main+0x30 [c:\repos\buggy\cpp\stackcorruption\stackcorruption1\stackcorruption1\source.cpp @ 16]

01 0113fe60 7759582d KERNEL32!BaseThreadInitThunk+0x24

02 0113fea8 775957fd ntdll!__RtlUserThreadStart+0x2f

03 0113feb8 00000000 ntdll!_RtlUserThreadStart+0x1b

0:000> u

StackCorruption1!main+0x30 [c:\repos\buggy\cpp\stackcorruption\stackcorruption1\stackcorruption1\source.cpp @ 16]:

003110d0 c3 ret

003110d1 cc int 3

003110d2 cc int 3

003110d3 cc int 3

003110d4 cc int 3

003110d5 cc int 3

003110d6 cc int 3

003110d7 cc int 3

とりあえずret命令で飛ぶアドレス0x706f6e6dは0x0113fe08から来ているようですので、このアドレスを書き換えた処理を突き止めるためにブレークポイントを貼ります。ライブデバッグでもないのにブレークポイントが使えるのが新鮮。

0:000> dd esp L4

0113fe08 706f6e6d 74737271 78777675 000a7a79

0:000> ba w4 0113fe08

g-コマンドで次のブレークポイントまで遡ることができるのか試したところ、できました。リターンアドレスを書き換えた処理はまさにここですね。ソースウィンドウもばっちりstrcpyを指してます。

0:000> g-

Breakpoint 0 hit

Time Travel Position: 32:36

eax=0113fdfc ebx=00e05000 ecx=00000003 edx=00000000 esi=00312108 edi=0113fe0c

eip=00311092 esp=0113fde8 ebp=0113fdf0 iopl=0 nv up ei pl nz ac pe nc

cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000216

StackCorruption1!foo+0x12:

00311092 f3a5 rep movs dword ptr es:[edi],dword ptr [esi]

0:000> k

# ChildEBP RetAddr

00 0113fdf0 003110af StackCorruption1!foo+0x12 [c:\repos\buggy\cpp\stackcorruption\stackcorruption1\stackcorruption1\source.cpp @ 6]

01 0113fe04 706f6e6d StackCorruption1!main+0xf [c:\repos\buggy\cpp\stackcorruption\stackcorruption1\stackcorruption1\source.cpp @ 12]

WARNING: Frame IP not in any known module. Following frames may be wrong.

02 0113fe4c 74528744 0x706f6e6d

03 0113fe60 7759582d KERNEL32!BaseThreadInitThunk+0x24

04 0113fea8 775957fd ntdll!__RtlUserThreadStart+0x2f

05 0113feb8 00000000 ntdll!_RtlUserThreadStart+0x1b

一応lnコマンドでシンボル名を引いてみる。

0:000> ln eip

Browse module

Set bu breakpoint

[c:\repos\buggy\cpp\stackcorruption\stackcorruption1\stackcorruption1\source.cpp @ 6] (00311080) StackCorruption1!foo+0x12 | (003110a0) StackCorruption1!main

今まで客先でしか起きない現象をどうやって調査するかということは本当に悩ましい問題だったわけですが、TTDは新しい、かつ非常に強力な選択肢になりそうです。もっと色々使いこなしていきたいですね。

ちなみに今回は"Launch executable (advanced)"からプロセスを起動する形でレコーディングを開始していますが、"Attach to process"にも"Record process with Time Travel Debugging"のチェックが追加されています。プロセスの開始時点からだけでなく途中からでもレコーディングができるのは大変助かります。


気になったところ

TTD使ってみて気になったことがいくつか。

  • ファイルサイズの問題。ほんの数行のコードでさえ45MBのサイズになりました。実際のアプリで取ると膨大なサイズになります。少なくともレコーディングし続けて運用といったことは不可能でしょう。
  • サービスプロセスを起動時からデバッグするにはどうすればよいのか。

あと、WinDbg PreviewにはModelというタブがあるのですが、これでTTDの情報を階層構造で見ることができます。そして、この情報はコマンドウィンドウからLINQで検索できます。Unknown Exceptionが大量に出てて目的の例外がどこか分からないとかデバッグしてるとありがちですが、これで検索できますし、Positionが出ているのでさくっと探して!ttコマンドで飛べます。

f:id:A-penguin:20170927005354p:image