Ticket #22386

Open Date: 2010-07-07 12:32

Last Update: 2015-11-07 21:05

マクロ長時間稼動時にApplication Fault

Reporter:hailaoOwner:(None)
Priority:5 - MediumMileStone:(None)
Type:BugsSeverity:5 - Medium
Component:Tera Term MacroStatus:Open
ResolutionNone

Details

数分間隔にコマンド送信して出力結果をログ保存するマクロを複数の宛先に並列で稼動させると、 数時間~数日後にWindowsのApplication Faultが発生し、Teratermが停止してしまいます。 本事象はバージョン4.65、4.66にて発生確認済みです。

必要であれば、Application Fault発生時に作成されるappcompat.txtを送付致します。

Attachment File

Attachment File List
7e92_appcompat.txt (25KB)
submitted by hailao at 2010-07-11 21:27 [File ID: 4383]
File Description: appcompat.txt
Application_Fault.JPG (30KB)
submitted by hailao at 2010-07-11 21:41 [File ID: 4384]
File Description: WindowsのApplicationFault表示
TTL.zip (2KB)
submitted by hailao at 2010-07-15 02:19 [File ID: 4385]
5eda_appcompat.txt (21KB)
submitted by hailao at 2010-07-19 08:59 [File ID: 4387]
File Description: snapshot-20100717.zipでの再現時のappcompat.txt
Application_Fault.txt (623bytes)
submitted by hailao at 2010-08-05 08:54 [File ID: 4391]
Stack_Trace_20100807.txt (2KB)
submitted by hailao at 2010-08-07 09:24 [File ID: 4392]
File Description: debug-20100807.zipでの再現時スタックトレース
Add New attachment
Add attachment filesPlease login to add new attachment

Ticket History - 3/38 Histories [Show all old Histories]

2010-07-07 12:32 Updated by: hailao

  • New Ticket "マクロ長時間稼動時にApplication Fault" created

2010-07-08 16:49 Updated by: yutakapon

  • Owner Update from (None) to yutakapon

Comment

当方においても、一週間以上Tera Termマクロでのランニングは行っていますが、 そのような現象は発生していません。

再現手順を教えてください。 また、マクロとappcompat.txtについても添付をお願いします。

2010-07-11 21:27 Updated by: hailao

  • File 7e92_appcompat.txt (File ID: 4383) is attached

2010-07-11 21:41 Updated by: hailao

  • File Application_Fault.JPG (File ID: 4384) is attached

2010-07-11 22:01 Updated by: hailao

  • Component Update from (None) to Tera Term Macro

Comment

早速のご返信ありがとうございます。
WindowsのApplicationFaultエラー表示とappcompat.txtを添付いたします。

マクロの動きは以下になります。
1.sendlnで出力したいコマンドが複数行記述されたテキストファイルをfileopenする。
2.filereadlnで上記テキストファイルを1行読み込み、読み込んだ文字列をファイル名としてlogopenでログファイル作成
3.上記2で読み込んだ文字列をsendlnでコマンドを送信
4.ログ出力が終わったらlogclose実施
5.上記2のテキストファイルの読み込みが最終行になるまで2~5の繰り返し
6.上記2のテキストファイルの読み込みが最終行になったら、filecloseして60秒pauseで待機
7.上記1へ戻る

当初は7~1へ戻る処理をfor文を使用して行っていましたが、同時実行するマクロが多くなってくると、
「Stack overflow」で止まってしまうため、goto文での処理としております。

マクロ本体の送付ですが、切り分けしやすいよう、一旦当方で余分なコードを省略してから送付させて頂きます。
省略するとはいえ、当然100%再現する状態のマクロで送付させて頂きます。

なお、再現環境はWindowsXP_SP3ですが、特定の機器のみで再現するわけではなく、
他の機器(XP_SP2)でも試してみましたが、やはり再現しております。

2010-07-15 02:19 Updated by: hailao

  • File TTL.zip (File ID: 4385) is attached

2010-07-15 02:34 Updated by: hailao

