プロジェクト

全般

プロフィール

バグ #1137

3.6.0 で画像プレビュー表示に失敗することがある

Izumi Tsutsui10ヶ月前に追加. 9ヶ月前に更新.

ステータス:
終了
優先度:
通常
担当者:
対象バージョン:
プラグイン名:
ブランチ:
クラッシュする:
いいえ

説明

例によって NetBSD + pkgsrc という特殊環境なので環境依存の問題かもしれませんが

3.6.0-develop で Twitter TL の添付画像の URL をクリックしてプレビューウインドウを開いた場合、
表示に失敗して「error」の画像表示になることがあります。感覚的に 3回に1回くらい。

「error」の表示についても、
一瞬正しい画像が表示されてから「error」になる場合、
いきなり「error」になる場合、とがあります。

--debug オプションつきで起動して「error」が発生した時の出力は以下のような感じです。
mikutter-preview-log.txt

何度も失敗を繰り返していると、そのうち ruby が SEGV で死んでしまうようです。
画像を開かない場合は落ちることはないようです。

関係あるかわかりませんが ruby-gnome2 のバージョンは 3.2.1 です。

mikutter-preview-log.txt (5.48 KB) mikutter-preview-log.txt Izumi Tsutsui, 2017-12-24 22:41
openimg-segv-akkie.txt (86.3 KB) openimg-segv-akkie.txt Akira Ouchi, 2017-12-25 11:08
window.rb.diff (957 Bytes) window.rb.diff Izumi Tsutsui, 2018-01-02 13:10

関係しているリビジョン

リビジョン 8d84308c (差分)
toshi_a 初音10ヶ月前に追加

画像読み込み中にThreadが競合する可能性があった refs #1137

履歴

#1 Akira Ouchi10ヶ月前に更新

私も確認できたので貼ります。特定の画像出必ず起きるといった感じではないようでした(落ちたときに開いた画像を次に開いてら大丈夫だった)。

#2 Izumi Tsutsui10ヶ月前に更新

あひる焼きメモ

某スレより


https://social.mikutter.hachune.net/@moguno/99249760559208235

画像プレビューの奴rectがとちゅうでnilにならないと有り得ない?

https://social.mikutter.hachune.net/@ahiru/99249833279294838

pixbufloader.ssc(:area_updated, self)のブロックを評価中にrect = nilが実行され、rect[:left]の評価の次の瞬間にrect = nilとなり rect[:top]で例のエラーが発生とか…?

https://social.mikutter.hachune.net/@ahiru/99249835672532434

エラーのログを信じるならそうなってしまいそう

https://social.mikutter.hachune.net/@ahiru/99249857713652180

Thread.new ブロック内で Delayer.new ブロック作ってて、それはいいんだけど、その中で rect = nil にしてるのが見た目上怪しいが

https://social.mikutter.hachune.net/@ahiru/99249858551978788

どういったタイミングで起こりうるのかはまだ追ってない

https://social.mikutter.hachune.net/@moguno/99250000549630839

Delayerってメインスレッドが暇にならないと動かないはずだけと、法則が崩れる要素がある?

https://social.mikutter.hachune.net/@ahiru/99250023582251888

この辺把握してないのよな


たしかに openimg/window.rb の start_loading で rect が途中で nil になっている感じはしますが、
source:core/plugin/openimg/window.rb@ce152e52#L16
なにかしら atomic 的なロックがいるんですかね

#3 Izumi Tsutsui10ヶ月前に更新

激しくテキトーな修正でエラーになっている箇所の処理で rect を別変数に入れてみると、
window.rb.diff
何度画像プレビューをクリックしても error になることはないようです。

#4 Izumi Tsutsui10ヶ月前に更新

理屈がわかっていないので闇雲に調べた結果のメモにしかなりませんが

こんな感じに rect 更新の前後に notice の表示を入れてそれぞれどのように呼ばれているかを見てみました。

すると、このような結果↓で、 if rect の成立側と非成立側がほぼ同時に呼ばれてる感じがします。

notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:20:in `block in start_loading': start_loading: #<Plugin::Photo::Photo:0xb8a9cf00>
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:34:in `block (3 levels) in start_loading': start_loading: start rect in Delayer
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:25:in `block (2 levels) in start_loading': start_loading: start updating rect
/usr/pkg/share/mikutter/core/plugin/openimg/window.rb:26:in `block (2 levels) in start_loading': undefined method `[]' for nil:NilClassnotice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:41:in `block (3 levels) in start_loading': start_loading: end rect in Delayer

     from /usr/pkg/share/mikutter/core/mui/gtk_extension.rb:33:in `block in safety_signal_connect'
     from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `invoke'
     from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `block in define_method'
     from /usr/pkg/share/mikutter/core/plugin/openimg/openimg.rb:42:in `block (3 levels) in <top (required)>'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block (3 levels) in download_mainloop'
     from /usr/pkg/lib/ruby/2.3.0/set.rb:306:in `each_key'
     from /usr/pkg/lib/ruby/2.3.0/set.rb:306:in `each'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block (2 levels) in download_mainloop'
     from /usr/pkg/share/mikutter/core/utils.rb:278:in `block in atomic'
     from /usr/pkg/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
     from /usr/pkg/share/mikutter/core/utils.rb:278:in `atomic'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block in download_mainloop'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:142:in `loop'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:142:in `download_mainloop'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:128:in `block in download_routine'
     from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:155:in `open_uri'
     from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:717:in `open'
     from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:35:in `open'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:127:in `download_routine'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:113:in `cache_read_or_download'
     from /usr/pkg/share/mikutter/core/serialthread.rb:70:in `block in new_thread'
