Closed Bug 984274 Opened 6 years ago Closed 6 years ago

Intermittent test_sandbox_permission.html | Test timed out.

Categories

(Core :: Permission Manager, defect)

x86
Gonk (Firefox OS)
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla33
Tracking Status
firefox31 --- wontfix
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: cbook, Assigned: ayang)

References

()

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 11 obsolete files)

2.53 KB, patch
fabrice
: review+
fabrice
: feedback+
Details | Diff | Splinter Review
46 bytes, text/x-github-pull-request
fabrice
: review+
Details | Review
b2g_emulator_vm b2g-inbound opt test mochitest-1 on 2014-03-16 20:29:21 PDT for push 26c82a370b06

slave: tst-linux64-spot-942

https://tbpl.mozilla.org/php/getParsedLog.php?id=36248186&tree=B2g-Inbound

37 INFO TEST-UNEXPECTED-FAIL | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | Test timed out.
The tests are actually passed, but somehow it blocks for a long time before running tests.


09:08:26     INFO -  32 INFO TEST-END | /tests/b2g/components/test/mochitest/test_permission_deny.html | finished in 3554ms
09:08:26     INFO -  33 INFO TEST-START | /tests/b2g/components/test/mochitest/test_sandbox_permission.html
09:08:29     INFO -  ############################### browserElementPanning.js loaded
09:08:29     INFO -  ######################## BrowserElementChildPreload.js loaded
09:08:33     INFO -  *** UTM:SVC TimerManager:notify - notified @mozilla.org/b2g/webapps-update-timer;1
09:08:42     INFO -  LoadPlugin: failed to initialize shared library libXt.so [libXt.so: cannot open shared object file: No such file or directory]
09:08:42     INFO -  LoadPlugin: failed to initialize shared library libXext.so [libXext.so: cannot open shared object file: No such file or directory]
09:08:42     INFO -  LoadPlugin: failed to initialize shared library /usr/lib/mozilla/plugins/libtotem-narrowspace-plugin.so [/usr/lib/mozilla/plugins/libtotem-narrowspace-plugin.so: wrong ELF class: ELFCLASS64]
09:08:42     INFO -  LoadPlugin: failed to initialize shared library /usr/lib/mozilla/plugins/librhythmbox-itms-detection-plugin.so [/usr/lib/mozilla/plugins/librhythmbox-itms-detection-plugin.so: wrong ELF class: ELFCLASS64]
09:08:42     INFO -  LoadPlugin: failed to initialize shared library /usr/lib/mozilla/plugins/libtotem-mully-plugin.so [/usr/lib/mozilla/plugins/libtotem-mully-plugin.so: wrong ELF class: ELFCLASS64]
09:08:42     INFO -  LoadPlugin: failed to initialize shared library /usr/lib/mozilla/plugins/libtotem-cone-plugin.so [/usr/lib/mozilla/plugins/libtotem-cone-plugin.so: wrong ELF class: ELFCLASS64]
09:08:42     INFO -  LoadPlugin: failed to initialize shared library /usr/lib/mozilla/plugins/libtotem-gmp-plugin.so [/usr/lib/mozilla/plugins/libtotem-gmp-plugin.so: wrong ELF class: ELFCLASS64]
09:08:51     INFO -  ###################################### forms.js loaded
09:08:51     INFO -  ############################### browserElementPanning.js loaded
09:08:51     INFO -  ######################## BrowserElementChildPreload.js loaded
09:10:33     INFO -  *** UTM:SVC TimerManager:notify - notified timerID: user-agent-updates-timer
09:10:34     INFO -  *** UTM:SVC TimerManager:registerTimer - id: user-agent-updates-timer
09:13:53     INFO -  34 INFO TEST-INFO | dumping last 11 message(s)
09:13:53     INFO -  35 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
09:13:53     INFO -  36 INFO TEST-INFO | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | request permissions for ["video-capture"]
09:13:53     INFO -  37 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected number of permissions
09:13:53     INFO -  38 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected permission type
09:13:53     INFO -  39 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected permission option
09:13:53     INFO -  40 INFO TEST-INFO | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | request permissions for ["audio-capture","video-capture"]
09:13:53     INFO -  41 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected number of permissions
09:13:53     INFO -  42 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected permission type
09:13:53     INFO -  43 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected permission option
09:13:54     INFO -  44 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected permission type
09:13:54     INFO -  45 INFO TEST-PASS | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | expected permission option
09:13:54     INFO -  46 INFO TEST-INFO | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | request permissions for ["audio-capture"]
09:13:54     INFO -  47 INFO TEST-UNEXPECTED-FAIL | /tests/b2g/components/test/mochitest/test_sandbox_permission.html | Test timed out.
Test harness print out the queued test logs while test is finished/timeout, so the log time doesn't mean anything.

