[BUG] Regression caused by "media: gspca: convert to vb2"

[BUG] Regression caused by "media: gspca: convert to vb2"

[Matti Hämäläinen]

Hello!

Last week while testing some webcams that use gspca-based v4l2 drivers, I 
noticed that the driver was spewing some errors in klog whenever the 
program using them issued VIDIOC_STREAMOFF ioctl. This seems to be a
regression caused by commit 1f5965c4dfd7665f2914a1f1095dcc6020656b04
"media: gspca: convert to vb2" in the mainline kernel.

The errors were as follows (with gspca_main debug=3):
[ 2497.147902] gspca_zc3xx 3-9.3.2:1.0: isoc 32 pkts size 768 = bsize:24576
[ 2498.194657] gspca_zc3xx 3-9.3.2:1.0: probe 2wr ov vga 0x0000
[ 2499.602538] gspca_zc3xx 3-9.3.2:1.0: found int in endpoint: 0x82, buffer_len=8, interval=10
[ 2501.785244] gspca_zc3xx 3-9.3.2:1.0: kill transfer
[ 2501.787218] gspca_zc3xx 3-9.3.2:1.0: urb status: -2
[ 2501.787223] gspca_main: usb_submit_urb() ret -1
[ 2501.789217] gspca_zc3xx 3-9.3.2:1.0: urb status: -2
[ 2501.789222] gspca_main: usb_submit_urb() ret -1
[ 2501.791218] gspca_zc3xx 3-9.3.2:1.0: urb status: -2
[ 2501.791223] gspca_main: usb_submit_urb() ret -1
[ 2501.791226] gspca_zc3xx 3-9.3.2:1.0: releasing urbs
[ 2501.795919] gspca_zc3xx 3-9.3.2:1.0: found int in endpoint: 0x82, buffer_len=8, interval=10
[ 2501.870710] gspca_zc3xx 3-9.3.2:1.0: stream off OK

Additionally I noticed that on another PC I could trigger a complete 
hard system lockup simply by unplugging the USB camera when a video 
capture was ongoing AND while running under Xorg. (For some reason
without Xorg there was no hang.)

Also, on the same system another gspca camera (again with this commit) 
results in following errors on "clean" disconnect, e.g. plug on/off and no 
capture running:

[ 8492.613643] STV06xx 4-2:1.0: URB error -84, resubmitting
[ 8492.661638] STV06xx 4-2:1.0: URB error -84, resubmitting
[ 8492.709638] STV06xx 4-2:1.0: URB error -84, resubmitting
[ 8492.755542] usb 4-2: USB disconnect, device number 3


While I am no kernel dev, I believe that the changes to the mutex locking 
in the aforementioned commit are probably causing some race conditions.

What I think is happening in the first case (urb status errors) is that 
when userspace program does ioctl(fd, VIDIOC_STREAMOFF, V4L2_BUF_TYPE_VIDEO_CAPTURE),
the kernel goes to gspca_stream_off() and through that to destroy_urbs().

Meanwhile fill_frame() can get called from isoc_irq(), which then results
in the failures that spew "urb status: -2" to klog, goto resubmit ->
"usb_submit_urb() ret -1"

Sorry if I've forgotten to provide some relevant information,
feel free to ask if something is required.

-- 
] ccr/TNSP ^ pWp  ::  ccr@tnsp.org  ::  https://tnsp.org/~ccr/
] https://tnsp.org/hg/ -- https://www.openhub.net/accounts/ccr
] PGP key: 7BED 62DE 898D D1A4 FC4A  F392 B705 E735 307B AAE3

Re: [BUG] Regression caused by "media: gspca: convert to vb2"

[Hans Verkuil]

Hi Matti,

