1045421 - XPCShell failures started up across multiple trees with test_crash_manager.js | test failed (with xpcshell return code: 0), see following log:

Status: RESOLVED FIXED

(Toolkit :: Crash Reporting, defect)

Description

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

This started up this evening. There was a service outage in PHX tonight around the same time this showed up, so it might be related to that.

https://tbpl.mozilla.org/php/getParsedLog.php?id=44760175&tree=Mozilla-Central

18:41:44     INFO -  TEST-PASS | C:\slave\test\build\tests\xpcshell\tests\dom\plugins\test\unit\test_persist_in_prefs.js | test passed (time: 263.000ms)
18:41:44     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\dom\plugins\test\unit\test_plugin_default_state_xpi.js | running test ...
18:41:44     INFO -  TEST-PASS | C:\slave\test\build\tests\xpcshell\tests\dom\plugins\test\unit\test_plugin_default_state_xpi.js | test passed (time: 433.000ms)
18:41:44     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\services\common\tests\unit\test_storageservice_client.js | running test ...
18:41:47     INFO -  TEST-PASS | C:\slave\test\build\tests\xpcshell\tests\services\common\tests\unit\test_storageservice_client.js | test passed (time: 2674.000ms)
18:41:47     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\toolkit\components\crashes\tests\xpcshell\test_crash_manager.js | running test ...
18:41:48  WARNING -  TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\toolkit\components\crashes\tests\xpcshell\test_crash_manager.js | test failed (with xpcshell return code: 0), see following log:
18:41:48     INFO -  >>>>>>>
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 0 pending (2)
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2)
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | running event loop



LATER



18:41:48     INFO -  Creating directory: c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqo1tx7\\dummy-dir-41
18:41:48     INFO -  Creating directory: c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqo1tx7\\dummy-dir-42
18:41:48     INFO -  Creating directory: c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqo1tx7\\dummy-dir-43
18:41:48     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/toolkit/components/crashes/tests/xpcshell/test_crash_manager.js | [test_prune_old : 174] 2 == 2
18:41:48     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/toolkit/components/crashes/tests/xpcshell/test_crash_manager.js | [test_prune_old : 179] Old crash has been pruned. - 1 == 1
18:41:48     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/toolkit/components/crashes/tests/xpcshell/test_crash_manager.js | [test_prune_old : 182] Proper crash was pruned. - "id2" == "id2"
18:41:48     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/toolkit/components/crashes/tests/xpcshell/test_crash_manager.js | [test_prune_old : 188] 0 == 0
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 11 pending (2)
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | test test_prune_old finished (2)
18:41:48     INFO -  TEST-INFO | C:/slave/test/build/tests/xpcshell/tests/toolkit/components/crashes/tests/xpcshell/test_crash_manager.js | Starting test_schedule_maintenance
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | test test_schedule_maintenance pending (2)
18:41:48     INFO -  Creating directory: c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqo1tx7\\dummy-dir-45
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 11 finished (2)
18:41:48     INFO -  Creating directory: c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqo1tx7\\dummy-dir-46
18:41:48     INFO -  Creating directory: c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqo1tx7\\dummy-dir-47
18:41:48     INFO -  Creating directory: c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqo1tx7\\dummy-dir-48
18:41:48  WARNING -  TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/toolkit/components/crashes/tests/xpcshell/test_crash_manager.js | 0 == 1 - See following stack:
18:41:48     INFO -      C:/slave/test/build/tests/xpcshell/tests/toolkit/components/crashes/tests/xpcshell/test_crash_manager.js:test_schedule_maintenance:200
18:41:48     INFO -      _run_next_test@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:1308:9
18:41:48     INFO -      do_execute_soon/<.run@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:570:9
18:41:48     INFO -      _do_main@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:191:5
18:41:48     INFO -      _execute_test@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:405:5
18:41:48     INFO -      @-e:1:1
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
18:41:48  WARNING -  TEST-UNEXPECTED-FAIL | C:\\slave\\test\\build\\tests\\xpcshell\\head.js | Unexpected exception 2147500036
18:41:48     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
18:41:48     INFO -  <<<<<<<






Not sure at this point if it'll just go away on its own with new builds.

