Project

General

Profile

致命的 #994

delayer-deferrd 1.1.0を使うと特定の操作でmikutterが落ちる

Added by Satoshi Okuno over 2 years ago. Updated 3 months ago.

Status:
新規
Priority:
通常
Assignee:
-
Target version:
Start date:
2017-03-14
Due date:
% Done:

0%

プラグイン名:

Description

下記の環境で、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>'


Related issues

Related to 致命的 #995: CPU使用率が常に100%になり、メモリを大量に確保しつづけることがある終了2017-03-16

Actions

Associated revisions

Revision 6f92b280 (diff)
Added by toshi_a 初音 almost 2 years ago

5ヶ月頑張ってもdeferred 1.1のバグを潰せなかったので1.0系を使用する refs #994

History

#1

Updated by toshi_a 初音 over 2 years ago

ポストボックスに文字列をコピペする

再現しませんでした。

mikutter-uwm-hommageで追加されるポストボックス横のボタンを押下する。(ファイル選択ダイアログ表示)

再現しませんでした。

・設定画面から「リスト」ダイアログを表示

再現しました。全く同じバックトレースが得られています。

一番目を除くと、ダイアログボックスを表示する処理なので、メインループが別の場所に奪われる箇所ですね。詳しく調査してみます。

#2

Updated by toshi_a 初音 over 2 years ago

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 (ショートカットキー設定画面の、キーバインドと割り当てるコマンドを設定するダイアログボックス)
  • core/plugin/bugreport/bugreport.rb
    • L45 (mikutter起動時に、前回クラッシュした時のレポートを送信するかを問うダイアログボックス)
  • core/plugin/change_account/account_control.rb
    • L85 (新規Twitterアカウントを追加する時のダイアログボックス)

バグレポートのダイアログボックスは、Delayer内部だがDeferred内部ではないのでクラッシュしていないと考えられる。他の箇所については、コールスタックが複雑なので個別に検証する必要がある。同じ部分でも、場合によってDeferredを経由するかどうかは変わる可能性があるので、検証の際には気をつける。

#3

Updated by Izumi Tsutsui over 2 years ago

  • バックトレース updated (diff)

あまり参考にならないかもしれませんが、こちらで 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」
#4

Updated by toshi_a 初音 about 2 years ago

  • Related to 致命的 #995: CPU使用率が常に100%になり、メモリを大量に確保しつづけることがある added
#5

Updated by toshi_a 初音 almost 2 years ago

関係しそうなコードをざっと読みましたが、 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()の中で呼ばれてました。他にもいくつか読みましたが、普通帯域脱出をしようと思わないところで使われていることが多い印象を受けました。

クラッシュしているのは

  1. そういう変な場所からFiberを生成またはレジュームしているか、
  2. gtk2などのExtensionが、ある処理をrb_protect()をとおして呼んでいるのを知らずにコードを書いてしまっている

くらいだと思われます。いずれにしても、読むべきコードが多すぎるので、クラッシュした場所ではなくDeferredオブジェクトが作られた場所(バックトレース)を入手して、どういった時にクラッシュするかがわからないかなぁと思っています。

#6

Updated by Izumi Tsutsui over 1 year ago

あまり役に立たない情報ですが

「どうやったら確実に再現させられるか」という観点だと以下でほぼ確実に 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回発生しました。

#7

Updated by Osamu Koga 3 months ago

この問題は #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 のコンテキストとは異なるため、このようなエラーになる可能性が高いと思います。

#8

Updated by Osamu Koga 3 months ago

クラッシュを再現するためのプラグインを作りました。 https://github.com/osak/mikutter_fiber_crash
GTKの挙動を完全に理解しきれてないので少し想定と挙動が違いますが、手元で試した限りでは100%再現します。(2019/04/28時点の最新develop 4f798a3d で確認)

Also available in: Atom PDF