バグ #994
完了
delayer-deferrd 1.1.0を使うと特定の操作でmikutterが落ちる
説明
下記の環境で、Fiber由来の例外が頻発するようになりました。
- macOS Sierra
- Ruby2.4.0p0（homebrew）
- mikutter 3.5.4
- delayer-deferrd 1.1.0
確実に再現するのは以下のパターンです。
それぞれバックトレースを付けています。
- ポストボックスに文字列をコピペする
- mikutter-uwm-hommageで追加されるポストボックス横のボタンを押下する。（ファイル選択ダイアログ表示）
- 設定画面から「リスト」ダイアログを表示
- delayer-deferrdを1.0.4にすると不再現になります。
- この例外は、Fiber生成時とresume読み出し時において、スレッドがC言語レベルで持ってるメンバprotect_tagが異なる時に発生するようです。protect_tagはrb_protect()と言う「Procを実行して例外とか大域脱出が起きたか否かを返す」関数で更新されるようです。
- 結局、何をやってるのかよくわからず、protect_tagが書き換わる条件が突き止められてない今日この頃です。
たちまちは調査継続しようと思います。
再現手順
・ポストボックスに文字列をコピペする
FiberError fiber called across stack rewinding barrier
{MIKUTTER_DIR}-xxx/vendor/bundle/ruby/2.4.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferred.rb:60:in `fiber'
{MIKUTTER_DIR}-xxx/vendor/bundle/ruby/2.4.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferredable.rb:69:in `block in _call'
{MIKUTTER_DIR}-xxx/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
{MIKUTTER_DIR}-xxx/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
{MIKUTTER_DIR}-xxx/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
{MIKUTTER_DIR}-xxx/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
{MIKUTTER_DIR}-xxx/core/plugin/gtk/delayer.rb:10:in `block in boot'
{MIKUTTER_DIR}-xxx/core/plugin/gtk/mainloop.rb:10:in `main'
{MIKUTTER_DIR}-xxx/core/plugin/gtk/mainloop.rb:10:in `mainloop'
mikutter.rb:66:in `boot!'
mikutter.rb:95:in `<main>'
・mikutter-uwm-hommageで追加されるポストボックス横のボタンを押下する。（ファイル選択ダイアログ表示）
FiberError fiber called across stack rewinding barrier
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferred.rb:60:in `fiber'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferredable.rb:69:in `block in _call'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
{MIKUTTER_DIR}/core/plugin/gtk/delayer.rb:10:in `block in boot'
/Users/moguno/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `run'
/Users/moguno/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `choose_image_file'
/Users/moguno/.mikutter/plugin/mikutter-uwm-hommage/postbox.rb:216:in `block in initialize'
{MIKUTTER_DIR}/core/mui/gtk_extension.rb:33:in `block in safety_signal_connect'
{MIKUTTER_DIR}/core/plugin/gtk/mainloop.rb:10:in `main'
{MIKUTTER_DIR}/core/plugin/gtk/mainloop.rb:10:in `mainloop'
mikutter.rb:66:in `boot!'
mikutter.rb:95:in `<main>'
・設定画面から「リスト」ダイアログを表示
FiberError fiber called across stack rewinding barrier
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferred.rb:60:in `fiber'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferredable.rb:69:in `block in _call'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
{MIKUTTER_DIR}/vendor/bundle/ruby/2.4.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
{MIKUTTER_DIR}/core/plugin/gtk/delayer.rb:10:in `block in boot'
{MIKUTTER_DIR}/core/mui/gtk_mtk.rb:368:in `main'
{MIKUTTER_DIR}/core/mui/gtk_mtk.rb:368:in `dialog'
{MIKUTTER_DIR}/core/mui/gtk_mtk.rb:329:in `scrolled_dialog'
{MIKUTTER_DIR}/core/mui/gtk_crud.rb:181:in `popup_input_window'
{MIKUTTER_DIR}/core/mui/gtk_crud.rb:159:in `block in record_update'
{MIKUTTER_DIR}/core/mui/gtk_crud.rb:158:in `selected_each'
{MIKUTTER_DIR}/core/mui/gtk_crud.rb:158:in `record_update'
{MIKUTTER_DIR}/core/mui/gtk_crud.rb:37:in `block in update_button'
{MIKUTTER_DIR}/core/mui/gtk_extension.rb:33:in `block in safety_signal_connect'
{MIKUTTER_DIR}/core/plugin/gtk/mainloop.rb:10:in `main'
{MIKUTTER_DIR}/core/plugin/gtk/mainloop.rb:10:in `mainloop'
mikutter.rb:66:in `boot!'
mikutter.rb:95:in `<main>'
・mikutter-uwm-hommage で画像ファイル選択ダイアログが出てクリックしようとした時 その1 by tsutsui
/usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferred.rb:59:in `resume': fiber called across stack rewinding barrier
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferred.rb:59:in `fiber'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferredable.rb:69:in `block in _call'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `call'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
from /usr/pkg/share/mikutter/core/plugin/gtk/delayer.rb:10:in `block in boot'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `call'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `run'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `choose_image_file'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/postbox.rb:216:in `block in initialize'
from /usr/pkg/share/mikutter/core/mui/gtk_extension.rb:33:in `call'
from /usr/pkg/share/mikutter/core/mui/gtk_extension.rb:33:in `block in safety_signal_connect'
from /usr/pkg/share/mikutter/core/plugin/gtk/mainloop.rb:10:in `call'
from /usr/pkg/share/mikutter/core/plugin/gtk/mainloop.rb:10:in `main'
from /usr/pkg/share/mikutter/core/plugin/gtk/mainloop.rb:10:in `mainloop'
from /usr/pkg/share/mikutter/mikutter.rb:64:in `boot!'
from /usr/pkg/share/mikutter/mikutter.rb:93:in `<main>'
・mikutter-uwm-hommage で画像ファイル選択ダイアログが出てクリックしようとした時 その2 by tsutsui
/usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferred.rb:59:in `fiber': fiber called across stack rewinding barrier (FiberError)
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-deferred-1.1.0/lib/delayer/deferred/deferredable.rb:69:in `block in _call'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `call'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/procedure.rb:24:in `run'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/extend.rb:58:in `run_once'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer/extend.rb:30:in `run'
from /usr/pkg/lib/ruby/gems/2.2.0/gems/delayer-0.0.2/lib/delayer.rb:43:in `method_missing'
from /usr/pkg/share/mikutter/core/plugin/gtk/delayer.rb:10:in `block in boot'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `call'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `run'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/penguin.rb:57:in `choose_image_file'
from /home/tsutsui/.mikutter/plugin/mikutter-uwm-hommage/postbox.rb:216:in `block in initialize'
from /usr/pkg/share/mikutter/core/mui/gtk_extension.rb:33:in `call'
from /usr/pkg/share/mikutter/core/mui/gtk_extension.rb:33:in `block in safety_signal_connect'
from /usr/pkg/share/mikutter/core/plugin/gtk/mainloop.rb:10:in `call'
from /usr/pkg/share/mikutter/core/plugin/gtk/mainloop.rb:10:in `main'
from /usr/pkg/share/mikutter/core/plugin/gtk/mainloop.rb:10:in `mainloop'
from /usr/pkg/share/mikutter/mikutter.rb:64:in `boot!'
from /usr/pkg/share/mikutter/mikutter.rb:93:in `<main>'
関連するチケット
toshi_a 初音 さんがほぼ8年前に更新
ポストボックスに文字列をコピペする
再現しませんでした。
mikutter-uwm-hommageで追加されるポストボックス横のボタンを押下する。（ファイル選択ダイアログ表示）
再現しませんでした。
・設定画面から「リスト」ダイアログを表示
再現しました。全く同じバックトレースが得られています。
一番目を除くと、ダイアログボックスを表示する処理なので、メインループが別の場所に奪われる箇所ですね。詳しく調査してみます。
toshi_a 初音 さんがほぼ8年前に更新
Gtkのメインループ（＝メインスレッド）の処理中にGtk.mainが再度呼ばれると、Delayerジョブの中でDelayerループが呼ばれる。
Deferredブロックの中でDeferredが呼ばれる可能性があるということで、Deferred 1.1.0からはDeferredのWorkerのFiberの中でWorkerのFiber#resumeを呼ぶということが起こりそう。その場合、FiberErrorが発生する。
Gtk.mainを呼び出して再帰メインループを作り出している全ての部分でこれが発生する可能性があるということ。Gtk.mainを呼び出しているのは以下の部分。
（正式なバグ報告はないが、本件と関係がありそうなツイートを見かけていたので、分かる範囲で参考程度に書いておいた。）
- core/mui/gtk_mtk.rb
- L306 (汎用のID/Passwordを問うアカウントダイアログを表示するユーティリティ)
- L368 (汎用のOK/キャンセルダイアログを表示するユーティリティ)
- 本チケットの3つ目のバックトレース「設定画面から「リスト」ダイアログを表示 」
- core/plugin/gtk/mainloop.rb
- L10 (mikutterのメインループ。おそらく今回の問題の対象外)
- core/plugin/shortcutkey/shortcutkey_listview.rb
- L127 (ショートカットキー設定画面の、キーバインドと割り当てるコマンドを設定するダイアログボックス)
- しかし相変わらずmikutterのショートカットキーの設定ウィンドウが開けず… https://twitter.com/MysticDoll/status/841928612567764993
- L127 (ショートカットキー設定画面の、キーバインドと割り当てるコマンドを設定するダイアログボックス)
- core/plugin/bugreport/bugreport.rb
- L45 (mikutter起動時に、前回クラッシュした時のレポートを送信するかを問うダイアログボックス)
- core/plugin/change_account/account_control.rb
- L85 (新規Twitterアカウントを追加する時のダイアログボックス)
- 拝啓 @toshi_a 氏 垢追加しようとしてPINコード入れるとクラッシュします(3.5.4 3.5.3に上書きインスコ) 敬具 #mikutter https://twitter.com/taka_hvc1/status/841612064393109504
- L85 (新規Twitterアカウントを追加する時のダイアログボックス)
バグレポートのダイアログボックスは、Delayer内部だがDeferred内部ではないのでクラッシュしていないと考えられる。他の箇所については、コールスタックが複雑なので個別に検証する必要がある。同じ部分でも、場合によってDeferredを経由するかどうかは変わる可能性があるので、検証の際には気をつける。
Izumi Tsutsui さんがほぼ8年前に更新
- バックトレース を更新 (差分)
あまり参考にならないかもしれませんが、こちらで mikutter-uwm-hommage の操作で発生した時の状況と
バックトレースを付けておきます。
- NetBSD 7.1_RC2
- ruby 2.2.6 (pkgsrc)
- mikutter 3.5.4 (pkgsrc)
- mikutter-uwm-hommage 353cdb862046ad98dad98280be819a93e7d17eaa
- delayer-deferred-1.1.0
- 「mikutter-uwm-hommage で画像ファイル選択ダイアログが出てクリックしようとした時 その1 by tsutsui」
- 「mikutter-uwm-hommage で画像ファイル選択ダイアログが出てクリックしようとした時 その2 by tsutsui」
toshi_a 初音 さんが7年以上前に更新
関係しそうなコードをざっと読みましたが、 rb_protect() はmogunoさんが説明に書いているとおりで、rb_thread_tのprotect_tagとは、rb_protect()の再帰呼出しレベルが異なることを検出するためにfiber_switch()関数では利用されている値のようですね。これ以上の意味がありそうでしたが、この先の調査を考えるとあまり意味が無さそうだったので、これ以上の深追いはしていません。
「fiber called across stack rewinding barrier」はprotect_tagが違う、すなわち再帰レベルが異なる場合に発生する例外のようです。Fiberは、同じrb_protect()のコンテキストでないと呼べないというルールがあるということになります。
このルールについては調べていても出てこなかったし、今まで知らずに書いていたので何故踏まなかったのか疑問だったので、protect_tagが違う具体的なケースを探りました。
CRubyのコードを読んでいる限り、例えばHash#fetchに存在しないキーを渡した時に発生する例外KeyErrorの説明に、key.inspectの結果が使われるようですが、このinspectがrb_protect()の中で呼ばれてました。他にもいくつか読みましたが、普通帯域脱出をしようと思わないところで使われていることが多い印象を受けました。
クラッシュしているのは
- そういう変な場所からFiberを生成またはレジュームしているか、
- gtk2などのExtensionが、ある処理をrb_protect()をとおして呼んでいるのを知らずにコードを書いてしまっている
くらいだと思われます。いずれにしても、読むべきコードが多すぎるので、クラッシュした場所ではなくDeferredオブジェクトが作られた場所（バックトレース）を入手して、どういった時にクラッシュするかがわからないかなぁと思っています。
Izumi Tsutsui さんが6年以上前に更新
あまり役に立たない情報ですが
「どうやったら確実に再現させられるか」という観点だと以下でほぼ確実に FiberError が発生します。- mikutter 3.6.5 を入れる
- なので delayer-deferred は 2.0.0
- display_requirements.rb を入れる
- mikutter-uwm-hommage を入れる
- mikutter を起動
- 起動直後の TL やアイコンを大量に表示している最中に mikutter-uwm-hommage のツイートボタン横の写真投稿ボタンを押す
- →ダイアログが出た直後くらいにクラッシュ
今 NetBSDておくれLive Image環境で試したところでは5回中5回発生しました。
Osamu Koga さんが5年以上前に更新
この問題は #1240 と同じやつだと思うんですが、あっちのチケットのバックトレースもこちらと同様に (https://dev.mikutter.hachune.net/attachments/443#L375) ダイアログを開いた瞬間に Delayer.run を叩きに行って、delayer-deferredがFiberをresumeしようとして死んでるようなので、「DelayerのキューにDeferredが入ってる時にダイアログを開くと落ちる」が再現手順として有力なのではないかと思います。
rb_protect についてはおそらく https://silverhammermba.github.io/emberb/c/#rb_protect が一番まともな説明だと思います。要するに、CレベルからRubyのメソッドを呼ぶとき、通常はRubyの例外が飛ぶとCのスタックトレースも巻き込んでロールバックしようとしますが、Cレベルで何らかの状態を管理しているライブラリはそれをされるとマズいことがあるので、何かが起きても絶対ここで巻き戻しを止めて、例外が起きたかどうかはエラーコードで通知するよ、という関数のようです。
gtk2-3.3.2でこれを利用しているコードは見当たりませんでしたが、glib2-3.3.2では rbgutil_callback.c という、かなり汎用ライブラリっぽい名前のファイルで使われているので、GTKのシグナルもこれを間接的に使っているのではないかと推察されます（実際、どのスタックトレースもsscが絡んでいるので、ある程度の妥当性はあると思います）。sscのブロックがrb_protect内で実行されているとすると、DeferredのFiberが通常最初に実行される gtk/delayer.rb のコンテキストとは異なるため、このようなエラーになる可能性が高いと思います。
Osamu Koga さんが5年以上前に更新
クラッシュを再現するためのプラグインを作りました。 https://github.com/osak/mikutter_fiber_crash
GTKの挙動を完全に理解しきれてないので少し想定と挙動が違いますが、手元で試した限りでは100%再現します。（2019/04/28時点の最新develop 4f798a3d で確認）
toshi_a 初音 さんが5年以上前に更新
- ステータス を 新規 から 実装待ち に変更
Mastodonでワイワイしていて気づきましたが、Gtk.mainだとstack rewinding barrierが作られてしまうので、一度だけイベントを実行するGtk.main_iterationを呼び出すメインループを自分で書けばいろいろと問題が起こらないことがわかりました。
この変更は topic/994-avoid-rewind-stack-rewinding-barrier にpushしました。
ただ、今のコードでは、普通に終了しようとするとウィンドウだけ閉じられてmikutterが動き続ける状態になってしまう問題があります。
toshi_a 初音 さんが5年以上前に更新
#1322 の修正がまずくて、何からの条件で Gtk.main を抜けた後にもう一度呼び出すと、当然Stack Rewinding Barrierももう一度作られるので、DelayerキューになにかジョブがあればFiberErrorが発生します。
この修正ではそもそもGtk.mainを呼ばないため、この問題が発生しません。皆で使って見て、感覚値でいいのでフィードバック欲しいです。
toshi_a 初音 さんが5年以上前に更新
一回 #1322 の正常終了と思われる現象が再現しましたが、SystemExit例外が発生していたので、もう一度再現してくれたら原因がわかりそう
toshi_a 初音 さんが5年以上前に更新
- トラッカー を 致命的 から バグ に変更
- ステータス を 実装待ち から レビュー待ち に変更
- 担当者 を Satoshi Okuno にセット
- 開始日 を削除 (
2017-03-14) - プラグイン名 を削除 (
？) - バックトレース を更新 (差分)
- 再現手順 を更新 (差分)
- ブランチ を topic/994-avoid-rewind-stack-rewinding-barrier にセット
- クラッシュする を はい にセット
クリップボードからの貼付け時など、 Gtk.idle_add_priority のコールバックがrb_protect()の中で呼ばれるタイミングがあることがわかりました。
そもそも、 #994-9 で、メインループをGtkではなくmikutter側でやるようになったので、 Delayer.run もGtkに任せず、mikutterで呼ぶようにしました。Gtkに長時間tickを供給しないと、ユーザからはUIが短時間フリーズしたように見えるので、Delayerのジョブが途切れるたびにGtkイベントの存在を確認しています。
この変更によって、 Delayer.run がGtkから呼ばれることは決して無くなったので、GtkによってFiberErrorが発生することは完全になくなりました。
ただ、クラッシュは再現できていませんが、未だ僅かですがDelayerが異なるrb_protect()の中から呼ばれていることが確認できました。とはいえ、クラッシュの頻度は減っているでしょう。
変わった点として、ショートカットキーダイアログなど、一部のダイアログボックスが表示されている間、mikutterが完全に停止するようになりました。これは3.10で実施する他の変更によって直ります。
Akira Ouchi さんが5年以上前に更新
起動直後のpostboxに対するクリップボード貼り付けなどの乱雑な操作、また #994-8 のプラグインでmikutterがクラッシュしないことを手元の環境※で確認できました。
※mac OS Mojave + MacPorts + ruby 2.6.3
toshi_a 初音 さんが5年以上前に更新
- 担当者 を Satoshi Okuno から toshi_a 初音 に変更
- 対象バージョン を 3.5 から 3.10 に変更
akkiesoftにレビューしてもらえたので、developにmergeし、3.10でリリースすることにします。
まだDelayer側の変更をリリースしてないのでその後にチケットをクローズします。
toshi_a 初音 さんが5年以上前に更新
- ステータス を レビュー待ち から 終了 に変更
Delayerの変更が特に意味もない上、2倍以上速度が遅くなることが分かったので、見送ることにします。このチケットでやるべきことは終わったのでcloseします。