Flickering mjpeg stream of ipcamera binding after upgrade to 3.2

kuczerek · December 23, 2021, 10:10am

Hello community,

I recently upgraded to 3.2 and changed my URLs to the new standard of the camera binding. For some reason in 3.2 the mjpeg stream is flickering every few seconds, sometimes minutes, like the following example. I didn’t change anything according to the ffmpeg installation. The recording is taken from the pure browserwindow, without implementing the image in an openhab widget.

Animation

Has someone else the same problems? Openhab is on a Raspberry Pi 4 with ffmpeg version 4.1.8-0+deb10u1+rpt1

Regards,
Boris.

matt1 · December 23, 2021, 10:23am

What is creating the mjpeg, is it the camera or is it getting converted by ffmpeg? If the latter then that can occur if ffmpeg is using UDP and not TCP for the input from the camera. What does the TRACE log show when you when you request the ipcamera.mjpeg stream?

kuczerek · December 23, 2021, 11:11am

I think the stream is created by the camera. I passed a URL of my camera to the binding configuration field “MJPEG URL”. If I enter the same URL in a normal browser window I get a smooth stream. If I enter the URL provided by the binding in a normal browser window I get the flickering stream.

I think I’m not on low level TCP / UDP, but on HTTP over TCP/IP, since I use a http URL to provide the MJPEG stream to the binding. The HTTP URL is using Port 80, and not the special TCP or UDP ports, which are additionally offered by my camera.

This is the trace log

2021-12-23 11:57:54.849 [DEBUG] [amera.internal.servlet.CameraServlet] - GET:/ipcamera.mjpeg, received from 192.168.50.50
2021-12-23 11:57:54.851 [DEBUG] [amera.internal.servlet.CameraServlet] - First stream requested, opening up stream from camera
2021-12-23 11:57:54.856 [TRACE] [era.internal.handler.IpCameraHandler] - Sending camera: GET: http://192.168.50.72:80/cgi-bin/mjpg/video.cgi?channel=0&subtype=1

rainer.stoff · December 24, 2021, 8:53am

I also have this problem.

I have exactly the same setup as the thread creator and was previously on version 3.1.1, there everything worked (mjpeg through the camera, RPI 4, …).

paglatz · December 25, 2021, 2:56pm

Hi together!

awesome, just wanted to create an own topic for this. I do have exactly the same issue since my upgrade to OH3.2. It was working for me in the latest version of OH3.1 perfectly fine.

Playing around with the jmpeg settings in the INSTAR webui hasn’t had any effect, although i really tried a lot.

Here is my TRACE log:

2021-12-25 15:32:06.096 [TRACE] [era.internal.handler.IpCameraHandler] - Sending camera: GET: http://192.168.1.3:80/tmpfs/snap.jpg
2021-12-25 15:32:35.458 [DEBUG] [amera.internal.servlet.CameraServlet] - Now there are 0 ipcamera.mjpeg streams open.
2021-12-25 15:32:35.459 [DEBUG] [amera.internal.servlet.CameraServlet] - All ipcamera.mjpeg streams have stopped.
2021-12-25 15:32:35.559 [DEBUG] [amera.internal.servlet.CameraServlet] - GET:/ipcamera.mjpeg, received from 192.168.1.2
2021-12-25 15:32:35.561 [DEBUG] [amera.internal.servlet.CameraServlet] - First stream requested, opening up stream from camera
2021-12-25 15:32:35.571 [TRACE] [era.internal.handler.IpCameraHandler] - Sending camera: GET: http://192.168.1.3:80/mjpegstream.cgi?-chn=12
2021-12-25 15:32:36.095 [TRACE] [era.internal.handler.IpCameraHandler] - Sending camera: GET: http://192.168.1.3:80/tmpfs/snap.jpg

My setup:

Raspberry Pi 4, 4GB
OH3.2
ffmpeg version 4.1.8-0+deb10u1+rpt1
INSTAR IN-9020HD, LAN based
ipcamera binding, thing, MJPEG URL channel and item created in the web ui
Display via

Video url="http://192.168.1.2:8080/ipcamera/19216814412/ipcamera.mjpeg" encoding="mjpeg"

Would be very thankful for any hint
Patrick

matt1 · December 28, 2021, 6:52am

Can someone post some TRACE level with the special build that is here? This one will log extra stuff to help fault find what is going on. I can not reproduce it here with Dahua, Hikvision and Instar cameras.

Index of /openhab/IpCameraBinding/ (pcmus.com)

paglatz · December 28, 2021, 11:05am

Hi Matt,

I will test it, but it’s my sons fourth birthday will check it tomorrow I guess (or late evening today)

Thanks for all your support! If you want to, we can also have a TeamViewer session to debug the issue …

Thanks
Patrick

kuczerek · December 28, 2021, 11:33am

Hi Matt,

thanks for providing this version. I will post a TRACE this evening or tomorrow

Regards,
Boris.

SaschaQ88 · December 28, 2021, 3:10pm

Hi @matt1 ,

