Crash with PDF on OS X

Question

Crash with PDF on OS X

Opened this issue 9 years ago · 27 comments

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

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

Answer 1 · 2015-11-30T08:40:34.000Z

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

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

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

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

Answer 2 · 2015-11-30T08:43:23.000Z

ありがとうございます。

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

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

Answer 3 · 2015-11-30T08:45:09.000Z

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

Answer 4 · 2015-11-30T08:48:26.000Z

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

Answer 5 · 2015-11-30T14:45:54.000Z

ありがとうございます！
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

Answer 6 · 2015-12-01T00:10:10.000Z

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

Answer 7 · 2015-12-02T00:07:05.000Z

Out of memoryみたいです。

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

cairo: stable 1.14.4 (bottled)

Answer 8 · 2015-12-02T08:18:12.000Z

Backtraceをとってみました。

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

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

Answer 9 · 2015-12-02T10:22:50.000Z

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

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

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

Answer 10 · 2015-12-02T11:01:27.000Z

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

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

Answer 11 · 2015-12-02T14:14:27.000Z

あぁ、すみません。。。
ログレベルが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()の中をステップ実行します。

Answer 12 · 2015-12-03T00:08:36.000Z

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

Answer 13 · 2015-12-03T01:29:12.000Z

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

Answer 14 · 2015-12-04T11:23:50.000Z

ここの処理に注目しました。
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を実行してこのライブラリにブレークポイントって仕掛けられるかご存知でしょうか？

Answer 15 · 2015-12-04T12:37:11.000Z

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

Answer 16 · 2015-12-05T08:32:24.000Z

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

Answer 17 · 2015-12-06T02:18:40.000Z

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

% 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

Answer 18 · 2015-12-06T10:39:38.000Z

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

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

Answer 19 · 2015-12-06T13:38:10.000Z

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

Answer 20 · 2015-12-06T13:41:56.000Z

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

Answer 21 · 2015-12-06T14:11:30.000Z

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

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

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

Answer 22 · 2015-12-06T14:43:24.000Z

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

Answer 23 · 2015-12-07T00:06:59.000Z

これは、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);
    }
}

Answer 24 · 2015-12-07T01:18:13.000Z

おぉ！

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

Answer 25 · 2015-12-07T02:17:11.000Z

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

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

Answer 26 · 2015-12-07T02:37:28.000Z

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を呼び出しているところがどこかを
調べれば良さそうですね。

Answer 27 · 2015-12-07T02:42:44.000Z

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

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