kerberos-io / agent

An open and scalable video surveillance system for anyone making this world a better and more peaceful place.
https://kerberos.io
MIT License
642 stars 78 forks source link

Connection resetting from agent to USB Camera (transformed to RTSP stream) #58

Closed vadimzharov closed 1 year ago

vadimzharov commented 1 year ago

I have an USB camera on my Lenovo laptop (running Fedora 35 Linux) and I ran RTSP Simple server according to this guide https://github.com/kerberos-io/camera-to-rtsp to expose it via RTSP as a container.

The command I used is: podman run --rm --name rtsp-server --network=host -d --privileged -v $PWD/rtsp-simple-server.yml:/rtsp-simple-server.yml kerberos/rtsp-simple-server

File rtsp-simple-server.yml changed according to the doc, added lines:

paths:
       usbcam:
        runOnInit: ffmpeg -f v4l2 -i /dev/video0 -preset ultrafast -c:v libx264 -f rtsp rtsp://<MY_IP>:$RTSP_PORT/$RTSP_PATH
        runOnInitRestart: yes 

The server is working and I can connect to the camera using VLC and see live video without any interruptions.

Then I ran agent using latest docker image using this command: podman run --rm --name kerberos -p 8081:80 -d kerberos/agent:latest

Both containers are running on the same host (Lenovo with Fedora).

The agent is working and accessible via port 8081, and I can successfully add camera in agent UI using URL rtsp://:8554/usbcam - if I click Verify connection it saying Camera settings are successfully verified. However, the Live view doesn't work - it shows nothing (only button Configure connection).

Also in the dashboard the message in IP camera frame is flipping from "Connected" to "Disconnected"

If I enable Continuous recording - then recording is happening - I see files available in Recordings - and each file has length 16-20 sec. It means agent can connect to the camera and do recordings, but looks like the connection is interrupting.

In rtsp-simple-server container I see following log messages:

2022/12/01 01:22:12 INF [RTSP] [conn <MY IP>:36654] opened
2022/12/01 01:22:12 INF [RTSP] [session 250958557] created by <MY IP>:36654
2022/12/01 01:22:12 INF [RTSP] [session 250958557] is reading from path 'usbcam', with TCP, 1 track (H264)
2022/12/01 01:22:36 INF [RTSP] [conn <MY IP>:36654] closed (read tcp <MY IP>:8554-><MY IP>:36654: read: connection reset by peer)
2022/12/01 01:22:36 INF [RTSP] [session 250958557] destroyed (not in use)

Looks like the connection between agent and rtsp server is resetting each ~20 sec.

But this is not happening for VLC connection, it stays for any period of time, for example, if I open streaming in VLC:

2022/12/01 01:31:08 INF [RTSP] [conn <MY IP>:39496] opened
2022/12/01 01:31:08 INF [RTSP] [session 284726513] created by <MY IP>:39496
2022/12/01 01:31:08 INF [RTSP] [session 284726513] is reading from path 'usbcam', with UDP, 1 track (H264)

It stays forever and finish only when I stop streaming in VLC with this message in logs:

2022/12/01 01:44:35 INF [RTSP] [session 284726513] destroyed (teared down by 1<MY IP>:39496)
2022/12/01 01:44:35 INF [RTSP] [conn <MY IP>:39496] closed (EOF)

Also I noticed in Agent container logs that machinery is restarting constantly:

