986261 - Telemetry experiments unit tests hang when they fail

Status: RESOLVED FIXED

(Firefox Health Report Graveyard :: Client: Desktop, defect)

Description

[Gregory Szorc [:gps]]

I'm writing xpcshell tests for bug 974024 and I noticed that xpcshell tests can hang when a test fails using the current test pattern:

add_task(function* () {
  let e = let experiments = new Experiments.Experiments(gPolicy);

  Assert.ok(false);

  yield experiments.uninit();
  yield removeCacheFile();
});

I haven't tracked down why. I do know putting the 2 cleanup lines inside a finally block doesn't fix things.

This is potentially a deadlock in experiments code that could prevent application shutdown. So, chaining up to the tracking bug.

Even if it's test-only, this is still a moderate issue: hanging tests are very not cool.

Partial output from test follows.

0:03.09 OS Controller Received message from worker {"id":19}
 0:03.09
 0:03.09 TEST-INFO | (xpcshell/head.js) | test run_next_test 2 pending (2)
 0:03.09
 0:03.09 TEST-INFO | (xpcshell/head.js) | test test_getExperiments finished (2)
 0:03.09 TEST-INFO | /Users/gps/src/firefox/obj-firefox.noindex/_tests/xpcshell/browser/experiments/test/xpcshell/test_api.js | Starting test_lastActiveToday
 0:03.09
 0:03.09 TEST-INFO | (xpcshell/head.js) | test test_lastActiveToday pending (2)
 0:03.09 1395362345507	Browser.Experiments	TRACE	enabled=true, true
 0:03.09 1395362345507	Browser.Experiments	TRACE	enabled=true, true
 0:03.10
 0:03.10 TEST-UNEXPECTED-FAIL | /Users/gps/src/firefox/obj-firefox.noindex/_tests/xpcshell/browser/experiments/test/xpcshell/test_api.js | false == true - See following stack:
JS frame :: /Users/gps/src/firefox/obj-firefox.noindex/_tests/xpcshell/browser/experiments/test/xpcshell/test_api.js :: test_lastActiveToday :: line 271
JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 282
JS frame :: resource://gre/modules/Task.jsm :: TaskImpl :: line 247
JS frame :: resource://gre/modules/Task.jsm :: createAsyncFunction/asyncFunction :: line 224
JS frame :: resource://gre/modules/Task.jsm :: Task_spawn :: line 139
JS frame :: /Users/gps/src/firefox/testing/xpcshell/head.js :: _run_next_test :: line 1407
JS frame :: /Users/gps/src/firefox/testing/xpcshell/head.js :: do_execute_soon/<.run :: line 508
JS frame :: /Users/gps/src/firefox/testing/xpcshell/head.js :: _do_main :: line 174
JS frame :: /Users/gps/src/firefox/testing/xpcshell/head.js :: _execute_test :: line 378
JS frame :: -e :: <TOP_LEVEL> :: line 1
native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
 0:03.10
 0:03.10 TEST-INFO | (xpcshell/head.js) | exiting test
 0:03.10
 0:03.10 TEST-INFO | (xpcshell/head.js) | test run_next_test 2 finished (2)
 0:03.10 OS Controller Posting message {"fun":"read","args":[{"string":"/var/folders/20/0m2k6lq56kdf4q_kdgzmhjkw0000gn/T/tmpTs_JrY/experiments.json"},{"compression":"lz4"},{"compression":"lz4"}],"id":20}
 0:03.10 OS Controller Message posted
 0:03.10 1395362345511	DeferredSave.extensions.json	DEBUG	Starting write
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 1395362345512	addons.manager	DEBUG	shutdown
 0:03.10 1395362345513	addons.xpi	DEBUG	shutdown
 0:03.10 1395362345513	addons.xpi-utils	DEBUG	shutdown
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 OS Controller Received message from worker {"fail":{"operation":"open","unixErrno":2,"path":"/var/folders/20/0m2k6lq56kdf4q_kdgzmhjkw0000gn/T/tmpTs_JrY/experiments.json"},"id":20}
 0:03.10 OS Controller Posting message {"fun":"remove","args":[{"string":"/var/folders/20/0m2k6lq56kdf4q_kdgzmhjkw0000gn/T/tmpTs_JrY/experiments.json"}],"id":21}
 0:03.10 OS Controller Message posted
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.10 OS Controller Received message from worker {"id":21}
 0:03.10 OS Controller Posting message {"fun":"writeAtomic","args":[{"string":"/var/folders/20/0m2k6lq56kdf4q_kdgzmhjkw0000gn/T/tmpTs_JrY/extensions.json"},{"string":"{\\"schemaVersion\\":16,\\"addons\\":[]}"},{"tmpPath":{"string":"/var/folders/20/0m2k6lq56kdf4q_kdgzmhjkw0000gn/T/tmpTs_JrY/extensions.json.tmp"}}],"id":22}
 0:03.10 OS Controller Message posted
 0:03.10
 0:03.10 TEST-UNEXPECTED-FAIL | /Users/gps/src/firefox/testing/xpcshell/head.js | Unexpected exception 2147500036
 0:03.10
 0:03.11 TEST-INFO | (xpcshell/head.js) | exiting test
 0:03.11 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.11 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.11 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.11 [400] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/gps/src/firefox/dom/base/Console.cpp, line 317
 0:03.11 OS Controller Received message from worker {"ok":32,"id":22}
 0:03.11 1395362345520	DeferredSave.extensions.json	DEBUG	Write succeeded
 0:03.11 1395362345520	addons.xpi	DEBUG	Notifying XPI shutdown observers
 0:03.11 1395362345521	addons.manager	DEBUG	Async provider shutdown done
 0:03.11
 0:03.11 TEST-INFO | /Users/gps/src/firefox/obj-firefox.noindex/_tests/xpcshell/browser/experiments/test/xpcshell/test_api.js -> file:///Users/gps/src/firefox/obj-firefox.noindex/_tests/xpcshell/toolkit/mozapps/extensions/test/xpcshell/head_addons.js | "gXPISaveError set to: null"

