Closed Bug 1682165 Opened 5 years ago Closed 5 years ago

Intermittent mozmake.EXE[1]: *** [force-cargo-test-run] Error 101 | thread 'private::string::test::string_ipc' panicked at 'Cannot get test value for string metric in non-parent process!'

Categories

(Toolkit :: Telemetry, defect, P1)

defect

Tracking

()

RESOLVED FIXED
86 Branch
Tracking Status
firefox86 --- fixed

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][stockwell unknown])

Attachments

(1 file)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=324377951&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KcFnwsdbRSOXkx13Tk483Q/runs/0/artifacts/public/logs/live_backing.log


[task 2020-12-13T10:24:38.488Z] 10:24:38     INFO -  test private::uuid::test::uuid_ipc ... FAILED
[task 2020-12-13T10:24:38.490Z] 10:24:38     INFO -  failures:
[task 2020-12-13T10:24:38.490Z] 10:24:38     INFO -  ---- private::string::test::string_ipc stdout ----
[task 2020-12-13T10:24:38.491Z] 10:24:38     INFO -  thread 'private::string::test::string_ipc' panicked at 'Cannot get test value for string metric in non-parent process!', toolkit\components\glean\api\src\private\string.rs:107:17
[task 2020-12-13T10:24:38.491Z] 10:24:38     INFO -  stack backtrace:
[task 2020-12-13T10:24:38.492Z] 10:24:38     INFO -     0:   0xe0f848 - core::fmt::write
[task 2020-12-13T10:24:38.492Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\core\src\fmt\mod.rs:1080
[task 2020-12-13T10:24:38.492Z] 10:24:38     INFO -     1:   0xd4d731 - std::io::Write::write_fmt<test::helpers::sink::Sink>
[task 2020-12-13T10:24:38.493Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\io\mod.rs:1516
[task 2020-12-13T10:24:38.494Z] 10:24:38     INFO -     2:   0xdf4acc - std::io::impls::{{impl}}::write_fmt<Write>
[task 2020-12-13T10:24:38.494Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\io\impls.rs:179
[task 2020-12-13T10:24:38.495Z] 10:24:38     INFO -     3:   0xdfe00a - std::sys_common::backtrace::_print
[task 2020-12-13T10:24:38.495Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:61
[task 2020-12-13T10:24:38.495Z] 10:24:38     INFO -     4:   0xdfe00a - std::sys_common::backtrace::print
[task 2020-12-13T10:24:38.496Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:48
[task 2020-12-13T10:24:38.496Z] 10:24:38     INFO -     5:   0xdfe00a - std::panicking::default_hook::{{closure}}
[task 2020-12-13T10:24:38.497Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:208
[task 2020-12-13T10:24:38.497Z] 10:24:38     INFO -     6:   0xdfdbb3 - std::panicking::default_hook
[task 2020-12-13T10:24:38.497Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:224
[task 2020-12-13T10:24:38.498Z] 10:24:38     INFO -     7:   0xdfe77e - std::panicking::rust_panic_with_hook
[task 2020-12-13T10:24:38.498Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:577
[task 2020-12-13T10:24:38.498Z] 10:24:38     INFO -     8:   0xd02f14 - std::panicking::begin_panic::{{closure}}<str*>
[task 2020-12-13T10:24:38.499Z] 10:24:38     INFO -                         at Z:\task_1607853069\fetches\rustc\lib\rustlib\src\rust\library\std\src\panicking.rs:506
[task 2020-12-13T10:24:38.499Z] 10:24:38     INFO -     9:   0xcfda6d - std::sys_common::backtrace::__rust_end_short_backtrace<closure-0,!>
[task 2020-12-13T10:24:38.499Z] 10:24:38     INFO -                         at Z:\task_1607853069\fetches\rustc\lib\rustlib\src\rust\library\std\src\sys_common\backtrace.rs:153
[task 2020-12-13T10:24:38.500Z] 10:24:38     INFO -    10:   0xd02ee8 - std::panicking::begin_panic<str*>
[task 2020-12-13T10:24:38.500Z] 10:24:38     INFO -                         at Z:\task_1607853069\fetches\rustc\lib\rustlib\src\rust\library\std\src\panicking.rs:505
[task 2020-12-13T10:24:38.501Z] 10:24:38     INFO -    11:   0xd0f0d3 - fog::private::string::{{impl}}::test_get_value
[task 2020-12-13T10:24:38.501Z] 10:24:38     INFO -                         at z:\build\build\src\toolkit\components\glean\api\src\private\string.rs:107
[task 2020-12-13T10:24:38.501Z] 10:24:38     INFO -    12:   0xd0f0d3 - fog::private::string::StringMetric::test_get_value
[task 2020-12-13T10:24:38.502Z] 10:24:38     INFO -                         at z:\build\build\src\toolkit\components\glean\api\src\private\string.rs:67
[task 2020-12-13T10:24:38.503Z] 10:24:38     INFO -    13:   0xd0f0d3 - fog::private::string::test::string_ipc::{{closure}}
[task 2020-12-13T10:24:38.503Z] 10:24:38     INFO -                         at z:\build\build\src\toolkit\components\glean\api\src\private\string.rs:179
[task 2020-12-13T10:24:38.503Z] 10:24:38     INFO -    14:   0xd0f0d3 - std::panicking::try::do_call
[task 2020-12-13T10:24:38.504Z] 10:24:38     INFO -                         at Z:\task_1607853069\fetches\rustc\lib\rustlib\src\rust\library\std\src\panicking.rs:381
[task 2020-12-13T10:24:38.504Z] 10:24:38     INFO -    15:   0xd0f0d3 - std::panicking::try
[task 2020-12-13T10:24:38.505Z] 10:24:38     INFO -                         at Z:\task_1607853069\fetches\rustc\lib\rustlib\src\rust\library\std\src\panicking.rs:345
[task 2020-12-13T10:24:38.505Z] 10:24:38     INFO -    16:   0xd0f0d3 - std::panic::catch_unwind
[task 2020-12-13T10:24:38.505Z] 10:24:38     INFO -                         at Z:\task_1607853069\fetches\rustc\lib\rustlib\src\rust\library\std\src\panic.rs:382
[task 2020-12-13T10:24:38.505Z] 10:24:38     INFO -    17:   0xd0f0d3 - fog::private::string::test::string_ipc
[task 2020-12-13T10:24:38.506Z] 10:24:38     INFO -                         at z:\build\build\src\toolkit\components\glean\api\src\private\string.rs:178
[task 2020-12-13T10:24:38.506Z] 10:24:38     INFO -    18:   0xd0f0d3 - fog::private::string::test::string_ipc::{{closure}}
[task 2020-12-13T10:24:38.507Z] 10:24:38     INFO -                         at z:\build\build\src\toolkit\components\glean\api\src\private\string.rs:158
[task 2020-12-13T10:24:38.507Z] 10:24:38     INFO -    19:   0xd0f0d3 - core::ops::function::FnOnce::call_once<closure-0,tuple<>>
[task 2020-12-13T10:24:38.508Z] 10:24:38     INFO -                         at Z:\task_1607853069\fetches\rustc\lib\rustlib\src\rust\library\core\src\ops\function.rs:227
[task 2020-12-13T10:24:38.508Z] 10:24:38     INFO -    20:   0xd76903 - core::ops::function::FnOnce::call_once
[task 2020-12-13T10:24:38.509Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\core\src\ops\function.rs:227
[task 2020-12-13T10:24:38.509Z] 10:24:38     INFO -    21:   0xd76903 - test::__rust_begin_short_backtrace<fn()>
[task 2020-12-13T10:24:38.510Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\test\src\lib.rs:516
[task 2020-12-13T10:24:38.510Z] 10:24:38     INFO -    22:   0xd74b50 - alloc::boxed::{{impl}}::call_once
[task 2020-12-13T10:24:38.510Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\alloc\src\boxed.rs:1042
[task 2020-12-13T10:24:38.511Z] 10:24:38     INFO -    23:   0xd74b50 - std::panic::{{impl}}::call_once
[task 2020-12-13T10:24:38.511Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panic.rs:308
[task 2020-12-13T10:24:38.512Z] 10:24:38     INFO -    24:   0xd74b50 - std::panicking::try::do_call
[task 2020-12-13T10:24:38.512Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panicking.rs:381
[task 2020-12-13T10:24:38.513Z] 10:24:38     INFO -    25:   0xd74b50 - std::panicking::try
[task 2020-12-13T10:24:38.513Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panicking.rs:345
[task 2020-12-13T10:24:38.514Z] 10:24:38     INFO -    26:   0xd74b50 - std::panic::catch_unwind
[task 2020-12-13T10:24:38.514Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panic.rs:382
[task 2020-12-13T10:24:38.515Z] 10:24:38     INFO -    27:   0xd74b50 - test::run_test_in_process
[task 2020-12-13T10:24:38.515Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\test\src\lib.rs:543
[task 2020-12-13T10:24:38.516Z] 10:24:38     INFO -    28:   0xd74b50 - test::run_test::run_test_inner::{{closure}}
[task 2020-12-13T10:24:38.516Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\test\src\lib.rs:449
[task 2020-12-13T10:24:38.517Z] 10:24:38     INFO -    29:   0xd4c9d5 - std::sys_common::backtrace::__rust_begin_short_backtrace<closure-0,tuple<>>
[task 2020-12-13T10:24:38.517Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\sys_common\backtrace.rs:137
[task 2020-12-13T10:24:38.517Z] 10:24:38     INFO -    30:   0xd4c9d5 - std::sys_common::backtrace::__rust_begin_short_backtrace<closure-0,tuple<>>
[task 2020-12-13T10:24:38.518Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\sys_common\backtrace.rs:137
[task 2020-12-13T10:24:38.518Z] 10:24:38     INFO -    31:   0xd52e67 - std::thread::{{impl}}::spawn_unchecked::{{closure}}::{{closure}}
[task 2020-12-13T10:24:38.519Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\thread\mod.rs:464
[task 2020-12-13T10:24:38.519Z] 10:24:38     INFO -    32:   0xd52e67 - std::panic::{{impl}}::call_once
[task 2020-12-13T10:24:38.520Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panic.rs:308
[task 2020-12-13T10:24:38.520Z] 10:24:38     INFO -    33:   0xd52e67 - std::panicking::try::do_call
[task 2020-12-13T10:24:38.520Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panicking.rs:381
[task 2020-12-13T10:24:38.521Z] 10:24:38     INFO -    34:   0xd52e67 - std::panicking::try
[task 2020-12-13T10:24:38.521Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panicking.rs:345
[task 2020-12-13T10:24:38.522Z] 10:24:38     INFO -    35:   0xd52e67 - std::panic::catch_unwind
[task 2020-12-13T10:24:38.522Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\panic.rs:382
[task 2020-12-13T10:24:38.522Z] 10:24:38     INFO -    36:   0xd52e67 - std::thread::{{impl}}::spawn_unchecked::{{closure}}
[task 2020-12-13T10:24:38.523Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\std\src\thread\mod.rs:463
[task 2020-12-13T10:24:38.523Z] 10:24:38     INFO -    37:   0xd52e67 - core::ops::function::FnOnce::call_once<closure-0,tuple<>>
[task 2020-12-13T10:24:38.524Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\core\src\ops\function.rs:227
[task 2020-12-13T10:24:38.524Z] 10:24:38     INFO -    38:   0xe075aa - alloc::boxed::{{impl}}::call_once
[task 2020-12-13T10:24:38.525Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\alloc\src\boxed.rs:1042
[task 2020-12-13T10:24:38.525Z] 10:24:38     INFO -    39:   0xe075aa - alloc::boxed::{{impl}}::call_once
[task 2020-12-13T10:24:38.525Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\library\alloc\src\boxed.rs:1042
[task 2020-12-13T10:24:38.525Z] 10:24:38     INFO -    40:   0xe075aa - std::sys::windows::thread::{{impl}}::new::thread_start
[task 2020-12-13T10:24:38.526Z] 10:24:38     INFO -                         at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys\windows\thread.rs:56
[task 2020-12-13T10:24:38.526Z] 10:24:38     INFO -    41: 0x77497c04 - BaseThreadInitThunk
[task 2020-12-13T10:24:38.527Z] 10:24:38     INFO -    42: 0x77d0ab8f - RtlInitializeExceptionChain
[task 2020-12-13T10:24:38.527Z] 10:24:38     INFO -    43: 0x77d0ab5a - RtlInitializeExceptionChain
[task 2020-12-13T10:24:38.527Z] 10:24:38     INFO -  thread 'private::string::test::string_ipc' panicked at 'called `Option::unwrap()` on a `None` value', toolkit\components\glean\api\src\private\string.rs:187:75

[task 2020-12-13T10:24:38.674Z] 10:24:38     INFO -    41: 0x77d0ab5a - RtlInitializeExceptionChain
[task 2020-12-13T10:24:38.675Z] 10:24:38     INFO -  failures:
[task 2020-12-13T10:24:38.675Z] 10:24:38     INFO -      private::string::test::string_ipc
[task 2020-12-13T10:24:38.675Z] 10:24:38     INFO -      private::timespan::test::smoke_test_timespan
[task 2020-12-13T10:24:38.675Z] 10:24:38     INFO -      private::timespan::test::timespan_ipc
[task 2020-12-13T10:24:38.676Z] 10:24:38     INFO -      private::uuid::test::sets_uuid_value
[task 2020-12-13T10:24:38.676Z] 10:24:38     INFO -      private::uuid::test::uuid_ipc
[task 2020-12-13T10:24:38.676Z] 10:24:38     INFO -  test result: FAILED. 12 passed; 5 failed; 12 ignored; 0 measured; 0 filtered out
[task 2020-12-13T10:24:38.676Z] 10:24:38     INFO -       Running `z:/build/workspace/obj-build\i686-pc-windows-msvc\release\deps\qcms-0d1772f953a6675e.exe`

[task 2020-12-13T10:24:38.684Z] 10:24:38     INFO -  error: test failed, to rerun pass '-p fog --lib'
[task 2020-12-13T10:24:38.684Z] 10:24:38     INFO -  z:/build/build/src/config/makefiles/rust.mk:358: recipe for target 'force-cargo-test-run' failed
[task 2020-12-13T10:24:38.685Z] 10:24:38     INFO -  mozmake.EXE[1]: *** [force-cargo-test-run] Error 101
[task 2020-12-13T10:24:38.685Z] 10:24:38     INFO -  mozmake.EXE[1]: Leaving directory 'z:/build/workspace/obj-build/toolkit/library/rust'
[task 2020-12-13T10:24:38.685Z] 10:24:38     INFO -  z:/build/build/src/config/recurse.mk:99: recipe for target 'toolkit/library/rust/rusttests' failed
[task 2020-12-13T10:24:38.686Z] 10:24:38     INFO -  mozmake.EXE: *** [toolkit/library/rust/rusttests] Error 2
[task 2020-12-13T10:24:38.690Z] 10:24:38     INFO -  7 compiler warnings present.
[task 2020-12-13T10:24:38.799Z] 10:24:38     INFO -  WARNING | IO Completion Port failed to signal process shutdown
[task 2020-12-13T10:24:38.799Z] 10:24:38     INFO -  Parent process 3688 exited with children alive:
[task 2020-12-13T10:24:38.799Z] 10:24:38     INFO -  PIDS: 3432
[task 2020-12-13T10:24:38.800Z] 10:24:38     INFO -  Attempting to kill them, but no guarantee of success
[task 2020-12-13T10:24:38.800Z] 10:24:38     INFO -   Config object not found by mach.
[task 2020-12-13T10:24:38.800Z] 10:24:38     INFO -  Configure complete!
[task 2020-12-13T10:24:38.800Z] 10:24:38     INFO -  Be sure to run |mach build| to pick up any changes
[task 2020-12-13T10:24:38.801Z] 10:24:38     INFO -  Hey! Builds initiated with `mach build $A_SPECIFIC_TARGET` may not always work, even if the code being built is correct. Consider doing a bare `mach build` instead.```

Chris, could this be related to changes in Bug 1673642. It looks to have started around the time it was first landed here https://bugzilla.mozilla.org/show_bug.cgi?id=1673642#c8. Treeherder link.
Failures history: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2020-11-13&endday=2020-12-13&tree=trunk&bug=1682165
Thank you in advance for looking.

Flags: needinfo?(chutten)
Whiteboard: [retriggered][stockwell needswork:owner]

(not chris, but familiar with that part of the code base)

This was addressed in bug 1680789. Let's keep this open for a week to see if these infrequent intermittens are going away.

Flags: needinfo?(chutten)

Jan-Erik, thanks for looking. I filed this because these kind of bustages are still happening even after bug 1680789 was merged to central and thus deemed as fixed.

Failure log from 15th December: https://treeherder.mozilla.org/logviewer?job_id=324511926&repo=autoland&lineNumber=14302

The failure rate is not high with 7 failures since the 10th of December: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2020-12-08&endday=2020-12-15&tree=trunk&bug=1682165

Assignee: nobody → jrediger
Priority: P5 → P1

test_get_value in those "child" tests triggers a panic, which of
course still unwinds and therefore poisons the Glean mutex.
catch_unwind only catches the panic after that.

Now why this would only result intermittenly in test failures?
I don't really know.

(In reply to Jan-Erik Rediger [:janerik] from comment #8)

Created attachment 9196072 [details]
Bug 1682165 - Don't trigger a panic in test code. r?chutten!

test_get_value in those "child" tests triggers a panic, which of
course still unwinds and therefore poisons the Glean mutex.
catch_unwind only catches the panic after that.

Now why this would only result intermittenly in test failures?
I don't really know.

If I had to guess it only poisons the individual Glean inside the test. Maybe test ordering determines whether we try to access that specific Glean instance inside another test later?

(In reply to Chris H-C :chutten from comment #9)

If I had to guess it only poisons the individual Glean inside the test. Maybe test ordering determines whether we try to access that specific Glean instance inside another test later?

but that doesn't explain why it would sometimes work within a single test (e.g. string::string_ipc). the "sub-process" context runs on the same thread, no async-ness to deal with. How can its panic not be seen by the test_get_value right after?

Pushed by jrediger@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/147fa757c671 Don't trigger a panic in test code. r=chutten
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → 86 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: