[Rust] Intermittent build failure in parquet encoding

[asfimport]

I saw this test failure locally

---- encodings::encoding::tests::test_bool stdout ----
thread 'encodings::encoding::tests::test_bool' panicked at 'Invalid byte when reading bool', parquet/src/util/bit_util.rs:73:18
 

I ran "cargo test" again and it passed

 

We have seen this happen in CI as well

Reporter: Andy Grove / @andygrove
Assignee: Greg Bowyer / @GregBowyer

Related issues:

• [Rust] [Parquet] Intermittent test failure thread 'encodings::encoding::tests::test_bool' panicked at 'Invalid byte when reading bool' (is related to)

PRs and other links:

• GitHub Pull Request #8948
• GitHub Pull Request #8993

_{Note: This issue was originally created as ARROW-10943. Please see the migration documentation for further details.}

[asfimport]

Andrew Lamb / @alamb:
see #8930 (comment) for some more context

I ran the arrow test suite this morning under valgrind and it didn't report any issue

It started happening after #8698 was merged (though that did not necessarily introduce the problem). [~gbowyer@fastmail.co.uk] did you see anything similar to this during development

[asfimport]

Greg Bowyer / @GregBowyer:
I didnt see anything during development of 8698, is this specific to windows?

[asfimport]

Greg Bowyer / @GregBowyer:
It might be unrelated:

 

A hacked version of miri (adding in atomic fetch_max) has the following complaint

 

 

greg@gregslaptop ~/.../rust/parquet $ MIRIFLAGS="-Zmiri-disable-isolation" cargo +nightly miri test 'encodings::encoding::tests::test_bool'
   Compiling parquet v3.0.0-SNAPSHOT (/home/greg/projects/arrow/rust/parquet)
    Finished test [unoptimized + debuginfo] target(s) in 1.94s
     Running /home/greg/projects/arrow/rust/target/x86_64-unknown-linux-gnu/debug/deps/parquet-9bca74cf6a2c2a95running 1 test
test encodings::encoding::tests::test_bool ... error: Undefined Behavior: accessing memory with alignment 2, but alignment 4 is required
    --> parquet/src/util/bit_packing.rs:84:13
     |
84   |     *out = ((*in_buf) >> 1) & 1;
     |             ^^^^^^^^^ accessing memory with alignment 2, but alignment 4 is required
     |
     = help: this indicates a bug in the program: it performed an invalid operation, and caused Undefined Behavior
     = help: see https://doc.rust-lang.org/nightly/reference/behavior-considered-undefined.html for further information     = note: inside `util::bit_packing::unpack1_32` at parquet/src/util/bit_packing.rs:84:13
note: inside `util::bit_packing::unpack32` at parquet/src/util/bit_packing.rs:36:14
    --> parquet/src/util/bit_packing.rs:36:14
     |
36   |         1 => unpack1_32(in_ptr, out_ptr),
     |              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `util::bit_util::BitReader::get_batch::<bool>` at parquet/src/util/bit_util.rs:554:30
    --> parquet/src/util/bit_util.rs:554:30
     |
554  |                     in_ptr = unpack32(in_ptr, out_ptr, num_bits);
     |                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `<bool as data_type::private::ParquetValueType>::decode` at parquet/src/data_type.rs:684:31
    --> parquet/src/data_type.rs:684:31
     |
684  |             let values_read = bit_reader.get_batch(&mut buffer[..num_values], 1);
     |                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `<encodings::decoding::PlainDecoder<data_type::BoolType> as encodings::decoding::Decoder<data_type::BoolType>>::get` at parquet/src/encodings/decoding.rs:197:9
    --> parquet/src/encodings/decoding.rs:197:9
     |
197  |         T::T::decode(buffer, &mut self.inner)
     |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `encodings::encoding::tests::put_and_get::<data_type::BoolType>` at parquet/src/encodings/encoding.rs:1271:9
    --> parquet/src/encodings/encoding.rs:1271:9
     |
1271 |         decoder.get(output)
     |         ^^^^^^^^^^^^^^^^^^^
note: inside `<data_type::BoolType as encodings::encoding::tests::EncodingTester<data_type::BoolType>>::test_internal` at parquet/src/encodings/encoding.rs:1214:28
    --> parquet/src/encodings/encoding.rs:1214:28
     |
