Assert with v4l2loopback

[dumblob]

Does anyone have any idea how to use uStreamer (patched if needed) for low-latency streaming of desktop (whole or at least a given window) into mjpeg?

[mdevaev]

This is the interteresting case. Try this: https://superuser.com/questions/411897/using-desktop-as-fake-webcam-on-linux

After getting /dev/videoX you can stream it using ustreamer.

[dumblob]

Thanks for the quick response. I've tried that and it works - for couple of seconds and then uStreamer dumps core with assertion (ffmpeg runs further without any errors nor interruption). See below

ffmpeg -f x11grab -r 30 -s 1680x1050 -i :1.0+0,0 -vcodec rawvideo -pix_fmt rgb565 -threads 4 -f v4l2 /dev/video2
...

0$ ustreamer -q 97 -m RGB565 -r 1680x1050 -d /dev/video2
-- INFO  [744770.269      main] -- Installing SIGINT handler ...
-- INFO  [744770.269      main] -- Installing SIGTERM handler ...
-- INFO  [744770.269      main] -- Ignoring SIGPIPE ...
-- INFO  [744770.269      main] -- Using internal blank placeholder
-- INFO  [744770.269      main] -- Listening HTTP on [127.0.0.1]:8080
-- INFO  [744770.269      http] -- Starting HTTP eventloop ...
-- INFO  [744770.269    stream] -- Using V4L2 device: /dev/video2
-- INFO  [744770.269    stream] -- Using desired FPS: 0
================================================================================
-- INFO  [744770.269    stream] -- Device fd=8 opened
-- INFO  [744770.269    stream] -- Using input channel: 0
-- INFO  [744770.269    stream] -- Using TV standard: DEFAULT
-- INFO  [744770.269    stream] -- Using resolution: 1680x1050
-- INFO  [744770.269    stream] -- Using pixelformat: RGB565
-- INFO  [744770.269    stream] -- Changing HW FPS is not supported
-- INFO  [744770.269    stream] -- Using IO method: MMAP
-- INFO  [744770.269    stream] -- Requested 3 HW buffers, got 2
-- INFO  [744770.270    stream] -- Capturing started
-- INFO  [744770.270    stream] -- Using JPEG quality: 97%
-- INFO  [744770.270    stream] -- Creating pool with 2 workers ...
-- INFO  [744770.270    stream] -- Capturing ...
-- INFO  [744776.178      http] -- HTTP: Registered client: [127.0.0.1]:46906, id=c0f4afcb-5f23-4214-aacc-3eaa155d7202; clients now: 1
-- INFO  [744796.642      http] -- HTTP: Registered client: [127.0.0.1]:46910, id=57351147-4295-4737-88ca-e81be4556a8b; clients now: 2
-- INFO  [744796.716      http] -- HTTP: Disconnected client: [127.0.0.1]:46906, id=c0f4afcb-5f23-4214-aacc-3eaa155d7202, Success (reading,eof); clients now: 1
ustreamer: src/encoder.c:204: encoder_compress_buffer: Assertion `dev->run->hw_buffers[buf_index].used > 0' failed.
Aborted (core dumped)
$ echo $?
134

My system is recent Arch with kernel 5.4.61-1-lts #1 SMP Wed, 26 Aug 2020 18:35:48 +0000 x86_64 GNU/Linux . I'm running X11 with FVWM (i.e. very basice) window manager. I've connected to the mjpeg stream with Chromium 84.0.4147.105 (I used the trick advance_headers=1).

I've also tried rgb24 and different -q numbers. Always the same issue - after few seconds it gets black and either dumps core immediately or after another few seconds.

[mdevaev]

Which version of ustreamer are you using?

[mdevaev]

Okay, reproduced.

[mdevaev]

This looks like a ustreamer bug, but it actually looks like a v4l2loopback bug. The device gives us two buffers with the index 0 and 1. The problem is (simplified):

• ustreamer requests a buffer
• v4l2 gives a buffer of 0
• ustreamer requests a buffer
• v4l2 gives buffer 1
• ustreamer decides that it wants to skip this frame and returns buffer 1
• ustreamer requests a buffer
• v4l2 provides the buffer 0 for the SECOND TIME

Log

-- DEBUG [89859.875    stream] -- Calling ioctl(VIDIOC_DQBUF) ...
-- DEBUG [89859.875    stream] -- Got a new frame in buffer: index=0, bytesused=2098176
-- VERB  [89859.875    stream] -- Correcting approx_comp_time: 0.447 -> 0.454 (last_comp_time=0.513)
-- VERB  [89859.875    stream] -- Fluency: delay=0.227, grab_after=89860.102
-- DEBUG [89859.875    stream] -- Assigned new frame in buffer 0 to worker 0
-- DEBUG [89859.950  worker-1] -- Calling ioctl(VIDIOC_QBUF) index=1 ...
-- DEBUG [89859.950      http] -- Refreshing HTTP exposed ...
-- VERB  [89859.950      http] -- HTTP: Exposed new frame; full exposition time = 0.000000
-- DEBUG [89859.950  worker-0] -- Worker 0 compressing JPEG from buffer 0 ...
-- VERB  [89859.951  worker-0] -- Compressing buffer 0 using CPU
--------------------------------------------------------------------------------
-- DEBUG [89859.975    stream] -- Waiting for worker ...
-- VERB  [89859.976  worker-1] -- Compressed new JPEG: size=306809, time=0.545, worker=1, buffer=1
-- DEBUG [89859.976  worker-1] -- Worker 1 waiting for a new job ...
-- PERF  [89859.976    stream] -- ##### Encoded picture exposed; worker=1
-- DEBUG [89859.976    stream] -- Calling select() on video device ...
-- DEBUG [89859.976    stream] -- Device select() --> 1
-- DEBUG [89859.977    stream] -- Frame is ready
-- DEBUG [89859.977    stream] -- Calling ioctl(VIDIOC_DQBUF) ...
-- DEBUG [89859.977    stream] -- Got a new frame in buffer: index=1, bytesused=2098176
-- VERB  [89859.977    stream] -- Passed 1 frames for fluency: now=89859.977, grab_after=89860.102
-- DEBUG [89859.979    stream] -- Calling ioctl(VIDIOC_QBUF) index=1 ...
--------------------------------------------------------------------------------
-- DEBUG [89859.980    stream] -- Waiting for worker ...
-- PERF  [89859.980    stream] -- ----- Encoded picture dropped; worker=1
-- DEBUG [89859.980    stream] -- Calling select() on video device ...
-- DEBUG [89860.008      http] -- Refreshing HTTP exposed ...
-- VERB  [89860.008      http] -- HTTP: Exposed new frame; full exposition time = 0.000000
-- DEBUG [89860.008    stream] -- Device select() --> 1
-- DEBUG [89860.008    stream] -- Frame is ready
-- DEBUG [89860.008    stream] -- Calling ioctl(VIDIOC_DQBUF) ...
-- DEBUG [89860.009    stream] -- Got a new frame in buffer: index=0, bytesused=2098176
-- VERB  [89860.009    stream] -- Passed 2 frames for fluency: now=89860.008, grab_after=89860.102
-- DEBUG [89860.009    stream] -- Calling ioctl(VIDIOC_QBUF) index=0 ...
--------------------------------------------------------------------------------
-- DEBUG [89860.009    stream] -- Waiting for worker ...
-- PERF  [89860.009    stream] -- ----- Encoded picture dropped; worker=1
-- DEBUG [89860.009    stream] -- Calling select() on video device ...
-- DEBUG [89860.157    stream] -- Device select() --> 1
-- DEBUG [89860.157    stream] -- Frame is ready
-- DEBUG [89860.157    stream] -- Calling ioctl(VIDIOC_DQBUF) ...
-- DEBUG [89860.157    stream] -- Got a new frame in buffer: index=0, bytesused=2098176
-- PERF  [89860.157    stream] -- A new second has come; captured_fps=2
-- VERB  [89860.157    stream] -- Correcting approx_comp_time: 0.454 -> 0.463 (last_comp_time=0.545)
-- VERB  [89860.157    stream] -- Fluency: delay=0.232, grab_after=89860.389
-- DEBUG [89860.158    stream] -- Assigned new frame in buffer 0 to worker 1
-- DEBUG [89860.421  worker-0] -- Calling ioctl(VIDIOC_QBUF) index=0 ...
-- DEBUG [89860.421  worker-1] -- Worker 1 compressing JPEG from buffer 0 ...
-- VERB  [89860.421  worker-0] -- Compressed new JPEG: size=156895, time=0.470, worker=0, buffer=0
ustreamer: src/encoder.c:204: encoder_compress_buffer: Assertion `dev->run->hw_buffers[buf_index].used > 0' failed.

