Random panics related to `malloc()` while rendering PDF to PNG

Question

Random panics related to `malloc()` while rendering PDF to PNG

neslinesli93 opened this issue 3 years ago · 10 comments

Hi, I've tried using your library to handle PDF-to-PNG conversions, and sometimes my program crashes with the following error when executing even a simple single-page conversion: malloc(): unsorted double linked list corrupted. It's more likely to happen if you run the program multiple times in a row.

Basically I've copied muconvert.c from the mutool suite: https://github.com/ArtifexSoftware/mupdf/blob/master/source/tools/muconvert.c

Here is the code to reproduce the bug, just put an example.pdf along with main.rs:

// main.rs

use mupdf::document::Document;
use mupdf::document_writer::DocumentWriter;
use mupdf::Matrix;

const IDENTITY: Matrix = Matrix {
    a: 1.0,
    b: 0.0,
    c: 0.0,
    d: 1.0,
    e: 0.0,
    f: 0.0,
};

fn main() {
    let density = 300;
    let height = 1500;

    let mut writer =
        DocumentWriter::new("./out.png", "png", options(density, height).as_str()).unwrap();
    let doc = Document::open("./example.pdf").unwrap();
    let count = doc.page_count().unwrap();
    println!("Pdf has {} pages", count);

    for i in 0..count {
        let page0 = doc.load_page(i).unwrap();
        let mediabox = page0.bounds().unwrap();
        let device = writer.begin_page(mediabox).unwrap();
        page0.run(&device, &IDENTITY).unwrap();
        writer.end_page().unwrap();
    }

    println!("Done!");
}

fn options(density: usize, height: usize) -> String {
    format!("resolution={},height={}", density, height)
}

Answer 1 · 2022-06-23T01:29:28.000Z

Can you make a PR that add this as a test case? We have asan setup in CI, it may be able to tell us what’s going on.

Answer 2 · 2022-06-23T07:42:37.000Z

Can you make a PR that add this as a test case? We have asan setup in CI, it may be able to tell us what’s going on.

Done: #44

It fails locally when running cargo test, but I can't use asan since I don't currently have the nightly toolchain

Answer 3 · 2022-08-01T02:27:49.000Z

Now that we upgraded to mupdf 1.20.2, it only reproduces on Windows on CI with two different kind of result:

exit code: 0xc0000374, STATUS_HEAP_CORRUPTION - https://github.com/messense/mupdf-rs/runs/7599728797?check_suite_focus=true
thread 'test_issue_43_malloc' panicked at 'called Result::unwrap()on anErr value: MuPdf(MuPdfError { code: 2, message: "cannot open file '/tmp/out1.png': No such file or directory" })', tests\test_issues.rs:61:27 - https://github.com/messense/mupdf-rs/runs/7599799578?check_suite_focus=true

Edit: reproduced again on Linux: https://github.com/messense/mupdf-rs/runs/7603563439?check_suite_focus=true

Answer 4 · 2022-08-01T02:28:52.000Z

Unfortunately I don't own a Windows PC to investigate.

Answer 5 · 2022-08-01T03:30:25.000Z

OK, got a core dump on Linux. No idea what's going on though.