[1] http://dxr.mozilla.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/SimpleTest.js#337
Component: WebRTC → WebRTC: Audio/Video
Can't reproduce it after adding logs. I will try again with a clean build.

https://tbpl.mozilla.org/?tree=Try&rev=89972f692275
This seems to have significantly spiked recently. Can you please take another look? :)
Flags: needinfo?(ayang)
Component: WebRTC: Audio/Video → Permission Manager
My initial attempts to bisect this down appear to be pointing at this merge to m-c:
https://hg.mozilla.org/mozilla-central/pushloghtml?startID=26870&endID=26871

Bob, the test landing from bug 985135 is in there. I'm wondering if we're getting cross-pollution from that or something. I'll try to keep bisecting on inbound to further narrow down the range.
Flags: needinfo?(bobowencode)
Actually, I've now been able to reproduce on an older m-c rev which includes the original patch for bug 985135 instead :P
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #129)
> My initial attempts to bisect this down appear to be pointing at this merge
> to m-c:
> https://hg.mozilla.org/mozilla-central/pushloghtml?startID=26870&endID=26871
> 
> Bob, the test landing from bug 985135 is in there. I'm wondering if we're
> getting cross-pollution from that or something. I'll try to keep bisecting
> on inbound to further narrow down the range.

I'm not familiar with that test, but it's possible.
I'll take a look, not sure how much time I'll have though.
Flags: needinfo?(bobowencode)
Retriggers on m-c are pointing to the below merge as when it started. Bug 985135 definitely stands out there, but I can try to bisect down to a specific push on inbound if it's felt there's any value in doing so.
https://hg.mozilla.org/mozilla-central/pushloghtml?startID=26867&endID=26868
this is now getting close to perma/very frequent orange
It is easy to reproduce on emulator with audio+video gUM request.

It asserts at http://dxr.mozilla.org/mozilla-central/source/dom/camera/GonkCameraControl.cpp?from=GonkCameraControl.cpp#1044 in my local test.

In normal situation, nsGonkCameraControl::StopImpl() should be called in camera thread.
But it's possbile to be called in mail thread via MediaEngineWebRTCVideoSource::DeallocImpl() -> nsGonkCameraControl::~nsGonkCameraControl().

I'll do more tests on try to confirm it is the root cause.
Flags: needinfo?(ayang)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #141)
> Retriggers on m-c are pointing to the below merge as when it started. Bug
> 985135 definitely stands out there, but I can try to bisect down to a
> specific push on inbound if it's felt there's any value in doing so.
> https://hg.mozilla.org/mozilla-central/pushloghtml?startID=26867&endID=26868

I can't tell why the hit-rate is getting high in these pushes.
I'm afraid it could be other bugs except for comment 176.
I've run the test 5 times on try, with and without the change for bug 985135.

It failed 2 times without the fix and 3 times with it.
Obviously this isn't conclusive, but I'm not all that sure that my patch has caused this increase.
The retriggers on m-c seem to quite conclusively point at that merge as the culprit, but I've done more retriggers on the push prior to be sure. If bug 985135 isn't at fault, we'll need to bisect within that range on inbound to narrow it down further. Thanks for following up, Bob!
Conveniently, rev 1a00dde01343 on inbound already shows one of those failures too, which predates bug 985135 landing. Inbound retriggers going :)
The rapid failed ratio caused by testcase of bug 978660.
It opens the buggy emulator camera hal and deadlock easily. Then the following testcase will be timeout.
Here is the try without the testcase, https://tbpl.mozilla.org/?tree=Try&rev=07f332c0b6ef.

:schien will update the testcase of bug 978660 soon.
It's sad that we cannot write any test that initiate camera on emulator. I'll disable part of test_permission_gum_remember.html in Bug 1019572 and file another bug for the camera HAL on b2g emulator.
Summary: Intermittent | test_sandbox_permission.html | Test timed out. → Intermittent test_sandbox_permission.html | Test timed out.