On 2/19/19 6:30 AM, Matti Hämäläinen wrote:
> 
> Hello!
> 
> Last week while testing some webcams that use gspca-based v4l2 drivers, I 
> noticed that the driver was spewing some errors in klog whenever the 
> program using them issued VIDIOC_STREAMOFF ioctl. This seems to be a
> regression caused by commit 1f5965c4dfd7665f2914a1f1095dcc6020656b04
> "media: gspca: convert to vb2" in the mainline kernel.
> 
> The errors were as follows (with gspca_main debug=3):
> [ 2497.147902] gspca_zc3xx 3-9.3.2:1.0: isoc 32 pkts size 768 = bsize:24576
> [ 2498.194657] gspca_zc3xx 3-9.3.2:1.0: probe 2wr ov vga 0x0000
> [ 2499.602538] gspca_zc3xx 3-9.3.2:1.0: found int in endpoint: 0x82, buffer_len=8, interval=10
> [ 2501.785244] gspca_zc3xx 3-9.3.2:1.0: kill transfer
> [ 2501.787218] gspca_zc3xx 3-9.3.2:1.0: urb status: -2
> [ 2501.787223] gspca_main: usb_submit_urb() ret -1
> [ 2501.789217] gspca_zc3xx 3-9.3.2:1.0: urb status: -2
> [ 2501.789222] gspca_main: usb_submit_urb() ret -1
> [ 2501.791218] gspca_zc3xx 3-9.3.2:1.0: urb status: -2
> [ 2501.791223] gspca_main: usb_submit_urb() ret -1
> [ 2501.791226] gspca_zc3xx 3-9.3.2:1.0: releasing urbs
> [ 2501.795919] gspca_zc3xx 3-9.3.2:1.0: found int in endpoint: 0x82, buffer_len=8, interval=10
> [ 2501.870710] gspca_zc3xx 3-9.3.2:1.0: stream off OK
> 
> Additionally I noticed that on another PC I could trigger a complete 
> hard system lockup simply by unplugging the USB camera when a video 
> capture was ongoing AND while running under Xorg. (For some reason
> without Xorg there was no hang.)
> 
> Also, on the same system another gspca camera (again with this commit) 
> results in following errors on "clean" disconnect, e.g. plug on/off and no 
> capture running:
> 
> [ 8492.613643] STV06xx 4-2:1.0: URB error -84, resubmitting
> [ 8492.661638] STV06xx 4-2:1.0: URB error -84, resubmitting
> [ 8492.709638] STV06xx 4-2:1.0: URB error -84, resubmitting
> [ 8492.755542] usb 4-2: USB disconnect, device number 3
> 
> 
> While I am no kernel dev, I believe that the changes to the mutex locking 
> in the aforementioned commit are probably causing some race conditions.
> 
> What I think is happening in the first case (urb status errors) is that 
> when userspace program does ioctl(fd, VIDIOC_STREAMOFF, V4L2_BUF_TYPE_VIDEO_CAPTURE),
> the kernel goes to gspca_stream_off() and through that to destroy_urbs().
> 
> Meanwhile fill_frame() can get called from isoc_irq(), which then results
> in the failures that spew "urb status: -2" to klog, goto resubmit ->
> "usb_submit_urb() ret -1"
> 
> Sorry if I've forgotten to provide some relevant information,
> feel free to ask if something is required.
> 

Which kernel version are you using?

I got other, similar reports as well and I plan to look at it next week.

Regards,

	Hans

Re: [BUG] Regression caused by "media: gspca: convert to vb2"

[Matti Hämäläinen]

[-- Attachment #1: Type: text/plain, Size: 1251 bytes --]

On Tue, 19 Feb 2019, Hans Verkuil wrote:

> Hi Matti,
>
> On 2/19/19 6:30 AM, Matti Hämäläinen wrote:
>>
>> Hello!
>>
>> Last week while testing some webcams that use gspca-based v4l2 drivers, I
>> noticed that the driver was spewing some errors in klog whenever the
>> program using them issued VIDIOC_STREAMOFF ioctl. This seems to be a
>> regression caused by commit 1f5965c4dfd7665f2914a1f1095dcc6020656b04
>> "media: gspca: convert to vb2" in the mainline kernel.

[...]
>
> Which kernel version are you using?
>
> I got other, similar reports as well and I plan to look at it next week.

Hi Hans,

Sorry, forgot to mention that. First I noticed it on a vanilla 4.20.8 
kernel, but bisected to the mentioned commit in Linus' mainline tree, 
which was merged in some 4.18-rc. 4.17.x and earlier without the 
change work fine.

I just tested with git://linuxtv.org/media_tree.git of today 
(5.0.0-rc7-test-00312-gb3c786566d8f), and the problems persist.
Actually I got my other PC to hard lockup, too, when disconnecting the 
camera while capture was on.


-- 
] ccr/TNSP ^ pWp  ::  ccr@tnsp.org  ::  https://tnsp.org/~ccr/
] https://tnsp.org/hg/ -- https://www.openhub.net/accounts/ccr
] PGP key: 7BED 62DE 898D D1A4 FC4A  F392 B705 E735 307B AAE3