HOME会社概況業務内容開発分野開発事例CANモジュールソフテックだよりお問い合わせ
HOME > ソフテックだより > 第67号(2008年6月4日発行) 技術レポート「Windowsネイティブプログラムのエラー解析」

「ソフテックだより」では、ソフトウェア開発に関する情報や開発現場における社員の取り組みなどを定期的にお知らせしています。
さまざまなテーマを取り上げていますので、他のソフテックだよりも、ぜひご覧下さい。

ソフテックだより(発行日順)のページへ
ソフテックだより(技術分野別)のページへ
ソフテックだより(シーン別)のページへ


ソフテックだより 第67号(2008年6月4日発行)

技術レポート

「Windowsネイティブプログラムのエラー解析」

Windowsプログラム(C/C++)の厄介な問題のひとつに、アプリケーションエラーがあります。
最近では.NET Framework上で動作するマネージドプログラム(※1)のプログラムが増えてきているため、アプリケーションエラーが発生する可能性は低いと思いますが、まだまだ現役のネイティブプログラム(※2)は多いため、避けては通れない問題です。

そんな中、先日、私にアプリケーションエラーの調査依頼があり、担当することになりました。しかし、数年振りにアプリケーションエラーの解析をしてみると忘れていることばかりで、いろいろ思い出しながらの作業でした。今回はその時にどのような手順で進めていったかをまとめてみたいと思います。

解析には、いろいろな前準備も必要ですので、以下の順で説明したいと思います。

  1. プログラムのビルド設定
  2. ターゲットPCでの設定
  3. アプリケーションエラー発生
  4. ログファイルからの解析
  5. クラッシュダンプファイルからの解析
  6. まとめ

1.〜2.までは解析を進める上で必要な前準備となり、3.〜5.までが実際のアプリケーションエラー発生〜解析となります。

また、今回使用するプログラムのソースは以下のものを用います。

#include "stdafx.h"

int FuncA(char* buf1, char* buf2, int size)

{

        buf1 += 100000000;

        memcpy(buf1, buf2, size);

        return 1;

}

int _tmain(int argc, _TCHAR* argv[])