Comment

お世話になります。
マクロをアップしました。TTL.zipを解凍してご確認下さい。

マクロ本体のtest1.ttl-test6.ttlは9行目が異なる以外、同じ内容です。
9行目は出力するログファイル名の先頭部分を決める文字列です。
同一機器に同じマクロを実行した場合、ログファイル名が重複してしまうため、
9行目の数字を変更してあります。

CMD.txtはsendln出力したいコマンドを記載しております。

マクロの動きに関しては、前回記載したとおりです。
実行手順は以下を参照下さい。

1.CMD.txtを開いて送信したいコマンドを編集 2.実行対象機器にTeratermで手動ログイン
3.コントロールメニューからマクロを選択し、test1.ttlを実行。

上記要領でtest6.ttlまで実行し、6並列で長時間稼動させます。
当方では24h程度で本事象の発生を確認しております。

お手数ですが、解析の程、よろしくお願い致します。

2010-07-16 11:19 Updated by: yutakapon

Comment

マクロありがとうございます。当方でも再現することを確認しました。 ttpmacro.exe プログラムの中で、メモリ破壊(BOF)が起きているようです。 現在、調査中です。

2010-07-17 23:38 Updated by: yutakapon

Comment

詳細な原因はまだ判明していないのですが、ワークアラウンドを適用したアーカイブを作りました。 これで再現するか試してもらえるでしょうか?

http://ttssh2.sourceforge.jp/snapshot/ snapshot-20100717.zip

2010-07-19 08:57 Updated by: hailao

Comment

snapshot-20100717.zipで確認したところ、やはり再現しました。
再現時のappcompat.txtをアップします。

2010-07-19 08:59 Updated by: hailao

  • File 5eda_appcompat.txt (File ID: 4387) is attached

2010-07-28 20:55 Updated by: yutakapon

Comment

クラッシュしたときの詳細なスタックトレースを採取してみないと、原因がわかりません。 そこで、デバッグ情報込みのアーカイブを作りましたので、こちらで再現させてみて、 そのときのスタックトレース情報を採取願います。

http://ttssh2.sourceforge.jp/snapshot/snapshot-20100728.zip

2010-07-31 10:06 Updated by: hailao

Comment

すいません、スタックトレースの取得方法がよく分かりません。 お手数ですが、取得手順を教えて頂けますでしょうか。

2010-08-01 00:07 Updated by: yutakapon

Comment

hailao への返信

すいません、スタックトレースの取得方法がよく分かりません。 お手数ですが、取得手順を教えて頂けますでしょうか。

Tera Termがアプリケーションフォルトでクラッシュした際に、ダイアログが出てくる はずなので、その内容を取得しておいてもらえればよいです。 ダイアログでは CTRL+C でクリップボードへコピーできたと思います。

2010-08-05 08:53 Updated by: hailao

Comment

ダイアログをCTRL+Cでコピーした内容をアップしました。 よろしくお願い致します。

2010-08-05 08:54 Updated by: hailao

  • File Application_Fault.txt (File ID: 4391) is attached

2010-08-06 01:10 Updated by: yutakapon

Comment

hailao への返信

ダイアログをCTRL+Cでコピーした内容をアップしました。 よろしくお願い致します。

どうもありがとうございます。 ソケットの二重クローズ問題があるようなので、修正を行ってみました。 以下のアーカイブでも再現するでしょうか?

http://ttssh2.sourceforge.jp/snapshot/snapshot-20100806.zip

2010-08-06 08:32 Updated by: None

Comment

snapshot-20100806.zipで試したところ、やはり再現しました。 ダイアログのCTRL+Cでコピーした内容をアップします。 ソケットクローズの問題が発生しているようです。

2010-08-06 08:35 Updated by: None

Comment

ファイルのアップロードがうまくできないため、こちらに貼り付けます。BR


Tera Term: Application fault


eax=00000000 ebx=7FFDE000 ecx=00C99768 edx=77D514E0 esi=00000000 edi=00000001

