Concurrency in tests result in undefined behavior

[Rikorose]

🐛 Bug Reports

Maybe similar to #19.

I am testing my rust library against a python library. Therefor pyo3::Python::acquire_gil() is called in several tests. In each test i am setting up the imports like:

let globals = PyDict::new(gil.python());
globals.set_item("librosa", gil.python().import("librosa")?)?;
globals.set_item("np", gil.python().import("numpy")?)?;

When executing my tests with
RUST_BACKTRACE=full RUST_TEST_THREADS=1 cargo test --verbose --test spectrum
everything runs fine.

But for
RUST_BACKTRACE=full RUST_TEST_THREADS=2 cargo test --verbose --test spectrum
for some tests (not all!) fail with

Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'np' is not defined

or

Traceback (most recent call last):
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "<string>", line 1, in <module>
AttributeError: 'int' object has no attribute 'abs'
NameError: name 'np' is not defined

(I use np.abs(), np somehow became an int)

full trace

       Fresh version_check v0.1.5
       Fresh unicode-xid v0.1.0
       Fresh libc v0.2.43
       Fresh cfg-if v0.1.6
       Fresh ucd-util v0.1.2
       Fresh lazy_static v1.2.0
       Fresh utf8-ranges v1.0.2
       Fresh proc-macro-hack-impl v0.4.1
       Fresh rawpointer v0.1.0
       Fresh rustc-serialize v0.3.24
       Fresh rand_core v0.3.0
       Fresh either v1.5.0
       Fresh spin v0.4.10
       Fresh regex-syntax v0.6.3
       Fresh thread_local v0.3.6
       Fresh proc-macro-hack v0.4.1
       Fresh rand_core v0.2.2
       Fresh itertools v0.7.8
       Fresh proc-macro2 v0.4.23
       Fresh num-traits v0.2.6
       Fresh matrixmultiply v0.1.15
       Fresh rand v0.5.5
       Fresh memchr v2.1.1
       Fresh quote v0.6.10
       Fresh mashup-impl v0.1.9
       Fresh num-integer v0.1.39
       Fresh num-complex v0.2.1
       Fresh num-complex v0.1.43
       Fresh aho-corasick v0.6.9
       Fresh syn v0.15.20
       Fresh mashup v0.1.9
       Fresh ndarray v0.12.0
       Fresh rustfft v2.1.0
       Fresh regex v1.0.6
       Fresh pyo3-derive-backend v0.5.2
       Fresh ndarray-rand v0.8.0
       Fresh pyo3cls v0.5.2
       Fresh pyo3 v0.5.2
       Fresh numpy v0.4.0-alpha.1
       Fresh audio-featrs v0.1.0 (/home/rik/Projects/audio-featrs)
    Finished dev [unoptimized + debuginfo] target(s) in 0.06s
     Running `/home/rik/Projects/audio-featrs/target/debug/deps/spectrum-f8cb5092fca4628b`

running 9 tests
test test_stft_build_assertion_2 ... ok
test test_stft_build_assertion_1 ... ok
test test_stft_build_assertion_3 ... ok
test test_stft_build_assertion_4 ... ok
/home/rik/.local/lib/python3.7/site-packages/sklearn/externals/joblib/externals/cloudpickle/cloudpickle.py:47: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses
  import imp
test test_stft_pad_truncate_1 ... ok
Traceback (most recent call last):
  File "<string>", line 1, in <module>
NameError: name 'np' is not defined
test test_stft_pad_truncate_2 ... FAILED
test test_stft_pad_truncate_3 ... ok
test test_stft_pad_truncate_5 ... ok
test test_stft_pad_truncate_4 ... ok

failures:

---- test_stft_pad_truncate_2 stdout ----
process
{'librosa': <module 'librosa' from '/home/rik/.local/lib/python3.7/site-packages/librosa/__init__.py'>, 'np': <module 'numpy' from '/home/rik/.local/lib/python3.7/site-packages/numpy/__init__.py'>}
{'x': array([-0.6413505 ,  0.1146059 , -0.81843805, -0.5711856 , -0.29123425,
        0.12136364, -0.10037255, -0.259588  ,  0.51836467, -0.90735674],
      dtype=float32), 'n_fft': 7, 'hop_length': 2, 'win_length': 7, 'window': 'hann'}