Comment 1

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Test disabled in https://hg.mozilla.org/mozilla-central/rev/56efa7ae8500 until gps can take a look at it.

Comment 2

[Ryan VanderMeulen [:RyanVM]]

test_schedule_maintenance was added by gps in bug 875562. We've already been able to reproduce these on Aurora33 and Beta32, and I have no reason to believe we couldn't hit this on esr31 and b2g30 as well. Some sort of timebomb in the test?

Comment 3

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Pushed to aurora and beta with a corrected bug number in the commit message (trunk trees had it as bug 1045419):

https://hg.mozilla.org/mozilla-central/raw-rev/56efa7ae8500
https://hg.mozilla.org/releases/mozilla-beta/rev/6782bc9ae760

I don't have the esr or b2g trees cloned at the moment, but Ryan wants this to go to ESR31 and b2g30, so I'll needinfo him so he can do it in the morning.

Comment 4

[Ryan VanderMeulen [:RyanVM]]

As expected, it's perma-failing on 30+

https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/6782bc9ae760
https://hg.mozilla.org/releases/mozilla-esr31/rev/29505feecd98
https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/eaadcd59e65a

Comment 5

[Gregory Szorc [:gps]]

Attachment: crash-manager.patch

There was a hard-coded date in test_crash_manager.js of around August 3,
2013. This meant that about a year later we would start to run into
boundary issues since we weren't wrapping Date.now() inside
CrashManager.jsm.

It turns out the actual value of DUMMY_DATE doesn't really matter. So,
the test has been changed to produce a value that is reasonably modern.

While I was debugging this, I noticed we're not getting logging in the
tests. So I added that.

Comment 6

[Marco Mucci [:MarcoM]]

Hi Greg, can you assign a point value and mark this bug as either [qa+] or [qa-] for verification.

Comment 7

[Gregory Szorc [:gps]]

It took me about 15 minutes to fix it, so I guess that's a 1?

Comment 8

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8464111 [details] [diff] [review]
crash-manager.patch

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

The date fix looks fine, but see the point on the logging below.

::: toolkit/components/crashes/CrashManagerTest.jsm
@@ +29,5 @@
> +  let log = Log.repository.getLogger("Crashes.CrashManager");
> +  log.level = Log.Level.All;
> +  let appender = new Log.DumpAppender();
> +  appender.level = Log.Level.All;
> +  log.addAppender(appender);

This is fine for xpcshell tests which run each in their own environment, but for e.g. mochitest-browser you'll end up adding an additional DumpAppender per test.
Can we do this better or just have a dump pref for the logging in CrashManager.jsm?

Comment 9

[Gregory Szorc [:gps]]

Comment on attachment 8464111 [details] [diff] [review]
crash-manager.patch

Gah, I think my comment got swallowed.

I think we should land this as-is and worry about the mochitest implications later. We have patches actively landing against CrashManager.jsm and I don't want disabled tests while development is ongoing.

Comment 10

[Georg Fritzsche [:gfritzsche]]

This seems like it isn't too much effort to fix or am i missing something?

Comment 11

[Gregory Szorc [:gps]]

I'll fix it.

Comment 12

[Gregory Szorc [:gps]]

Attachment: p

Prevent double appender.

Comment 13

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8468582 [details] [diff] [review]
p

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

Looks good to me.

Comment 14

[Gregory Szorc [:gps]]

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

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/d5387e9486f1

Comment 16

[Gregory Szorc [:gps]]

[Tracking Requested - why for this release]:

I'm requesting uplift of this test-only change so we can reinstate test coverage of released builds. I don't anticipate anything touching this code to be uplifted to Aurora or earlier. But you never know. This uplift should be harmless.

Comment 17

[Ryan VanderMeulen [:RyanVM]]

test-only changes don't need approval for uplift, just land them a=test-only or set checkin-needed and I'll get it. Note that it'll need to land on b2g30, esr31, beta, and aurora.

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/77f82e775608
https://hg.mozilla.org/releases/mozilla-beta/rev/ac0afa7b1b25
https://hg.mozilla.org/releases/mozilla-esr31/rev/ee9983a19037
https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/9625c431d3a0

Comment 19

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/ac0afa7b1b25

Comment 20

[Gregory Szorc [:gps]]

Thanks for the landing assist, Ryan!