1093797 - [Window Mangaement] Camera viewfinder will appear black if the user goes in card view and back into camera after a fresh flash

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Gaia::Camera, defect)

Description

[KTucker [:KTucker][Inactive 3/4/2016]]

Description:
Camera viewfinder will appear black if the user goes into card view and then back into camera after a fresh flash.

Prerequisite: Factory reset the dut before performing these steps.

Repro Steps:
1)  Updated Flame to Build ID: 20141104001202
2)  Tap the camera app icon.
3)  Immediately after tapping on the camera app icon, hold the home button on the dut to enter card view.
4)  Tap on the camera app while in card view and observe.

Actual:
The viewfinder on the camera will be black.

Expected:
The camera viewfinder works as expected without issue.

Environmental variables:
Device: Flame 2.1 (319mb)(Kitkat Base)(Shallow Flash)
BuildID: 20141104001202
Gaia: 8b0cf889ae0d48a9eb7ecdcb9b67590de45cc5e5
Gecko: 388b03efe92d
Version: 34.0 (2.1)
Firmware: v188-1
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

Notes:
Repro frequency: 100%
See attached: video clip

Please note that I am unable to get a logcat. The issue does not occur if i go into settings first before opening the camera app after a fresh flash.

Comment 1

[KTucker [:KTucker][Inactive 3/4/2016]]

This issue also occurs on the Flame 2.2

The viewfinder appears black if the user goes into camera after a fresh flash, immediately opens card view and goes back into the camera app.

Device: Flame 2.2(319mb)(KitKat)(Shallow Flash)
Build ID: 20141104040207
Gaia: 3c50520982560ccba301474d1ac43706138fc851
Gecko: 54d05732f29b
Version: 36.0a1 (2.2)
Firmware Version: v188-1
User Agent: Mozilla/5.0 (Mobile; rv:36.0) Gecko/36.0 Firefox/36.

--------------------------------------------------------------------

This issue does not reproduce on the Flame 2.0

The viewfinder appears as expected without issue.

Flame 2.0

Device: Flame 2.0(319mb)(KitKat)(Shallow Flash)
BuildID: 20141104000201
Gaia: fe2167fa5314c7e71c143a590914cbf3771905a8
Gecko: 241e51806687
Version: 32.0 (2.0)
Firmware: V188-1
User Agent: Mozilla/5.0 (Mobile; rv:32.0) Gecko/32.0 Firefox/32.0

Comment 2

[Joshua Mitchell (Inactive)]

NI Camera Owner for a blocking call -

Comment 3

[No-Jun Park [:njpark]]

[Blocking Requested - why for this release]:

just curious, after a fresh flash, if you restart the phone, does this still reproduce?  Or does this only happen after the fresh flash?  For me if I restart the phone and follow STR, when it enters the card view, the card view screen is all black.  but when I tap the screen, it switches to the camera app.  I think there is an issue with card view rendering if card view is entered too fast before the app finishes loading.

Either case, it shows dark screen (in my case, it's the card view, and in your case, it's the viewfinder) so blocking with the UI breakage reason.

Comment 4

[KTucker [:KTucker][Inactive 3/4/2016]]

In reply to comment 3, the card view appears correctly for me in 2.1. I know in 2.2 there is an issue with the card view showing black.

I get this issue 100% of the time after a factory reset.

I tried reflashing the phone and restarting the phone instead of using "reset" and I was still able to reproduce the issue.

Comment 5

[Gregor Wagner [:gwagner]]

Just to clarify: This only happens after a fresh flash? After a reboot it works fine?

Comment 6

[Mike Habicher [:mikeh] (high bugzilla latency)]

I just tested this with gonk v188-1 and:

Gaia-Rev        7c9e7cabbde941b976e0e40a3a1d94e21aa9c5e9
Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/62990ec7ad78
Build-ID        20141105040206
Version         36.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  40
FW-Date         Tue Oct 21 15:59:42 CST 2014
Bootloader      L1TC10011880

...and applying the STR, the Camera app works properly: the viewfinder comes up.

To be sure, I confirmed both the case where I'm prompted for geolocation permission, and the case where I'm not. In both cases, the app works as expected.

No-Jun, can you confirm?

Comment 7

[KTucker [:KTucker][Inactive 3/4/2016]]