Librosa
Error calling _librosa_stft(): PyErr { type: Py(0x7f99a4fca4e0, PhantomData) }
thread 'test_stft_pad_truncate_2' panicked at 'called `Result::unwrap()` on an `Err` value: ()', libcore/result.rs:1009:5
stack backtrace:
   0:     0x56328b4474f3 - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::hca8039cd7b37e496
                               at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:     0x56328b441bc8 - std::sys_common::backtrace::_print::h0093469aea281e95
                               at libstd/sys_common/backtrace.rs:71
   2:     0x56328b446414 - std::panicking::default_hook::{{closure}}::h734c9b92530fb071
                               at libstd/sys_common/backtrace.rs:59
                               at libstd/panicking.rs:211
   3:     0x56328b4460fc - std::panicking::default_hook::h0a909303812f5148
                               at libstd/panicking.rs:221
   4:     0x56328b446b20 - std::panicking::rust_panic_with_hook::h9e1a9124d130318a
                               at libstd/panicking.rs:476
   5:     0x56328b4466a1 - std::panicking::continue_panic_fmt::hc42f82c8a3d91193
                               at libstd/panicking.rs:390
   6:     0x56328b446585 - rust_begin_unwind
                               at libstd/panicking.rs:325
   7:     0x56328b459f1c - core::panicking::panic_fmt::hbfebcf4144746115
                               at libcore/panicking.rs:77
   8:     0x56328b2ad5b1 - core::result::unwrap_failed::h55bd315fb2b0235d
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libcore/macros.rs:26
   9:     0x56328b2ac327 - <core::result::Result<T, E>>::unwrap::h6392165a86b4da31
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libcore/result.rs:808
  10:     0x56328b362355 - spectrum::_test_stft::h6d25a0d25174d7eb
                               at tests/spectrum.rs:115
  11:     0x56328b3628f4 - spectrum::test_stft_pad_truncate_2::h02d4fcb5f2eea8b5
                               at tests/spectrum.rs:142
  12:     0x56328b2bdd79 - spectrum::test_stft_pad_truncate_2::{{closure}}::h239020c96780fcc8
                               at tests/spectrum.rs:140
  13:     0x56328b300f7d - core::ops::function::FnOnce::call_once::h16b726a5a0315153
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libcore/ops/function.rs:238
  14:     0x56328b3b369e - <F as alloc::boxed::FnBox<A>>::call_box::h7a98c6e94763ae35
                               at libtest/lib.rs:1471
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libcore/ops/function.rs:238
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/liballoc/boxed.rs:673
  15:     0x56328b455279 - __rust_maybe_catch_panic
                               at libpanic_unwind/lib.rs:102
  16:     0x56328b3ab783 - std::sys_common::backtrace::__rust_begin_short_backtrace::h32de52ca171cdf4b
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/panicking.rs:289
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/panic.rs:398
                               at libtest/lib.rs:1426
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/sys_common/backtrace.rs:136
  17:     0x56328b3ac624 - std::panicking::try::do_call::h0d861e7c44b3b31c
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/thread/mod.rs:477
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/panic.rs:319
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/panicking.rs:310
  18:     0x56328b455279 - __rust_maybe_catch_panic
                               at libpanic_unwind/lib.rs:102
  19:     0x56328b3b389c - <F as alloc::boxed::FnBox<A>>::call_box::hc2e6c696dadbc1f5
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/panicking.rs:289
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/panic.rs:398
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/libstd/thread/mod.rs:476
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/liballoc/boxed.rs:673
  20:     0x56328b44915d - std::sys::unix::thread::Thread::new::thread_start::h2911d13670fb7547
                               at /rustc/13c9439925797cd7a65c917d047c07a500d9bfe6/src/liballoc/boxed.rs:683
                               at libstd/sys_common/thread.rs:24
                               at libstd/sys/unix/thread.rs:90
  21:     0x7f99a4c5d58d - start_thread
  22:     0x7f99a4b71652 - clone
  23:                0x0 - <unknown>


failures:
    test_stft_pad_truncate_2

test result: FAILED. 8 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

Sometimes I even get a (signal: 11, SIGSEGV: invalid memory reference)

full trace

RUST_BACKTRACE=full RUST_TEST_THREADS=2 cargo test --verbose --test spectrum
       Fresh version_check v0.1.5
       Fresh cfg-if v0.1.6
       Fresh unicode-xid v0.1.0
       Fresh libc v0.2.43
       Fresh ucd-util v0.1.2
       Fresh lazy_static v1.2.0
       Fresh proc-macro-hack-impl v0.4.1
       Fresh utf8-ranges v1.0.2
       Fresh rustc-serialize v0.3.24
       Fresh either v1.5.0
       Fresh rand_core v0.3.0
       Fresh rawpointer v0.1.0
       Fresh spin v0.4.10
       Fresh regex-syntax v0.6.3
       Fresh thread_local v0.3.6
       Fresh proc-macro-hack v0.4.1
       Fresh itertools v0.7.8
       Fresh rand_core v0.2.2
       Fresh proc-macro2 v0.4.23
       Fresh num-traits v0.2.6
       Fresh matrixmultiply v0.1.15
       Fresh rand v0.5.5
       Fresh memchr v2.1.1
       Fresh quote v0.6.10
       Fresh mashup-impl v0.1.9
       Fresh num-complex v0.1.43
       Fresh num-complex v0.2.1
       Fresh num-integer v0.1.39
       Fresh aho-corasick v0.6.9
       Fresh syn v0.15.20
       Fresh mashup v0.1.9
       Fresh ndarray v0.12.0
       Fresh rustfft v2.1.0
       Fresh regex v1.0.6
       Fresh pyo3-derive-backend v0.5.2
       Fresh ndarray-rand v0.8.0
       Fresh pyo3cls v0.5.2
       Fresh pyo3 v0.5.2
       Fresh numpy v0.4.0-alpha.1
       Fresh audio-featrs v0.1.0 (/home/rik/Projects/audio-featrs)
    Finished dev [unoptimized + debuginfo] target(s) in 0.06s
     Running `/home/rik/Projects/audio-featrs/target/debug/deps/spectrum-f8cb5092fca4628b`

