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

Reporter

Description

•

6 years ago

treeherder

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

(not currently active) Ted Mielczarek

Comment 1

•

6 years ago

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

Andreas Tolfsen ❲:ato❳

Assignee

Comment 2

•

6 years ago

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)

Andreas Tolfsen ❲:ato❳

Assignee

Comment 3

•

6 years ago

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 hidden (mozreview-request)

When tests are run in parallel threads, it is possible for tests that
use logging::set_max_level to cause race conditions in other tests.
This patch ensures that the logging tests that use this function
are guarded by a mutex.

For example, when set_max_level(Level::Info) is called in test_max_level,
test_set_max_level may have also called set_max_level(Level::Fatal).
This causes a race condition between the first line and the second
line in test_max_level because the atomic test level will have been
changed away from Level::Info to Level::Fatal.

Review commit: https://reviewboard.mozilla.org/r/221942/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/221942/

James Graham [:jgraham]

Comment 5

•

6 years ago

mozreview-review

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+

Pulsebot

Comment 6

•

6 years ago

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

Natalia Csoregi [:nataliaCs]

Comment 7

•

6 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/8c1b6b21bcaa

Status: ASSIGNED → RESOLVED

Closed: 6 years ago

status-firefox60: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla60

Comment hidden (Intermittent Failures Robot)

8 failures in 675 pushes (0.012 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* mozilla-central: 2

Platform breakdown:
* linux32: 4
* linux64: 3
* windows2012-64-noopt: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1439582&startday=2018-02-19&endday=2018-02-25&tree=all

Comment hidden (Intermittent Failures Robot)

2 failures in 782 pushes (0.003 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2

Platform breakdown:
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1439582&startday=2018-04-16&endday=2018-04-22&tree=trunk

BMO Automation

Comment 10

•

1 year ago

Moving bug to Remote Protocol::Marionette component per bug 1815831.

Component: geckodriver → Marionette

Product: Testing → Remote Protocol

Bugzilla

Quick Search

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

Categories

(Remote Protocol :: Marionette, defect, P5)

Tracking

(firefox60 fixed)

People

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

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5

Comment 6

Comment 7

Comment 8

Comment 9

Comment 10

Attachment

General

Description

File Name

Content Type