【情報募集】状況を再現・エリア移動の拍子に？フリーズ

[takuto_cw]

CardWirthPy_20130910 + WinXPで、状況を再現・エリア移動（あるいはキャンプ画面へ移行）の拍子に？　フリーズしたことがありました。

issue #91 のバグを追っていて、今日１日で４回くらい出くわしたのですが、再現方法がまだ見つかっておりません。エラーも何も出ずにいきなり落ちたり、「ご迷惑をおかけします（略）Pythonのエラーを送信する・しない」といったメッセージが出たりとまちまちです。今のところエラーログには何も残っていません。

本来こういうのは、きっちり再現方法を掴んでから書くべきなのでしょうけれど……同じ操作をしているはずなのに今度は問題なく動いたりなどして、捜査が難航しております。

フリーズ級バグはβ前に何とかしたい、これは広く情報を募った方がよさそうだ…ということで issue 立てました。もし何かお気づきになられたら、些細なことでも、書き込みいただけないでしょうか？　よろしくお願いします。

[k4nagatsuki]

ありがとうございます。これはクリティカルですね。

いつから発生したかがわかればいいのですが……。

[k4nagatsuki]

現象の不安定さから推測してメモリアクセス違反だとしたら、怪しいのは最近導入したボタン無効化イメージ周りでしょうか。あそこはCのコードが入っていますので。

一見した所違反するようなコードにはなっていないようにも思えますが、何かミスがあるのかも。再現性の高い操作があればすぐ確かめられるのですが。

[tachi gigas]

こちらでも、フリーズしたので同じ手順を取ると何も起こらない、操作が受け付けられないのでエラーが発生したと思われるもエラーログなし、同じ手順をとっても正常な動作をする、ような事があります。頻度は少ないですが。

最近のであった事例として、店シナに出て再度入った時にフリーズしたことがあります。やはり再現性もなく、ログには出ていません。むむむ…。

[k4nagatsuki]

7725d6d0c5f3 怪しいところを修正してみました。

[takuto_cw]

レスくださった皆様、ありがとうございます。

いつから発生したかがわかれば

ああそうか、再現方法でなくそちらを調べる手がありました。

こちらでも、フリーズしたので～

自分のところだけじゃなかったんですね。今回みたいな再現しにくいバグだと人数・試行回数が頼りですし。ちょっと安心。

怪しいところを修正

早速ありがとうございます。おかげさまで、今のところフリーズは再現していません。もうしばらく、じっくり様子を見てみます。当たりでありますように。

[tachi gigas]

関係あるかどうかはちょっとあれですが、フリーズする前に即刻異常終了ダイアログが出る現象に僥倖にも立ち会えました。アプリケーションログにあったものを以下コピペします。何かの参考になれば幸いです。

手順

• Windows 7 SP1 64bit
• 戦闘中にデバッグ画面を開いた
• 冒険者の状態を編集しようとした（ちょっとクリック時間が長かった）

ログ

障害が発生しているアプリケーション名: python.exe、バージョン: 0.0.0.0、タイム スタンプ: 0x5193f37d
障害が発生しているモジュール名: SDL_ttf.dll、バージョン: 0.0.0.0、タイム スタンプ: 0x4a5e185f
例外コード: 0xc0000005
障害オフセット: 0x00005f00
障害が発生しているプロセス ID: 0xa24
障害が発生しているアプリケーションの開始時刻: 0x01ceafb157e8eab4
障害が発生しているアプリケーション パス: C:\python27\python.exe
障害が発生しているモジュール パス: C:\python27\lib\site-packages\pygame\SDL_ttf.dll
レポート ID: 9f41b4af-1ba4-11e3-ad7d-ecd8622c6257

[takuto_cw]

情報ありがとうございます。原因が同じかどうかはともかく、まだフリーズバグは残っている、と……。

これはフリーズに出くわしたら、片っ端から状況を記録していくしかなさそうですね。アプリケーションログというものがあるとは知りませんでした。ちょっとgoogle先生に聞いてきます。

[k4nagatsuki]

やはりメモリを破壊してるようですね。SDL_ttf.dllの中でエラーが起きるなんて考えられない。

いつから起きたのか、つまりどのcommitから発生しているのかがわかれば後は簡単なのですが……。

[takuto_cw]

コメントありがとうございます。メモリ破壊を先生に聞いてきたところです。ええと、個別のクラッシュ状況を調べるより、

どのcommitから発生しているのかがわかれば

こっちを調べた方がいい、という理解で合っているでしょうか。適当に commit 100 個分くらい巻き戻して適当に 10 分くらい操作しまくる。フリーズしなければ一応大丈夫ということにして（たまたま遭わなかっただけかもしれない）今度は commit 50 個分進めて……以下繰り返していけばいいかな。よし、これなら自分でもできる。

[k4nagatsuki]

時期的に特に怪しいのがto_disabledimage()周りだと思います。こちらでは一度これを無効にして試してみようと考えてます。

確実に再現する方法があればこれで確実にわかるのですが、再現性が無いのでずっと不安がつきまとう事にはなりますが。

[takuto_cw]

フリーズの再現方法が見つかりました！

まずフリーズが発生する状況は、
　「デバッガを表示しながら」「エリア移動すると」「ごくまれに」発生する。 （エリア移動の何が効いてるのか…デバッガの表示更新するから？　そのへんは分かりません）

エリア移動を 200 回繰り返すテストシナリオ作りました。お試しください。おそらく 200 回行く前に凍るかと。