{"level":"info","msg":"ProcessMotion: Motion detection enabled.","time":"2022-12-01T02:02:37+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 3","time":"2022-12-01T02:02:40+01:00"}
{"level":"info","msg":"HandleStream: packet size 129966","time":"2022-12-01T02:02:41+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 4","time":"2022-12-01T02:02:45+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 4","time":"2022-12-01T02:02:50+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 4","time":"2022-12-01T02:02:55+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 4","time":"2022-12-01T02:03:00+01:00"}
{"level":"info","msg":"Main: Restarting machinery.","time":"2022-12-01T02:03:00+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 4","time":"2022-12-01T02:03:00+01:00"}
{"level":"info","msg":"Main: Restarting machinery.","time":"2022-12-01T02:03:00+01:00"}
{"level":"info","msg":"RunAgent: waiting 3 seconds to make sure everything is properly closed.","time":"2022-12-01T02:03:01+01:00"}
{"level":"info","msg":"Successfully Opened config.json from opensource","time":"2022-12-01T02:03:04+01:00"}
{"level":"info","msg":"RunAgent: opening RTSP stream","time":"2022-12-01T02:03:04+01:00"}
{"level":"info","msg":"RunAgent: opened RTSP stream","time":"2022-12-01T02:03:04+01:00"}
{"level":"info","msg":"RunAgent: SetMaxGopCount was set with: 10","time":"2022-12-01T02:03:04+01:00"}
{"level":"info","msg":"ConfigureMQTT: not starting as running in Offline mode.","time":"2022-12-01T02:03:04+01:00"}
{"level":"info","msg":"HandleRecordStream: Start motion based recording ","time":"2022-12-01T02:03:04+01:00"}
{"level":"info","msg":"ProcessMotion: Motion detection enabled.","time":"2022-12-01T02:03:04+01:00"}
{"level":"info","msg":"HandleStream: packet size 84577","time":"2022-12-01T02:03:06+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:07+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:12+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:17+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:22+01:00"}
{"level":"info","msg":"Main: Restarting machinery.","time":"2022-12-01T02:03:22+01:00"}
{"level":"info","msg":"RunAgent: waiting 3 seconds to make sure everything is properly closed.","time":"2022-12-01T02:03:23+01:00"}

Troubleshooting Done docker image kerberos/agent:latest I tried to run agent on separate RPI4 host - and I'm having the same issue (USB camera on Lenovo Laptop and agent on RPI) - connection resetting after ~20 sec.

Host Specs: Lenovo T260 with Fedora 36 + podman + USB camera Agent tested also on RPI4 with Ubuntu 22.04

cedricve commented 1 year ago

Thanks @vadimzharov for the very detailed information! It looks like the agent is able to open the stream, but cannot read the packets (or just for some seconds). The behaviour below happens, if the agent is not able to read key frames.

{"level":"info","msg":"HandleStream: packet size 84577","time":"2022-12-01T02:03:06+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:07+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:12+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:17+01:00"}
{"level":"info","msg":"ControlAgent: Number of packets read 5","time":"2022-12-01T02:03:22+01:00"}
{"level":"info","msg":"Main: Restarting machinery.","time":"2022-12-01T02:03:22+01:00"}

The log is showing though that it is able to read the first key frame, but afterwards no new packets were able to read. The mechanism you see in place is that it checks if the stream is working for 4 times in a row, and if not it will restart the agent as an issue occurred with the stream (as it assumed that no new key frames means, a dead stream).

Please note that VLC and this Kerberos Agent are different. Kerberos Agent is more lightweight and doesn't contain fallback mechanisms as VLC, so if VLC processes a stream it might correct the stream on the fly to be able to view it.

My advise would be to look into the stream, and gather some more statistics using ffplay to know more about the headers. Also I would like to modify the ffmpeg configuration a bit, it might be that we need to force some attributes like keyframe interval.

vadimzharov commented 1 year ago

Sorry, I'm not good with ffmpeg/ffplay, so I don't know how to properly look into stream. I installed ffplay, and when I ran this command: ffplay rtsp://<MY_IP>:8554/usbcam I'm getting this output:

ffplay version 5.0.2 Copyright (c) 2003-2022 the FFmpeg developers
  built with gcc 12 (GCC)
  configuration: --prefix=/usr --bindir=/usr/bin --datadir=/usr/share/ffmpeg --docdir=/usr/share/doc/ffmpeg --incdir=/usr/include/ffmpeg --libdir=/usr/lib64 --mandir=/usr/share/man --arch=x86_64 --optflags='-O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection' --extra-ldflags='-Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -Wl,--build-id=sha1 ' --extra-cflags=' -I/usr/include/rav1e' --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libvo-amrwbenc --enable-version3 --enable-bzlib --enable-chromaprint --disable-crystalhd --enable-fontconfig --enable-frei0r --enable-gcrypt --enable-gnutls --enable-ladspa --enable-libaom --enable-libdav1d --enable-libass --enable-libbluray --enable-libbs2b --enable-libcdio --enable-libdrm --enable-libjack --enable-libfreetype --enable-libfribidi --enable-libgsm --enable-libilbc --enable-libmp3lame --enable-libmysofa --enable-nvenc --enable-openal --enable-opencl --enable-opengl --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librsvg --enable-librav1e --enable-librubberband --enable-libsmbclient --enable-version3 --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libsvtav1 --enable-libtheora --enable-libtwolame --enable-libvorbis --enable-libv4l2 --enable-libvidstab --enable-libvmaf --enable-version3 --enable-vapoursynth --enable-libvpx --enable-vulkan --enable-libglslang --enable-libwebp --enable-libx264 --enable-libx265 --enable-libxvid --enable-libxml2 --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-avfilter --enable-libmodplug --enable-postproc --enable-pthreads --disable-static --enable-shared --enable-gpl --disable-debug --disable-stripping --shlibdir=/usr/lib64 --enable-lto --enable-libmfx --enable-runtime-cpudetect
  libavutil      57. 17.100 / 57. 17.100
  libavcodec     59. 18.100 / 59. 18.100
  libavformat    59. 16.100 / 59. 16.100
  libavdevice    59.  4.100 / 59.  4.100
  libavfilter     8. 24.100 /  8. 24.100
  libswscale      6.  4.100 /  6.  4.100
  libswresample   4.  3.100 /  4.  3.100
  libpostproc    56.  3.100 / 56.  3.100
Input #0, rtsp, from 'rtsp://<MY_IP>:8554/usbcam': 0B f=0/0   
  Metadata:
    title           : Stream
  Duration: N/A, start: 0.253678, bitrate: N/A
  Stream #0:0: Video: h264 (High 4:2:2), yuv422p(progressive), 1280x720, 10 fps, 10 tbr, 90k tbn

And I can see output from my camera without any interruptions. I don't know if this is relevant, but window with video appears after ~ 8 seconds after I execute the command. VLC has similar delay before show the video.

vadimzharov commented 1 year ago

Ok, I googled keyframe interval (again, I don't know what I'm doing). I added -x264-params keyint=120:scenecut=0 to RTSP server config, so it looks like this:

paths:
       usbcam:
        runOnInit: ffmpeg -f v4l2 -i /dev/video0 -preset ultrafast -c:v libx264 -x264-params keyint=120:scenecut=0 -f rtsp rtsp://<my_ip>:$RTSP_PORT/$RTSP_PATH
        runOnInitRestart: yes 

And now camera connection is stable (not flipping in Agent dashboard) and I can see live view/can set region of interest and agent is able to write recordings length more than 20 sec - so looks like agent is working as it should be.

Please advice if I applied correct settings (keyframe interval) or any other settings I need to apply for the agent.

cedricve commented 1 year ago

Interesting, I believe it depends on the USB camera you might use, but you did exactly what I was referring to. This is setting the keyinterval to every "120frames", which means if your usb camera has 20FPS, it will generate a keyframe every 120/20=6s. Personally I would pull it down to 60.

Let me update the configuration and add the x264-params, so other people can benefit from this.

Please keep us posted if your setup stays "stable" even after a few days.

cedricve commented 1 year ago

Modified the configuration file, thanks for reporting. I changed force keyint to 60, not sure if you experimented with that as well. Feel free to reopen this issue if anymore problems @vadimzharov .

vadimzharov commented 1 year ago

Comment just to confirm that solution is working. I changed the value to 60 and command is runOnInit: ffmpeg -f v4l2 -i /dev/video0 -preset ultrafast -c:v libx264 -x264-params keyint=60:scenecut=0 -f rtsp rtsp://<my_ip>:$RTSP_PORT/$RTSP_PATH Camera + agent have been working with no issues for more than 24 hours, recording/motion detection works. Thank you @cedricve !