GNOME Bugzilla – Bug 740040
v4l2src: Fails in presence of V4L2_BUF_FLAG_ERROR
Last modified: 2015-07-03 15:04:09 UTC
Created attachment 290564 [details] Log file as described in bug description Hi, On Ubuntu 14.04 using Gstreamer 1.4.x, I'm having a problem getting a v4l2src to work reliably. It appears that the driver is working ok (according to the attached logs) but almost immediately there's an indication that the bufferpool has reached the end of the stream. Here's the command line I used to generate the attached log: GST_DEBUG="v4l2*:7" gst-launch-1.0 v4l2src ! video/x-raw, format=YUY2, width=1920,height=1080,framerate=2997/100 ! checksumsink 2> gst.log Rebooting the machines (I've tested this on several) will solve the issue...for one invocation. Then, if I run the command line a second time, the above issue occurs again and again. My capture device is a USB3 capture dongle manufactured by Magewell (http://www.magewell.com/hardware/dongles/xi100dusb-hdmi/xi100dusb-hdmi_features.html?lang=en) Thank you!
BTW, this problem is not exhibited in Gstreamer 1.2 or earlier.
Hmm, driver is broken, it does not set buffer.bytesused, see: dequeued buffer 0x7f9ef0011000 seq:0 (ix=0), mem 0x20c1650 used 0, plane=0, flags 00002041, ts 0:00:00.000000000, pool-queued=1, buffer=0x7f9ef0011000 This is a driver bug. Can you identify this driver, is it upstream ? I can't really workaround that easily, since failing on payload=0 is needed to detect end of draining sequence in the encoder. Also, in 1.4, the size will be validated later, and the buffers will fail to map. In 1.2, we where ignoring bytesused, and using length, this is wrong of course. p.s. Overloading EOS here for empty payload buffers is probably a bad idea, I may considered using GST_FLOW_CUSTOM_ERROR in the future.
Thanks very much for the quick response, Nicolas! The device is using the native Linux USB Video Class driver (http://www.ideasonboard.org/uvc/). I will test this with a webcam (which should use the same driver) and see if I get similar results, then report back. Thanks again! Arthur
(In reply to comment #3) > Thanks very much for the quick response, Nicolas! > > The device is using the native Linux USB Video Class driver > (http://www.ideasonboard.org/uvc/). I will test this with a webcam (which > Oh, that's an interesting fact then, what kernel version is this ? Even though it's not a GStreamer bug, I'd be interested to know more, map the history of this potential UVC bug, and maybe change my decision. Obviously if it's firmware bug, it would be a little harder, but I'm open to quirks as long as they are not breaking any other features.
It's kernel 3.13.0-39-generic I've tested now with a webcam and am not able to reproduce the results. In other words, the webcam works just fine. So, this must be an issue with the UVC implementation made by the capture card manufacturer. I'll contact them for support. Thanks very much Nicolas for your help! I really appreciate it! Arthur
Ok, good thing I had a second look. The buffer has the ERROR flag set in. In this case it's normal that payload is set to 0, since none of the pixels are guarantied to be valid. BUF_FLAG_ERROR is not handle by GStreamer. I think I'm suppose to change this into a GAP and ignore the buffer. In the past we would simply push the corrupted buffer downstream. No need to bother the vendor then.
Oh ok, thanks Nicolas. So is this something you would address on your end? I'll hold off on reaching out to the manufacturer if you feel this is something you can fix. Thanks again!!!!
May I ask for one more trace ? I'd like to see the sequence number when it works (in 1.2). I'd like to see the sequence number, it's in a trace that starts with "dequeued buffer". Yes, it's something that I'll address in GStreamer. I don't know why you have a corrupted buffer, but we should recover as state by the spec: "When this flag is set, the buffer has been dequeued successfully, although the data might have been corrupted. This is recoverable, streaming may continue as normal and the buffer may be reused normally. Drivers set this flag when the VIDIOC_DQBUF ioctl is called."
Hi Nicolas, Here's the first seven "dequeued buffer" entries from version 1.2. Let me know if I can provide more for you. Thanks! 0:00:00.148865828 [333m 1088[00m 0x6d65e0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:766:gst_v4l2_buffer_pool_dqbuf:<v4l2bufferpool0>[00m dequeued buffer 0x7f296001c030 seq:0 (ix=0), mem 0x7f29665ce000 used 894928, flags 00002005, ts 2276:38:15.845432000, pool-queued=3, buffer=0x7f296001c030 0:00:00.151611591 [333m 1088[00m 0x6d65e0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:766:gst_v4l2_buffer_pool_dqbuf:<v4l2bufferpool0>[00m dequeued buffer 0x7f296001c140 seq:1 (ix=1), mem 0x7f29661d9000 used 829440, flags 00002005, ts 2276:38:15.847879000, pool-queued=2, buffer=0x7f296001c140 0:00:00.205571143 [333m 1088[00m 0x6d65e0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:766:gst_v4l2_buffer_pool_dqbuf:<v4l2bufferpool0>[00m dequeued buffer 0x7f296001c250 seq:2 (ix=2), mem 0x7f2965de4000 used 4147200, flags 00002005, ts 2276:38:15.893770000, pool-queued=2, buffer=0x7f296001c250 0:00:00.238941065 [333m 1088[00m 0x6d65e0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:766:gst_v4l2_buffer_pool_dqbuf:<v4l2bufferpool0>[00m dequeued buffer 0x7f296001c360 seq:3 (ix=3), mem 0x7f29659ef000 used 4147200, flags 00002005, ts 2276:38:15.927123000, pool-queued=2, buffer=0x7f296001c360 0:00:00.272306747 [333m 1088[00m 0x6d65e0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:766:gst_v4l2_buffer_pool_dqbuf:<v4l2bufferpool0>[00m dequeued buffer 0x7f296001c030 seq:4 (ix=0), mem 0x7f29665ce000 used 4147200, flags 00002005, ts 2276:38:15.960491000, pool-queued=2, buffer=0x7f296001c030 0:00:00.305673019 [333m 1088[00m 0x6d65e0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:766:gst_v4l2_buffer_pool_dqbuf:<v4l2bufferpool0>[00m dequeued buffer 0x7f296001c140 seq:5 (ix=1), mem 0x7f29661d9000 used 4147200, flags 00002005, ts 2276:38:15.993843000, pool-queued=2, buffer=0x7f296001c140 0:00:00.339042540 [333m 1088[00m 0x6d65e0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:766:gst_v4l2_buffer_pool_dqbuf:<v4l2bufferpool0>[00m dequeued buffer 0x7f296001c250 seq:6 (ix=2), mem 0x7f2965de4000 used 4147200, flags 00002005, ts 2276:38:16.027210000, pool-queued=2, buffer=0x7f296001c250
BTW, here is the output on 1.4.4 after I reboot the machine. It always works the first time after reboot on 1.4.4, but then dies on subsequent attempts. 0:00:00.121411306 [336m 2507[00m 0x1edf6d0 [33;01mLOG [00m [00m v4l2allocator gstv4l2allocator.c:1294:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator>[00m dequeued buffer 0 (flags 0x2005) 0:00:00.121424070 [336m 2507[00m 0x1edf6d0 [37mDEBUG [00m [00m v4l2allocator gstv4l2allocator.c:1298:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator>[00m driver pretends buffer is queued even if dequeue succeeded 0:00:00.121432874 [336m 2507[00m 0x1edf6d0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:1091:gst_v4l2_buffer_pool_dqbuf:<v4l2src0:pool:src>[00m dequeued buffer 0x7fcb3c011000 seq:0 (ix=0), mem 0x1ddf650 used 4147200, plane=0, flags 00002001, ts 0:00:20.298175000, pool-queued=1, buffer=0x7fcb3c011000 0:00:00.133593102 [336m 2507[00m 0x1edf6d0 [33;01mLOG [00m [00m v4l2allocator gstv4l2allocator.c:1294:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator>[00m dequeued buffer 1 (flags 0x2005) 0:00:00.133598592 [336m 2507[00m 0x1edf6d0 [37mDEBUG [00m [00m v4l2allocator gstv4l2allocator.c:1298:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator>[00m driver pretends buffer is queued even if dequeue succeeded 0:00:00.133602604 [336m 2507[00m 0x1edf6d0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:1091:gst_v4l2_buffer_pool_dqbuf:<v4l2src0:pool:src>[00m dequeued buffer 0x7fcb3c011110 seq:1 (ix=1), mem 0x1ddf6e0 used 4147200, plane=0, flags 00002001, ts 0:00:20.308641000, pool-queued=1, buffer=0x7fcb3c011110 0:00:00.146825344 [336m 2507[00m 0x1edf6d0 [33;01mLOG [00m [00m v4l2allocator gstv4l2allocator.c:1294:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator>[00m dequeued buffer 0 (flags 0x2005) 0:00:00.146831734 [336m 2507[00m 0x1edf6d0 [37mDEBUG [00m [00m v4l2allocator gstv4l2allocator.c:1298:gst_v4l2_allocator_dqbuf:<v4l2src0:pool:src:allocator>[00m driver pretends buffer is queued even if dequeue succeeded 0:00:00.146836286 [336m 2507[00m 0x1edf6d0 [33;01mLOG [00m [00m v4l2 gstv4l2bufferpool.c:1091:gst_v4l2_buffer_pool_dqbuf:<v4l2src0:pool:src>[00m dequeued buffer 0x7fcb3c011000 seq:2 (ix=0), mem 0x1ddf650 used 4147200, plane=0, flags 00002001, ts 0:00:20.323491000, pool-queued=1, buffer=0x7fcb3c011000
Ok, that is interesting. So if you run it a second time on 1.2, do you get "flags 00002041" (the 4 means the buffer is corrupted) ? What I'm working on is a way to conceal the corrupted buffer and keep going. What I'm thinking though, is that we get corrupted buffer in 1.4 because the queue is smaller (2 buffers instead of 4 on 1.2). Is this your own build ? If so, could you change GST_V4L2_MIN_BUFFERS to 4 instead of 2 and retest ? If so, I'll probably go back to default of 4 buffers (for v4l2src) along with code to not fail when buffer is corrupted. p.s. sys/v4l2/gstv4l2object.h:41:#define GST_V4L2_MIN_BUFFERS 2
On 1.2, both times I run it, I get a few 00002045 flags in the first few messages, then it stabilizes and goes to 00002005 (I assume that's normal behavior). There is no difference the first or second time I run it. Regarding setting the GST_V4L2_MIN_BUFFERS to 4, I actually saw a message about this before I filed the bug and gave it a try and it had no effect. I've just tried it again, first setting it to 4 (and recompiling, reinstalling) and then trying 8 for the heck of it. Neither had any effect. :-( Thanks!
Ok, that confirms the corrupted buffers happens in any case, it's not directly our fault. I'll let you know as soon as I have a patch for you to test.
Created attachment 290805 [details] [review] Handle corrupted buffer with empty payload I've written this patch to address the issue. Would it be possible to patch gst-plugins-good and report if it's actually working on your HW. I've been simulating test here, as I don't seem to get any error on the USB device I own. Note that ideally we should send GAPs, but for 1.4 I think I would stick with just this, as adding GAPs is somewhat a feature, and something not that well tested.
Yay!!! It's looking good! I've applied the patch and am now able to successfully get video from the capture device repeatedly. No issue so far. I will continue to test...
1.5 commit b9992e43475265a4da2ae4aae0128fec12d9bfc2 Author: Nicolas Dufresne <nicolas.dufresne@collabora.co.uk> Date: Sun Nov 16 12:34:17 2014 -0500 v4l2: Handle corrupted buffer with empty payload This allow skipping buffer flagged with ERROR that has no payload. This is typical behaviour when a recovererable error occured during capture in the driver, but that no valid data was ever written into that buffer. This patch also translate V4L2_BUF_FLAG_ERROR into GST_BUFFER_FLAG_CORRUPTED. Hence decoding error produce by decoder due to missing frames will now be correctly marked. Finally, this fixes a buffer leak when EOS is reached. https://bugzilla.gnome.org/show_bug.cgi?id=740040
Comment on attachment 290805 [details] [review] Handle corrupted buffer with empty payload 1.4 commit f8726a5d5f1bbbc6d0df8280ccf53247e1f9f019 Author: Nicolas Dufresne <nicolas.dufresne@collabora.co.uk> Date: Sun Nov 16 12:34:17 2014 -0500 v4l2: Handle corrupted buffer with empty payload This allow skipping buffer flagged with ERROR that has no payload. This is typical behaviour when a recovererable error occured during capture in the driver, but that no valid data was ever written into that buffer. This patch also translate V4L2_BUF_FLAG_ERROR into GST_BUFFER_FLAG_CORRUPTED. Hence decoding error produce by decoder due to missing frames will now be correctly marked. Finally, this fixes a buffer leak when EOS is reached. https://bugzilla.gnome.org/show_bug.cgi?id=740040
Thanks for the report, and testing, this bug will be fixed in next stable release of GStreamer.
Thanks so much Nicolas!!!!
*** Bug 745190 has been marked as a duplicate of this bug. ***
As the duplicate mention, we are checking flags on the wrong buffer in the copy path.
Created attachment 297943 [details] [review] [PATCH] v4l2bufferpool: Check corruption flag on the right buffer We where checking the buffer we are copying to instead of the buffer we are copying from. https://bugzilla.gnome.org/show_bug.cgi?id=740040 --- sys/v4l2/gstv4l2bufferpool.c | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-)
Review of attachment 297943 [details] [review]: Master: commit 63746c4131352a880c1a127d464b013b57d597fb Author: Aleix Conchillo Flaqué <aleix@oblong.com> Date: Wed Feb 25 16:45:11 2015 -0800 v4l2bufferpool: Check corruption flag on the right buffer We where checking the buffer we are copying to instead of the buffer we are copying from. https://bugzilla.gnome.org/show_bug.cgi?id=740040 In 1.4: commit 2e125b6f5b74f5faa45763355570f74f286e6957 Author: Aleix Conchillo Flaqué <aleix@oblong.com> Date: Wed Feb 25 16:45:11 2015 -0800 v4l2bufferpool: Check corruption flag on the right buffer We where checking the buffer we are copying to instead of the buffer we are copying from. https://bugzilla.gnome.org/show_bug.cgi?id=740040
Thanks.
*** Bug 751573 has been marked as a duplicate of this bug. ***