1018895 - AsyncShutdown crashes should output cause-specific failure messages that are TBPL parsable

Status: RESOLVED FIXED

(Toolkit :: Async Tooling, defect)

Description

[Ed Morley [:emorley]]

Broken out from bug 1012924 comment 8.

The current failures result in log output of the form:
https://tbpl.mozilla.org/php/getParsedLog.php?id=40738505&tree=B2g-Inbound
{
...
09:39:44     INFO -  WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"}] Barrier: profile-before-change
09:40:17     INFO -  System JS : ERROR resource://gre/modules/AddonManager.jsm:1137 - NS_ERROR_NOT_INITIALIZED: AddonManager is not initialized
09:40:35     INFO -  ERROR: At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources. Conditions: [{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"},{"name":"Experiments.jsm shutdown","state":"(none)"}] Barrier: profile-before-change
09:40:35     INFO -  [Parent 2447] ###!!! ABORT: file resource://gre/modules/AsyncShutdown.jsm, line 691
09:40:35     INFO -  [Parent 2447] ###!!! ABORT: file resource://gre/modules/AsyncShutdown.jsm, line 691
09:40:36     INFO -  [3058] ###!!! ABORT: Aborting on channel error.: file /builds/slave/b2g-in-l64-0000000000000000000/build/ipc/glue/MessageChannel.cpp, line 1532
09:40:36     INFO -  [3058] ###!!! ABORT: Aborting on channel error.: file /builds/slave/b2g-in-l64-0000000000000000000/build/ipc/glue/MessageChannel.cpp, line 1532
09:40:36     INFO -  TEST-INFO | Main app process: killed by SIGSEGV
09:40:36  WARNING -  TEST-UNEXPECTED-FAIL | Shutdown | application terminated with exit code 11
}

The TBPL failure excerpt shows:
{
[Parent 2447] ###!!! ABORT: file resource://gre/modules/AsyncShutdown.jsm, line 691
[Parent 2447] ###!!! ABORT: file resource://gre/modules/AsyncShutdown.jsm, line 691
[3058] ###!!! ABORT: Aborting on channel error.: file /builds/slave/b2g-in-l64-0000000000000000000/build/ipc/glue/MessageChannel.cpp, line 1532
[3058] ###!!! ABORT: Aborting on channel error.: file /builds/slave/b2g-in-l64-0000000000000000000/build/ipc/glue/MessageChannel.cpp, line 1532
TEST-UNEXPECTED-FAIL | Shutdown | application terminated with exit code 11
PROCESS-CRASH | Shutdown | application crashed [@ mozalloc_abort(char const*)]
}

...but this is generic for all AsyncShutdown crashes.

TBPL's regex are here:
https://hg.mozilla.org/webtools/tbpl/file/tip/php/inc/GeneralErrorFilter.php

However rather than adding to that list, I believe we should change the log.error() line to read:
{
TEST-UNEXPECTED-FAIL | Experiments.jsm shutdown | At least one completion condition failed to complete within a reasonable amount of time.
}

...or else add the failure reason to the ABORT string.

David, would you mind taking a look at this? :-)

Comment 1

[Ed Morley [:emorley]]

(In reply to Ed Morley [:edmorley UTC+0] from comment #0)
> However rather than adding to that list, I believe we should change the
> log.error() line

I mean err(msg):
http://hg.mozilla.org/mozilla-central/file/d6fccb7c56a8/toolkit/modules/AsyncShutdown.jsm#l678
http://hg.mozilla.org/mozilla-central/file/d6fccb7c56a8/toolkit/modules/AsyncShutdown.jsm#l103

Comment 2

[David Teller [:Yoric] (please use "needinfo")]

I'll tweak things a little, as discussed over IRC.

Comment 3

[David Teller [:Yoric] (please use "needinfo")]

Attachment: Make the output of AsyncShutdown easier to parse by tbpl

This patch makes the following changes:
- calls to `addBlocker` now capture the filename/lineNumber of the caller, which is then reused as the filename/lineNumber during any crash;
- in the crash message, the explanations common to all AsyncShutdown timeouts appear at the end, with the meaningful stuff appearing first.

Comment 4

[Nathan Froyd [:froydnj]]

Comment on attachment 8432468 [details] [diff] [review]
Make the output of AsyncShutdown easier to parse by tbpl

Review of attachment 8432468 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with the below addressed.

::: toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js
@@ +28,5 @@
>    do_print("after crash: " + extra.AsyncShutdownTimeout);
>    let info = JSON.parse(extra.AsyncShutdownTimeout);
> +  equal(info.phase, "testing-async-shutdown-crash");
> +  equal(info.conditions[0].name, "A blocker that is never satisfied");
> +  equal(info.conditions[0].filename, "-e"); // Name of the file used to spawn the process

Maybe add an "in this case, the -e argument to the xpcshell test runner" or somesuch?

::: toolkit/modules/AsyncShutdown.jsm
@@ +685,5 @@
>  	  let state = this.state;
>  
> +          // If you change the following message, please make sure
> +          // that any meaningful information appears first. This helps
> +          // automatically sort oranges.

I guess you mean that things like the topic and the state appear earlier in the message rather than later?  If so, could you expand a little bit on "meaningful information"?  I think saying "earlier in the message" would be better than saying "first".

Comment 5

[Ed Morley [:emorley]]

Comment on attachment 8432468 [details] [diff] [review]
Make the output of AsyncShutdown easier to parse by tbpl

Review of attachment 8432468 [details] [diff] [review]:
-----------------------------------------------------------------

Looks great from a TBPL POV - thank you very much for doing this :-)

Comment 6

[David Teller [:Yoric] (please use "needinfo")]

Attachment: Make the output of AsyncShutdown easier to parse by tbpl, v2

Applied feedback. Also took the opportunity to squeeze in one more test.

Comment 7

[David Teller [:Yoric] (please use "needinfo")]

Try: https://tbpl.mozilla.org/?tree=Try&rev=06b11b7f8119

Comment 8

[David Teller [:Yoric] (please use "needinfo")]

Sorry, wrong Try link
Try: https://tbpl.mozilla.org/?tree=Try&rev=6b212b0e007c

Comment 9

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/993e88c0c67e

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/993e88c0c67e

Comment 11

[Ed Morley [:emorley]]

The output for this looks like:
19:40:18     INFO -  ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"Experiments.jsm shutdown","state":"(none)","filename":"resource://app/modules/experiments/Experiments.jsm","lineNumber":409},{"name":"Experiments.jsm shutdown","state":"(none)","filename":"resource://app/modules/experiments/Experiments.jsm","lineNumber":409},{"name":"Experiments.jsm shutdown","state":"(none)","filename":"resource://app/modules/experiments/Experiments.jsm","lineNumber":409},{"name":"Experiments.jsm shutdown","state":"(none)","filename":"resource://app/modules/experiments/Experiments.jsm","lineNumber":409},{"name":"Experiments.jsm shutdown","state":"(none)","filename":"resource://app/modules/experiments/Experiments.jsm","lineNumber":409}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.

Is it intended that there are multiple identical conditions listed?

Comment 12

[David Teller [:Yoric] (please use "needinfo")]

Deflecting.

Comment 13

[Benjamin Smedberg]

In the current design of the experiment mochitest-chrome tests, that is expected. It would be nice to fix that but that's mainly low-value code cleanup.