またこのバグは、少なくとも 7fe244e の頃から存在することがわかりました。これ以上巻き戻すとシナリオ開始時にエラーが出てしまったため、これ以前はテストできていません。

そういえば #91 を調べていたとき、どういう条件だと背景が表示されないのか試行錯誤していて、エリア移動を何十回も繰り返しました。状況再現でもエリア移動しますし、自分がフリーズに１日４回も遭ったのも、そのせいだと考えれば説明がつきます。

tachi_gigas さんの出会ったフリーズは…「店シナリオに入ろうとした」の方は、同じ要因かも。「冒険者の状態を編集しようとした」の方は、別件かもしれませんね。

[k4nagatsuki]

これは素晴らしい。ありがとうございます。目当てにしていたところは全然的外れでしたね。

これを手懸りに調査してみます。私の他にも何か気づいた方がいらっしゃったらどんどん情報をください。

[k4nagatsuki]

63cb21a76ee7 おそらく直りました。以下調査結果と推測。

wxPythonは中でwxWidgetというC++のライブラリを使っています。C++ではプログラマがメモリ管理をしないといけないので、それを少し楽にするために(たぶん)参照カウントという仕組みが使われています。

今回の件の調査中、稀に次のようなエラーを発する事がありました。

wx._core.PyAssertionError: C++ assertion "m_refData->m_count > 0" failed at ..\..\src\common\object.cpp(346) in wxObject::UnRef(): invalid ref data count

これはおそらく参照カウントの処理経過で矛盾が発生してしまっているというエラーです(assertionというのはプログラムが正常に動いているかチェックするためのコードを埋め込むことです)。

なぜ矛盾が出るのか。実はpygame側のスレッドでwxPythonのオブジェクトを生成している所が少なくとも一箇所ありました。画面下部のステータスバーの更新でこれが使用されていました。

wxWidgetは基本的にシングルスレッドで動くのですが、ステータスバーの更新処理とデバッガの更新処理が同時に走った結果、複数のスレッドでwxWdigetのオブジェクトの生成と破棄が繰り返され、メモリ管理中に参照カウント等の矛盾が発生してしまっていたと考えられます。assertionに引っかからず解放してはいけないメモリを解放してしまい、アクセス違反を発生させてしまう事もあるでしょう。

たぶんそうしたことでランダムに異常が起きていたのではないかと思います。pygame側でwxWidgetのオブジェクトを作らないようにして試しに無限にエリア移動するシナリオを一晩動かしてみたのですが、今でも元気にエリア移動を続けています(ごめんよ冒険者)。

現象を高確率で再現できなければここまで辿りつけなかったでしょう。takuto_cwさんに感謝します。ありがとうございました。

[takuto_cw]

帰ってきたら、大物バグがとっくに退治されていた……ありがとうございます！　おつかれさまです。CardWirthPy_20130914 でエリア移動しまくりましたが、全然普通に動いてます。

そして今更、フリーズの用法を間違えていたことに気づく自分。フリーズは画面が静止するやつで、自分とこの現象はハングアップというんですね……うああもう恥ずかしい。ずっとウソ情報書いてました。ごめんなさい。

解説もありがとうございます。詳しくない自分でもイメージ掴めました。CWPyでランダムに異常が起こる場合、どんな原因が考えられるかが分かって、面白いし参考になります。

さて、自分の遭ったバグは直していただきましたが、tachi_gigas さんのはもしかしたら別件かもしれないんですよね……。別件は別 issue にした方がわかりやすいと思うので、一旦この issue は解決済みにしてしまおうかと考えています。再利用をご希望でしたらコメントください。

情報をお寄せくださった tachi_gigas さん（まだ解決してないと知らされなければ、自分は再現方法を調査しませんでした）、調査・作業してくださった k4nagatsuki さん。改めて、どうもありがとうございました。

[k4nagatsuki]

いや、フリーズでもいいと思いますよ。Windows上で応答なしの状態になってしまいますし。

例のテストシナリオでSDL_ttf.dllでもエラーが起きる件は確認しています。メモリを破壊しているとすればどこでもエラーは発生しうるわけです。そしてエラー自体もステータスバーの描画のタイミングでwxPythonの処理が発生すればどこでも起こりうるわけで、ダイアログを開いた時に起きた問題もおそらく同じ原因ではないでしょうか(これを希望的観測とかいう)。

tachi_gigasさんが問題無いと思えばこのIssueはクローズしてしまってよいと思います。

なお、調べた所、他にwxPythonのデータを作っている箇所はメッセージやテキストセル周りで数箇所あるのですが、デバッガの更新処理等と競合するタイミングがあまり無さそうなので、そこにはTODO(FIXMEの方がよかったな)コメントをつけておきました。これらはpygameで日本語フォントを使えない問題に対処するためにwxPythonを利用しているだけなので、pygameのアップデートでフォント問題が修正されれば自ずと解決すると考えています。その前にテキスト描画周辺で似たような問題が発生した場合は仕方ないので本格的に掃討します。

[tachi gigas]

見ました。お疲れ様です。

takuto_cw さんが提示された検証シナリオのエラーのアプリケーションログ内容が同じなので、あくまで個人の感想ですが、同件と思っております。再発したらしたで立て直しても問題ないと思います。

[takuto_cw]

tachi_gigas さんのも同じ原因（のようだ）ときいて、安心しました。

ではフリーズが再発したら立て直すということで。一旦解決済みとさせていただきます。