[FFmpeg-user] Seeking guidance on debugging rtsp copy to file

[Rich Andrews]

ffmpeg is being run as a python subprocess with careful attention to its
given FD's.  That part appears likely to be working especially as other
usages of ffmpeg to do non-network things such as transcoding work quite
well using the same subprocess design.  It is not believed ffmpeg is
deadlocking on STDIN, STDOUT or STDERR I/O.

The ffmpeg being used is ffmpeg version 4.1.3-1+rpt1 Copyright (c)
2000-2019 the FFmpeg developers built with gcc 8 (Raspbian 8.3.0-6+rpi1)
(full banner below).

ffmpeg is spawned as ffmpeg -nostdin -hide_banner -loglevel verbose -y
-rtsp_transport tcp -i rtsp://192.168.1.168/1 -vcodec copy -acodec copy -f
mp4 {output_url} It is receiving an RTSP substream from an HVEC HDMI
encoder.

What happens is that over time, sometimes within minutes, sometimes after
an hour, ffmpeg ceases writing to {output_url} without outputting
information. STDERR appears as

frame=51659 fps= 20 q=-1.0 size= 519424kB time=00:43:53.63
bitrate=1615.7kbits/s speed= 1x
frame=51669 fps= 19 q=-1.0 size= 519680kB time=00:43:54.09
bitrate=1616.2kbits/s speed=0.988x

At this point, the ffmpeg subprocess will just sit there and not respond to
signaling from the parent (sigint, currently testing sigterm and sigkill)
the parent process will also block on the ffmpeg subprocess exit at this
time, meaning that the parent also does not exit.   There is much work to
be done on this point as this is known to be a common source of issues.

ffmpeg when ceasing to write to {output_url} appears to take signals from
an unrelated shell (poor notes on this front, but certainly sigterm works
and IIRC sigint) and exits as would be expected.

When in this condition, I've inspected the ffmpeg subprocess.  Its FDs
appear as:

pi at raspberrypi:/tmp $ sudo ls -l /proc/31855/fd
total 0
lr-x------ 1 root root 64 Jan  8 21:18 0 -> /dev/null
l-wx------ 1 root root 64 Jan  8 21:18 1 ->
/tmp/ffmpeg_rtsp_91eac707-3ac3-4080-a5a9-8d9768eaea10.stdout
l-wx------ 1 root root 64 Jan  8 21:18 2 ->
/tmp/ffmpeg_rtsp_91eac707-3ac3-4080-a5a9-8d9768eaea10.stderr
lrwx------ 1 root root 64 Jan  8 21:18 3 -> 'socket:[4128650]'
lrwx------ 1 root root 64 Jan  8 21:18 4 -> 'socket:[4147521]'
l-wx------ 1 root root 64 Jan  8 21:18 5 ->
/tmp/91eac707-3ac3-4080-a5a9-8d9768eaea10.rtsp
lrwx------ 1 root root 64 Jan  8 21:18 6 -> 'socket:[4143741]'

strace shows

pi at raspberrypi:/tmp $ sudo strace -p 31855
strace: Process 31855 attached
poll([{fd=4, events=POLLIN}], 1, 100)   = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 100)   = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 100)   = 0 (Timeout)

So it appears to me that ffmpeg is probably working properly and that the
RTSP stream maybe goes away on the network.   The RTSP server seems to not
go away (remains on LAN, ICMP pings to it are not interrupted).

My next steps are:

1) Replicate this via a shell invocation of ffmpeg vs. as a subprocess
2) Kill remote RTSP server or otherwise perturb WLAN and characterize
ffmpeg exit behavior wrt the socket (difficult as this gear is all remote)
3) Try and catch this condition with -loglevel debug

So my questions could probably have been more brief, "What other debugging
techniques can be applied to introspecting the state of ffmpeg?".   I'm
guessing it has something to do with the RTSP stream, RTSP signaling and
the WLAN.   But maybe more experienced eyes will see something here and
help provide some guidance as to what I can do from ffmpeg's point of view.

Thanks!

ffmpeg version 4.1.3-1+rpt1 Copyright (c) 2000-2019 the FFmpeg
developers built with gcc 8 (Raspbian 8.3.0-6+rpi1)
  configuration: --prefix=/usr --extra-version=1+rpt1 --toolchain=hardened
--libdir=/usr/lib/arm-linux-gnueabihf
--incdir=/usr/include/arm-linux-gnueabihf --arch=arm --enable-gpl
--disable-stripping --enable-avresample --disable-filter=resample
--enable-avisynth --enable-gnutls --enable-ladspa --enable-libaom
--enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca
--enable-libcdio --enable-libcodec2 --enable-libflite
--enable-libfontconfig --enable-libfreetype --enable-libfribidi
--enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame
--enable-libmysofa --enable-libopenjpeg --enable-libopenmpt
--enable-libopus --enable-libpulse --enable-librsvg --enable-librubberband
--enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex
--enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab
--enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp
--enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzmq
--enable-libzvbi --enable-lv2 --enable-omx --enable-omx-rpi --enable-mmal
--enable-openal --enable-opengl --enable-sdl2 --enable-libdc1394
--enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r
--enable-libx264 --arch=armhf --enable-shared
  libavutil      56. 22.100 / 56. 22.100
  libavcodec     58. 35.100 / 58. 35.100
  libavformat    58. 20.100 / 58. 20.100
  libavdevice    58.  5.100 / 58.  5.100
  libavfilter     7. 40.101 /  7. 40.101
  libavresample   4.  0.  0 /  4.  0.  0
  libswscale      5.  3.100 /  5.  3.100
  libswresample   3.  3.100 /  3.  3.100
  libpostproc    55.  3.100 / 55.  3.100
Hyper fast Audio and Video encoder