ebp=00000000 esp=0012FA10 eip=0040758C efl=00010202

cs=001B ss=0023 ds=0023 es=0023 fs=003B gs=0000

Exception: ACCESS_VIOLATION

#1 0x0040758c in closesocket() + 0xfffd65d0 at TTERMPRO.exe #2 0x0042209e in closesocket() + 0xffff10e2 at TTERMPRO.exe #3 0x00422ecd in closesocket() + 0xffff1f11 at TTERMPRO.exe #4 0x77d0012a in SetShellWindowEx() + 0x198 at USER32.dll


OK


2010-08-07 00:53 Updated by: yutakapon

Comment

None への返信

ファイルのアップロードがうまくできないため、こちらに貼り付けます。BR ---------------------------

これでも再現してしまいましたか…。 ちょっとサイズが大きいですが、デバッグビルドしたアーカイブを作りました。 これで再現できれば、もう少し詳細なスタックトレースが採取できると思うので、 再現試験をお願いします。

http://ttssh2.sourceforge.jp/snapshot/ debug-20100807.zip

2010-08-07 09:23 Updated by: None

Comment

debug-20100807.zipで再現させたApplication_faultの出力をアップします。

2010-08-07 09:24 Updated by: hailao

  • File Stack_Trace_20100807.txt (File ID: 4392) is attached

2010-08-09 00:37 Updated by: yutakapon

Comment

None への返信

debug-20100807.zipで再現させたApplication_faultの出力をアップします。

どうもありがとうございます。 開発チーム内でも調査中ですが、やはり「メモリ破壊」に見えているのですが、 根が深く、原因特定までいたっていません。

問題解決へ導くためには、もう少し再現条件の絞り込みをする必要がありそうです。 開発チーム内では、実際に再現できていないのですが、絞り込みをすることは 可能でしょうか? #logopen -> logcloseを繰り返すと、落ちるとか。

2010-08-10 00:18 Updated by: hailao

Comment

コメントありがとうございます。
どのコードが原因となっているのか特定できるくらいに絞り込んでみます。
絞込みまで少々お時間を頂くことになるかもしれませんが、よろしくお願い致します。

2010-08-16 03:48 Updated by: hailao

Comment

お世話になります。

切り分けの詳細は以下になります。
1.Telnet接続→1分間隔で実行コマンド毎にlogopen->logclose→100%再現
2.Telnet接続→logopen→1分間隔でコマンド実行→再現せず
3.Telnet接続→1分間隔でコマンド実行→再現せず

上記から、やはり#logopen -> logcloseを繰り返すと発生する事象のようです。
2のlogopenしたままの状態では再現しないことから、logclose->次のlogopenに切り替わる過程で
何らかのメモリ破壊が起きているものと考えられます。

ちなみにWindows7環境で確認したところ、再現時にアプリケーションエラー以外にOut of Resourceという表示が 出力されました。

2010-08-16 09:36 Updated by: yutakapon

Comment

hailao への返信

お世話になります。

切り分けの詳細は以下になります。
1.Telnet接続→1分間隔で実行コマンド毎にlogopen->logclose→100%再現
2.Telnet接続→logopen→1分間隔でコマンド実行→再現せず
3.Telnet接続→1分間隔でコマンド実行→再現せず

上記から、やはり#logopen -> logcloseを繰り返すと発生する事象のようです。
2のlogopenしたままの状態では再現しないことから、logclose->次のlogopenに切り替わる過程で
何らかのメモリ破壊が起きているものと考えられます。

切り分け、どうもありがとうございます。これでだいぶ絞込みできそうです。 ところで、logopenの"LogPath"に渡されているパス名の長さが気になるのですが、どのくらいの 長さになっているのでしょうか? Tera Termは1つの文字列は256バイトまでしか保持できません。

> logopen LogPath 0 1 0 0 1

また、再現用マクロ(TTL.zip)において、"pause"を削除すれば、再現試験を加速できると 思われるのですが、pauseを取ると、どのくらいの時間で再現できるのでしょうか?