1214 |               actual_total = put_and_get(
     |  ____________________________^
1215 | |                 &mut encoder,
1216 | |                 &mut decoder,
1217 | |                 &values[..],
1218 | |                 &mut result_data[..],
1219 | |             )?;
     | |_____________^
note: inside `<data_type::BoolType as encodings::encoding::tests::EncodingTester<data_type::BoolType>>::test` at parquet/src/encodings/encoding.rs:1159:24
    --> parquet/src/encodings/encoding.rs:1159:24
     |
1159 |                 enc => Self::test_internal(enc, total, type_length),
     |                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside `encodings::encoding::tests::test_bool` at parquet/src/encodings/encoding.rs:967:9
    --> parquet/src/encodings/encoding.rs:967:9
     |
967  |         BoolType::test(Encoding::PLAIN, TEST_SET_SIZE, -1);
     |         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
note: inside closure at parquet/src/encodings/encoding.rs:966:5
    --> parquet/src/encodings/encoding.rs:966:5
     |
966  | /     fn test_bool() {
967  | |         BoolType::test(Encoding::PLAIN, TEST_SET_SIZE, -1);
968  | |         BoolType::test(Encoding::PLAIN_DICTIONARY, TEST_SET_SIZE, -1);
969  | |         BoolType::test(Encoding::RLE, TEST_SET_SIZE, -1);
970  | |     }
     | |_____^
     = note: inside <[closure@parquet/src/encodings/encoding.rs:966:5: 970:6] as std::ops::FnOnce<()>>::call_once - shim` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
     = note: inside `<fn() as std::ops::FnOnce<()>>::call_once - shim(fn())` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
     = note: inside `test::__rust_begin_short_backtrace::<fn()>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:516:5
     = note: inside closure at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:507:30
     = note: inside `<[closure@test::run_test::{closure#2}] as std::ops::FnOnce<()>>::call_once - shim(vtable)` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
     = note: inside `<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send> as std::ops::FnOnce<()>>::call_once` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:1328:9
     = note: inside `<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>> as std::ops::FnOnce<()>>::call_once` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:322:9
     = note: inside `std::panicking::r#try::do_call::<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>, ()>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:379:40
     = note: inside `std::panicking::r#try::<(), std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:343:19
     = note: inside `std::panic::catch_unwind::<std::panic::AssertUnwindSafe<std::boxed::Box<dyn std::ops::FnOnce() + std::marker::Send>>, ()>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:396:14
     = note: inside `test::run_test_in_process` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:538:18
     = note: inside closure at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:449:39
     = note: inside `test::run_test::run_test_inner` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:474:13
     = note: inside `test::run_test` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:504:28
     = note: inside `test::run_tests::<[closure@test::run_tests_console::{closure#2}]>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:283:13
     = note: inside `test::run_tests_console` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/console.rs:289:5
     = note: inside `test::test_main` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:121:15
     = note: inside `test::test_main_static` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/test/src/lib.rs:140:5
     = note: inside `main`
     = note: inside `<fn() as std::ops::FnOnce<()>>::call_once - shim(fn())` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
     = note: inside `std::sys_common::backtrace::__rust_begin_short_backtrace::<fn(), ()>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:125:18
     = note: inside closure at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:66:18
     = note: inside `std::ops::function::impls::<impl std::ops::FnOnce<()> for &dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe>::call_once` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:259:13
     = note: inside `std::panicking::r#try::do_call::<&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe, i32>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:379:40
     = note: inside `std::panicking::r#try::<i32, &dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:343:19
     = note: inside `std::panic::catch_unwind::<&dyn std::ops::Fn() -> i32 + std::marker::Sync + std::panic::RefUnwindSafe, i32>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:396:14
     = note: inside `std::rt::lang_start_internal` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:51:25
     = note: inside `std::rt::lang_start::<()>` at /home/greg/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:65:5
     = note: this error originates in an attribute macro (in Nightly builds, run with -Z macro-backtrace for more info)error: aborting due to previous errorerror: test failed, to rerun pass '--lib'`

 

[asfimport]

Greg Bowyer / @GregBowyer:
A terrible PR #8948 might solve this? It would be good to solve with a reproducible test suite.

I might try to see if ubsan can find similar issues to miri

[asfimport]

Greg Bowyer / @GregBowyer:
The miri hack is here rust-lang/miri#1653

[asfimport]

Andrew Lamb / @alamb:
Some data:

I can reproduce this error regularly, though non deterministically, by running the tests in a loop with a shell script such as:

#!/bin/bash
# run a command in a loop

cd /Users/alamb/Software/arrow2/rust
export PARQUET_TEST_DATA=`pwd`/../cpp/submodules/parquet-testing/data
export ARROW_TEST_DATA=`pwd`/../testing/data

i=0
while true; do
    echo "iteration $i"
    cargo test -p parquet  -- test_bool
    i=$((i+1))
done

I am going to try this approach with [~gbowyer@fastmail.co.uk]'s PR 8948

cc @andygrove

[asfimport]

Greg Bowyer / @GregBowyer:
 I managed to nail down a deterministic test, looks to be RLE encoding related.

 

    #[test]
    fn test_bool_bug() {
        const total: usize = TEST_SET_SIZE;
        const type_length: i32 = -1;
        let mut encoder = create_test_encoder::<BoolType>(type_length, Encoding::RLE);
        let mut decoder = create_test_decoder::<BoolType>(type_length, Encoding::RLE);
        //let mut values = <T as RandGen<T>>::gen_vec(type_length, total);        
        let values: Vec<bool> = vec![
            true, true, true, true, true, true, true, true, true, false,
            true, false, true, false, true, true, true, false, false, true, true, true, true, true,
            false, true, true, false, false, true, false, false, false, true, false, false, false,
            false, true, false, true, false, false, true, false, false, false, true, true, true, false,
            true, true, true, true, false, true, false, true, false, false, true, true, false, true,
            false, false, true, true, true, true, true, true, true, false, false, true, true, false,
            true, false, true, true, true, false, true, false, true, false, false, false, true, true,
            false, true, true, true, true, false, true, true, false, false, false, false, true, false,
            true, true, true, false, true, false, false, false, false, true, false, true, true, false,
            true, false, true, false, false, true, false, true, true, true, true, true, true, true,
            true, true, true, false, false, true, false, false, false, true, true, false, false, false,
            false, false, true, true, false, false, false, true, false, true, true, true, true, true,
            true, false, false, false, false, true, false, false, false, false, true, false, false,
            false, false, false, false, true, true, true, true, false, true, false, false, true, true,
            true, false, true, false, true, false, false, false, false, false, true, false, false,
            false, true, true, true, true, false, false, false, false, true, true, true, true, false,
            true, true, true, false, true, false, true, true, false, false, true, false, true, false,
            false, true, false, true, true, false, false, false, true, false, true, true, true, false,
            true, true, false, false, false, true, true, false, false, false, false, false, false,
            true, true, false, false, false, true, true, false, false, true, false, false, true, true,
            false, true, true, false, true, true, false, true, false, false, false, false, false,
            false, true, false, true, true, false, false, false, false, false, false, false, false,
            false, true, false, false, false, false, false, true, false, false, true, true, false,
            false, true, true, false, true, true, false, false, true, false, true, false, true, true,
            true, false, false, false, true, true, true, false, true, false, false, true, false, false,
            false, true, false, false, true, false, true, true, true, false, true, true, true, true,
            false, false, true, false, true, false, true, false, false, true, true, false, false, true,
            false, true, false, false, true, false, true, false, false, false, true, true, true, false,
            false, false, true, false, true, false, false, false, true, false, true, false, false,
            false, false, true, true, false, true, false, false, true, true, true, false, true, false,
            false, true, false, true, false, false, true, false, true, true, true, true, true, true,
            true, true, false, false, false, false, false, false, false, true, false, true, true,
            false, true, false, true, false, true, true, true, true, false, true, true, true, true,
            true, false, false, false, false, true, false, true, true, true, true, true, false, true,
            true, false, true, true, false, false, false, true, false, true, false, true, true, false,
            true, true, false, true, true, true, false, true, false, false, false, false, false, false,
            false, true, false, true, false, true, false, true, true, true, true, true, false, true,
            false, false, true, true, true, true, false, true, false, false, false, true, false, true,
            true, false, true, true, false, false, false, false, true, false, true, true, false, false,
            false, true, true, false, false, true, true, true, true, false, false, false, true, true,
            true, true, true, true, false, false, false, false, false, false, false, false, true, true,
            false, true, true, true, false, true, true, false, true, true, false, false, true, false,
            false, true, true, false, false, true, false, true, true, true, true, true, true, false,
            true, false, true, false, true, true, true, true, true, true, true, false, false, true,
            false, false, true, true, false, true, false, true, false, true, false, false, true, true,
            false, true, false, true, true, true, true, true, true, false, false, false, true, true,
            false, true, false, false, true, true, false, false, true, false, true, true, false, true,
            false, true, false, true, false, true, true, false, false, false, false, true, true, true,
            false, true, true, true, false, true, false, false, false, true, false, false, true, false,
            false, true, false, true, true, false, true, false, false, true, false, true, true, false,
            false, false, false, false, true, true, true, true, false, false, false, true, false,
            false, false, true, false, true, true, true, true, false, false, false, true, true, true,
            false, false, true, false, false, false, false, true, false, true, false, true, false,
            false, false, true, false, false, false, false, true, true, true, true, false, false, true,
            false, true, false, true, true, true, false, false, true, true, true, false, true, true,
            false, true, true, false, true, false, false, false, false, false, true, true, false, true,
            false, true, false, true, false, true, true, true, true, true, true, true, false, false,
            false, true, true, true, false, false, true, false, true, false, true, false, false, false,
            true, true, false, true, true, false, false, false, false, false, true, true, true, false,
            true, true, true, true, true, false, false, true, true, true, false, true, true, false,
            true, false, false, false, false, false, true, false, true, true, true, true, true, true,
            true, true, true, true, true, false, true, true, true, false, false, false, true, true,
            true, true, true, true, false, false, true, false, false, false, false, false, true, false,
            false, false, false, true, true, false, true, true, true, true, true, true, true, true,
            false, true, true, false, true, false, false, true, false, true, false, true, true, true,
            true, false, true, false, false, true, true, false, false, true, false, true, true, false,
            false, true, false, true, true, true, true, false, false, false, true, true, true, true,
            true, false, false, true, false, true, false, false, false, true, true, true, true, false,
            false, true, false, false, true, true, false, true, true, false, false, false, false,
            false, true, false, false, true, false, true, false, true, false, true, false, true, true,
            true, true, false, true, false, true, false, true, false, true, false, false, true, false,
            true, false, true, false, false, true, true, true, false, true, true, false, true, false,
            false, false, false, true, false, true, false, true, false, false, false, true, false,
            true, false, false, true, false, false, true, false, false, false, true, true, false, true,
            true, true, true, false, false
        ];

        let mut result_data = vec![bool::default(); total];

        // Test put/get spaced.
        let num_bytes = bit_util::ceil(total as i64, 8);
        let valid_bits = random_bytes(num_bytes as usize);
        let values_written = encoder.put_spaced(&values[..], &valid_bits[..]).unwrap();
        let data = encoder.flush_buffer().unwrap();
        decoder.set_data(data, values_written).unwrap();

        let _ = decoder.get_spaced(
            &mut result_data[..],
            values.len() - values_written,
            &valid_bits[..],
        ).unwrap();

        // Check equality
        for i in 0..total {
            if bit_util::get_bit(&valid_bits[..], i) {
                assert_eq!(result_data[i], values[i]);
            } else {
                assert_eq!(result_data[i], bool::default());
            }
        }

        let mut actual_total = put_and_get(
            &mut encoder,
            &mut decoder,
            &values[..],
            &mut result_data[..],
        ).unwrap();


        assert_eq!(actual_total, total);
        assert_eq!(result_data, values);
    }

[asfimport]

Greg Bowyer / @GregBowyer:
Running the shell loop and above test, I think #8993 fixes this issue

[asfimport]

Jorge Leitão / @jorgecarleitao:
Issue resolved by pull request 8993
#8993

[asfimport]

Andy Grove / @andygrove:
No, not specific to Windows. I see it on Ubuntu.