IPC reader panics with out of bounds error

[andygrove]

Describe the bug

I am working on a PR in DataFusion and hit this during query execution.

thread 'tokio-runtime-worker' panicked at 'range end index 51144 out of range for slice of length 49000', /home/andy/.cargo/registry/src/github.com-1ecc6299db9ec823/arrow-4.4.0/src/ipc/reader.rs:42:21

To Reproduce
I don't have a repro case yet. I will try and create one.

Expected behavior
Don't panic.

Additional context
None

[andygrove]

I just saw some more context for this, so maybe not truly an Arrow IPC bug after all (although it would be nice to avoid the panic).

[2021-07-13T00:53:57Z INFO  ballista_executor::flight_service] FetchPartition PartitionId { job_id: "IuNhtqp", stage_id: 1, partition_id: 1 } reading /tmp/.tmpu1eS3W/IuNhtqp/1/1/data.arrow
[2021-07-13T00:53:57Z WARN  ballista_executor::flight_service] Error streaming results: Status { code: Internal, message: "ArrowError: IoError(\"failed to fill whole buffer\")" }

[andygrove]

I have a repro case with a 2MB IPC file

[andygrove]

   0:     0x5618aef90350 - std::backtrace_rs::backtrace::libunwind::trace::ha5edb8ba5c6b7a6c
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
   1:     0x5618aef90350 - std::backtrace_rs::backtrace::trace_unsynchronized::h0de86d320a827db2
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5618aef90350 - std::sys_common::backtrace::_print_fmt::h97b9ad6f0a1380ff
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x5618aef90350 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h14be7eb08f97fe80
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:46:22
   4:     0x5618aefb488f - core::fmt::write::h2ca8877d3e0e52de
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/fmt/mod.rs:1094:17
   5:     0x5618aef8a655 - std::io::Write::write_fmt::h64f5987220b618f4
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/io/mod.rs:1584:15
   6:     0x5618aef9290b - std::sys_common::backtrace::_print::h7f1a4097308f2e0a
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:49:5
   7:     0x5618aef9290b - std::sys_common::backtrace::print::h1f799fc2ca7f5035
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:36:9
   8:     0x5618aef9290b - std::panicking::default_hook::{{closure}}::hf38436e8a3ce1071
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:208:50
   9:     0x5618aef923dd - std::panicking::default_hook::he2f8f3fae11ed1dd
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:225:9
  10:     0x5618aef92f1d - std::panicking::rust_panic_with_hook::h79a18548bd90c7d4
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:591:17
  11:     0x5618aef92ab7 - std::panicking::begin_panic_handler::{{closure}}::h212a72cc08e25126
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:497:13
  12:     0x5618aef907ec - std::sys_common::backtrace::__rust_end_short_backtrace::hbd6897dd42bc0fcd
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:141:18
  13:     0x5618aef92a19 - rust_begin_unwind
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:493:5
  14:     0x5618ae1b04d1 - core::panicking::panic_fmt::h77ecd04e9b1dd84d
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/panicking.rs:92:14
  15:     0x5618ae1b06c2 - core::slice::index::slice_end_index_len_fail::hd279a020961a5d28
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/slice/index.rs:41:5
  16:     0x5618aed07880 - arrow::ipc::reader::create_array::h51b477fa0b7ed975
  17:     0x5618aed0b93e - arrow::ipc::reader::read_record_batch::hea6f1b2225384031
  18:     0x5618ae33616d - <arrow::ipc::reader::FileReader<R> as core::iter::traits::iterator::Iterator>::next::ha6974b73b82470a3
  19:     0x5618ae314e73 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::hfd74ebb4f5544b8f
  20:     0x5618ae337c61 - tokio::runtime::task::harness::poll_future::hbf927d6278c69d82
  21:     0x5618ae337f02 - tokio::runtime::task::harness::Harness<T,S>::poll::h06844f434726e106
  22:     0x5618aec47472 - std::thread::local::LocalKey<T>::with::hdf0f7e2cffb9cca7
  23:     0x5618aec6364a - tokio::runtime::thread_pool::worker::Context::run_task::h96fcb0e955022e88
  24:     0x5618aec62823 - tokio::runtime::thread_pool::worker::Context::run::h4ba1c4818ac70106
  25:     0x5618aec48bc5 - tokio::macros::scoped_tls::ScopedKey<T>::set::h38b5613b61fed270
  26:     0x5618aec62292 - tokio::runtime::thread_pool::worker::run::h9d87413bc8c002e8
  27:     0x5618aec6c62e - tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut::h2e40e7478a3cb9f5
  28:     0x5618aec4e6c5 - std::panicking::try::hda54480cbbb459f9
  29:     0x5618aec5e663 - tokio::runtime::task::harness::Harness<T,S>::poll::h206460627d87f644
  30:     0x5618aec54f3a - std::sys_common::backtrace::__rust_begin_short_backtrace::hd08015b3d11daec5
  31:     0x5618aec6b028 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h4cad2e4d517fce10
  32:     0x5618aef9687a - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h75c2ca1daad47228
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/alloc/src/boxed.rs:1546:9
  33:     0x5618aef9687a - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hdf9f8afc9d34e311
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/alloc/src/boxed.rs:1546:9
  34:     0x5618aef9687a - std::sys::unix::thread::Thread::new::thread_start::hc238bac7748b195d
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys/unix/thread.rs:71:17
  35:     0x7f0b2ac9b6db - start_thread
  36:     0x7f0b2a42271f - __clone
  37:                0x0 - <unknown>