ちなみにWindows7環境で確認したところ、再現時にアプリケーションエラー以外にOut of Resourceという表示が 出力されました。

その出力は、どこに表示されていましたか? Windows7は使ったことがないので、よくわからないのですが、もしかしてTera Termがメモリリーク している可能性もありそうです。タスクマネージャで、"ttermpro.exe"もしくは"ttpmacro.exe"の メモリ使用量が、再現するまでメモリが増加していく感じでしたでしょうか?

2010-08-17 22:12 Updated by: yutakapon

Comment

以下のようなマクロを組んで、再現試験をしてみましたが、再現する様子はありませんでした。

:loop
LogPath='C:\Documents and Settings\yutaka\My Documents\TeraTermMacro\TTL\foo.log'
logopen LogPath 0 1 0 0 1
mpause 10
logclose
goto loop

2010-08-17 23:31 Updated by: hailao

Comment

お世話になります。
どうやら文字列256バイトを超過していたようです。
Cドライブ直下で試してみたところ、現時点で再現しておりません(13h経過中)
引き続き長時間稼働させて再現しないか見てみます。

2010-08-18 01:10 Updated by: yutakapon

Comment

hailao への返信

お世話になります。
どうやら文字列256バイトを超過していたようです。
Cドライブ直下で試してみたところ、現時点で再現しておりません(13h経過中)
引き続き長時間稼働させて再現しないか見てみます。

情報どうもありがとうございます。 やはり、バッファオーバーフローするバグが潜在しているようです。修正したいと思うのですが、 差し支えなければ、再現時のフルパス名を教えてください。

2010-08-18 12:08 Updated by: maya

Comment

調査してみました。

まずは再現条件から。messagebox を出すだけの単純なマクロファイルを作ります。

; 255 文字 ... OK
D:\work\test\dg82q34rfugo ue98n  349803u4 yut 8u34tu 34g 45 g453 34\as uq3 4u34 u43 0 ake ru# 4tu34 u03u4 uf3 4uu 34 i34i I[tgkdfsmh iorg egre asdfa sdj owiej roiweofjjasjlkjsz;kfjgkjrehgkjhndk sa\423f 4ioj iojsdaj kjd 38yer98 43t waioj kjl34joitu\pxl.ttl
; 256 文字 ... すぐ落ちる
D:\work\test\dg82q34rfugo ue98n  349803u4 yut 8u34tu 34g 45 g453 34\as uq3 4u34 u43 0 ake ru# 4tu34 u03u4 uf3 4uu 34 i34i I[tgkdfsmh iorg egre asdfa sdj owiej roiweofjjasjlkjsz;kfjgkjrehgkjhndk sa\423f 4ioj iojsdaj kjd 38yer98 43t waioj kjl34joitu\pxlx.ttl
; 259 文字 ... もちろんすぐ落ちる。手元の XP ではこれより長いファイル名を作れなかった。
D:\work\test\dg82q34rfugo ue98n  349803u4 yut 8u34tu 34g 45 g453 34\as uq3 4u34 u43 0 ake ru# 4tu34 u03u4 uf3 4uu 34 i34i I[tgkdfsmh iorg egre asdfa sdj owiej roiweofjjasjlkjsz;kfjgkjrehgkjhndk sa\423f 4ioj iojsdaj kjd 38yer98 43t waioj kjl34joitu\pxlxlxl.ttl

ということで、MATH_PATH (260) を使うべきなのにそうしていない箇所がありそうです。

ファイル名に使われる変数に、256の決めうちとteraterm.h内での#define MAXPATHLEN 256を使っているところをすべて洗う必要がありそうです。マジックナンバーの256はそのままで良いところもあるので、修正すべき・しなくてもよいの判別に注意が必要です。

2010-08-18 23:40 Updated by: yutakapon

Comment

maya への返信

調査してみました。 まずは再現条件から。messagebox を出すだけの単純なマクロファイルを作ります。

私も再現させてみましたが、これは GetFileName()#ttmdlg.cpp の GetOpenFileName() がエラーに なっているだけではないでしょうか。 nMaxFileメンバが 256 なので、APIがはじいていると思われます。

