株式会社 ソフテック
制御用ソフトウェアの受託開発を手がけて５２年の経験と
受注案件６９９５件（2024年3月末時点）の実績
受注案件６９９５件（2024年3月末時点）の実績
「ソフテックだより」では、ソフトウェア開発に関する情報や開発現場における社員の取り組みなどを定期的にお知らせしています。
さまざまなテーマを取り上げていますので、他のソフテックだよりも、ぜひご覧下さい。
ソフテックだより（発行日順）のページへ
ソフテックだより 技術レポート（技術分野別）のページへ
ソフテックだより 現場の声（シーン別）のページへ
Windowsプログラム（C/C++）の厄介な問題のひとつに、アプリケーションエラーがあります。
最近では.NET Framework上で動作するマネージドプログラム(※1)のプログラムが増えてきているため、アプリケーションエラーが発生する可能性は低いと思いますが、まだまだ現役のネイティブプログラム(※2)は多いため、避けては通れない問題です。
そんな中、先日、私にアプリケーションエラーの調査依頼があり、担当することになりました。しかし、数年振りにアプリケーションエラーの解析をしてみると忘れていることばかりで、いろいろ思い出しながらの作業でした。今回はその時にどのような手順で進めていったかをまとめてみたいと思います。
解析には、いろいろな前準備も必要ですので、以下の順で説明したいと思います。
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としています。
ソースを見れば、この時点でもうおかしなプログラムであることは明らかですが、今回はこのソースを使っていきます。
※また、分かりやすさのため、コンパイルの最適化は無効としています。
まず、アプリケーションエラーの解析に必要な情報は、プログラムのビルド時に設定する必要があります。
このリスティングファイル（ソースとアセンブリコード）によって、アプリケーションエラーが発生した際の、プログラムのアドレスを特定することができるようにします。
中間ファイル（.cod）を出力させるには、「構成プロパティ」の「C/C++」-「出力ファイル」-「アセンブリの出力」にて、アセンブリコード、コンピュータ語コード、ソースコード（/FAcs）を設定します。
※具体的な.codファイルの内容は以降のリスティングファイルで説明します。
オブジェクト毎のアドレスを示すMAPファイルも作成しておきましょう。
「構成プロパティ」の「リンカ」-「デバッグ」-「マップ ファイルの作成」にて、はい/いいえを設定できます。
デバッグシンボルは、以降で説明するクラッシュダンプファイルを使った解析の際に必要となるものです。
デフォルトの設定でプログラムデータエース（.pdb）ファイルが生成されますが、以下の「構成プロパティ」にて設定が可能です。
以上の設定を終えたら、プログラムをビルドして、「Crash.exe」を生成してください。
次にターゲットPCで、ワトソン博士の設定を行います。
ワトソン博士は、アプリケーションエラーが発生した際の、ログファイルとクラッシュダンプファイルの生成を行ってくれます。
通常であれば、Windowsのデフォルトデバッガがワトソン博士に設定されていますが、Visual Studioなどのデバッガがインストールされると、デバッガはそちらに変更されています。
よって、もとのワトソン博士へ戻してやることになります。
スタートメニューからファイル名を指定して実行にて「drwtsn32」と打ち込み、OKを押します。すると以下画面が表示されます。基本的には設定は変更する必要はありませんが、ログファイルパスや、クラッシュダンプファイルパスを変更したい場合にはこの画面にて設定します。
スタートメニューからファイル名を指定して実行にて「drwtsn32 -i」と打ち込み、OKを押すと以下画面が表示されますので、これでワトソン博士がデバッガとして登録されました。
その他に、デバッグ環境のPCと実際のターゲットPCで注意する点としては、使用するdllも合わせておく必要があります。（mfcやatl等）
使用するdllのバージョンが異なると、プログラムの動きも異なりますので注意してください。
※スタティックリンクでビルドしておくのであれば、これは注意する必要ありません。
ここまでで、ようやくソフトの準備とターゲットPCの準備が終わりました。
実際に、「Crash.exe」を実行してみます。
すると、よく見慣れた画面がでてきます。アプリケーションエラー発生です。
ここでは、送信しないボタンを押して、このダイアログを終了させます。
すると、先ほどのワトソン博士で設定したフォルダ（C:\Documents and Settings\All Users\Application Data\Microsoft\Dr Watson）へ、ログファイル「drwtsn32.log」とクラッシュダンプファイル「user.dmp」ができているはずです。
この2つのファイルから、解析を行っていきます。
アプリケーションエラーで発生したファイルの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
「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を使ってみたいと思います。
次にアプリケーションエラーで発生したもう1つのファイル「user.dmp」を使った解析を説明します。
まず、WinDBGをhttp://www.microsoft.com/japan/whdc/devtools/debugging/installx86.mspxからダウンロードしてきます。
WinDBGのインストールが完了したら、「user.dmp」ファイルをWinDBGで開きます。
その際には、ビルド時に出力した.pdbファイルもロードします。
すると以下のような例外が発生した状態で画面が開きます。
この状態で、ソースおよびアセンブラ、コールスタック、ローカル変数を確認することができます。
コールスタック画面で、スタックを移動するとそれに合わせて、ソースやアセンブラ、ローカル変数の値が変化します。
コールスタックでは、デバッグシンボル（.pdb）があれば、関数名＋引数まで自動で出してくれます。
その他の具体的な使い方は、WinDBGのヘルプを見て覚えることになりますが、「drwtsn32.log」と.codファイルから解析するよりは明らかに早いです。（昔はこんなに使いやすくなかったような気もしますが）
ただ、「drwtsn32.log」と.codファイルからも解析できないと、WinDBGを使っても例外となっている理由が分からない場合もあるので、C/C++が動く仕組みを知っておく必要があります。
ここまで、アプリケーションエラーの解析方法を、「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．）
関連ページへのリンク
関連するソフテックだより