{

        char x[10];

        char* y;

        int z = FuncA(x, y, 10);

        return 0;

今回対象とするプログラムは、VC++(Visual Studio C++ 2005)で作成したWin32コンソールアプリケーションです。exe名はCrashとしています。
ソースを見れば、この時点でもうおかしなプログラムであることは明らかですが、今回はこのソースを使っていきます。

※また、分かりやすさのため、コンパイルの最適化は無効としています。

1. プログラムのビルド設定

まず、アプリケーションエラーの解析に必要な情報は、プログラムのビルド時に設定する必要があります。

(1). リスティングファイル

このリスティングファイル(ソースとアセンブリコード)によって、アプリケーションエラーが発生した際の、プログラムのアドレスを特定することができるようにします。
中間ファイル(.cod)を出力させるには、「構成プロパティ」の「C/C++」-「出力ファイル」-「アセンブリの出力」にて、アセンブリコード、コンピュータ語コード、ソースコード(/FAcs)を設定します。

※具体的な.codファイルの内容は以降のリスティングファイルで説明します。

(2). MAPファイル

オブジェクト毎のアドレスを示すMAPファイルも作成しておきましょう。
「構成プロパティ」の「リンカ」-「デバッグ」-「マップ ファイルの作成」にて、はい/いいえを設定できます。

(3). プログラムデータベース

デバッグシンボルは、以降で説明するクラッシュダンプファイルを使った解析の際に必要となるものです。
デフォルトの設定でプログラムデータエース(.pdb)ファイルが生成されますが、以下の「構成プロパティ」にて設定が可能です。

  1. 「C/C++」-「出力ファイル」-「プログラム データ ベース ファイルの名前」
  2. 「リンカ」-「デバッグ」-「デバッグ情報の生成」-「プログラム データ ベース ファイルの生成」

以上の設定を終えたら、プログラムをビルドして、「Crash.exe」を生成してください。

ビルド設定やビルド環境(Visual StudioのSPバージョン等)が異なると生成される情報が変わってきますので注意してください。
2. ターゲットPCでの設定

次にターゲットPCで、ワトソン博士の設定を行います。
ワトソン博士は、アプリケーションエラーが発生した際の、ログファイルとクラッシュダンプファイルの生成を行ってくれます。
通常であれば、Windowsのデフォルトデバッガがワトソン博士に設定されていますが、Visual Studioなどのデバッガがインストールされると、デバッガはそちらに変更されています。
よって、もとのワトソン博士へ戻してやることになります。

(1). ワトソン博士設定

スタートメニューからファイル名を指定して実行にて「drwtsn32」と打ち込み、OKを押します。すると以下画面が表示されます。基本的には設定は変更する必要はありませんが、ログファイルパスや、クラッシュダンプファイルパスを変更したい場合にはこの画面にて設定します。

(2). ワトソン博士をデバッガへ設定

スタートメニューからファイル名を指定して実行にて「drwtsn32 -i」と打ち込み、OKを押すと以下画面が表示されますので、これでワトソン博士がデバッガとして登録されました。

(3). Dllのバージョンをあわせる

その他に、デバッグ環境のPCと実際のターゲットPCで注意する点としては、使用するdllも合わせておく必要があります。(mfcやatl等)
使用するdllのバージョンが異なると、プログラムの動きも異なりますので注意してください。
※スタティックリンクでビルドしておくのであれば、これは注意する必要ありません。

3. アプリケーションエラー発生

ここまでで、ようやくソフトの準備とターゲットPCの準備が終わりました。
実際に、「Crash.exe」を実行してみます。
すると、よく見慣れた画面がでてきます。アプリケーションエラー発生です。

ここでは、送信しないボタンを押して、このダイアログを終了させます。
すると、先ほどのワトソン博士で設定したフォルダ(C:\Documents and Settings\All Users\Application Data\Microsoft\Dr Watson)へ、ログファイル「drwtsn32.log」とクラッシュダンプファイル「user.dmp」ができているはずです。
この2つのファイルから、解析を行っていきます。

4. ログファイルからの解析

アプリケーションエラーで発生したファイルの1つ「drwtsn32.log」を使った解析を最初に説明します。
drwtsn32.logの中には以下のようになっていると思います。

アプリケーション例外が発生しました:

        アプリケーション: C:\Crash\release\Crash.exe (pid=4976)

        発生時間:  2008/06/02 @ 18:10:58.437

        例外番号:  c0000005 (アクセス違反)

*----> システム情報 <----*

        コンピュータ名: ****

        ユーザー名: ****

        ターミナル セッション Id: 0

        プロセッサの数: 2

        プロセッサの種類: x86 Family 6 Model 15 Stepping 2

        Windows バージョン: 5.1

        現在のビルド: 2600

        Service Pack: 2

        現在のタイプ: Multiprocessor Free

        登録されている会社名: SOFTECH

        登録されている所有者: ****

・・・・・・・・・・・・・・以下省略・・・・・・・・・・・・・・

上記赤字部分に例外番号が表示されていますが、c0000005はアプリケーションエラーの中でおそらく最も多いアクセスバイオレーション(メモリアクセスの保護違反)です。
このログファイルから、例外が発生している箇所を探してみましょう。
エディタで「フォールト」という文字列で検索をかけると、以下のような部分を見つけることができます。

ファンクション: MSVCR80!memcpy

      7814514c 89448fe4        mov     [edi+ecx*4-0x1c],eax

      78145150 8b448ee8       mov     eax,[esi+ecx*4-0x18]

      78145154 89448fe8        mov     [edi+ecx*4-0x18],eax

      78145158 8b448eec        mov     eax,[esi+ecx*4-0x14]

      7814515c 89448fec         mov     [edi+ecx*4-0x14],eax

      78145160 8b448ef0        mov     eax,[esi+ecx*4-0x10]

      78145164 89448ff0         mov     [edi+ecx*4-0x10],eax

      78145168 8b448ef4        mov     eax,[esi+ecx*4-0xc]

      7814516c 89448ff4         mov     [edi+ecx*4-0xc],eax

      78145170 8b448ef8        mov     eax,[esi+ecx*4-0x8]

フォールト ->78145174 89448ff8        mov   [edi+ecx*4-0x8],eax ds:0023:0608e068=????????

      78145178 8b448efc        mov     eax,[esi+ecx*4-0x4]

      7814517c 89448ffc         mov     [edi+ecx*4-0x4],eax

      78145180 8d048d00000000  lea     eax,[00000000+ecx*4]

      78145187 03f0            add     esi,eax

      78145189 03f8            add     edi,eax

      7814518b ff249594511478 jmp dword ptr [MSVCR80!memcpy+0x174 (78145194)+edx*4]

      78145192 8bff            mov     edi,edi

      78145194 a4              movsb

      78145195 51              push    ecx

      78145196 1478            adc     al,0x78

*----> スタック バックトレース <----*

WARNING: Stack unwind information not available. Following frames may be wrong.

*** ERROR: Symbol file could not be found.  Defaulted to export symbols for C:\WINDOWS\system32\kernel32.dll -

ChildEBP RetAddr  Args to Child              

0012ff3c 004017ff 0608e068 0040302c 0000000a MSVCR80!memcpy+0x154

0012ff50 0040182f 0608e068 0040302c 0000000a Crash!FuncA+0x1f

0012ff7c 00401170 00000001 003a3f48 003a4b00 Crash!wmain+0x1f

0012ffc0 7c816fd7 0012e0dc 7c94e1fe 7ffdf000 Crash!__tmainCRTStartup+0x10f

0012fff0 00000000 004012b9 00000000 78746341 kernel32!RegisterWaitForInputIdle+0x49

*----> ロウ スタック ダンプ <----*

000000000012ff34  01 00 00 00 78 33 40 00 - 50 ff 12 00 ff 17 40 00  ....x3@.P.....@.

000000000012ff44  68 e0 08 06 2c 30 40 00 - 0a 00 00 00 7c ff 12 00  h...,0@.....|...

000000000012ff54  2f 18 40 00 68 e0 08 06 - 2c 30 40 00 0a 00 00 00  /.@.h...,0@.....

000000000012ff64  4c 10 40 00 18 30 40 00 - 20 30 40 00 1c 30 40 00  L.@..0@. 0@..0@.

000000000012ff74  14 20 3e 62 2c 30 40 00 - c0 ff 12 00 70 11 40 00  . >b,0@.....p.@.

フォールトの文字がある赤字部分が例外を発生させている箇所です。memcpyで例外が発生しているのはわかりますが、それ以上は分かりません。
そこで、スタックフレームを逆から見たスタックバックトレースを見てみます。
通常はアプリケーションのベースアドレスはデフォルトで00400000ですので、その付近のアドレスが「Crash.exe」がコールしている関数です。以下.mapファイルから今回作成した関数を探すと、アドレス004017e0〜401FFFがFuncA〜wmainまでの関数のアドレスであることが分かります。

0001:000007e0       ?FuncA@@YAHPAD0H@Z    004017e0 f   Crash.obj

0001:00000810       _wmain                     00401810 f   Crash.obj

0002:00000000       __imp__GetCurrentProcessId@ 0 00402000     kernel32:KERNEL32.dll

ちなみに、「Crash!FuncA+0x1f」というのは、FuncAアドレス+0x1fアドレスのコードを指します。.codファイルを見てみると、

「0001f 83 c4 0c        add    esp, 12                        ; 0000000cH」

というコードがあるので、ここを指していることになります。

スタックバックトレースからこのアドレスに近いRetAddrを探すと、memcpyがまず見つかります(今回は関数コールが浅いためすぐに見つかりましたが、一般のプログラムにおいては自分で作成した関数付近のアドレスが見つかることはまれです)。
memcpyで例外が発生しているからmemcpyへ渡す引数がおかしいだろうというのがすぐ分かりますが、それは呼び出し元関数のローカル変数がおかしいということを指します。

ChildEBPは呼び出し元関数のローカル変数のアドレスを指します。このことから、赤字部分がFuncAのローカル変数、青字部分がwmainのローカル変数ということが分かります。
次に.codファイルから、pushを調べていくと、スタックには以下のようにデータが格納されていることが分かります。

0012ff3c  50 ff 12 00:ChildEBP。memcpyが呼び出されベースポインタを退避。

0012ff4c  ff 17 40 00:RetAddr。memcpyはcallされリターンアドレスを格納。

0012ff44  68 e0 08 06:memcpy引数1

0012ff48  2c 30 40 00:memcpy引数2

0012ff4c  0a 00 00 00:memcpy引数3

0012ff50  7c ff 12 00:ChildEBP。FuncAが呼び出されベースポインタを退避。

0012ff54  2f 18 40 00:RetAddr。FuncAはcallされリターンアドレスが格納。

0012ff58  68 e0 08 06:FuncA引数buf1

0012ff5c  2c 30 40 00:FuncA引数buf2

0012ff60  0a 00 00 00:FuncA引数size

0012ff64  4c 10 40 00:z

0012ff68  18 30 40 00 20 30 40 00 1c 30 40 00:x サイズは10だがアライメント分+2

0012ff74  14 20 3e 62:ArrayPad

0012ff78  2c 30 40 00:y

memcpyへ渡される第1引数は0608e068(0012FF68+05F5E100(100000000))、第2引数は0040302cとなります。
プログラム通りといえば、プログラム通りですが、第1引数はアプリケーションアドレスの範囲を超えており異常です。
第2引数はプログラムコードを指しており、.mapファイルを見るとmerr.objを参照していることが分かります。実際yは初期化されていないので、どこを指すかは不定ですが、今回はこのようになっています。

0003:00000000       ___security_cookie           00403000     MSVCRT:gs_cookie.obj

0003:00000004       ___security_cookie_complement 00403004     MSVCRT:gs_cookie.obj

0003:00000008       ___native_dllmain_reason     00403008     MSVCRT:natstart.obj

0003:0000000c       ___native_vcclrit_reason     0040300c     MSVCRT:natstart.obj

0003:00000010       ___globallocalestatus        00403010     MSVCRT:xthdloc.obj

0003:00000014       ___defaultmatherr            00403014     MSVCRT:merr.obj

0003:0000035c       __forceCRTManifest           0040335c     MSVCRT:crtmanifest.obj

FuncAのリスティングファイル(青字部分は私が追加したコメントです)

EXTRN   @__security_check_cookie@4:PROC

EXTRN   _memcpy:PROC

PUBLIC  ?FuncA@@YAHPAD0H@Z                             ; FuncA

; Function compile flags: /Odtp

; File C:\crash\crash\crash.cpp

_TEXT   SEGMENT

_buf1$ = 8                                             ; size = 4

_buf2$ = 12                                            ; size = 4

_size$ = 16                                            ; size = 4

?FuncA@@YAHPAD0H@Z PROC                                ; FuncA

; 8    : {

;ベースポインタ退避して、; スタックポインタをベースポインタへ設定

  00000 55             push   ebp          

  00001 8b ec          mov    ebp, esp     

; 9    :        buf1 += 100000000;

;eax レジスタを使ってbuf1へ100000000加算

  00003 8b 45 08        mov   eax, DWORD PTR _buf1$[ebp]

  00006 05 00 e1 f5 05  add    eax, 100000000        ; 05f5e100H

  0000b 89 45 08        mov   DWORD PTR _buf1$[ebp], eax

; 10   :        memcpy(buf1, buf2, size);

; 引数をスタックへ積み上げ。(_cdecl呼出しなのでsize,buf2,buf1の順で積み上げ)

  0000e 8b 4d 10        mov   ecx, DWORD PTR _size$[ebp]

  00011 51             push   ecx

  00012 8b 55 0c        mov   edx, DWORD PTR _buf2$[ebp]

  00015 52             push   edx

  00016 8b 45 08        mov   eax, DWORD PTR _buf1$[ebp]

  00019 50             push   eax

; _memcpyをコールし、スタックポインタを引数分12(size=4,buf2=4,buf1=4)戻す。

  0001a e8 00 00 00 00  call   _memcpy

  0001f 83 c4 0c        add   esp, 12                       ; 0000000cH

; 11   :        return 1;

; 戻り値はeaxレジスタで返す

  00022 b8 01 00 00 00  mov    eax, 1

; 12   : }

Mainのリスティングファイル(青字部分は私が追加したコメントです)

PUBLIC  __$ArrayPad$

PUBLIC  _wmain

EXTRN   ___security_cookie:DWORD

; Function compile flags: /Odtp

_TEXT   SEGMENT

_z$ = -24                                              ; size = 4

_x$ = -20                                              ; size = 10

__$ArrayPad$ = -8                                      ; size = 4

_y$ = -4                                               ; size = 4

_argc$ = 8                                             ; size = 4

_argv$ = 12                                            ; size = 4

_wmain  PROC

; 16   : {

;ベースポインタ退避して、; スタックポインタをベースポインタへ設定

  00030 55             push   ebp

  00031 8b ec          mov    ebp, esp

; スタックポインタをローカル変数分24(z=4, x=10+2, ArrayPad=4, y=4)バイト進ませる。

  00033 83 ec 18        sub   esp, 24                       ; 00000018H

;スタックポインタ保持(スタックバッファオーバー検出用)

  00036 a1 00 00 00 00  mov    eax, DWORD PTR ___security_cookie

  0003b 33 c5          xor    eax, ebp

  0003d 89 45 f8        mov   DWORD PTR __$ArrayPad$[ebp], eax

; 17   :        char x[10];

; 18   :        char* y;

; 19   :

; 20   :        int z = FuncA(x, y, 10);

; 引数をスタックへ積み上げ。_cdecl呼出しなので(size,buf2,buf1の順で積み上げ)

  00040 6a 0a          push   10                    ; 0000000aH

  00042 8b 45 fc        mov   eax, DWORD PTR _y$[ebp]

  00045 50             push   eax

  00046 8d 4d ec        lea   ecx, DWORD PTR _x$[ebp]

  00049 51             push   ecx

;FuncAをコールし戻り値をzへ格納。また、スタックポインタを引数分12(z=4,y=4,x=4)戻す。

  0004a e8 00 00 00 00  call   ?FuncA@@YAHPAD0H@Z    ; FuncA

  0004f 83 c4 0c        add   esp, 12                       ; 0000000cH

  00052 89 45 e8        mov   DWORD PTR _z$[ebp], eax

; 21   :        return 0;

;戻り値を0で返す。

  00055 33 c0          xor    eax, eax

; 22   : }

;スタックポインタを最初に保持していたものと現在のもので比較(スタックバッファオーバー検出)し、ベースポインタを戻す

  00057 8b 4d f8        mov   ecx, DWORD PTR __$ArrayPad$[ebp]

  0005a 33 cd          xor    ecx, ebp

  0005c e8 00 00 00 00  call   @__security_check_cookie@4

  00061 8b e5          mov    esp, ebp

  00063 5d             pop    ebp

  00064 c3             ret    0

_wmain  ENDP

_TEXT   ENDS

END

.codファイルとログファイルから、以上のように解析していくことになります。
Cのソースでは数行のプログラムですが、アセンブラで解析するとなるとやっぱり大変です。

そこで、次はWinDBGを使ってみたいと思います。

5. クラッシュダンプファイルからの解析

次にアプリケーションエラーで発生したもう1つのファイル「user.dmp」を使った解析を説明します。
まず、WinDBGをhttp://www.microsoft.com/japan/whdc/devtools/debugging/installx86.mspxからダウンロードしてきます。

WinDBGはWindowsドライバ等のカーネルデバッガとして使用されるものですが、クラッシュダンプファイルも扱うことができます。
現時点のバージョンは、Version 6.9.3.113でした。

WinDBGのインストールが完了したら、「user.dmp」ファイルをWinDBGで開きます。
その際には、ビルド時に出力した.pdbファイルもロードします。
すると以下のような例外が発生した状態で画面が開きます。

この状態で、ソースおよびアセンブラ、コールスタック、ローカル変数を確認することができます。
コールスタック画面で、スタックを移動するとそれに合わせて、ソースやアセンブラ、ローカル変数の値が変化します。
コールスタックでは、デバッグシンボル(.pdb)があれば、関数名+引数まで自動で出してくれます。
その他の具体的な使い方は、WinDBGのヘルプを見て覚えることになりますが、「drwtsn32.log」と.codファイルから解析するよりは明らかに早いです。(昔はこんなに使いやすくなかったような気もしますが)

ただ、「drwtsn32.log」と.codファイルからも解析できないと、WinDBGを使っても例外となっている理由が分からない場合もあるので、C/C++が動く仕組みを知っておく必要があります。

6. まとめ

ここまで、アプリケーションエラーの解析方法を、「drwtsn32.log」と「user.dmp」とでの解析方法をまとめてみました。
しかし、このワトソン博士のログがいつもこのような情報を残してくれるとは限りません。むしろ残してくれないような場合がほとんどです。

例えば下のような場合ですが、MFC71.dllからnt.dllを呼び出しているところで例外が発生しています。アプリケーションアドレスはどこにも出てこず、WinDBGで見てもスタック情報はこれ以上残っていません。
こうなると、ログから原因を特定するのは無理に近いです。

*----> スレッド Id 0xd3c の状態のダンプ  <----*

eax=00000020 ebx=069ea510 ecx=7ff97000 edx=00000020 esi=00000000 edi=069ea510

eip=7c941010 esp=0d53fa0c ebp=0d53fa50 iopl=0        nv up ei pl nz na pe nc

cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000            efl=00000202

ファンクション: ntdll!RtlEnterCriticalSection

        7c940ffc 0000            add     [eax],al

        7c940ffe 0000            add     [eax],al

        7c941000 90              nop

        7c941001 90              nop

        7c941002 90              nop

        7c941003 90              nop

        7c941004 90              nop

        ntdll!RtlEnterCriticalSection:

        7c941005 648b0d18000000  mov     ecx,fs:[00000018]

        7c94100c 8b542404        mov     edx,[esp+0x4]

フォールト ->7c941010 837a1400      cmp dword ptr[edx+0x14],0x0 ds:0023:00000034=????????

        7c941014 754f            jnz   ntdll!RtlEnterCriticalSection+0x60 (7c941065)

        7c941016 f0ff4204        lock    inc dword ptr [edx+0x4]

        7c94101a 7519            jnz   ntdll!RtlEnterCriticalSection+0x30 (7c941035)

        7c94101c 8b4124          mov     eax,[ecx+0x24]

        7c94101f 89420c          mov     [edx+0xc],eax

        7c941022 c7420801000000  mov     dword ptr [edx+0x8],0x1

        7c941029 33c0            xor     eax,eax

        7c94102b c20400          ret     0x4

        7c94102e 8da42400000000  lea     esp,[esp]

        7c941035 8b4124          mov     eax,[ecx+0x24]

*----> スタック バック トレース <----*

WARNING: Stack unwind information not available. Following frames may be wrong.

ChildEBP RetAddr  Args to Child       

0d53fa50 7c1cd34b 069ea510 00000081 00000000 ntdll!RtlEnterCriticalSection+0xb

0d53fefc 7c150ff8 005468cd 00000000 069dc958 MFC71!Ordinal5346+0x33

0d53ff80 7c349565 08def69c 00000000 00000000 MFC71!Ordinal4590+0xd1

0d53ffb4 7c80b683 06a04f70 00000000 00000000 MSVCR71!endthreadex+0xa0

0d53ffec 00000000 7c3494f6 06a04f70 00000000 kernel32!GetModuleFileNameA+0x1b4

これを解決するためには、発生した状況や、考えられる条件から仮説を立て、1つずつ検証していくという時間をかけた地道な方法しかありません。
よって、このような状態にならないためにも、ログファイルやクラッシュダンプファイルに頼るのではなく、しっかりとした設計、また、必要十分なテストを実施してソフトを出荷していくことが必要となります。

また、余談ですが、久しぶりにVC++プログラムのアセンブラを見ると、「security_check_cookie」や「ArrayPad」というスタックチェックのコードが増えていました。
VC++6.0にはなかったとは思い、調べてみるとスタックのバッファオーバーラン検出処理でした。
(http://msdn.microsoft.com/ja-jp/magazine/cc337897.aspx)
現在でもC/C++の改良を行っていることにも驚いたのと同時に、たまにはアセンブラも見てみるものだなあと感じる今日このごろです。

(H.K.)

[参考文献]
日経BPソフトプレス発行
インサイドWindows上・下[第4版]
日経BPソフトプレス発行
.NET&Windowsプログラマのためのデバッグテクニック徹底解説
[注釈]
※1
共通ランタイム環境CLR(CommonLanguageRuntime)の管理下で実行されるプログラム。C#.NETやVB.NETプログラムで、メモリ管理等が強化されている。
※2
CLR上で動作しない従来のCやC++プログラム

関連ページへのリンク

関連するソフテックだより