Closed Bug 1047599 Opened 10 years ago Closed 9 years ago

Intermittent test_app_install.html,test_navigator_resolve_identity.html,test_bug707564.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED

Categories

(Core Graveyard :: DOM: Apps, defect)

ARM
Android
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: RyanVM, Unassigned)

Details

(Keywords: intermittent-failure)

https://tbpl.mozilla.org/php/getParsedLog.php?id=45066726&tree=Fx-Team

Android 2.3 Emulator fx-team opt test mochitest-7 on 2014-08-01 09:03:57 PDT for push 55f293b3d816
slave: tst-linux64-spot-876

09:54:15     INFO -  22 INFO TEST-START | /tests/dom/datastore/tests/test_app_install.html
09:54:15     INFO -  23 INFO dumping last 2 message(s)
09:54:15     INFO -  24 INFO if you need more context, please use SimpleTest.requestCompleteLog() in your test
09:54:15     INFO -  25 INFO TEST-PASS | /tests/dom/datastore/tests/test_app_install.html | getDataStores exists 
09:54:15     INFO -  26 INFO TEST-PASS | /tests/dom/datastore/tests/test_app_install.html | getDataStores exists and it's a function 
09:54:15     INFO -  27 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_app_install.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_app_install.html:55
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  28 INFO TEST-OK | /tests/dom/datastore/tests/test_app_install.html | took 3845ms
09:54:15     INFO -  29 INFO TEST-START | /tests/dom/datastore/tests/test_arrays.html
09:54:15     INFO -  30 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_arrays.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_arrays.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  31 INFO TEST-OK | /tests/dom/datastore/tests/test_arrays.html | took 2506ms
09:54:15     INFO -  32 INFO TEST-START | /tests/dom/datastore/tests/test_basic.html
09:54:15     INFO -  33 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_basic.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_basic.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  34 INFO TEST-OK | /tests/dom/datastore/tests/test_basic.html | took 2977ms
09:54:15     INFO -  35 INFO TEST-START | /tests/dom/datastore/tests/test_basic_worker.html
09:54:15     INFO -  36 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_basic_worker.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_basic_worker.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  37 INFO TEST-OK | /tests/dom/datastore/tests/test_basic_worker.html | took 3568ms
09:54:15     INFO -  38 INFO TEST-START | /tests/dom/datastore/tests/test_bug1008044.html
09:54:15     INFO -  39 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_bug1008044.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_bug1008044.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  40 INFO TEST-OK | /tests/dom/datastore/tests/test_bug1008044.html | took 2923ms
09:54:15     INFO -  41 INFO TEST-START | /tests/dom/datastore/tests/test_bug924104.html
09:54:15     INFO -  42 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_bug924104.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_bug924104.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  43 INFO TEST-OK | /tests/dom/datastore/tests/test_bug924104.html | took 2573ms
09:54:15     INFO -  44 INFO TEST-START | /tests/dom/datastore/tests/test_bug957086.html
09:54:15     INFO -  45 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_bug957086.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_bug957086.html:23
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  46 INFO TEST-OK | /tests/dom/datastore/tests/test_bug957086.html | took 3436ms
09:54:15     INFO -  47 INFO TEST-START | /tests/dom/datastore/tests/test_bug976311.html
09:54:15     INFO -  48 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_bug976311.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_bug976311.html:23
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  49 INFO TEST-OK | /tests/dom/datastore/tests/test_bug976311.html | took 2996ms
09:54:15     INFO -  50 INFO TEST-START | /tests/dom/datastore/tests/test_bug986056.html
09:54:15     INFO -  51 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_bug986056.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_bug986056.html:27
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  52 INFO TEST-OK | /tests/dom/datastore/tests/test_bug986056.html | took 2982ms
09:54:15     INFO -  53 INFO TEST-START | /tests/dom/datastore/tests/test_certifiedApp.html
09:54:15     INFO -  54 INFO dumping last 3 message(s)
09:54:15     INFO -  55 INFO if you need more context, please use SimpleTest.requestCompleteLog() in your test
09:54:15     INFO -  56 INFO TEST-PASS | /tests/dom/datastore/tests/test_certifiedApp.html | DataStore is not an available interface 
09:54:15     INFO -  57 INFO TEST-PASS | /tests/dom/datastore/tests/test_certifiedApp.html | DataStore is not an available interface 
09:54:15     INFO -  58 INFO TEST-PASS | /tests/dom/datastore/tests/test_certifiedApp.html | getDataStores should not exist 
09:54:15     INFO -  59 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_certifiedApp.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_certifiedApp.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  60 INFO TEST-OK | /tests/dom/datastore/tests/test_certifiedApp.html | took 2767ms
09:54:15     INFO -  61 INFO TEST-START | /tests/dom/datastore/tests/test_changes.html
09:54:15     INFO -  62 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_changes.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_changes.html:29
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  63 INFO TEST-OK | /tests/dom/datastore/tests/test_changes.html | took 2903ms
09:54:15     INFO -  64 INFO TEST-START | /tests/dom/datastore/tests/test_duplicate.html
09:54:15     INFO -  65 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_duplicate.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_duplicate.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  66 INFO TEST-OK | /tests/dom/datastore/tests/test_duplicate.html | took 3171ms
09:54:15     INFO -  67 INFO TEST-START | /tests/dom/datastore/tests/test_keys.html
09:54:15     INFO -  68 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_keys.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_keys.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  69 INFO TEST-OK | /tests/dom/datastore/tests/test_keys.html | took 2757ms
09:54:15     INFO -  70 INFO TEST-START | /tests/dom/datastore/tests/test_oop.html
09:54:15     INFO -  71 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_oop.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_oop.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  72 INFO TEST-OK | /tests/dom/datastore/tests/test_oop.html | took 2665ms
09:54:15     INFO -  73 INFO TEST-START | /tests/dom/datastore/tests/test_oop_events.html
09:54:15     INFO -  74 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_oop_events.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_oop_events.html:23
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  75 INFO TEST-OK | /tests/dom/datastore/tests/test_oop_events.html | took 2914ms
09:54:15     INFO -  76 INFO TEST-START | /tests/dom/datastore/tests/test_readonly.html
09:54:15     INFO -  77 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_readonly.html | Test timed out. 
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  78 INFO TEST-OK | /tests/dom/datastore/tests/test_readonly.html | took 307806ms
09:54:15     INFO -  79 INFO TEST-START | /tests/dom/datastore/tests/test_sync.html
09:54:15     INFO -  80 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_sync.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_sync.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  81 INFO TEST-OK | /tests/dom/datastore/tests/test_sync.html | took 2670ms
09:54:15     INFO -  82 INFO TEST-START | /tests/dom/datastore/tests/test_sync_worker.html
09:54:15     INFO -  83 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_sync_worker.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_sync_worker.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  84 INFO TEST-OK | /tests/dom/datastore/tests/test_sync_worker.html | took 2424ms
09:54:15     INFO -  85 INFO TEST-START | /tests/dom/datastore/tests/test_transactions.html
09:54:15     INFO -  86 INFO TEST-UNEXPECTED-FAIL | /tests/dom/datastore/tests/test_transactions.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED:  at http://mochi.test:8888/tests/dom/datastore/tests/test_transactions.html:22
09:54:15     INFO -  TEST-INFO | expected PASS
09:54:15     INFO -  87 INFO TEST-OK | /tests/dom/datastore/tests/test_transactions.html | took 2589ms
https://tbpl.mozilla.org/php/getParsedLog.php?id=45431212&tree=Mozilla-Inbound