running 9 tests
test test_stft_build_assertion_2 ... ok
test test_stft_build_assertion_1 ... ok
test test_stft_build_assertion_3 ... ok
test test_stft_build_assertion_4 ... ok
/home/rik/.local/lib/python3.7/site-packages/sklearn/externals/joblib/externals/cloudpickle/cloudpickle.py:47: DeprecationWarning: the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses
  import imp
test test_stft_pad_truncate_1 ... ok
error: process didn't exit successfully: `/home/rik/Projects/audio-featrs/target/debug/deps/spectrum-f8cb5092fca4628b` (signal: 11, SIGSEGV: invalid memory reference)

The SIGSEGV become more likely for more threads, e.g. aprox. 9/10 for 3 threads, while 2 threads its only 1/10.

Am I using pyo3::Python::acquire_gil() wrong? Is this not thread-safe? As far as I can tell, this is called in every(?) test of this library.

🌍 Environment

• Your operating system and version: Fedora 29
• Your python version: Tested with 2.7 and 3.7
• How did you install python (e.g. apt or pyenv)? Did you use a virtualenv?: dnf, virtualenv
• Your rust version (rustc --version): rustc 1.32.0-nightly (13c943992 2018-11-18)
• Are you using the latest pyo3 version? Have you tried using latest master (replace version = "0.x.y" with git = "https://github.com/PyO3/pyo3")?: I am using pyo3 version 0.5.2, git breaks compatibility with rust-numpy

💥 Reproducing

Please provide a minimal working example. This means both the rust code and the python.

Please also write what exact flags are required to reproduce your results.

[konstin]

Thanks for the report, but I fear this isn't sufficient to reproduce the bug. Could you provide e.g. a minimal lib.rs with two tests that show this behaviour?

[Rikorose]

Yes I will try

[Rikorose]

Hi, please see my repo: https://github.com/Rikorose/test_pyo3

[kngwyu]

Nice example! Thanks.
I run a modfied code like

fn _test(size: usize) {
    static mut LOCKED: bool = false;
    let gil = Python::acquire_gil();
    unsafe {
        println!("LOCKED_before: {}", LOCKED);
        if !LOCKED {
            LOCKED = true;
        }
    }
    let mut x = Array1::random(size, F32(Normal::new(-1., 1.)));

    let py_x = _test_pyo3(gil.python(), x.clone())
        .map_err(|e| {
            eprintln!("Error calling _test_pyo3(): {:?}", e);
            e.print_and_set_sys_last_vars(gil.python());
        })
        .unwrap();

    x.mapv_inplace(f32::exp);
    assert_close(
        &x.as_slice().unwrap(),
        &py_x.as_slice().unwrap(),
        1e-6.into(),
    );
    unsafe {
        println!("LOCKED_after: {}", LOCKED);
        if LOCKED {
            LOCKED = false;
        }
    }
}

and got

running 10 tests
LOCKED_before: false
LOCKED_before: true
LOCKED_before: true
LOCKED_before: true
LOCKED_before: true
LOCKED_before: true
LOCKED_before: true
LOCKED_before: true
LOCKED_before: true
LOCKED_before: true
LOCKED_after: true
test test_7 ... ok
Error calling _test_pyo3(): PyErr { type: Py(0x7f3eedcab440, PhantomData) }
Error calling _test_pyo3(): PyErr { type: Py(0x7f3eedcab440, PhantomData) }
LOCKED_after: false
test test_9 ... ok
LOCKED_after: false
test test_8 ... ok
LOCKED_after: false
test test_5 ... ok
LOCKED_after: false
test test_4 ... ok
LOCKED_after: false
test test_6 ... ok
LOCKED_after: false
test test_1 ... ok
LOCKED_after: false
test test_3 ... ok
Traceback (most recent call last):
  File "<string>", line 1, in <module>
Traceback (most recent call last):
NameError: name 'np' is not defined
thread 'test_2' panicked at 'called `Result::unwrap()` on an `Err` value: ()', src/libcore/result.rs:1009:5
note: Run with `RUST_BACKTRACE=1` for a backtrace.
  File "<string>", line 1, in <module>
test test_2 ... FAILED
NameError: name 'np' is not defined
thread 'test_10' panicked at 'called `Result::unwrap()` on an `Err` value: ()', src/libcore/result.rs:1009:5
test test_10 ... FAILED

.

So it's apparently codes are executed in parallel.
But... I can say nothing about this, because I don't know nothing about what PyGILState_Ensure does.
It looks creating a new thread when initializing, but do nothing when a thread is already initialized.

[zhenwenc]

Hi, is there any solution for this issue? Or we just have to use --test-threads=1? Thanks!

[Alexander-N]

This looks like another case of #756 and can probably be closed.

[davidhewitt]

I was thinking the same thing. 🎉

(FYI the fix was included in the recent #887 )