864550 - Camera - Video not recorded. An error prevented camera from recording the video

Status: RESOLVED WORKSFORME

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

Description

[Inder]

Test Steps:
1. Start Camcorder script.
2. After completing few iterations, “Video not recorded. An error prevented camera from recording the video.” Message displayed.
3. And camcorder script is not running.
Reproducibility: Seen multiple times.

The camcorder script records in a loop for couple of iterations. Each recording duration is about 10 to 20 seconds.

Comment 1

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

Inder, can you provide info on:
- the hardware platform/build this occurs on
- available space on the uSD card
- logcat output?

Comment 2

[Inder]

Logcat (too big to attach here):
https://docs.google.com/file/d/0B1o1jCbrNLXoRkF2ZzJaQjVEeE0/edit?usp=sharing

Excerpt where the issue happened:
04-22 11:36:22.209 15756 15756 E QCameraHWI_Preview: virtual android::status_t android::QCameraStream_preview::start(): X
04-22 11:36:22.209 15756 15756 E QCameraHWI: android::status_t android::QCameraHardwareInterface::startPreview2(): X error - can't start stream!
04-22 11:36:22.209 15756 15756 E QualcommCamera: Qint android::start_preview(camera_device*): X
04-22 11:36:27.049 15757 15757 I Gecko   : 1366610787053	Marionette	DEBUG	Got request: execute, data: {"to":"conn2.marionette1","specialPowers":false,"session":"6-b2g","newSandbox":true,"args":[],"type":"executeScript","value":"return startCapture();"}, id: {e6a13a48-36fe-44d9-8c41-f1ad16ba9601}
04-22 11:36:27.089 15757 15757 I Gecko   : 1366610787093	Marionette	INFO	sendToClient: {"from":"conn2.marionette1","value":0}, {e6a13a48-36fe-44d9-8c41-f1ad16ba9601}, {e6a13a48-36fe-44d9-8c41-f1ad16ba9601}
04-22 11:36:27.119   151  1458 E CAMERA FRAME_PROC: ...pp thread select timeout...

Not sure if its related to bug 846903 or not. This is happening on our reference device. The test build is using following SHA1s:
gaia: a80be95f553de517e5d8a159e04511cda5e38be4
gecko: 92f56f2e21daaa0a0bc153c0b7c3382a41674ff7
Not sure about the exact space on the sdcard used by the test folks but i am pretty sure it's not hitting the limit.

Comment 3

[Sotaro Ikeda [:sotaro]]

Inder, does your reference device use ics_strawberry or ics_chocolate?

Comment 4

[Inder]

ics_sb

Comment 5

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

Is there a 'cif' profile defined in your media_profiles.xml?

Comment 6

[Inder]

