Closed Bug 1078270 Opened 5 years ago Closed 5 years ago

Camera app dies/crashes after unlocking from lockscreen with passcode

Categories

(Core :: WebRTC: Audio/Video, defect)

35 Branch
x86_64
Linux
defect
Not set

Tracking

()

VERIFIED FIXED
mozilla35
Tracking Status
b2g-v2.0 --- unaffected
b2g-v2.1 --- unaffected
b2g-v2.2 --- affected

People

(Reporter: zcampbell, Assigned: aosmond)

References

Details

(Whiteboard: [xfail])

Attachments

(5 obsolete files)

Attached file camera_fail.log (obsolete) —
Gaia-Rev        428d59ecbbefe8e2528ad3c54aaef7b1b87d3440
Gecko-Rev       https://hg.mozilla.org/integration/b2g-inbound/rev/1e90de022656
Build-ID        20141006050714
Version         35.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20141006.060013
FW-Date         Mon Oct  6 06:00:23 EDT 2014
Bootloader      L1TC00011840


STR:
1. Configure Flame device with lockscreen and passcode.
2. Lock device
3. Swipe unlock to the camera
4. Wait for camera app to load
5. Wait around 10 seconds - screen will go black..
6. Tap power button - lockscreen is shown, not camera.


Regression range:
We cannot get an accurate regression range from our test automation because an unrelated bug caused all test results to be lost somewhere within the range of this bug being introduced. I will prepare a rough range.
After some discussion we realise that this is probably intentional, to stop perhaps the camera app running while its in your pocket.

During our automated test however, the screen turns off after 3-4 seconds instead of 10. Something is triggering turning it off before the test has completed. As the camera frame disappears out from underneath Marionette unexpectedly, the test then hangs.
Attached file debug.bug1078270.log (obsolete) —
Yes, the shutdown is graceful. We seem to receive an OnNavigation event (new page is supposed to load??) which triggers the shutdown.

10-06 10:08:28.940  1254  1254 I Gecko   : >>> OnNavigation event
10-06 10:08:28.940  1254  1254 I Gecko   : >>> Shutdown( aWindowId = 0x3 )

I've attached a log with camera logging enabled (latest b2g-inbound) in case it is useful.
Attached file camera.log (obsolete) —
OK, ignore the initial STR.

This was brought to our attention by the test automation which unlocks from lockscreen, takes a photo, etc.

Here is a better logcat which I captured which shows that the camera app is stopping perhaps prematurely.
 
line 2750, Marionette taps the capture button:
10-06 15:32:06.056 I/Gecko   (12034): 1412605926062 Marionette: emitting Touch event of type touchstart to element with id:  and tag name: DIV at coordinates (160, 508) relative to the viewport
10-06 15:32:06.056 I/Gecko   (12034): 1412605926070 Marionette: emitting Touch event of type touchend to element with id:  and tag name: DIV at coordinates (160, 508) relative to the viewport

line 4756:
10-06 15:32:12.536 W/Camera  (12034): [JavaScript Error: "NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMessageSender.sendAsyncMessage]" {file: "chrome://global/content/BrowserElementChildPreload.js" line: 43}]
10-06 15:32:12.546 E/Sensors (11713): change G sensor state "1 -> 0"
10-06 15:32:12.546 W/Camera  (12034): [JavaScript Error: "IndexedDB UnknownErr: IDBDatabase.cpp:779"]

line 4773:
10-06 15:32:12.596 I/Gecko   (11713): 
10-06 15:32:12.596 I/Gecko   (11713): ###!!! [Parent][MessageChannel] Error: Channel error: cannot send/recv
10-06 15:32:12.596 I/Gecko   (11713): 
10-06 15:32:12.596 W/CameraService(  200): Disconnecting camera client 0xb7aa8dc8 since the binder for it died (this pid 200)

line 4863:
10-06 15:32:12.766 W/CameraClient(  200): native_window_api_disconnect failed: Broken pipe (-32)
10-06 15:32:12.766 I/CameraClient(  200): Destroying camera 0
Attachment #8500430 - Attachment is obsolete: true
Also the other important thing is that in this case the photo is not saved to the sdcard.

