1078270 - Camera app dies/crashes after unlocking from lockscreen with passcode

Status: VERIFIED FIXED

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

Description

[Zac C (:zac)]

Attachment: camera_fail.log

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.

Comment 1

[Zac C (:zac)]

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.

Comment 2

[Andrew Osmond [:aosmond] (he/him)]

Attachment: debug.bug1078270.log

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.

Comment 3

[Zac C (:zac)]

Attachment: camera.log

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

Comment 4

[Zac C (:zac)]

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

Comment 5

[Tony Chung [:tchung]]

[Blocking Requested - why for this release]:

is this a regression?  also caught by automation

Comment 6

[David Flanagan [:djf]]

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.

Comment 7

[Hema Koka [:hema]]

QA, Could you please check if this is a regression?

Comment 8

[David Flanagan [:djf]]

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)

Comment 9

[Zac C (:zac)]

I'll check that range :djf, thanks!

Comment 10

[Zac C (:zac)]

(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.

Comment 11

[Zac C (:zac)]

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.

Comment 12

[Andrew Osmond [:aosmond] (he/him)]

(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.

Comment 13

[Andrew Osmond [:aosmond] (he/him)]

Attachment: 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.

Comment 14

[Eugen Sawin [:esawin]]

(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.

Comment 15

[Andrew Osmond [:aosmond] (he/him)]

Attachment: 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 :).

Comment 16

[Andrew Osmond [:aosmond] (he/him)]

(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...).

Comment 17

[Andreas Pehrson [:pehrsons]]

(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.

Comment 18

[Andreas Pehrson [:pehrsons]]

The new patch is in and behaves better. See attachment 8503058 [details] [diff] [review].

Comment 19

[Eugen Sawin [:esawin]]

Do we still need to do anything here?

Comment 20

[Andrew Osmond [:aosmond] (he/him)]

I can confirm bug 879717 fixes this issue as a consequence but it got reverted again for other build failures.

Comment 21

[Andrew Osmond [:aosmond] (he/him)]

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.

Comment 22

[Eugen Sawin [:esawin]]

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).

Comment 23

[Andrew Osmond [:aosmond] (he/him)]

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.

Comment 24

[Tim Guan-tin Chien [:timdream] (please needinfo)]

This bug is listed as v2.2 319MB smoketest blocker but closed a month ago.

Is the fix not verified?

Comment 25

[Eric Chang [:ericcc] [:echang]]

Hi Tim, thanks for the reminder.
Hi Edward, Cynthia, please check if we can request script code uplifted to V2.2, thanks.

Comment 26

[Edward Chen[:edchen]]

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