1170664 - Include stack traces for process crashes

Status: NEW

(Testing :: Mochitest, defect)

Description

[Eric Rahm [:erahm]]

Logviewer currently shows me that there was a process crash, what the assertion was, but doesn't include the stack trace. This would be very useful for quickly triaging bugs.

Example output from a recent crash during a mochitest e10s run [1]:

> 4132 16:29:39 INFO - DeviceRunner TEST-UNEXPECTED-FAIL | dom/media/test/test_imagecapture.html | application timed out after 450.0 seconds with no output
> 4133 16:29:39 WARNING - PROCESS-CRASH | dom/media/test/test_imagecapture.html | application crashed [@ mozilla::detail::log_test]
> 6161 16:31:01 ERROR - Return code: 241
> 6163 16:31:01 ERROR - No tests run or test summary not found
> 18104 16:31:09 INFO - 06-01 23:21:42.860 F/MOZ_Assert( 846): Assertion failure: level != LogLevel::Disabled, at ../../dist/include/mozilla/Logging.h:49
> 18175 16:31:09 ERROR - Return code: 1

[1] https://treeherder.mozilla.org/logviewer.html#?job_id=10331714&repo=mozilla-inbound

Comment 1

[Jonathan Griffin (:jgriffin)]

Ted, is this the same as bug 1143547?

Comment 2

[Eric Rahm [:erahm]]

Note: there was a stack trace in the raw log (waaaaay further down from the assert). Hence my desire to have it in the quick view.

Comment 3

[Jonathan Griffin (:jgriffin)]

I see one stack trace in the log, immediately after the crash, although it doesn't appear in the quick view.  I don't see a stack trace for the assertion.  Can you point to what you mean?

Comment 4

[Eric Rahm [:erahm]]

I think this is just user error. I got confused by the order of things in the log viewer (crash first, assert later). So I clicked the assert line and didn't see a stack (and then went to the raw log and found the stack trace for the crash caused by the assert).

Now that I go back I see that I can click the PROCESS-CRASH crash line, and lo and behold, there is the stack trace I was looking for. I'm happy to close this invalid unless you think the ordering of the messages is an error.

Comment 5

[Jonathan Griffin (:jgriffin)]

I think the fact that we don't get a stack trace for the MOZ_ASSERT is a bug, but is filed as bug 929128.  I think Treeherder is doing the right thing here, unless we want to start including the stack traces in the quick view.

Comment 6

[(not currently active) Ted Mielczarek]

So this particular case is confusing, but it's because we print the test harness output, then the stack trace for any minidumps we found after the run, and then finally we dump logcat.

so we get:
16:29:39     INFO -  DeviceRunner TEST-UNEXPECTED-FAIL | dom/media/test/test_imagecapture.html | application timed out after 450.0 seconds with no output
16:29:39  WARNING -  PROCESS-CRASH | dom/media/test/test_imagecapture.html | application crashed [@ mozilla::detail::log_test]
<...>
16:31:01     INFO - dumping logcat
16:31:01     INFO - Running command: ['cat', '/builds/slave/test/build/emulator-5554.log']
<...>
16:31:09     INFO -  06-01 23:21:42.860 F/MOZ_Assert(  846): Assertion failure: level != LogLevel::Disabled, at ../../dist/include/mozilla/Logging.h:49

The double-timestamps in the logcat output are especially confusing. The first one is the timestamp from when we dumped logcat to the log, the second is the timestamp from logcat itself! For extra bonus fun, I think the timestamps are either in different timezones (PST vs. UTC) or the emulator clock is just wrong.