Closed Bug 1439582 Opened 2 years ago Closed 2 years ago

Intermittent make[2]: *** [force-cargo-test-run] Error 101

Categories

(Testing :: geckodriver, defect, P5)

defect

Tracking

(firefox60 fixed)

RESOLVED FIXED
mozilla60
Tracking Status
firefox60 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: ato)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: aciure [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=163141275&repo=mozilla-central

https://queue.taskcluster.net/v1/task/Qwp1r2lRSLuh03cnfUA1Nw/runs/0/artifacts/public/logs/live_backing.log

[task 2018-02-20T10:50:47.650Z] 10:50:47     INFO -                        at /checkout/src/libpanic_unwind/lib.rs:101
[task 2018-02-20T10:50:47.650Z] 10:50:47     INFO -   15: 0x5660526a - <F as alloc::boxed::FnBox<A>>::call_box::h32b5a395b4aa6a50
[task 2018-02-20T10:50:47.650Z] 10:50:47     INFO -                        at /checkout/src/libstd/panicking.rs:459
[task 2018-02-20T10:50:47.650Z] 10:50:47     INFO -                        at /checkout/src/libstd/panic.rs:365
[task 2018-02-20T10:50:47.650Z] 10:50:47     INFO -                        at /checkout/src/libstd/thread/mod.rs:405
[task 2018-02-20T10:50:47.650Z] 10:50:47     INFO -                        at /checkout/src/liballoc/boxed.rs:815
[task 2018-02-20T10:50:47.651Z] 10:50:47     INFO -   16: 0x5664ba5b - std::sys_common::thread::start_thread::hd0080befbd549a92
[task 2018-02-20T10:50:47.651Z] 10:50:47     INFO -                        at /checkout/src/liballoc/boxed.rs:825
[task 2018-02-20T10:50:47.651Z] 10:50:47     INFO -                        at /checkout/src/libstd/sys_common/thread.rs:24
[task 2018-02-20T10:50:47.652Z] 10:50:47     INFO -   17: 0x5664320b - std::sys::unix::thread::Thread::new::thread_start::h90af79a783f99198
[task 2018-02-20T10:50:47.652Z] 10:50:47     INFO -                        at /checkout/src/libstd/sys/unix/thread.rs:90
[task 2018-02-20T10:50:47.652Z] 10:50:47     INFO -   18: 0xf777d953 - <unknown>
[task 2018-02-20T10:50:47.653Z] 10:50:47     INFO - failures:
[task 2018-02-20T10:50:47.653Z] 10:50:47     INFO -     logging::tests::test_max_level
[task 2018-02-20T10:50:47.653Z] 10:50:47     INFO - test result: FAILED. 15 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out
[task 2018-02-20T10:50:47.653Z] 10:50:47     INFO - error: test failed, to rerun pass '--bin geckodriver'
[task 2018-02-20T10:50:47.654Z] 10:50:47     INFO - /builds/worker/workspace/build/src/config/rules.mk:990: recipe for target 'force-cargo-test-run' failed
[task 2018-02-20T10:50:47.654Z] 10:50:47     INFO - make[2]: *** [force-cargo-test-run] Error 101
[task 2018-02-20T10:50:47.654Z] 10:50:47     INFO - make[2]: Target 'check' not remade because of errors.
[task 2018-02-20T10:50:47.655Z] 10:50:47     INFO - make[2]: Leaving directory '/builds/worker/workspace/build/src/obj-firefox/testing/geckodriver'
[task 2018-02-20T10:50:47.655Z] 10:50:47     INFO - /builds/worker/workspace/build/src/config/recurse.mk:100: recipe for target 'testing/geckodriver/check' failed
[task 2018-02-20T10:50:47.655Z] 10:50:47     INFO - make[1]: *** [testing/geckodriver/check] Error 2
[task 2018-02-20T10:50:47.667Z] 10:50:47     INFO - TEST-PASS | check_spidermonkey_style.py | ok
[task 2018-02-20T10:50:47.674Z] 10:50:47     INFO - make[2]: Leaving directory '/builds/worker/workspace/build/src/obj-firefox/js/src'
[task 2018-02-20T10:50:47.682Z] 10:50:47     INFO - make[2]: Entering directory '/builds/worker/workspace/build/src/obj-firefox/js/src/build'
[task 2018-02-20T10:50:47.682Z] 10:50:47     INFO - /builds/worker/workspace/build/src/obj-firefox/_virtualenv/bin/python /builds/worker/workspace/build/src/config/check_vanilla_allocations.py libjs_static.a
[task 2018-02-20T10:50:48.463Z] 10:50:48     INFO -    Compiling atty v0.2.2
[task 2018-02-20T10:50:48.463Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name atty /builds/worker/workspace/build/src/third_party/rust/atty/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on -C metadata=19abb0703b1b3967 -C extra-filename=-19abb0703b1b3967 --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps/liblibc-e371c2d7776102e9.rlib --cap-lints allow`
[task 2018-02-20T10:50:48.486Z] 10:50:48     INFO -    Compiling memchr v1.0.2
[task 2018-02-20T10:50:48.487Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name memchr /builds/worker/workspace/build/src/third_party/rust/memchr/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on --cfg 'feature="default"' --cfg 'feature="libc"' --cfg 'feature="use_std"' -C metadata=cc83911fc8b8e9f1 -C extra-filename=-cc83911fc8b8e9f1 --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps/liblibc-e371c2d7776102e9.rlib --cap-lints allow`
[task 2018-02-20T10:50:48.510Z] 10:50:48     INFO -    Compiling rand v0.3.18
[task 2018-02-20T10:50:48.526Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name rand /builds/worker/workspace/build/src/third_party/rust/rand/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on -C metadata=ee1896e843a05e2e -C extra-filename=-ee1896e843a05e2e --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps/liblibc-e371c2d7776102e9.rlib --cap-lints allow`
[task 2018-02-20T10:50:48.607Z] 10:50:48     INFO -    Compiling thread-id v3.1.0
[task 2018-02-20T10:50:48.608Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name thread_id /builds/worker/workspace/build/src/third_party/rust/thread-id/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on -C metadata=ee6d4d6639113cb2 -C extra-filename=-ee6d4d6639113cb2 --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps/liblibc-e371c2d7776102e9.rlib --cap-lints allow`
[task 2018-02-20T10:50:48.648Z] 10:50:48     INFO -    Compiling time v0.1.38
[task 2018-02-20T10:50:48.648Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name time /builds/worker/workspace/build/src/third_party/rust/time/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on -C metadata=460a3c4e3410f89f -C extra-filename=-460a3c4e3410f89f --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps --target i686-unknown-linux-gnu -C linker=/builds/worker/workspace/build/src/build/cargo-linker -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps/liblibc-f2072ca037e1c143.rlib --cap-lints allow -C opt-level=2 -C debuginfo=2`
[task 2018-02-20T10:50:48.732Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name memchr /builds/worker/workspace/build/src/third_party/rust/memchr/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on --cfg 'feature="default"' --cfg 'feature="libc"' --cfg 'feature="use_std"' -C metadata=0851b4598dc99d7e -C extra-filename=-0851b4598dc99d7e --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps --target i686-unknown-linux-gnu -C linker=/builds/worker/workspace/build/src/build/cargo-linker -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps/liblibc-f2072ca037e1c143.rlib --cap-lints allow -C opt-level=2 -C debuginfo=2`
[task 2018-02-20T10:50:48.735Z] 10:50:48     INFO -    Compiling num_cpus v1.7.0
[task 2018-02-20T10:50:48.736Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name num_cpus /builds/worker/workspace/build/src/third_party/rust/num_cpus/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on -C metadata=b1ba03a83992d00f -C extra-filename=-b1ba03a83992d00f --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps --target i686-unknown-linux-gnu -C linker=/builds/worker/workspace/build/src/build/cargo-linker -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps/liblibc-f2072ca037e1c143.rlib --cap-lints allow -C opt-level=2 -C debuginfo=2`
[task 2018-02-20T10:50:48.760Z] 10:50:48     INFO -      Running `/builds/worker/workspace/build/src/rustc/bin/rustc --crate-name rand /builds/worker/workspace/build/src/third_party/rust/rand/src/lib.rs --crate-type lib --emit=dep-info,link -C opt-level=1 -C codegen-units=4 -C debuginfo=2 -C debug-assertions=on -C metadata=8a2c3df7baa95376 -C extra-filename=-8a2c3df7baa95376 --out-dir /builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps --target i686-unknown-linux-gnu -C linker=/builds/worker/workspace/build/src/build/cargo-linker -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps -L dependency=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/debug/deps --extern libc=/builds/worker/workspace/build/src/obj-firefox/toolkit/library/i686-unknown-linux-gnu/debug/deps/liblibc-f2072ca037e1c143.rlib --cap-lints allow -C opt-level=2 -C debuginfo=2`
[task 2018-02-20T10:50:48.768Z] 10:50:48     INFO - TEST-PASS | check_vanilla_allocations.py | ok
Slightly more context (Rust backtraces are pretty verbose):

[task 2018-02-20T10:50:47.539Z] 10:50:47     INFO -      Running `/builds/worker/workspace/build/src/obj-firefox/testing/geckodriver/./i686-unknown-linux-gnu/debug/deps/geckodriver-15041de7acf6b0b5`
[task 2018-02-20T10:50:47.541Z] 10:50:47     INFO - running 16 tests
[task 2018-02-20T10:50:47.557Z] 10:50:47     INFO - test logging::tests::test_level_repr ... ok
[task 2018-02-20T10:50:47.557Z] 10:50:47     INFO - test logging::tests::test_level_eq ... ok
[task 2018-02-20T10:50:47.557Z] 10:50:47     INFO - test logging::tests::test_level_from_log ... ok
[task 2018-02-20T10:50:47.557Z] 10:50:47     INFO - test logging::tests::test_level_from_str ... ok
[task 2018-02-20T10:50:47.557Z] 10:50:47     INFO - test logging::tests::test_level_to_str ... ok
[task 2018-02-20T10:50:47.557Z] 10:50:47     INFO - test logging::tests::test_level_into_log ... ok
[task 2018-02-20T10:50:47.558Z] 10:50:47     INFO - test marionette::tests::test_addon_install_params_missing_path ... ok
[task 2018-02-20T10:50:47.558Z] 10:50:47     INFO - test logging::tests::test_set_max_level ... ok
[task 2018-02-20T10:50:47.559Z] 10:50:47     INFO - test logging::tests::test_init_with_level ... ok
[task 2018-02-20T10:50:47.560Z] 10:50:47     INFO - test logging::tests::test_format_ts ... ok
[task 2018-02-20T10:50:47.560Z] 10:50:47     INFO - test capabilities::tests::test_profile ... ok
[task 2018-02-20T10:50:47.561Z] 10:50:47     INFO - test capabilities::tests::test_prefs ... ok
[task 2018-02-20T10:50:47.561Z] 10:50:47     INFO - test marionette::tests::test_addon_install_params_with_path ... ok
[task 2018-02-20T10:50:47.567Z] 10:50:47     INFO - test marionette::tests::test_addon_install_params_with_base64 ... ok
[task 2018-02-20T10:50:47.567Z] 10:50:47     INFO - test marionette::tests::test_addon_install_params_with_both_path_and_base64 ... ok
[task 2018-02-20T10:50:47.646Z] 10:50:47     INFO - test logging::tests::test_max_level ... FAILED
[task 2018-02-20T10:50:47.646Z] 10:50:47     INFO - failures:
[task 2018-02-20T10:50:47.646Z] 10:50:47     INFO - ---- logging::tests::test_max_level stdout ----
[task 2018-02-20T10:50:47.646Z] 10:50:47     INFO - 	thread 'logging::tests::test_max_level' panicked at 'assertion failed: `(left == right)`
[task 2018-02-20T10:50:47.646Z] 10:50:47     INFO -   left: `Fatal`,
[task 2018-02-20T10:50:47.647Z] 10:50:47     INFO -  right: `Info`', src/logging.rs:267:9
[task 2018-02-20T10:50:47.647Z] 10:50:47     INFO - stack backtrace:
[task 2018-02-20T10:50:47.647Z] 10:50:47     INFO -    0: 0x5664870d - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::h1161623548489f53
[task 2018-02-20T10:50:47.647Z] 10:50:47     INFO -                        at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
[task 2018-02-20T10:50:47.647Z] 10:50:47     INFO -    1: 0x5664ec83 - std::sys_common::backtrace::print::hf81721988fc483b5
[task 2018-02-20T10:50:47.647Z] 10:50:47     INFO -                        at /checkout/src/libstd/sys_common/backtrace.rs:68
[task 2018-02-20T10:50:47.647Z] 10:50:47     INFO -                        at /checkout/src/libstd/sys_common/backtrace.rs:57
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -    2: 0x566427f6 - std::panicking::default_hook::{{closure}}::h307410a777a3bd25
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -                        at /checkout/src/libstd/panicking.rs:381
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -    3: 0x56642389 - std::panicking::default_hook::heb8feab19bd5fff3
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -                        at /checkout/src/libstd/panicking.rs:391
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -    4: 0x56642c65 - std::panicking::rust_panic_with_hook::hbe8a7b70284bfc8f
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -                        at /checkout/src/libstd/panicking.rs:577
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -    5: 0x56642aca - std::panicking::begin_panic::h9298085721c5ca83
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -                        at /checkout/src/libstd/panicking.rs:538
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -    6: 0x56642a46 - std::panicking::begin_panic_fmt::h5bee0572e1c5ce3c
[task 2018-02-20T10:50:47.648Z] 10:50:47     INFO -                        at /checkout/src/libstd/panicking.rs:522
[task 2018-02-20T10:50:47.649Z] 10:50:47     INFO -    7: 0x565d4d0d - geckodriver::logging::tests::test_max_level::h8d4fb13508672f72
[task 2018-02-20T10:50:47.649Z] 10:50:47     INFO -                        at src/logging.rs:267

It looks like this is failing a geckodriver test.
Component: Build Config → geckodriver
Flags: needinfo?(ato)
Product: Core → Testing
The left side being "Fatal" would indicate that test_max_level
gets run at approximately the same time, and that there is a race
condition between the test parallelisation because the max log level
is stored on the heap in an AtomicUint.

In other words, between set_max_level(Level::Info) is called
in test_max_level and assert_eq!(max_level(), Level::Info),
test_set_max_level has also called set_max_level(Level::Fatal),
causing the assertion to fail.
Flags: needinfo?(ato)
I guess the solution here is to have a shared mutex between the
tests so that only one can run in parallel.
Assignee: nobody → ato
Status: NEW → ASSIGNED
Comment on attachment 8952705 [details]
Bug 1439582 - Use mutex to ensure tests for set_max_level are not racy.

https://reviewboard.mozilla.org/r/221942/#review227830
Attachment #8952705 - Flags: review?(james) → review+
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8c1b6b21bcaa
Use mutex to ensure tests for set_max_level are not racy. r=jgraham
https://hg.mozilla.org/mozilla-central/rev/8c1b6b21bcaa
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla60
You need to log in before you can comment on or make changes to this bug.