Closed Bug 1018895 Opened 6 years ago Closed 6 years ago

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

Categories

(Toolkit :: Async Tooling, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla32

People

(Reporter: emorley, Assigned: Yoric)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 1 obsolete file)

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? :-)
Flags: needinfo?(dteller)
Summary: AsyncShutdown crashes should output cause-specific TBPL parsable failure messages → AsyncShutdown crashes should output cause-specific failure messages that are TBPL parsable
(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
Depends on: 1018910
I'll tweak things a little, as discussed over IRC.
Flags: needinfo?(dteller)
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.
Assignee: nobody → dteller
Attachment #8432468 - Flags: review?(nfroyd)
Attachment #8432468 - Flags: review?(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]:
-----------------------------------------------------------------

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".
Attachment #8432468 - Flags: review?(nfroyd) → review+
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 :-)
Attachment #8432468 - Flags: review?(emorley) → review+
Applied feedback. Also took the opportunity to squeeze in one more test.
Attachment #8432468 - Attachment is obsolete: true
Attachment #8433160 - Flags: review+
https://hg.mozilla.org/integration/fx-team/rev/993e88c0c67e
Flags: in-testsuite+
Keywords: checkin-needed
Whiteboard: [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/993e88c0c67e
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → mozilla32
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?
Flags: needinfo?(dteller)
Deflecting.
Flags: needinfo?(dteller) → needinfo?(benjamin)
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.
Flags: needinfo?(benjamin)
Blocks: 1018910
No longer depends on: 1018910
Depends on: 1035773
You need to log in before you can comment on or make changes to this bug.