2010-08-19 01:14 Updated by: maya

Comment

yutakapon への返信

私も再現させてみましたが、これは GetFileName()#ttmdlg.cpp の GetOpenFileName() がエラーに なっているだけではないでしょうか。 nMaxFileメンバが 256 なので、APIがはじいていると思われます。

ttl のダブルクリック(関連づけから)だと char FileName[MAXPATHLEN] に入れるところで切り捨てられ、LoadMacroFile()#ttmbuff.c の中で _lopen() に失敗して終了しています。

ttpmacro.exe のダブルクリックから ttl を選んだときは、GetOpenFileName() が成功し、その直後でウォッチするとどういうわけか 256 バイトのファイル名を得ており(終端\0を含めると257なので行き過ぎ)、先に進んでいるようです。

少なくともこの時点で何かおかしいことが起きているので、この類の問題ではないかと見当をつけた次第です。

!TTLLogOpen() から追いかけると SetFile()#ttmdde.c に来て、char Cmd[256] に _snprintf_s(Cmd, sizeof(Cmd), _TRUNCATE, "%c%s", CmdSetFile, FN); しているので 259 文字のファイル名はあふれませんが入りきらず ttermpro.exe に伝わりませんし、ParamFileName()#ttdde.c では受け取り側が static char ParamFileName[256] なので、渡されたとしてもこちらも入り切りません。

他にも似たような所がありそうなので、全部チェックしなきゃだめなんじゃないの?というわけです。

2010-08-21 12:29 Updated by: maya

Comment

hailao への返信

お世話になります。
どうやら文字列256バイトを超過していたようです。

スナップショットを作成しました。問題となった環境でこのスナップショットを動かすとどうでしょうか?

http://ttssh2.sourceforge.jp/snapshot/snapshot-20100821.zip

ちなみに、その文字列(ファイル名?)にはマルチバイトは含まれているでしょうか?

2010-08-23 05:50 Updated by: hailao

Comment

お世話になります
スナップショットのバージョンで試してみます。
256バイト超過していた文字列ですが、マルチバイト文字列を相当数含んでおりました。

2010-08-23 07:07 Updated by: hailao

Comment

お世話になります。
マルチバイトを含んだ文字列で256バイト超過した環境下で
試したところ、やはり再現してしまいました。

2010-08-23 13:52 Updated by: maya

Comment

hailao への返信

マルチバイトを含んだ文字列で256バイト超過した環境下で
試したところ、やはり再現してしまいました。

TTL の文字列は 255 バイトまでしか認識しないので、それを超える長さのファイル名を logopen に渡しても開くのに失敗します。失敗しているかどうかは result を確認するとわかります。

256バイト以上になる文字列は次のうちどれですか? 1. マクロファイルのフルパス 2. ログファイルのフルパス 3. logopen に指定しているログファイルのファイル名(これは言語仕様上不可能なので、切り捨てられた文字列が渡る) 4. ttpmacro.exe のフルパス 5. その他

また、接続中に一切通信をせず logopen/logwrite/logclose のみでも再現しますか?

また、telnet 接続でこの問題が起こっているようですが、シリアル接続でも同じことが起こりますか?

yutakapon への返信

マルチバイトを含む場合には MAX_PATH バイトを超えるファイル名が作成されます。マルチバイト文字も 1 文字と数えて MAX_PATH-1 文字が最大になるようです。

例を挙げると、途中に「デスクトップ」が含まれている場合には、charMAX_PATH では 6 バイト足りなくなります。

2010-08-26 02:58 Updated by: hailao

Comment

返信がおくれました。
平日は本業が立て込んでいるので、週末に確認させてください。

2015-11-07 21:05 Updated by: yutakapon

  • Owner Update from yutakapon to (None)

Add Comment/Update #22386 (マクロ長時間稼動時にApplication Fault)

You are not logged in. I you are not logged in, your comment will be treated as an anonymous post. » Login