error: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:49:in `block (2 levels) in start_loading': exit
from /usr/pkg/lib/ruby/gems/2.3.0/gems/glib2-3.2.1/lib/glib2.rb:46:in `exit'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/glib2-3.2.1/lib/glib2.rb:46:in `exit_application'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `invoke'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `block in define_method'
from {MIKUTTER_DIR}/core/plugin/openimg/openimg.rb:42:in `block (3 levels) in <top (required)>'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block (3 levels) in download_mainloop'
from /usr/pkg/lib/ruby/2.3.0/set.rb:306:in `each_key'
from /usr/pkg/lib/ruby/2.3.0/set.rb:306:in `each'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block (2 levels) in download_mainloop'
from {MIKUTTER_DIR}/core/utils.rb:278:in `block in atomic'
from /usr/pkg/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
from {MIKUTTER_DIR}/core/utils.rb:278:in `atomic'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block in download_mainloop'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:142:in `loop'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:142:in `download_mainloop'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:128:in `block in download_routine'
from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:155:in `open_uri'
from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:717:in `open'
from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:35:in `open'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:127:in `download_routine'
from {MIKUTTER_DIR}/core/lib/diva_hacks/mixin/photo_mixin.rb:113:in `cache_read_or_download'
from {MIKUTTER_DIR}/core/serialthread.rb:70:in `block in new_thread'
error: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:60:in `block in start_loading': JPEG 画像ファイル (Improper call to JPEG library in state 205) の解釈でエラー
from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `invoke'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `block in define_method'
from {MIKUTTER_DIR}/core/plugin/openimg/window.rb:53:in `block (2 levels) in start_loading'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/chain/base.rb:18:in `activate'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:93:in `block (2 levels) in wait_and_activate'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:87:in `catch'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:87:in `block in wait_and_activate'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:86:in `catch'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:86:in `wait_and_activate'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:76:in `block (2 levels) in fiber'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:75:in `loop'
from /usr/pkg/lib/ruby/gems/2.3.0/gems/delayer-deferred-2.0.0/lib/delayer/deferred/worker.rb:75:in `block in fiber'

また、条件によっては start_loading が何度も呼ばれる現象が起きているようです。

notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:20:in `block in start_loading': start_loading: #<Plugin::Photo::Photo:0xb8ac796c>
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:25:in `block (2 levels) in start_loading': start_loading: start updating rect
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:30:in `block (2 levels) in start_loading': start_loading: end updating rect

 [738回くらい繰り返し]

notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:25:in `block (2 levels) in start_loading': start_loading: start updating rect
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:34:in `block (3 levels) in start_loading': start_loading: start rect in Delayer
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:41:in `block (3 levels) in start_loading': start_loading: end rect in Delayer
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:30:in `block (2 levels) in start_loading': start_loading: end updating rect
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:25:in `block (2 levels) in start_loading': start_loading: start updating rect
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:30:in `block (2 levels) in start_loading': start_loading: end updating rect

 [1600回くらい繰り返し]

notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:30:in `block (2 levels) in start_loading': start_loading: end updating rect
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:25:in `block (2 levels) in start_loading': start_loading: start updating rect
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:41:in `block (3 levels) in start_loading': start_loading: end rect in Delayer
notice: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:25:in `block (2 levels) in start_loading': start_loading: start updating rect
/usr/pkg/share/mikutter/core/plugin/openimg/window.rb:26:in `block (2 levels) in start_loading': undefined method `[]' for nil:NilClass
     from /usr/pkg/share/mikutter/core/mui/gtk_extension.rb:33:in `block in safety_signal_connect'
     from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `invoke'
     from /usr/pkg/lib/ruby/gems/2.3.0/gems/gobject-introspection-3.2.1/lib/gobject-introspection/loader.rb:576:in `block in define_method'
     from /usr/pkg/share/mikutter/core/plugin/openimg/openimg.rb:42:in `block (3 levels) in <top (required)>'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block (3 levels) in download_mainloop'
     from /usr/pkg/lib/ruby/2.3.0/set.rb:306:in `each_key'
     from /usr/pkg/lib/ruby/2.3.0/set.rb:306:in `each'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block (2 levels) in download_mainloop'
     from /usr/pkg/share/mikutter/core/utils.rb:278:in `block in atomic'
     from /usr/pkg/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
     from /usr/pkg/share/mikutter/core/utils.rb:278:in `atomic'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:146:in `block in download_mainloop'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:142:in `loop'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:142:in `download_mainloop'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:128:in `block in download_routine'
     from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:155:in `open_uri'
     from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:717:in `open'
     from /usr/pkg/lib/ruby/2.3.0/open-uri.rb:35:in `open'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:127:in `download_routine'
     from /usr/pkg/share/mikutter/core/lib/diva_hacks/mixin/photo_mixin.rb:113:in `cache_read_or_download'
     from /usr/pkg/share/mikutter/core/serialthread.rb:70:in `block in new_thread'