I'm going to try some timing changes to see if we are not interacting iwth the Camera app before it's ready for example (Wilson's suggestion).


Running the tests:
https://developer.mozilla.org/en-US/Firefox_OS/Platform/Automated_testing/gaia-ui-tests/Gaia_UI_Tests_Run_Tests

The test we are running is:
https://github.com/mozilla-b2g/gaia/blob/master/tests/python/gaia-ui-tests/gaiatest/tests/functional/lockscreen/test_lockscreen_unlock_to_camera_with_passcode.py
Assignee: nobody → aosmond
Whiteboard: [xfail]
[Blocking Requested - why for this release]:

is this a regression?  also caught by automation
blocking-b2g: --- → 2.1?
The logcat in comment #3 make this look like an unrelated indexed db or IPC bug is behind this. If so, :bent might be a good person to ask.

I wonder if the recent switch to having hte lockscreen as a separate app has anything to do with this.
QA, Could you please check if this is a regression?
The IndexedDB error makes me wonder if this is another regression caused by 994190. If it does not reproduce on 9/28 but does repro on 9/30, then I'd blame bug 994190. (And if so, please add this bug to the list of blockers for 994190)
I'll check that range :djf, thanks!
(In reply to David Flanagan [:djf] from comment #8)
> The IndexedDB error makes me wonder if this is another regression caused by
> 994190. If it does not reproduce on 9/28 but does repro on 9/30, then I'd
> blame bug 994190. (And if so, please add this bug to the list of blockers
> for 994190)

I can't directly connect bug 994190 to this bug unfortunately. This bug seems to be more recent.

I'll work on a range again.
I've got the range down to http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=46f41cc9392d&tochange=84204f793602

Any of those look suspicious? 

I'll keep testing further.
(In reply to Zac C (:zac) from comment #11)
> I've got the range down to
> http://hg.mozilla.org/mozilla-central/
> pushloghtml?fromchange=46f41cc9392d&tochange=84204f793602
> 
> Any of those look suspicious? 
> 
> I'll keep testing further.

Thanks Zac! I tested by removing one line from http://hg.mozilla.org/mozilla-central/rev/5da210c60d38 and it appears to have gone away. Specifically the line changed in HTMLVideoElement::UpdateScreenWakeLock() did the trick.
Appears to be a race condition where the video gets unpaused (mPaused=false) before the video container is retrieved (mHasVideo=true). That prevents the wake lock from getting created, so I changed it to kick the wake lock when mHasVideo changes.
Attachment #8500444 - Attachment is obsolete: true
Attachment #8500466 - Attachment is obsolete: true
Attachment #8502613 - Flags: review?(esawin)
Blocks: 1022669
(In reply to Andrew Osmond [:aosmond] from comment #13)
> Created attachment 8502613 [details] [diff] [review]
> Kick wake lock when video state updated, v1
> 
> Appears to be a race condition where the video gets unpaused (mPaused=false)
> before the video container is retrieved (mHasVideo=true). That prevents the
> wake lock from getting created, so I changed it to kick the wake lock when
> mHasVideo changes.

This seems related to the race condition in bug 879717, I fear the fixes would collide.
Flags: needinfo?(pehrsons)
(In reply to Eugen Sawin [:esawin] from comment #14)
> This seems related to the race condition in bug 879717, I fear the fixes
> would collide.

Ah, thanks for the pointer to that bug! I've updated the patch to follow the same path as part 3 in bug 879717. That patch does not resolve the race condition for camera (although it may for other applications) since mHasVideo can be set in two places, the second of which my new patch addresses. Hopefully this fits in better :).
Attachment #8502613 - Attachment is obsolete: true
Attachment #8502613 - Flags: review?(esawin)
Attachment #8502851 - Flags: review?(esawin)
(In reply to Andrew Osmond [:aosmond] from comment #15)
> Created attachment 8502851 [details] [diff] [review]
> Kick wake lock when video state updated, v2
> 
> (In reply to Eugen Sawin [:esawin] from comment #14)
> > This seems related to the race condition in bug 879717, I fear the fixes
> > would collide.
> 
> Ah, thanks for the pointer to that bug! I've updated the patch to follow the
> same path as part 3 in bug 879717. That patch does not resolve the race
> condition for camera (although it may for other applications) since
> mHasVideo can be set in two places, the second of which my new patch
> addresses. Hopefully this fits in better :).

Scratch that, I just realized I should have checked the others more closely, particular part 1. It seems to remove this location where mHasVideo may be set for camera. If I apply patches 1-3, mHasVideo is always false for camera, which suggests that line shouldn't be removed as the patch stands or I should somehow fix this on the camera side so the order of events are as expected (but I don't fully appreciate the state machine from HTMLMediaElement to know what, if anything, we could be doing wrong at the moment...).
(In reply to Andrew Osmond [:aosmond] from comment #16)
> Scratch that, I just realized I should have checked the others more closely,
> particular part 1. It seems to remove this location where mHasVideo may be
> set for camera. If I apply patches 1-3, mHasVideo is always false for
> camera, which suggests that line shouldn't be removed as the patch stands or
> I should somehow fix this on the camera side so the order of events are as
> expected (but I don't fully appreciate the state machine from
> HTMLMediaElement to know what, if anything, we could be doing wrong at the
> moment...).

Yeah, that state machine has been killing me too slowly over the last couple of days. :)
I'm in the process of wrapping up a new way to set mHasVideo. As you noted, it is always set to false in some cases with the old method. I'll be using the callback in DOMMediaStream so things should become more sturdy, and best of all, we can handle a case where we get a video track after metadata has loaded and playback started. Sounds like that might help here.
I'll put up a patch tomorrow.
Flags: needinfo?(pehrsons)
The new patch is in and behaves better. See attachment 8503058 [details] [diff] [review].
Do we still need to do anything here?
Flags: needinfo?(aosmond)
I can confirm bug 879717 fixes this issue as a consequence but it got reverted again for other build failures.
Depends on: 879717
Flags: needinfo?(aosmond)
Not reproducible on latest 2.0/2.1 builds on flame v184; introducing bug targeted firefox 35, so this would be blocking for 2.2.
blocking-b2g: 2.1? → 2.2?
Status: NEW → ASSIGNED
Component: Gaia::Camera → WebRTC: Audio/Video
Product: Firefox OS → Core
Target Milestone: --- → mozilla35
Version: unspecified → 35 Branch
Comment on attachment 8502851 [details] [diff] [review]
Kick wake lock when video state updated, v2

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

Cancelling the review, it's being fixed in bug 879717 (conflicting patches).
Attachment #8502851 - Flags: review?(esawin)
While bug 879717 has yet to land, it was broken up into smaller bugs and many of those dependencies have now landed. It is now working on master.
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Attachment #8502851 - Attachment is obsolete: true
This bug is listed as v2.2 319MB smoketest blocker but closed a month ago.

Is the fix not verified?
Flags: needinfo?(echang)
Hi Tim, thanks for the reminder.
Hi Edward, Cynthia, please check if we can request script code uplifted to V2.2, thanks.
Flags: needinfo?(edchen)
Flags: needinfo?(echang)
Flags: needinfo?(ctang)
For this ticket that we have verify this bug by automation script. This ticket was fixed after verifying bug by manual and gaia ui test though.

I will request automation team to turn on the test script.


[Environment]
Device firmware (base) 	L1TC000118D0
Device firmware (date) 	15 Jan 2015 16:57:45
Device firmware (incremental) 	eng.cltbld.20150115.035734
Device firmware (release) 	4.4.2
Device identifier 	flame
Gaia date 	13 Jan 2015 01:32:38
Gaia revision 	7c5b27cad370
Gecko build 	20150115002505
Gecko revision 	ce27f2692382
Gecko version 	37.0a2

[Result]
PASS
Status: RESOLVED → VERIFIED
Flags: needinfo?(edchen)
Flags: needinfo?(ctang)
blocking-b2g: 2.2? → ---
You need to log in before you can comment on or make changes to this bug.