i installed the Trace version and set the log level to debug. When i set to trace, there was only a lot of unreadable signs.

Here is what i got:

2021-12-28 16:08:26.547 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.576 [DEBUG] [era.internal.handler.IpCameraHandler] - Boundary Found

2021-12-28 16:08:26.576 [DEBUG] [era.internal.handler.IpCameraHandler] - Magic bytes found for jpg

2021-12-28 16:08:26.578 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.579 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.580 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.581 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.582 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.583 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.584 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.585 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.586 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.587 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.616 [DEBUG] [era.internal.handler.IpCameraHandler] - Boundary Found

2021-12-28 16:08:26.617 [DEBUG] [era.internal.handler.IpCameraHandler] - Magic bytes found for jpg

2021-12-28 16:08:26.618 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.619 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.620 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.621 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.622 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.623 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.624 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.625 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.626 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.631 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.656 [DEBUG] [era.internal.handler.IpCameraHandler] - Boundary Found

2021-12-28 16:08:26.657 [DEBUG] [era.internal.handler.IpCameraHandler] - Magic bytes found for jpg

2021-12-28 16:08:26.658 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.659 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

2021-12-28 16:08:26.660 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

paglatz · December 28, 2021, 8:58pm

Hi @matt1

i also have checked your SNAPSHOT.jar. I uninstalled the official ipcamera binding, placed the jar in the addons folder, rebooted the pi, set the log LEVEL to trace and got MASSIVE output with cryptic characters (6MB log file in ~30-60sec).

When i reduce the log level to DEBUG, i nearly get the same log as Sascha. In addition, i saw the following (manually went through all the log lines, dropping the cryptic lines):

2021-12-28 21:06:11.459 [TRACE] [era.internal.handler.IpCameraHandler] - Sending camera: GET: http://192.168.1.3:80/tmpfs/snap.jpg
2021-12-28 21:06:11.472 [TRACE] [era.internal.handler.IpCameraHandler] - DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
2021-12-28 21:06:20.160 [DEBUG] [amera.internal.servlet.CameraServlet] - GET:/ipcamera.mjpeg, received from 192.168.1.2
2021-12-28 21:06:20.167 [DEBUG] [amera.internal.servlet.CameraServlet] - Not the first stream requested but the stream from camera was closed
2021-12-28 21:06:20.178 [TRACE] [era.internal.handler.IpCameraHandler] - Sending camera: GET: http://192.168.1.3:80/mjpegstream.cgi?-chn=12
2021-12-28 21:06:20.193 [TRACE] [era.internal.handler.IpCameraHandler] - DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
2021-12-28 21:06:20.238 [TRACE] [era.internal.handler.IpCameraHandler] - --ThisMjpegStream
2021-12-28 21:06:20.241 [DEBUG] [era.internal.handler.IpCameraHandler] - Boundary Found
2021-12-28 21:06:20.242 [DEBUG] [era.internal.handler.IpCameraHandler] - Magic bytes found for jpg
2021-12-28 21:06:20.247 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.251 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.254 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.256 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.262 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.358 [TRACE] [era.internal.handler.IpCameraHandler] - --ThisMjpegStream
2021-12-28 21:06:20.360 [DEBUG] [era.internal.handler.IpCameraHandler] - Boundary Found
2021-12-28 21:06:20.362 [DEBUG] [era.internal.handler.IpCameraHandler] - Magic bytes found for jpg
2021-12-28 21:06:20.367 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.372 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.377 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.388 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.391 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.518 [TRACE] [era.internal.handler.IpCameraHandler] - --ThisMjpegStream
2021-12-28 21:06:20.521 [DEBUG] [era.internal.handler.IpCameraHandler] - Boundary Found
2021-12-28 21:06:20.522 [DEBUG] [era.internal.handler.IpCameraHandler] - Magic bytes found for jpg
2021-12-28 21:06:20.528 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.534 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.538 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.540 [DEBUG] [amera.internal.servlet.CameraServlet] - Now there are 0 ipcamera.mjpeg streams open.
2021-12-28 21:06:20.540 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.541 [DEBUG] [amera.internal.servlet.CameraServlet] - All ipcamera.mjpeg streams have stopped.
2021-12-28 21:06:20.544 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:20.546 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:21.813 [DEBUG] [amera.internal.servlet.CameraServlet] - GET:/ipcamera.mjpeg, received from 192.168.1.2
2021-12-28 21:06:21.815 [DEBUG] [amera.internal.servlet.CameraServlet] - First stream requested, opening up stream from camera
2021-12-28 21:06:21.834 [TRACE] [era.internal.handler.IpCameraHandler] - Sending camera: GET: http://192.168.1.3:80/mjpegstream.cgi?-chn=12
2021-12-28 21:06:21.845 [TRACE] [era.internal.handler.IpCameraHandler] - DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
2021-12-28 21:06:21.968 [TRACE] [era.internal.handler.IpCameraHandler] - --ThisMjpegStream
2021-12-28 21:06:21.969 [DEBUG] [era.internal.handler.IpCameraHandler] - Boundary Found
2021-12-28 21:06:21.971 [DEBUG] [era.internal.handler.IpCameraHandler] - Magic bytes found for jpg
2021-12-28 21:06:21.976 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:21.980 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:21.985 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:21.989 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary
2021-12-28 21:06:21.994 [DEBUG] [era.internal.handler.IpCameraHandler] - data with no boundary