Because of the race situation, two workers try to encode and release the same buffer at the same time. Unlike regular software, ustreamer encodes buffers in parallel, so this bug might not have been noticed earlier.

Can I ask you to report this issue to the v4l2loopback developer and talk to them? I have a lot of work on the main direction right now :(

[dumblob]

Sorry for coming back so late. Thanks for such speedy investigation! I'll try to report it to v4l2loopback and see what can be done.

I'm though alsou certain ustreamer should not dump its core and somehow "skip" this inconsistency despite producing garbled or somehow distorted results.

Dumping core is far worse in long running apps (which ustreamer is meant for) in practice than producing garbled/distorted results (ideally with a warning/error message for the first occurence of such issue).

Btw. this is not an objection - I myself write asserts everywhere instead of logging and only if such real issues come up I'll "upgrade" the assert to a log message or whatever. I'd be happy if ustreamer took this approach this time as well 😉.

Thoughts?

[mdevaev]

This is an incorrect situation and I do not know the correct way to handle it. Okay, I'm skipping a frame, but what should I do with the buffer? Should I release him or not? Even if I have a solution in this particular case, I believe that it is better for the software to fall than to do something strange that can lead to system failure.

[dumblob]

This is an incorrect situation and I do not know the correct way to handle it.

There is no correct way to handle that 😉.

Okay, I'm skipping a frame, but what should I do with the buffer? Should I release him or not?

I'd probably release him and issue a warn/error message. Basically I'd try to get rid of everything pointing to (or being referenced) from the state which caused the issue.

Even if I have a solution in this particular case, I believe that it is better for the software to fall than to do something strange that can lead to system failure.

Hm, I'd prefer to not break long running systems disregarding what the input device does. There might even exist HW behaving in such strange ways. Why would you prefer falling instead of gracefully "handling" it by "forgetting about the issue"?

[mdevaev]

Basically I'd try to get rid of everything pointing to (or being referenced) from the state which caused the issue.

Good point.

Hm, I'd prefer to not break long running systems disregarding what the input device does.

Minor errors can always be ignored, but what you found is a fundamental driver problem. It can be dangerous to continue working. Incorrect behavior can be caused by anything. What if the driver damages the kernel memory if I continue working? The problem should be fixed, not just ignored, even with a warning.

Why would you prefer falling instead of gracefully "handling" it by "forgetting about the issue"?

I didn't say I wouldn't do anything about this problem :) First I have to find out if it's even possible to work in this situation. If not, assert will be the best solution. Like this:

ustreamer: src/device.c:324: device_grab_buffer: Assertion `!dev->run->hw_buffers_busy[buf_info.index] && "V4L2 driver error: double grabbing of the buffer"' failed.

[mdevaev]

umlaeute/v4l2loopback#304

[mdevaev]

Okay, I changed my mind. I think in this situation, I can report the error message and reinitialize the device.

[mdevaev]

Okay, now in master is my fix for this problem. Ustreamer doesn't crash with an assert, it just closes the stream with the error and opens it again:

-- ERROR [32632.934    stream] -- V4L2 error: grabbed device buffer is already used: index=0, bytesused=2098176

Given that this is incorrect driver behavior with memory corruption, this is all I can do. As a temporary solution for v4l2loopback I suggest using a single buffer using uStreamer option --buffer=1. Unfortunately, performance suffers greatly with this, but this is all that can be done until the author of v4l2loopback fixes the problem. This is completely on his side.

[mdevaev]

Feel free to reopen if needed.

[dumblob]

Ustreamer doesn't crash with an assert, it just closes the stream with the error and opens it again

Thanks a lot! I'll test once there is a new release with this patch.