Crash with PDF on OS X

[kou]

OS XでPDFを表示すると落ちる。

詳細： https://gist.github.com/hiroyuki-sato/39aa614e6578709fa3a8

[kou]

@hiroyuki-sato たぶん、PopplerでPDFを処理しているときに例外が発生して、それが誰にも処理されずトップレベルまでいって、Rubyが例外の詳細を出力して、終了するという流れになっていると思います。で、その、最後の終了するところでクラッシュしていると思います。

このクラッシュの仕方だとバックトレースを見れないので、自分でどこでクラッシュしているかを調べていく必要があります。私ならRabbit内にpをたくさん入れてどこまでは動いている、どこからは動いていないというのを調べていくんですが、手元では再現しなかったのでそれはできません。

なので、とりあえず、Popplerで該当ファイルを読めるか確認してもらえませんか？以下のコマンドラインの結果を教えて欲しいです。

> ruby -r poppler -e 'p Poppler::Document.new("images/mail.pdf").pages'

[hiroyuki-sato]

ありがとうございます。

こんな感じになりました。

ruby -r poppler -e 'p Poppler::Document.new("images/mail.pdf").pages'
[#<Poppler::Page:0x7fbc93c3c830 ptr=0x7fbc92803880>]

[kou]

バッチリですね！
とするとどこで落ちているかをデバッグプリントして絞り込んでいくしかないですね。。。

[hiroyuki-sato]

あたりをつけてもらえれば試しますよ。(おそらく)ここから~この間みたいな。
今どの辺を調べて良いかもよくわかっていないので..

[kou]

ありがとうございます！
lib/rabbit/image/pdf.rbの中のそれぞれのメソッドの最初と最後に仕込んで欲しいです。

例：

diff --git a/lib/rabbit/image/pdf.rb b/lib/rabbit/image/pdf.rb
index 92e80f0..0941c24 100644
--- a/lib/rabbit/image/pdf.rb
+++ b/lib/rabbit/image/pdf.rb
@@ -28,6 +28,7 @@ module Rabbit
       end

       def draw(canvas, x, y, params={})
+        p [__method__, :start]
         if @document
           default_params = {
             :width => width,
@@ -37,6 +38,8 @@ module Rabbit
         else
           super
         end
+      ensure
+        p [__method__, :end]
       end

       def pixbuf

[hiroyuki-sato]

ありがとうございます!。時間をとってやってみます。少しお待ちを

[hiroyuki-sato]

Out of memoryみたいです。

https://gist.github.com/hiroyuki-sato/05a04a0c28f59b27e250#file-gistfile1-txt-L86

cairo: stable 1.14.4 (bottled)

[hiroyuki-sato]

Backtraceをとってみました。

これでわかりますか？(ちょっと難しそうな気がしていますが...)

https://gist.github.com/hiroyuki-sato/05a04a0c28f59b27e250#file-backtrace-txt

[kou]

ありがとうございます。
実は、欲しいのはRubyのバックトレースではなく、cairoがOut of memoryしたときのバックとレースなのです。。。

% G_DEBUG=fatal_warnings lldb ~/.rbenv/versions/2.2.3/bin/ruby -S rabbit ...

とするとOut of memoryになったところでクラッシュしてくれるかもしれないです。。。

[hiroyuki-sato]

いずれにしてもうまくいっていないっぽいのですが

https://gist.github.com/hiroyuki-sato/05a04a0c28f59b27e250#file-00lldb_backtrace-txt

• fatal_warningsではなくfatal-warningsでしょうか？
• 実行手順は下記のようだと思いますがいかがでしょうか？(exportは不要かも)

% export G_MESSAGES_DEBUG=all
% export G_DEBUG=fatal-warnings

% G_MESSAGES_DEBUG=all G_DEBUG=fatal-warnings lldb ~/.rbenv/versions/2.2.3/bin/ruby 
(lldb) target create "/path/to/home/.rbenv/versions/2.2.3/bin/ruby"
Current executable set to '/path/to/home/.rbenv/versions/2.2.3/bin/ruby' (x86_64).
(lldb) run -S ../rabbit/bin/rabbit

参照; https://developer.gnome.org/glib/stable/glib-running.html

[kou]

あぁ、すみません。。。
ログレベルがINFOなのでfatal_warningsでは止まりませんでした。。。
（実は、fatal-warningsでもfatal_warningsでも効くのです。）

cairoとPopplerをデバッグビルドしてデバッガーで追うしかないですね。。。
一応、デバッグ方法を書いておくと。。。

まず、エラーメッセージのcairo context errorでPopplerをgrepします。

すると、 http://cgit.freedesktop.org/poppler/poppler/tree/poppler/CairoOutputDev.cc#n199 だけがヒットします。

% grep -r -C5 'cairo context error' ./
./poppler/CairoOutputDev.cc-void CairoOutputDev::setCairo(cairo_t *cairo)
./poppler/CairoOutputDev.cc-{
./poppler/CairoOutputDev.cc-  if (this->cairo != NULL) {
./poppler/CairoOutputDev.cc-    cairo_status_t status = cairo_status (this->cairo);
./poppler/CairoOutputDev.cc-    if (status) {
./poppler/CairoOutputDev.cc:      error(errInternal, -1, "cairo context error: {0:s}\n", cairo_status_to_string(status));
./poppler/CairoOutputDev.cc-    }
./poppler/CairoOutputDev.cc-    cairo_destroy (this->cairo);
./poppler/CairoOutputDev.cc-    assert(!cairo_shape);
./poppler/CairoOutputDev.cc-  }
./poppler/CairoOutputDev.cc-  if (cairo != NULL) {

これを見ると、引数で渡ってきたcairo_tにエラーが設定されていればPopplerもエラーにしていることがわかります。

grepするとsetCairoでNULL以外を設定しているのはどれもcairo_create()の結果を渡していることがわかります。

% grep -r -C5 'setCairo (cr)' poppler/CairoOutputDev.cc
  saveImage (image);

  if (imgDrawCbk && imgDrawCbk (numImages - 1, imgDrawCbkData)) {
    surface = cairo_image_surface_create (CAIRO_FORMAT_ARGB32, width, height);
    cr = cairo_create (surface);
    setCairo (cr);
    cairo_translate (cr, 0, height);
    cairo_scale (cr, width, -height);

    CairoOutputDev::drawImageMask(state, ref, str, width, height, invert, interpolate, inlineImg);
    image->setImage (surface);
--
  saveImage (image);

  if (imgDrawCbk && imgDrawCbk (numImages - 1, imgDrawCbkData)) {
    surface = cairo_image_surface_create (CAIRO_FORMAT_ARGB32, width, height);
    cr = cairo_create (surface);
    setCairo (cr);
    cairo_translate (cr, 0, height);
    cairo_scale (cr, width, -height);

    CairoOutputDev::drawImageMask(state, ref, str, width, height, invert, inlineImg, gFalse);
    if (state->getFillColorSpace()->getMode() == csPattern) {
--
  saveImage (image);

  if (imgDrawCbk && imgDrawCbk (numImages - 1, imgDrawCbkData)) {
    surface = cairo_image_surface_create (CAIRO_FORMAT_ARGB32, width, height);
    cr = cairo_create (surface);
    setCairo (cr);
    cairo_translate (cr, 0, height);
    cairo_scale (cr, width, -height);

    CairoOutputDev::drawImage(state, ref, str, width, height, colorMap, interpolate, maskColors, inlineImg);
    image->setImage (surface);
--
  saveImage (image);

  if (imgDrawCbk && imgDrawCbk (numImages - 1, imgDrawCbkData)) {
    surface = cairo_image_surface_create (CAIRO_FORMAT_ARGB32, width, height);
    cr = cairo_create (surface);
    setCairo (cr);
    cairo_translate (cr, 0, height);
    cairo_scale (cr, width, -height);

    CairoOutputDev::drawSoftMaskedImage(state, ref, str, width, height, colorMap, interpolate,
                    maskStr, maskWidth, maskHeight, maskColorMap, maskInterpolate);
--
  saveImage (image);

  if (imgDrawCbk && imgDrawCbk (numImages - 1, imgDrawCbkData)) {
    surface = cairo_image_surface_create (CAIRO_FORMAT_ARGB32, width, height);
    cr = cairo_create (surface);
    setCairo (cr);
    cairo_translate (cr, 0, height);
    cairo_scale (cr, width, -height);

    CairoOutputDev::drawMaskedImage(state, ref, str, width, height, colorMap, interpolate,
                    maskStr, maskWidth, maskHeight, maskInvert, maskInterpolate);

なので、cairo_create()でOut of memoryになっていると推測できます。

あとは、どのcairo_create()のときにOut of memoryになっているかを見つけて、見つけたらそのcairo_create()の中をステップ実行します。

[hiroyuki-sato]

ありがとうございます。試してみます。気長にお待ちを

[kou]

ありがとうございます！ムリしない程度でお願いします！

[hiroyuki-sato]

ここの処理に注目しました。
https://gist.github.com/hiroyuki-sato/bee0d26d8353588df50a#file-00trace-txt-L151-L156

CairoOutputDev::restoreState ってところで呼び出されるのですが
https://gist.github.com/hiroyuki-sato/bee0d26d8353588df50a#file-cairooutputdev-cc-L311

restoreState関数はここしか読んでいないのに、ログがでないのはなんでしょうね？
https://gist.github.com/hiroyuki-sato/bee0d26d8353588df50a#file-cairooutputdev-cc-L1969

lldbやgdbで、rubyを実行してこのライブラリにブレークポイントって仕掛けられるかご存知でしょうか？

[kou]

gdbだとrunする前にb CairoOutputDev.cc:1969してからrunするとしかけられます！

[hiroyuki-sato]

OSXでgdbを動かすのに苦労しました。
http://qiita.com/takahashim/items/204ffa698afe09bd4e28

でやってみたのですが、ブレークポイントがうまく設定できないですね。
絶対通っているところに仕掛けてみたんですけどね。

困りました。

gdb /path/to/ruby
b CairoOutputDev.cc:315
run -I /tmp/ruby-gnome2/poppler/lib/ -I /tmp/ruby-gnome2/poppler/ext/poppler/ -I /tmp/rcairo/lib/ -I/tmp/rcairo/ext/cairo/ -S ../rabbit/bin/rabbit

[kou]

これだとどうでしょうか！？

% gdb --args /path/to/ruby -I /tmp/ruby-gnome2/poppler/lib/ -I /tmp/ruby-gnome2/poppler/ext/poppler/ -I /tmp/rcairo/lib/ -I/tmp/rcairo/ext/cairo/ ../rabbit/bin/rabbit
(gdb) b CairoOutputDev::CairoOutputDev
(gdb) r

[hiroyuki-sato]

https://gist.github.com/hiroyuki-sato/21475340e8091f5b99e1

ブレークポイント設定できました。一歩前進です。

が

libpoppler-glibの関数の情報が取得できていませんね。
popplerのCFLAGS関連全部 -g を -ggdb3をしてみたんですが..

(gdb) 
#0  0x000000010517de94 in ?? () from /tmp/poppler/lib/libpoppler-glib.8.dylib
#1  0x00007fff5fbf5e60 in ?? ()
#2  0x00000001090498f8 in Gfx::restoreState (this=0x10a1e1d30) at Gfx.cc:5468
#3  Gfx::opRestore (this=0x10a1e1d30, args=<optimized out>, numArgs=1219152)
    at Gfx.cc:957

さてどうしたものでしょう..

[kou]

Popplerに-ggdb3を指定した手順を教えてもらえますか？

[hiroyuki-sato]

./configureしたあと、
find . -name 'Makefile' -print | xargs perl -i -pe 's/ -g / -ggdb3 /g'
をしてmake clean ; makeです。

[hiroyuki-sato]

もうちょっと詳しく取得できました。

rubyがデバッグなしのものだったので、デバッグシンボルありのrubyでもう一度試しました。

https://gist.github.com/hiroyuki-sato/91c643caacec323e1a27

[hiroyuki-sato]

b CairoOutputDev::setCairo
でトレースした結果です。
まだ詳しく見ていないのでまた明日以降に確認します。
https://gist.github.com/hiroyuki-sato/926742f5668abffdd1ee

[hiroyuki-sato]

これは、rg_renderでステップかけた方がいいでしょうか？

#0  0x00000001072a1632 in CairoOutputDev::setCairo(_cairo*) () from /usr/local/opt/poppler/lib/libpoppler-glib.8.dylib
#1  0x0000000107293cef in _poppler_page_render(_PopplerPage*, _cairo*, bool, PopplerPrintFlags) ()
   from /usr/local/opt/poppler/lib/libpoppler-glib.8.dylib
#2  0x000000010727ecea in rg_render () from /tmp/ruby-gnome2/poppler/ext/poppler/poppler.bundle

glib/poppler-page.cc
と思いましたが、ここでブレークかけてもわかりませんね。

static void
_poppler_page_render (PopplerPage      *page,
          cairo_t          *cairo,
          GBool             printing,
                      PopplerPrintFlags print_flags)
{
  CairoOutputDev *output_dev;

  g_return_if_fail (POPPLER_IS_PAGE (page));

  output_dev = page->document->output_dev;
  output_dev->setCairo (cairo);
  output_dev->setPrinting (printing);

さらにrg_renderのところでも見てみましたが、ここでも分かりづらそうですね。

rbpoppler-page.c

static VALUE
rg_render(VALUE self, VALUE ps_file_or_cairo)
{
    if (RVAL2CBOOL(rb_obj_is_kind_of(ps_file_or_cairo, cPSFile))) {
        return page_render_to_ps(self, ps_file_or_cairo);
    } else {
        return page_render(self, ps_file_or_cairo);
    }
}

[kou]

おぉ！

#79 (comment) に書いた通り、ステップ実行するのはPopplerやpoppler gemの中ではなく、cairoのなかです。なので、PopplerレベルではsetCairo()の引数のcairo_tのcairo_status()が0じゃないことを確認できればOKです。確認できたらどこでcairo_tのcairo_satus()が0以外になったのかを確認するためにステップ実行します！

[hiroyuki-sato]

こんな感じにしているのですが、
https://gist.github.com/hiroyuki-sato/05ce79f7b46609d938cc#file-cairooutputdev-cc-L900

CAIRO_CREATEってメッセージが出てこないんですよね。やり方は間違えていないとは思うのですが、うーんというところで調べ中です。

[hiroyuki-sato]

out of memoryにステータスを変えているのは、下記のsetCairoですね。

glib/poppler-page.cc

static void
_poppler_page_render (PopplerPage      *page,
          cairo_t          *cairo,
          GBool             printing,
                      PopplerPrintFlags print_flags)
{
  CairoOutputDev *output_dev;

  g_return_if_fail (POPPLER_IS_PAGE (page));

  output_dev = page->document->output_dev;
  output_dev->setCairo (cairo);
  output_dev->setPrinting (printing);

こいつは、poppler_page_renderからのみ呼び出されているようなので

poppler/ext/poppler/rbpoppler-page.c
の中で、問題となるpoppler_page_renderを呼び出しているところがどこかを
調べれば良さそうですね。

[hiroyuki-sato]

あ、失礼何が言いたいかというと、現在ブレークポイントをかけているのはスーテータスが変わってしまったところでかけています。

ステータスが変わる前はどこか？ということを調べるのにブレークポイントはどこに仕掛ければいいかな？と思っているところです。