In reply to comment 5, I am able to reproduce it 100% after a fresh flash or factory reset. I was also able to get it after flashing the phone and then restarting the phone. I never open up any other apps first. I open camera and immediately hold the home button on the phone to enter card view while the camera app is still loading.

Comment 8

[Chris Kreinbring [:CKreinbring]]

Attachment: Log of black viewfinder on relaunch

I was able to get some logs with a flash script that turns on debugging tools by default.

Comment 9

[No-Jun Park [:njpark]]

(In reply to Mike Habicher [:mikeh] from comment #6)
> I just tested this with gonk v188-1 and:
> 
> Gaia-Rev        7c9e7cabbde941b976e0e40a3a1d94e21aa9c5e9
> Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/62990ec7ad78
> Build-ID        20141105040206
> Version         36.0a1
> Device-Name     flame
> FW-Release      4.4.2
> FW-Incremental  40
> FW-Date         Tue Oct 21 15:59:42 CST 2014
> Bootloader      L1TC10011880
> 
> ...and applying the STR, the Camera app works properly: the viewfinder comes
> up.
> 
> To be sure, I confirmed both the case where I'm prompted for geolocation
> permission, and the case where I'm not. In both cases, the app works as
> expected.
> 
> No-Jun, can you confirm?

Hi Mike, I can't repro it on the latest 2.1, but I can still see the issue in 2.2.  The build I shallow flashed on top of v188-1 is:
Gaia-Rev        068b9711277b06c7d633517f9e1fcb5624bb39b3
Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/a074c0112919
Build-ID        20141106040207
Version         36.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  40
FW-Date         Tue Oct 21 15:59:42 CST 2014
Bootloader      L1TC10011880

Kevin, could you see whether this still reproduces in 2.1?  I can't see it in
Gaia-Rev        9658b93b412bdcc0f953d668e8c8e68318c99fb8
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/76880403db44
Build-ID        20141106001204
Version         34.0
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  40
FW-Date         Tue Oct 21 15:59:42 CST 2014
Bootloader      L1TC10011880

Thanks!

Comment 10

[Marcia Knous [:marcia]]

qawanted for Comment 9 - triage team needs this information in to ascertain whether this is blocking.

Comment 11

[KTucker [:KTucker][Inactive 3/4/2016]]

I was able to reproduce this issue on today's Flame 2.1

Device: Flame 2.1(319mb)(KK)(Shallow Flash)
BuildID: 20141106001204
Gaia: 9658b93b412bdcc0f953d668e8c8e68318c99fb8
Gecko: 76880403db44
Version: 34.0 (2.1)
Firmware: V188-1
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

I got it on my second attempt after a factory reset. 

1. Factory reset the phone.
2. During the FTE, enable "cellular data" and keep tapping "Next" until reaching the homescreen.(Skip the tutorial)
3. Tap the camera icon and "immediately" hold the home button to enter card view.
4. Tap on the "Camera app" card to go back into camera. 
5. Tap to share "Geolocation".

Actual: The viewfinder will be completely blank and the buttons are non functional.

Comment 12

[Gregor Wagner [:gwagner]]

Sam, I think you mentioned something about sending a close event to the app when we launch the task manager. Do you think this might cause this issue?
It seems like a camera issue to me since other apps work as expected.

Comment 13

[KTucker [:KTucker][Inactive 3/4/2016]]

I just confirmed for Gregor that after reproducing the issue, I could reproduce it again after restarting the phone. It didn't require a factory reset on the second attempt.

Comment 14

[Sam Foster [:sfoster] (he/him)]

(In reply to Gregor Wagner [:gwagner] from comment #12)
> Sam, I think you mentioned something about sending a close event to the app
> when we launch the task manager. Do you think this might cause this issue?
> It seems like a camera issue to me since other apps work as expected.

It sounds like the camera app has not finished initializing before it is closed (by showing the task manager, via AppWindow.prototype.enterTaskManager) and its not able to recover from this state. I'm going to move this to the Camera component, but I'm happy to help troubleshoot or whatever is needed.

Comment 15

[Chris Kreinbring [:CKreinbring]]

The repro rates drops off greatly the further back I went to attempt to find the first broken build.  On the build listed below the bug reproed once out of 25 attempts.

BuildID: 20141001060621
Gaia: a23d2c490b39c4699c9375e25c4acdf396a2fa85
Gecko: 835ef55e175e
Platform Version: 35.0a1
Firmware Version: V188-1
User Agent: Mozilla/5.0 (Mobile; rv:35.0) Gecko/35.0 Firefox/35.0

Comment 16

[Joshua Mitchell (Inactive)]

Typically we don't do regression-windows on things with <50% repro rate - and a 4% repro rate is not something we can find an accurate window for. Chris found several spots he thought were his window but repro'd on both swaps invalidating those windows. The repro rate is just too low.

Comment 17

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

I'm having some luck reproducing it. I will try to root cause this.

Comment 18

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

Reproducing is quite difficult but I did get some hint of a possible root cause in 2.1 during the hiding of the app. The camera appears to be fully setup and configured by the application, but the preview was never started. After one enters the app the second time, touch-to-focus calls go through down to the driver (but obviously fail since the preview isn't running).

Around when the app is hidden this error occurs:
11-10 07:31:59.120  1234  1234 E GeckoConsole: [JavaScript Error: "TypeError: e.mozCamera is null" {file: "app://camera.gaiamobile.org/js/main.js" line: 3}]

My best guess at the moment is that we got interrupted between the parameter setting and starting the preview, and now the app is left in an inconsistent state.

Comment 19

[Andrew Overholt [:overholt]]

The triage group decided that regression = blocker so 2.1+.

Comment 20

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

Cause analysis and patch coming soon, just figured it out.

Comment 21

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

When the camera is first loaded without any cached configuration, we can see the defaults are set by the driver:

11-10 07:31:58.420   201   489 E QCamera2HWI: [KPI Perf] int qcamera::QCamera2HardwareInterface::openCamera(hw_device_t**): E PROFILE_OPEN_CAMERA camera id 0
11-10 07:31:58.820   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::initBatchUpdate(void*):Initializing batch parameter set
11-10 07:31:58.820   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setPreviewSize(const qcamera::QCameraParameters&): Requested preview size 1280 x 720
11-10 07:31:58.820   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setVideoSize(const qcamera::QCameraParameters&): Requested video size 1280 x 720
11-10 07:31:58.820   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setPictureSize(const qcamera::QCameraParameters&): Requested picture size 176 x 144

Eventually the application selects a new picture size:

11-10 07:31:58.950   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setPreviewSize(const qcamera::QCameraParameters&): Requested preview size 1280 x 720
11-10 07:31:58.950   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setVideoSize(const qcamera::QCameraParameters&): Requested video size 1280 x 720
11-10 07:31:58.950   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setPictureSize(const qcamera::QCameraParameters&): Requested picture size 2592 x 1944

We see it also pauses/resumes the focus module (confirms sane app state, onSuccess case of getCamera):

11-10 07:31:58.970   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setFaceDetection(bool): face process mask not changed, no ops here
11-10 07:31:58.970   201  1320 D QCamera2HWI: int qcamera::QCamera2HardwareInterface::sendCommand(int32_t, int32_t&, int32_t&): FaceDetection -> Disabled
11-10 07:31:58.980   201   201 E QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_auto_focus(camera_device*) : E PROFILE_CANCEL_AUTO_FOCUS
11-10 07:31:58.980   201   201 D QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_auto_focus(camera_device*) : X
11-10 07:31:58.980   201  1320 D QCameraParameters: int32_t qcamera::QCameraParameters::setFaceDetection(bool): FaceProcMask -> 1
11-10 07:31:58.980   201  1320 D QCamera2HWI: int qcamera::QCamera2HardwareInterface::sendCommand(int32_t, int32_t&, int32_t&): FaceDetection -> Enabled

And then it is released with no further configurations:

11-10 07:31:58.980   201   201 E QCamera2HWI: [KPI Perf] static void qcamera::QCamera2HardwareInterface::stop_preview(camera_device*): E PROFILE_STOP_PREVIEW
11-10 07:31:58.980   201  1320 D QCameraStateMachine: int32_t qcamera::QCameraStateMachine::procEvtPreviewStoppedState(qcamera::qcamera_sm_evt_enum_t, void*): already in preview stopped state, do nothing
11-10 07:31:58.980   201   201 D QCamera2HWI: [KPI Perf] static void qcamera::QCamera2HardwareInterface::stop_preview(camera_device*): X
11-10 07:31:58.980   201   201 E QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_picture(camera_device*): E PROFILE_CANCEL_PICTURE
11-10 07:31:58.980   201  1320 D QCameraStateMachine: int32_t qcamera::QCameraStateMachine::procEvtPreviewStoppedState(qcamera::qcamera_sm_evt_enum_t, void*): No ops for evt(20) in state(0)
11-10 07:31:58.980   201   201 D QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_picture(camera_device*): X
11-10 07:31:58.980   201   201 I CameraClient: Destroying camera 0
11-10 07:31:58.980   201   201 D QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::close_camera_device(hw_device_t*): E

An exception is thrown by the app shortly after, which may be a red herring (or a sign of another problem):

11-10 07:31:59.120  1234  1234 E GeckoConsole: [JavaScript Error: "TypeError: e.mozCamera is null" {file: "app://camera.gaiamobile.org/js/main.js" line: 3}]

Otherwise the app state seems fine, as best as can be gleaned from logcat. Now we see the camera is loaded again:

11-10 07:32:03.480   201   489 E QCamera2HWI: [KPI Perf] int qcamera::QCamera2HardwareInterface::openCamera(hw_device_t**): E PROFILE_OPEN_CAMERA camera id 0
11-10 07:32:03.740   201   489 D QCameraParameters: int32_t qcamera::QCameraParameters::initBatchUpdate(void*):Initializing batch parameter set
11-10 07:32:03.770   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setPreviewSize(const qcamera::QCameraParameters&): Requested preview size 1280 x 720
11-10 07:32:03.780   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setVideoSize(const qcamera::QCameraParameters&): Requested video size 1280 x 720
11-10 07:32:03.780   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setPictureSize(const qcamera::QCameraParameters&): Requested picture size 176 x 144

Here it pauses/resumes the focus module again:

11-10 07:32:03.840   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setFaceDetection(bool): face process mask not changed, no ops here
11-10 07:32:03.840   201  1372 D QCamera2HWI: int qcamera::QCamera2HardwareInterface::sendCommand(int32_t, int32_t&, int32_t&): FaceDetection -> Disabled
11-10 07:32:03.850   201   201 E QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_auto_focus(camera_device*) : E PROFILE_CANCEL_AUTO_FOCUS
11-10 07:32:03.850   201   201 D QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_auto_focus(camera_device*) : X
11-10 07:32:03.850   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setFaceDetection(bool): FaceProcMask -> 1
11-10 07:32:03.850   201  1372 D QCamera2HWI: int qcamera::QCamera2HardwareInterface::sendCommand(int32_t, int32_t&, int32_t&): FaceDetection -> Enabled

But it appears that the picture size was never updated:

11-10 07:32:03.960   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setPreviewSize(const qcamera::QCameraParameters&): Requested preview size 1280 x 720
11-10 07:32:03.960   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setVideoSize(const qcamera::QCameraParameters&): Requested video size 1280 x 720
11-10 07:32:03.960   201  1372 D QCameraParameters: int32_t qcamera::QCameraParameters::setPictureSize(const qcamera::QCameraParameters&): Requested picture size 176 x 144

And the last thing that happens is it is released again when the app is closed:

11-10 07:32:09.010   201   489 E QCamera2HWI: [KPI Perf] static void qcamera::QCamera2HardwareInterface::stop_preview(camera_device*): E PROFILE_STOP_PREVIEW
11-10 07:32:09.010   201  1372 D QCameraStateMachine: int32_t qcamera::QCameraStateMachine::procEvtPreviewStoppedState(qcamera::qcamera_sm_evt_enum_t, void*): already in preview stopped state, do nothing
11-10 07:32:09.010   201   489 D QCamera2HWI: [KPI Perf] static void qcamera::QCamera2HardwareInterface::stop_preview(camera_device*): X
11-10 07:32:09.010   201   489 E QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_picture(camera_device*): E PROFILE_CANCEL_PICTURE
11-10 07:32:09.010   201  1372 D QCameraStateMachine: int32_t qcamera::QCameraStateMachine::procEvtPreviewStoppedState(qcamera::qcamera_sm_evt_enum_t, void*): No ops for evt(20) in state(0)
11-10 07:32:09.010   201   489 D QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::cancel_picture(camera_device*): X
11-10 07:32:09.010   201   489 I CameraClient: Destroying camera 0
11-10 07:32:09.010   201   489 D QCamera2HWI: [KPI Perf] static int qcamera::QCamera2HardwareInterface::close_camera_device(hw_device_t*): E

The critical part to note here is that the picture size was never set. In the application state machine, the changing of the picture size is what triggers the camera configuration (which includes the preview size), upon which the successful completion of starts the preview display to the user. The picture size can only not trigger the configure / not be updated, if the application believes that it hasn't changed; it appears the application retains the cached picture size from the first load (which was forgotten) on camera release, such that on the second load, it was never actually set and the state machine stops. The fix is quite simple, clear the picture size on release.

Comment 22

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

Attachment: Gaia pull request, v1

See comment 21 to explain why this should fix the problem.

Comment 23

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

Attachment: Gaia pull request, v1 -- v2.1

Comment 24

[Justin D'Arcangelo [:justindarc]]

Comment on attachment 8521551 [details] [review]
Gaia pull request, v1

Minor style nit. Other than that, LGTM.

Comment 25

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

Comment on attachment 8521553 [details] [review]
Gaia pull request, v1 -- v2.1

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): Unknown. Flaw has been present for a long time, but it is highly dependent on timing so may not have been observed.
[User impact] if declined: Application preview will not start without a force close if the first time the user opens the camera app, they quickly go to the app switcher.
[Testing completed]: Manual verification and added new unit test.
[Risk to taking this patch] (and alternatives if risky): Minimal. The cached picture size is cleared when releasing the camera, so the application needs to handle it being undefined, but that is the normal when starting the camera with no saved configuration on first launch.
[String changes made]: None.

Comment 26

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

Attachment: Log for reproduction on 2.1

Adding log referenced in comment 21 for posterity. Application was opened (pid 1234) and home button held immediately, followed by reentering the app, waiting for a period of time and then closed. Application was then reopened (pid 1351) with a successful preview.

Comment 27

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

try: https://treeherder.mozilla.org/ui/#/jobs?repo=gaia-try&revision=114562a1fe8a

The failures don't appear to be related to my change and the retries I requested appear to pass.

Comment 28

[Carsten Book [:Tomcat]]

https://github.com/mozilla-b2g/gaia/commit/a222358a6210c0bb94e53e036ec8c73dc2e3d4d0

Comment 29

[Ryan VanderMeulen [:RyanVM]]

Please request Gaia v2.1 approval on this when you get a chance.

Comment 30

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

Comment on attachment 8521553 [details] [review]
Gaia pull request, v1 -- v2.1

Carry r+ from master. approval-gaia-v2.1? already set :).

Comment 31

[sarsenyev]

Verified the issue is fixed on 2.2 Flame

Flame 2.2

Device: Flame 2.2 Master (319mb)(Kitkat Base)(Shallow Flash)
BuildID: 20141113040205
Gaia: be8b0151d2f9a4c41fc63952128e0b723cd1161d
Gecko: ab137ddd3746
Version: 36.0a1 (2.2 Master)
Firmware: V188-1
User Agent: Mozilla/5.0 (Mobile; rv:36.0) Gecko/36.0 Firefox/36.0

Adding verifyme for 2.1

Comment 32

[sarsenyev]

As per comment 31, the issue is fixed on 2.2
The viewfinder appears on the screen after restoring the camera app from "card view"

Comment 33

[Ryan VanderMeulen [:RyanVM]]

v2.1: https://github.com/mozilla-b2g/gaia/commit/81160ad79e5b4c21967418dd63f1a1d08d77924e

Comment 34

[Yeojin Chung [:YeojinC]]

This issue is verified fixed on Flame 2.1.

Result: The viewfinder is displayed properly when the Camera app is restored from the card view.
  
Device: Flame 2.1 (319mb, KK, Shallow Flash)  
BuildID: 20141117001201
Gaia: 81160ad79e5b4c21967418dd63f1a1d08d77924e
Gecko: 3572aa3e6766
Version: 34.0 (2.1) 
Firmware Version: v188-1
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0