If you wish to, i can send you also the extended TRACE log as a private image (i believe the cryptic chars are the picture data and i would keep it as private as possible).

Thanks for your support
Patrick

matt1 · December 29, 2021, 3:00am

There is no need to, as the DEBUG logs are working and showed nothing is going wrong in the places I put that code, so nothing will be learnt by looking at the TRACE level.

@SaschaQ88 That shows it is getting a frame rate of 25 frames a second.
@paglatz Yours is around 8.4 frames a second.

This was calculated by the time between the boundaries. My first thoughts are this may be a non thread safe piece of code causing a race. So does changing the FPS to a number of different values and pausing and unpausing the cameras have any effect? If the timing is changed it may change what is happening and give us a clue as to where the issue is.

Your all using Pi4 so it may be that my faster CPU does not reproduce the issue. Changing the FPS here does not allow me to reproduce any issues even at 25FPS with a single camera.

If I can reproduce it, things would move faster so we need to work out what is different. I’ll have another look tonight to see what I can do to log further into the serving out of the stream as the incoming code is working without issues.

SaschaQ88 · December 29, 2021, 5:35am

Hi @matt1 ,

i have changed the FPS of the stream to several setting but nothing changed.

Best regards

Lukas_1st · December 29, 2021, 10:31am

Hi,

I have exactly the same effect with my Foscam cameras. I have the OpenHAB running on Pi3B. To verify the problem, I have run the ipcamera binding on the computer in the development environment and everything is fine here. The stream is transmitted all the time without any flickering or freezing.

kuczerek · December 29, 2021, 11:51am

@matt1 Is there any need to do further debugging with your special jar-file? I could install it too an provide some trace information - or did you already get what you want?

In the meantime I duplicated my installation on a second pi. It turns out, that the flicker doesn’t happen synchronously on both machines using the same configuration, camera stream, etc… Each one flickers in its own rhythm. Seems, that systemload doesn’t have a considerable effect. In my case the machine with lower systemload did flicker more often than the other machine, but maybe this is pure coincidence.

I noticed that during night the flicker effect is noticeably lower than at daytime. During the night my camera picture is only black / white, while on daytime it has normal colours.

matt1 · December 30, 2021, 1:33am

@paglatz
@rainer.stoff
@SaschaQ88
I just uploaded a newer jar here Index of /openhab/IpCameraBinding/

I did find a potential issue where if the FIFO buffer is running out of space it would cause the symptoms people are seeing. I added logging and increased the size of the FIFO in this build so it may fix/help the issue as well as log if that is the cause if it still happens.

kuczerek · December 30, 2021, 10:03am

HI @matt1
thank you, for trying to fix this problem. I tried the new jar. I think It’s better than before, but the the flickering is not totally gone.

I tried it on two different pi’s. While one the pi #1 it is nearly completely gone, on pi #2 it is reduced by maybe 70%. Both pi’s are Model 4b with 4 GB RAM, pi #1 is on Raspbian GNU/Linux 10 (buster), pi#2 on Raspbian GNU/Linux 11 (bullseye)". On pi#2 there is also a X-Window System online, this might cause additional load to the gpu, but I don’t know if the binding makes use of the gpu.

In DEBUG mode I get some of the following logs:

[DEBUG] [camera.internal.servlet.StreamOutput] - FIFO buffer has run out of space:Queue full

Not every a time a log entry is written the image is flickers, but every time the images flickers the log entry is written, sometimes two or three entries per flicker.

matt1 · December 30, 2021, 11:35am

Uploaded a new one, try to see if it is fixed now.

kuczerek · December 30, 2021, 12:10pm

I think that’s it!

Installed the jar on both pi’s and watched the stream for 10 minutes. Can’t see the problem anymore and no more log entries in DEBUG mode.

Very nice @matt1 Thanks a lot!!!

paglatz · December 30, 2021, 9:29pm

Hi @matt1,

perfect! Your fix is working for me as well! Thanks a thousand times for your support and your time spent on this! AWESOME.

Just out of interest: Is there any downside on increasing the FIFO size?

Thanks and happy new beginning of 2022!
Patrick

matt1 · December 31, 2021, 2:22am

It will use a tiny bit more ram, not enough to mention or notice. The alternative would be to use a tiny bit more non stop CPU to detect when the start of a new jpg frame occurs to throw away a whole frame.

It would be interesting to work out why this happens on your setups and not mine. Perhaps you have plenty of network traffic, a network switch can not keep up, or your using the wifi network card on the pi4? I will have to look at the way the fifo buffer is implemented some more in depth to make sure it is streamlined as much as can be for low CPU devices. Since someone posted it did not get worse with higher system load then I suspect it is not that.