(In reply to Mike Habicher [:mikeh] from comment #5)
> Is there a 'cif' profile defined in your media_profiles.xml?
Yes, and that hasn't changed since the beginning.

Comment 7

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

Inder, this appears in the log just before your snippet in comment 2.  Could the invalid event be a clue?

04-22 11:36:22.199 15756 15756 E QCameraHWI_Preview:  virtual android::status_t android::QCameraStream_preview::start() : initDisplayBuffers
04-22 11:36:22.199 15756 15756 E mm-libcamera2: mm_camera_stream_fsm_reg: Invalid evt=7, stream_state=3

Comment 8

[Ben Tian (inactive)]

Michael/Leo,

mm-camera met preview STREAM ON failure and afterward startPreview2() kept showing error as comment 2. Can you provide the error info & possible causes for gecko debugging?

04-22 11:36:12.869   151  1450 E mm-camera: config_CAMERA_START_VIDEO: E, ctrl->state = 5
04-22 11:36:12.869   151  1450 E mm-camera: CAMERA_START_VIDEO illegal state, ctrl->state = 5
04-22 11:36:12.869   151  1450 E mm-camera: config_MSM_V4L2_STREAM_ON:config_CAMERA_START_VIDEO, rc = -22
04-22 11:36:12.869   151  1450 E mm-camera: config_MSM_V4L2_STREAM_ON: X, rc = -22
04-22 11:36:12.869 15756 15821 E mm-libcamera2: mm_camera_stream_fsm_reg: ioctl VIDIOC_STREAMON failed: rc=-1
04-22 11:36:12.869 15756 15821 E mm-libcamera2: mm_camera_ch_fn: Failed in STREAM ON

Comment 9

[Michael Vines [:m1] [:evilmachines]]

(clearing ni? on me, please work with Inder directly)

Comment 10

[Inder]

Sorry for the delay in response. I was looking into some other issues. It seems like the camera control went in weird state and returned error. In config_CAMERA_START_VIDEO() it should have been in CAMERA_STATE_IDLE but it was already in CAMERA_STATE_STARTED state.
It could have been caused by some issues with getBufferFromSurface. Please see this in log:

04-22 11:36:12.849 15756 15821 E QCameraHWI_Preview: getBufferFromSurface: camera call genlock_lock, hdl=0x1bf0650
04-22 11:36:12.849 15756 15821 E QCameraHWI_Preview: getBufferFromSurface: genlock_lock_buffer hdl =0x1bf0650
04-22 11:36:12.849 15756 15821 E QCameraHWI_Preview: android::status_t android::QCameraStream_preview::getBufferFromSurface(): dequeue buf: 0x1bf0600
04-22 11:36:12.849 15756 15821 E QCameraHWI_Preview: android::status_t android::QCameraStream_preview::getBufferFromSurface(): idx = 6, fd = 120, size = 233472, offset = 0
04-22 11:36:12.849 15756 15821 E QCameraHWI_Preview: Cancelling preview buffer and set not owned 0x1bf0498
04-22 11:36:12.849 15756 15821 E QCameraHWI_Preview: Cancelling preview buffer and set not owned 0x1bf0650
04-22 11:36:12.849 15756 15821 E QCameraHWI_Preview: virtual android::status_t android::QCameraStream_preview::initDisplayBuffers(): idx = 0, fd = 96, size = 233472, cbcr_offset = 153600, y_offset = 0, offset = 0, vaddr = 0x417b9000

I looked through the logs of previous instance of this issue on a little older build and I see the following in the log. Though it doesn't show up in the current log I am not sure if something similar is happening with the preview buffer.

"03-07 14:17:35.259   519  1621 E QCameraHWI_Preview: virtual android::status_t android::QCameraStream_preview::initDisplayBuffers():BEGIN
03-07 14:17:35.259   519  1621 I Gecko   : setBufferCount: client owns some buffers
03-07 14:17:35.259   519  1621 E QCameraHWI_Preview: set_buffer_count failed: Invalid argument (22)
03-07 14:17:35.259   519  1621 E QCameraHWI_Preview: virtual android::status_t android::QCameraStream_preview::initDisplayBuffers(): cannot get memory from surface texture client, ret = -2147483648
03-07 14:17:35.259   519  1621 E QCameraHWI: android::status_t android::QCameraHardwareInterface::startPreview2(): X error - can't start stream!
03-07 14:17:35.259   519  1621 E QualcommCamera: Qint android::start_preview(camera_device*): X
03-07 14:17:35.279   131   131 I Gecko   : 1362646055286	Marionette	INFO	sendToClient: {"from":"conn50.marionette1","ok":true}, {f38aaf7a-1983-45f9-86b0-0e0616df8cb4}, {f38aaf7a-1983-45f9-86b0-0e0616df8cb4}"

Comment 11

[Ben Tian (inactive)]

> 04-22 11:36:12.869   151  1450 E mm-camera: config_CAMERA_START_VIDEO: E,
> ctrl->state = 5
> 04-22 11:36:12.869   151  1450 E mm-camera: CAMERA_START_VIDEO illegal
> state, ctrl->state = 5
More finding: previous config_CAMERA_START_VIDEO() changed CAMERA_STATE_IDLE to CAMERA_STATE_STARTED but following failure occurs and then QCameraHAL restarts. I think that's why the state remains CAMERA_STATE_STARTED when preview starts again.

04-22 11:32:56.949   151  1450 E mm-camera: MSM_CAM_IOCTL_RELEASE_STATS_BUFFER failed 
04-22 11:32:56.959   151  1458 E CAMERA FRAME_PROC: ...pp thread select timeout...
04-22 11:32:57.109   151   151 E mm-camera: qcamsvr_process_server_node_event: Ignore events with null payload
04-22 11:32:57.109   151   151 E mm-camera: qcamsvr_start: qcamsvr_process_server_node_event failed
...
04-22 11:32:58.269 15756 15756 E QualcommCamera: Qint android::get_number_of_cameras(): E
04-22 11:32:58.269 15756 15756 I QCameraHAL: Handle base =0x0x40dae294
04-22 11:32:58.269 15756 15756 I QCameraHAL: getCameraInfo: numOfCameras = 2
--

Inder, any insight or possible cause of this failure? Also can you share the test script for us to reproduce?

Comment 12

[Wayne Chang [:wchang]]

ni? inder for comment 11

Comment 13

[Inder]

I looked through the code and it seems the qcamsvr didn't send correct event type. Not sure what  caused it. Before the server failure I do see this though:
04-22 11:32:56.709   130  1687 E OMXNodeInstance: !!! Observer died. Quickly, do something, ... anything...
04-22 11:32:56.709   130   130 E OMXNodeInstance: !!! Observer died. Quickly, do something, ... anything...

Which would happen if the omx binder connection is dead. So, it's possible that could have triggered it. Let me check with test guys if i can share the test scripts or a simple STR.

Comment 14

[Ben Tian (inactive)]

Inder, I didn't get why dead omx binder connection results in incorrect event type to qcamsvr. Is it only possible to happen during recording?
Also to make sure, the camcorder script doesn't fail on android phones right?

Comment 15

[Inder]

(In reply to Ben Tian [:btian] from comment #14)
> Inder, I didn't get why dead omx binder connection results in incorrect
> event type to qcamsvr. Is it only possible to happen during recording?
I just noticed the two failures but am not sure if the two errors are related.
Basically the qcamsrv died for some reason. I have asked the test guys if they are able to reproduce this issue on recent builds. I will let you know what i find out.

> Also to make sure, the camcorder script doesn't fail on android phones right?
I don't think these scripts are run on Android phones.

Comment 16

[:gerard-majax]

I've tried reproducing it on a Keon running v1-train from this week-end, taking 11 short videos and not reproducing, neither taking 6 videos ranging between 15 and 25 seconds.

On which device are you having this ?

The return code in one of the logcat might be an indication, errno=22 being EINVAL.

Comment 17

[:gerard-majax]

Unable to reproduce on a Leo device too, buildid 20130425170448.

Comment 18

[Inder]

All our stability tests are performed on our reference device (QRD) based on 7x27a. Haven't yet heard back from test guys on this. Will update when I hear back from them.

Comment 19

[:gerard-majax]

(In reply to Inder from comment #18)
> All our stability tests are performed on our reference device (QRD) based on
> 7x27a. Haven't yet heard back from test guys on this. Will update when I
> hear back from them.

On which device should I try to reproduce ? And what do you call "camcorder script" ?

Comment 20

[Inder]

Since we haven't been able to reproduce the issue on recent builds I am closing the bug for now and will reopen if it resurfaces.