#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=139750494213696) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=139750494213696) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=139750494213696, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007f1a32e17476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007f1a32dfd7f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007f1a32e5e6f6 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7f1a32fb0b8c "%s\n") at ../sysdeps/posix/libc_fatal.c:155
#6  0x00007f1a32e75d7c in malloc_printerr (str=str@entry=0x7f1a32fb3c68 "malloc(): unsorted double linked list corrupted") at ./malloc/malloc.c:5664
#7  0x00007f1a32e7935c in _int_malloc (av=av@entry=0x7f1a28000030, bytes=bytes@entry=4770000) at ./malloc/malloc.c:4010
#8  0x00007f1a32e7a1b9 in __GI___libc_malloc (bytes=4770000) at ./malloc/malloc.c:3329
#9  0x00005565d0ec9cdb in fz_malloc_default (opaque=0x0, size=4770000) at source/fitz/memory.c:180
#10 0x00005565d0ec97d5 in do_scavenging_malloc (ctx=0x7f1a28000db0, size=4770000) at source/fitz/memory.c:51
#11 0x00005565d0ec993c in fz_malloc (ctx=0x7f1a28000db0, size=4770000) at source/fitz/memory.c:89
#12 0x00005565d0ed105d in fz_new_pixmap_with_data (ctx=0x7f1a28000db0, colorspace=0x7f1a2c012390, w=1060, h=1500, seps=0x0, alpha=0, stride=3180, samples=0x0) at source/fitz/pixmap.c:109
#13 0x00005565d0ed11a5 in fz_new_pixmap (ctx=0x7f1a28000db0, colorspace=0x7f1a2c012390, w=1060, h=1500, seps=0x0, alpha=0) at source/fitz/pixmap.c:135
#14 0x00005565d0ed121b in fz_new_pixmap_with_bbox (ctx=0x7f1a28000db0, colorspace=0x7f1a2c012390, bbox=..., seps=0x0, alpha=0) at source/fitz/pixmap.c:142
#15 0x00005565d0e8392c in fz_new_draw_device_with_options (ctx=0x7f1a28000db0, opts=0x7f1a2800f9b8, mediabox=..., pixmap=0x7f1a2800f9e8) at source/fitz/draw-device.c:3253
#16 0x00005565d102a0b0 in pixmap_begin_page (ctx=0x7f1a28000db0, wri_=0x7f1a2800f990, mediabox=...) at source/fitz/output-cbz.c:148
#17 0x00005565d0eeaae7 in fz_begin_page (ctx=0x7f1a28000db0, wri=0x7f1a2800f990, mediabox=...) at source/fitz/writer.c:312
#18 0x00005565d0ff62ca in mupdf_document_writer_begin_page (ctx=0x7f1a28000db0, writer=0x7f1a2800f990, mediabox=..., errptr=0x7f1a32908320) at wrapper.c:3118
#19 0x00005565d0e4253a in mupdf::document_writer::DocumentWriter::begin_page (self=0x7f1a329084c8, media_box=...) at src/document_writer.rs:31
#20 0x00005565d0e018f7 in test_issues::test_issue_43_malloc () at tests/test_issues.rs:59
#21 0x00005565d0e0499a in test_issues::test_issue_43_malloc::{closure#0} () at tests/test_issues.rs:37
#22 0x00005565d0dffbee in core::ops::function::FnOnce::call_once<test_issues::test_issue_43_malloc::{closure_env#0}, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/ops/function.rs:227
#23 0x00005565d0e3b2c3 in core::ops::function::FnOnce::call_once<fn(), ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/ops/function.rs:227
#24 test::__rust_begin_short_backtrace<fn()> () at library/test/src/lib.rs:574
#25 0x00005565d0e3a029 in alloc::boxed::{impl#44}::call_once<(), (dyn core::ops::function::FnOnce<(), Output=()> + core::marker::Send), alloc::alloc::Global> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/alloc/src/boxed.rs:1861
#26 core::panic::unwind_safe::{impl#23}::call_once<(), alloc::boxed::Box<(dyn core::ops::function::FnOnce<(), Output=()> + core::marker::Send), alloc::alloc::Global>> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panic/unwind_safe.rs:271
#27 std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<alloc::boxed::Box<(dyn core::ops::function::FnOnce<(), Output=()> + core::marker::Send), alloc::alloc::Global>>, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:492
#28 std::panicking::try<(), core::panic::unwind_safe::AssertUnwindSafe<alloc::boxed::Box<(dyn core::ops::function::FnOnce<(), Output=()> + core::marker::Send), alloc::alloc::Global>>> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:456
#29 std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<alloc::boxed::Box<(dyn core::ops::function::FnOnce<(), Output=()> + core::marker::Send), alloc::alloc::Global>>, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panic.rs:137
#30 test::run_test_in_process () at library/test/src/lib.rs:597
#31 test::run_test::run_test_inner::{closure#0} () at library/test/src/lib.rs:491
#32 0x00005565d0e061de in test::run_test::run_test_inner::{closure#1} () at library/test/src/lib.rs:518
#33 std::sys_common::backtrace::__rust_begin_short_backtrace<test::run_test::run_test_inner::{closure_env#1}, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/sys_common/backtrace.rs:122
#34 0x00005565d0e0b7a8 in std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure#0}<test::run_test::run_test_inner::{closure_env#1}, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/thread/mod.rs:498
#35 core::panic::unwind_safe::{impl#23}::call_once<(), std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<test::run_test::run_test_inner::{closure_env#1}, ()>> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/panic/unwind_safe.rs:271
#36 std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<test::run_test::run_test_inner::{closure_env#1}, ()>>, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:492
#37 std::panicking::try<(), core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<test::run_test::run_test_inner::{closure_env#1}, ()>>> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panicking.rs:456
#38 std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<test::run_test::run_test_inner::{closure_env#1}, ()>>, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/panic.rs:137
#39 std::thread::{impl#0}::spawn_unchecked_::{closure#1}<test::run_test::run_test_inner::{closure_env#1}, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/std/src/thread/mod.rs:497
#40 core::ops::function::FnOnce::call_once<std::thread::{impl#0}::spawn_unchecked_::{closure_env#1}<test::run_test::run_test_inner::{closure_env#1}, ()>, ()> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/core/src/ops/function.rs:227
#41 0x00005565d12b3593 in alloc::boxed::{impl#44}::call_once<(), dyn core::ops::function::FnOnce<(), Output=()>, alloc::alloc::Global> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/alloc/src/boxed.rs:1861
#42 alloc::boxed::{impl#44}::call_once<(), alloc::boxed::Box<dyn core::ops::function::FnOnce<(), Output=()>, alloc::alloc::Global>, alloc::alloc::Global> () at /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/alloc/src/boxed.rs:1861
#43 std::sys::unix::thread::{impl#2}::new::thread_start () at library/std/src/sys/unix/thread.rs:108
#44 0x00007f1a32e69b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#45 0x00007f1a32efba00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Answer 6 · 2022-08-03T21:12:55.000Z