Comment 1

[Georg Fritzsche [:gfritzsche]]

It is actually missing shutdown of the FHR reporter, which is in the last scheduled test task, which is skipped on failure.

Just adding |do_register_cleanup(() => gReporter._shutdown())| works, but i'm not sure if we can rely on async cleanup operations being waited upon.

Comment 2

[Georg Fritzsche [:gfritzsche]]

(In reply to Georg Fritzsche [:gfritzsche] from comment #1)
> Just adding |do_register_cleanup(() => gReporter._shutdown())| works, but
> i'm not sure if we can rely on async cleanup operations being waited upon.

Per [1] shutdown can prevent completion, i asked [2] on the issue here.

[1] https://ask.mozilla.org/question/349/do-promisestasks-run-to-completion-if-nobody-waits-for-them/
[2] https://ask.mozilla.org/question/376/how-to-properly-do-async-cleanup-in-xpcshell-tests/

Comment 3

[Gregory Szorc [:gps]]

This is why FHR has a synchronous _shutdown() API that spins the event loop. If you stuff it inside a finally {} in an add_task() xpcshell test, it does the right thing.

The xpcshell harness (and all other harnesses really) need a better API for performing post-test tasks. Read https://groups.google.com/d/msg/mozilla.dev.platform/14ER9uMe8Dw/6fukwFeXNAkJ.

Comment 4

[Georg Fritzsche [:gfritzsche]]

Attachment: Fix test cleanup

Actually |AbstractHealthReporter._shutdown()| waits on shutdown [1], so just registering a cleanup function here is fine for this specific case.

Per ask.mozilla.org i filed bug 988844 to fix the async cleanup situation for xpcshell.

[1] http://hg.mozilla.org/mozilla-central/annotate/441f5fd256e2/services/healthreport/healthreporter.jsm#l634%3C/p%3E

Comment 5

[Georg Fritzsche [:gfritzsche]]

(In reply to Gregory Szorc [:gps] from comment #3)
> This is why FHR has a synchronous _shutdown() API that spins the event loop.

Right, that's pretty awkward - we should at least move the awkwardness to xpcshell :)

Comment 6

[:Felipe Gomes (needinfo for replies!)]

Comment on attachment 8397827 [details] [diff] [review]
Fix test cleanup

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

Why can removeCacheFile be removed from the cleanup task?

Comment 7

[Georg Fritzsche [:gfritzsche]]

(In reply to :Felipe Gomes from comment #6)
> Why can removeCacheFile be removed from the cleanup task?

Because each xpcshell-test run gets its own (temporary) profile directory, so we don't actually have problems like stale state between browser-chrome tests.

Comment 8

[Georg Fritzsche [:gfritzsche]]

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

Comment 9

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

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