test_navigator_resolve_identity.html 
23   x = navigator.mozApps;

Definitely looks Apps-related from what I can tell.
Summary: Intermittent test_app_install.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED: at http://mochi.test:8888/tests/dom/datastore/tests/test_app_install.html:55 followed by a lot more like it → Intermittent test_app_install.html,test_navigator_resolve_identity.html,test_bug707564.html | uncaught exception - NS_ERROR_FACTORY_NOT_REGISTERED
The cause of this error is almost certainly a failure to load Webapps.js, perhaps much earlier in the process. Unfortunately the mochitest logs don't seem contain information about failures like that, which may happen even before the mochitest framework is loaded. But it should have been visible in the browser console/from nsIConsoleService. I don't know how the logging system works, but one thing the apps team could do to debug this is make sure all failure messages from the console service end up in these log files. gps do you know how that could be accomplished?
Flags: needinfo?(gps)
All the logging foo has been changing recently. Chris Manchester knows as much as anyone at this point.

Chris: This smells to me not like a regression from structured logging, but a feature request for messages of certain level from nsIConsoleService to be included in output. I'm not sure if we have a good mechanism to facilitate that or not (I typically use Log.jsm to log to DumpAppender).
Flags: needinfo?(gps) → needinfo?(cmanchester)
The headache here is sometimes the aggressive suppression/buffering we do to keep log size/noise down, but it looks like we have a special case in runtests.py that means, in general, anything logged to stdout before the first test starts is not suppressed. Things are fundamentally different on android though, so we may be working against different limitations. I would say what we should set up the ConsoleService to log errors to stdout (DumpAppender is probably still state of the art), make sure this is set up early enough to catch our target errors (I'm not sure how to do this reliably), and then ensure whatever's reading stdout knows they should be logged directly.

akachkach, from the perspective of structured logging for android mochitests, does this sound doable? Would anything keep us from logging these errors if they were printed to stdout?
Flags: needinfo?(cmanchester) → needinfo?(akachkach)
As chmanchester said, we don't buffer any log messages until the first test_start message is received. (and by the way: logging buffering is disabled by default locally, it's only activated when using --quiet)

If those log messages are directly dumped to stdout, they should bypass the buffering and be shown directly.
Flags: needinfo?(akachkach)
Inactive; closing (see bug 1180138).
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → WORKSFORME
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.