I cannot reproduce with the following C code:

#include <mupdf/fitz.h>
#include <mupdf/fitz/context.h>
#include <mupdf/fitz/document.h>
#include <mupdf/fitz/geometry.h>
#include <mupdf/fitz/types.h>
#include <mupdf/fitz/writer.h>

int main(int arg, char *argv[]) {
  fz_matrix matrix = fz_make_matrix(1.0, 0.0, 0.0, 1.0, 0.0, 0.0);
  int density = 300;
  int height = 1500;

  const char *options = "resolution=300,height=1500";

  fz_context *ctx = fz_new_context(NULL, NULL, FZ_STORE_UNLIMITED);
  fz_register_document_handlers(ctx);
  fz_document_writer *writer =
      fz_new_document_writer(ctx, "/tmp/out.png", "png", options);
  fz_document *doc = fz_open_document(ctx, "dummy.pdf");

  for (int i = 0; i < 50; ++i) {
    fz_page *page = fz_load_page(ctx, doc, 0);
    fz_rect bounds = fz_bound_page(ctx, page);
    fz_device *dev = fz_begin_page(ctx, writer, bounds);
    fz_run_page(ctx, page, dev, matrix, NULL);
    fz_end_page(ctx, writer);
    fz_drop_page(ctx, page);
  }
}

Which should be equivalent to the rust code in the test.
I have also noticed that when the test fails, it always does so on the second iteration of the loop. It looks like maybe a pointer aliasing issue?

Answer 7 · 2022-08-03T21:33:47.000Z

Valgrind does complain about this though: apparently, fz_end_page drops the device, making the explicit drop a double free

Answer 8 · 2022-08-03T21:45:58.000Z

Checked all other tests as well for good measure. No other issues detected by valgrind

Answer 9 · 2022-08-04T00:38:29.000Z

I wasn't able to run valgrind because it does not support some dwarf 5 debug info, https://www.mail-archive.com/valgrind-users@lists.sourceforge.net/msg07238.html, Thanks for the help!

Answer 10 · 2022-08-04T09:17:58.000Z

Rust 1.62 semi-accidentally switched std to DWARF5, so I used 1.61