error: {MIKUTTER_DIR}/core/plugin/openimg/window.rb:49:in `block (2 levels) in start_loading': exit

rect の設定と Delayer まわりの意図を理解できていないので
何がどうあるべきなのかわかっていませんが、どんなもんでしょう。

#5 Izumi Tsutsui10ヶ月前に更新

Delayer 内で rect=nil にしている記述をコメントアウトすると
ここまる1日ほどエラーは発生せず特に副作用もなく動いているようなのですが、
回避策としてはありなのでしょうか。

--- core/plugin/openimg/window.rb.orig    2017-12-23 01:57:54.000000000 +0900
+++ core/plugin/openimg/window.rb    2018-01-02 22:47:39.000000000 +0900
@@ -33,7 +33,7 @@
                          y: rect[:top],
                          width: rect[:right] - rect[:left],
                          height: rect[:bottom] - rect[:top])
-                rect = nil
+                #rect = nil
               end
             end
             true end

#6 toshi_a 初音10ヶ月前に更新

スマフォでコード見ただけですが、area_updateが呼び出される頻度が高いと nil#[] を呼んでしまうバグがありそうですね。今まで起こらなかったのはgdkpixbufなどのアップデートなどが原因かもしれません。いずれにせよこの実装には問題があるので検証します

#7 Izumi Tsutsui10ヶ月前に更新

ruby-gnome2 や gdkpixbuf2 のバージョンは 3.5.15 を動かしていたときと同一で、
その時は問題は起きておらず、3.6.0 にしたらプレビューの問題が発生するようになった、
という状況です。(要すれば再度検証してみます)

ログからすると
core/lib/diva_hacks/mixin/photo_mixin.rb
あたりが新規っぽかったので何か呼び出し方法変わったのかなと思っていたのですが
ちゃんと読んでいないので見当違いなことを書いているかもしれません。

#8 toshi_a 初音10ヶ月前に更新

以下のパッチで、確実に再現させることが出来るようになりました。

diff --git a/core/plugin/openimg/window.rb b/core/plugin/openimg/window.rb
index d1bdcf88..872d4104 100644
--- a/core/plugin/openimg/window.rb
+++ b/core/plugin/openimg/window.rb
@@ -18,8 +18,10 @@ module Plugin::Openimg
         Plugin.filtering(:openimg_pixbuf_from_display_url, photo, nil, nil)
       }.next { |_, pixbufloader, complete_promise|
         if pixbufloader.is_a? GdkPixbuf::PixbufLoader
+          mainthread_only
           rect = nil
           pixbufloader.ssc(:area_updated, self) do |_, x, y, width, height|
+            mainthread_only
             if rect
               rect[:left] = [rect[:left], x].min
               rect[:top] = [rect[:top], y].min
@@ -28,6 +30,7 @@ module Plugin::Openimg
             else
               rect = {left: x, top: y, right: x+width, bottom: y+height}
               Delayer.new do
+                mainthread_only
                 progress(pixbufloader.pixbuf,
                          x: rect[:left],
                          y: rect[:top],

上記のコードは、全て単一のスレッドで動くことを前提にしていましたが、area_updateシグナルのブロックが異なるスレッドで呼ばれているということがわかりました。従ってよくあるマルチスレッドのデータレースが起こりうるので、報告されたクラッシュレポートとも辻褄が合います。

#9 toshi_a 初音10ヶ月前に更新

  • ステータス新規 から レビュー待ち に変更
  • 担当者Izumi Tsutsui にセット

全く同じ状況では再現できなかったので確認できないので、再現する環境で試してもらってフィードバックをもらいたいです。

topic/1137-pixbufloader-error ブランチにpushしました。チケットにコメントを来れた人を中心に確認してもらえますか。

#10 Izumi Tsutsui10ヶ月前に更新

  • 担当者Izumi Tsutsui から toshi_a 初音 に変更

mikutter 3.6.0 相当のツリーに 8d84308c の window.rb の atomic 追加差分を当てて、
その修正版の起動後に Twitter 添付画像プレビューを 100回超試行して、
error 発生はありませんでした。修正できていると判断して良いと思います。

チケットのステータスは「master へマージされた時点で解決」としたほうがいいですかね。

#11 Akira Ouchi10ヶ月前に更新

同じく確認できました。

#12 toshi_a 初音9ヶ月前に更新

  • ステータスレビュー待ち から 終了 に変更

mergeしました

他の形式にエクスポート: Atom PDF