863311 - Add test function names to "Test pending" / "Test complete" messages

Status: RESOLVED FIXED

(Testing :: XPCShell Harness, defect)

Description

[:Irving Reid (No longer working on Firefox)]

Attachment: Add test function name to test pending / test finished messages

While trying to debug a hanging async xpcshell test, I got frustrated enough to implement some extra feedback in do_test_pending() and do_test_finished() to display the name of the test function, so it's easier to see where the test chaining broke down.

This adds an optional parameter to do_test_pending() and do_test_finished() so that tests calling those functions directly can name their pending/finished pairs, and fills in the name with the test function name where available in do_execute_soon() and run_next_test().

run_next_test() includes a pending / finished pair; these are logged as "run_next_test <test-number>".

Example output looks like:

 0:00.27 TEST-INFO | /Users/ireid/tbird/obj/mozilla-central/_tests/xpcshell/toolkit/mozapps/extensions/test/xpcshell/test_blocklistchange.js | running test ...
 0:31.05 TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
 0:31.05 TEST-INFO | (xpcshell/head.js) | test USER_SUPPLIED_STRING pending (2)
 0:31.05 TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2)
 0:31.05 TEST-INFO | (xpcshell/head.js) | running event loop
 0:31.05 TEST-INFO | (xpcshell/head.js) | test run_next_test 0 pending (2)
 0:31.05 TEST-INFO | /Users/ireid/tbird/obj/mozilla-central/_tests/xpcshell/toolkit/mozapps/extensions/test/xpcshell/test_blocklistchange.js | Starting run_app_update_test
 0:31.06 TEST-INFO | (xpcshell/head.js) | test run_app_update_test pending (3)
 0:31.06 TEST-INFO | (xpcshell/head.js) | test run_next_test 0 finished (3)
 0:31.06 TEST-INFO | (xpcshell/head.js) | test app_update_step_1 pending (3)
 0:31.06 TEST-INFO | (xpcshell/head.js) | test app_update_step_1 finished (3)
 0:31.11 TEST-INFO | (xpcshell/head.js) | test run_next_test 1 pending (3)
 0:31.11 TEST-INFO | (xpcshell/head.js) | test run_app_update_test finished (3)
 0:31.11 TEST-INFO | /Users/ireid/tbird/obj/mozilla-central/_tests/xpcshell/toolkit/mozapps/extensions/test/xpcshell/test_blocklistchange.js | Starting run_app_update_schema_test
 0:31.11 TEST-INFO | (xpcshell/head.js) | test run_app_update_schema_test pending (3)
 0:31.11 TEST-INFO | (xpcshell/head.js) | test run_next_test 1 finished (3)
 0:31.18 TEST-INFO | (xpcshell/head.js) | test run_next_test 2 pending (3)
 0:31.18 TEST-INFO | (xpcshell/head.js) | test run_app_update_schema_test finished (3)
 0:31.18 TEST-INFO | /Users/ireid/tbird/obj/mozilla-central/_tests/xpcshell/toolkit/mozapps/extensions/test/xpcshell/test_blocklistchange.js | Starting run_blocklist_update_test
 0:31.18 TEST-INFO | (xpcshell/head.js) | test run_blocklist_update_test pending (3)
 0:31.18 TEST-INFO | (xpcshell/head.js) | test run_next_test 2 finished (3)
 0:31.18 TEST-INFO | (xpcshell/head.js) | test run_blocklist_update_1 pending (3)
 0:31.18 TEST-INFO | (xpcshell/head.js) | test run_blocklist_update_1 finished (3)
 0:31.19 TEST-INFO | (xpcshell/head.js) | test run_blocklist_update_2 pending (3)
 0:31.19 TEST-INFO | (xpcshell/head.js) | test run_blocklist_update_2 finished (3)
...
 0:35.89 TEST-INFO | /Users/ireid/tbird/obj/mozilla-central/_tests/xpcshell/toolkit/mozapps/extensions/test/xpcshell/test_blocklistchange.js | Starting shutdown_httpserver
 0:35.89 TEST-INFO | (xpcshell/head.js) | test shutdown_httpserver pending (3)
 0:35.89 TEST-INFO | (xpcshell/head.js) | test run_next_test 10 finished (3)
 0:35.89 TEST-INFO | (xpcshell/head.js) | test USER_SUPPLIED_STRING finished (2)
 0:35.89 TEST-INFO | (xpcshell/head.js) | test run_next_test 11 pending (2)
 0:35.89 TEST-INFO | (xpcshell/head.js) | test shutdown_httpserver finished (2)
 0:35.89 TEST-INFO | (xpcshell/head.js) | test run_next_test 11 finished (1)
 0:35.89 TEST-INFO | (xpcshell/head.js) | exiting test
 0:35.89 TEST-INFO | (xpcshell/head.js) | 0 check(s) todo

Comment 1

[(not currently active) Ted Mielczarek]

Comment on attachment 739117 [details] [diff] [review]
Add test function name to test pending / test finished messages

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

I've always sort of wondered if we shouldn't make do_test_pending create and return an object, and force callers to pass that to do_test_finished, so we could account for mismatches, or blame the outstanding tests if we timeout. This seems like a good incremental improvement.

::: testing/xpcshell/head.js
@@ +428,5 @@
>    new _Timer(func, Number(delay));
>  }
>  
> +function do_execute_soon(callback, aName) {
> +  let funcName = (aName ? aName : callback.name);

Does this work well in practice or do we have a lot of anonymous functions being used with this?

Comment 2

[:Irving Reid (No longer working on Firefox)]

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #1)

> Does this work well in practice or do we have a lot of anonymous functions
> being used with this?

There are a lot of anonymous functions; at least this gives the option of adding names when you're trying to diagnose a failure. I'll add some text to the https://developer.mozilla.org/en-US/docs/Writing_xpcshell-based_unit_tests#Async_tests documentation to encourage using informative names on test functions.

I spent a bit of time looking into whether we can integrate with bug 433529 to get synthetic names for otherwise anonymous functions, but that information is only exposed through the Debugger and stack trace interfaces right now. If we can get bug 809561 done, we could also use Debugger to get displayName here.

Comment 3

[:Irving Reid (No longer working on Firefox)]

Comment on attachment 739117 [details] [diff] [review]
Add test function name to test pending / test finished messages

https://hg.mozilla.org/integration/mozilla-inbound/rev/be579e9be3e4

Comment 4

[Phil Ringnalda (:philor)]

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