stack backtrace:
   0:     0x5618aef90350 - std::backtrace_rs::backtrace::libunwind::trace::ha5edb8ba5c6b7a6c
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
   1:     0x5618aef90350 - std::backtrace_rs::backtrace::trace_unsynchronized::h0de86d320a827db2
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5618aef90350 - std::sys_common::backtrace::_print_fmt::h97b9ad6f0a1380ff
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x5618aef90350 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h14be7eb08f97fe80
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:46:22
   4:     0x5618aefb488f - core::fmt::write::h2ca8877d3e0e52de
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/fmt/mod.rs:1094:17
   5:     0x5618aef8a655 - std::io::Write::write_fmt::h64f5987220b618f4
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/io/mod.rs:1584:15
   6:     0x5618aef9290b - std::sys_common::backtrace::_print::h7f1a4097308f2e0a
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:49:5
   7:     0x5618aef9290b - std::sys_common::backtrace::print::h1f799fc2ca7f5035
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:36:9
   8:     0x5618aef9290b - std::panicking::default_hook::{{closure}}::hf38436e8a3ce1071
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:208:50
   9:     0x5618aef923dd - std::panicking::default_hook::he2f8f3fae11ed1dd
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:225:9
  10:     0x5618aef92f1d - std::panicking::rust_panic_with_hook::h79a18548bd90c7d4
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:591:17
  11:     0x5618aef92ab7 - std::panicking::begin_panic_handler::{{closure}}::h212a72cc08e25126
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:497:13
  12:     0x5618aef907ec - std::sys_common::backtrace::__rust_end_short_backtrace::hbd6897dd42bc0fcd
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:141:18
  13:     0x5618aef92a19 - rust_begin_unwind
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:493:5
  14:     0x5618ae1b04d1 - core::panicking::panic_fmt::h77ecd04e9b1dd84d
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/panicking.rs:92:14
  15:     0x5618ae1b0742 - core::slice::index::slice_index_order_fail::hb48730df1c4e3557
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/slice/index.rs:48:5
  16:     0x5618aecfdbc1 - arrow::array::transform::variable_size::build_extend::{{closure}}::h5fb95b50c5d0ff9c
  17:     0x5618aee26692 - arrow::compute::kernels::concat::concat::h25f114661c3cdd28
  18:     0x5618ae6b03ae - datafusion::physical_plan::coalesce_batches::concat_batches::hc54a680ed7b55a00
  19:     0x5618ae6aff38 - <datafusion::physical_plan::coalesce_batches::CoalesceBatchesStream as futures_core::stream::Stream>::poll_next::h6caf0292686d6e6c
  20:     0x5618ae7a3873 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h86b3faa275af3ab6
  21:     0x5618ae7a1409 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h4aa78f656535c21a
  22:     0x5618ae79ef22 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h3f7c54485515b7bd
  23:     0x5618ae3b6205 - <ballista_core::execution_plans::shuffle_writer::ShuffleWriterExec as datafusion::physical_plan::ExecutionPlan>::execute::{{closure}}::h6c7ed55df20eed71
  24:     0x5618ae3a5970 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h031b6db6c59f3b66
  25:     0x5618ae25ea6d - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h646e06d85fbf3852
  26:     0x5618ae248f52 - tokio::runtime::task::harness::poll_future::h8d2d631ce02d7ca4
  27:     0x5618ae24b2c2 - tokio::runtime::task::harness::Harness<T,S>::poll::hd0828841cf5e7439
  28:     0x5618aec47570 - std::thread::local::LocalKey<T>::with::hdf0f7e2cffb9cca7
  29:     0x5618aec6364a - tokio::runtime::thread_pool::worker::Context::run_task::h96fcb0e955022e88
  30:     0x5618aec624c9 - tokio::runtime::thread_pool::worker::Context::run::h4ba1c4818ac70106
  31:     0x5618aec48bc5 - tokio::macros::scoped_tls::ScopedKey<T>::set::h38b5613b61fed270
  32:     0x5618aec62292 - tokio::runtime::thread_pool::worker::run::h9d87413bc8c002e8
  33:     0x5618aec6c62e - tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut::h2e40e7478a3cb9f5
  34:     0x5618aec4e6c5 - std::panicking::try::hda54480cbbb459f9
  35:     0x5618aec5e663 - tokio::runtime::task::harness::Harness<T,S>::poll::h206460627d87f644
  36:     0x5618aec54f3a - std::sys_common::backtrace::__rust_begin_short_backtrace::hd08015b3d11daec5
  37:     0x5618aec6b028 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h4cad2e4d517fce10
  38:     0x5618aef9687a - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h75c2ca1daad47228
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/alloc/src/boxed.rs:1546:9
  39:     0x5618aef9687a - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hdf9f8afc9d34e311
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/alloc/src/boxed.rs:1546:9
  40:     0x5618aef9687a - std::sys::unix::thread::Thread::new::thread_start::hc238bac7748b195d
                               at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys/unix/thread.rs:71:17
  41:     0x7f0b2ac9b6db - start_thread
  42:     0x7f0b2a42271f - __clone
  43:                0x0 - <unknown>

[jorgecarleitao]

Could you upload the file?

[andygrove]

I've uploaded it to Google Drive: https://drive.google.com/file/d/1C7h_VE6F3PrChyOf3lkUrUmA33kmdowm/view?usp=sharing

[andygrove]

Sorry for the noise. It looks like I had two threads writing to the same file.