Universalmediaserver: ffmpeg transcoded files are no longer playing as of 10.3.0

[mbentley]

Problem

I am running UMS headless inside of a Docker container. With what I assume is the new capability of "Improved automatic maximum bandwidth setting and enabled it by default", it looks like this is causing videos that were previously rendering fine to fail transcoding with ffmpeg. In taking a look at the differences, I found that it worked as of 10.2.0 but stopped working in 10.3.0. My best guess is that this problem came from #2399.

I'm not sure if it is just because I am running headless or not but it is passing in invalid argument to ffmpeg. In digging into the change a bit, it seems like there must be something in the handling of Automatic (Wireless) that isn't working in src/main/java/net/pms/encoders/FFMpegVideo.java + some settings I have set in my config (see below for my config) that are causing the value to be set in the parameter to not be returned properly.

Workaround:

Set automatic_maximum_bitrate = false in UMS.conf

Problem Details

I was digging through the logs and found where it is complaining about an invalid argument in 10.3.0:

DEBUG 11:58:53.612 [ffmpeg-12-2] ffmpeg version N-56320-ge937457b7b-static https://johnvansickle.com/ffmpeg/  Copyright (c) 2000-2021 the FFmpeg developers
DEBUG 11:58:53.612 [ffmpeg-12-2]   built with gcc 8 (Debian 8.3.0-6)
DEBUG 11:58:53.612 [ffmpeg-12-2]   configuration: --enable-gpl --enable-version3 --enable-static --disable-debug --disable-ffplay --disable-indev=sndio --disable-outdev=sndio --cc=gcc --enable-fontconfig --enable-frei0r --enable-gnutls --enable-gmp --enable-libgme --enable-gray --enable-libaom --enable-libfribidi --enable-libass --enable-libvmaf --enable-libfreetype --enable-libmp3lame --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libopenjpeg --enable-librubberband --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libvorbis --enable-libopus --enable-libtheora --enable-libvidstab --enable-libvo-amrwbenc --enable-libvpx --enable-libwebp --enable-libx264 --enable-libx265 --enable-libxml2 --enable-libdav1d --enable-libxvid --enable-libzvbi --enable-libzimg
DEBUG 11:58:53.612 [ffmpeg-12-2]   libavutil      56. 66.100 / 56. 66.100
DEBUG 11:58:53.612 [ffmpeg-12-2]   libavcodec     58.125.101 / 58.125.101
DEBUG 11:58:53.612 [ffmpeg-12-2]   libavformat    58. 68.100 / 58. 68.100
DEBUG 11:58:53.612 [ffmpeg-12-2]   libavdevice    58. 12.100 / 58. 12.100
DEBUG 11:58:53.612 [ffmpeg-12-2]   libavfilter     7.107.100 /  7.107.100
DEBUG 11:58:53.612 [ffmpeg-12-2]   libswscale      5.  8.100 /  5.  8.100
DEBUG 11:58:53.612 [ffmpeg-12-2]   libswresample   3.  8.100 /  3.  8.100
DEBUG 11:58:53.612 [ffmpeg-12-2]   libpostproc    55.  8.100 / 55.  8.100
DEBUG 11:58:53.648 [ffmpeg-12-2] Input #0, avi, from '/media/tv_shows/Star.Trek-.Enterprise/Season.4/S04E01.Storm.Front.(1).avi':
DEBUG 11:58:53.648 [ffmpeg-12-2]   Metadata:
DEBUG 11:58:53.648 [ffmpeg-12-2]     software        : VirtualDubMod 1.5.4.1 (build 2178/release)
DEBUG 11:58:53.648 [ffmpeg-12-2]   Duration: 00:42:48.94, start: 0.000000, bitrate: 1143 kb/s
DEBUG 11:58:53.648 [ffmpeg-12-2]   Stream #0:0: Video: mpeg4 (DX50 / 0x30355844), yuv420p, 720x416 [SAR 1:1 DAR 45:26], 945 kb/s, 23.98 fps, 23.98 tbr, 23.98 tbn, 30k tbc
DEBUG 11:58:53.648 [ffmpeg-12-2]   Stream #0:1: Audio: ac3 ([0] [0][0] / 0x2000), 48000 Hz, stereo, fltp, 192 kb/s
DEBUG 11:58:53.648 [ffmpeg-12-2] [NULL @ 0x6f1db80] Unable to find a suitable output format for 'Automatic'
DEBUG 11:58:53.648 [ffmpeg-12-2] Automatic: Invalid argument

Taking a look at the ffmpeg commands that are used to launch each, I see there is a difference:

10.2.0

DEBUG 12:05:07.921 [ffmpeg-2] Starting /opt/ums/linux/ffmpeg -y -loglevel info -i /media/tv_shows/Star.Trek-.Enterprise/Season.4/S04E01.Storm.Front.(1).avi -bufsize 1835k -maxrate 24000k -g 5 -q:v 1 -qmin 2 -c:a copy -c:v mpeg2video -f vo
b /tmp/UMS-ums/ffmpegvideo_57_1616328307606

10.3.0

DEBUG 11:59:31.743 [ffmpeg-20] Starting /opt/ums/linux/ffmpeg -y -loglevel info -i /media/tv_shows/Star.Trek-.Enterprise/Season.4/S04E01.Storm.Front.(1).avi -bufsize 1835k -maxrate 999000k Automatic (Wireless) -c:a copy -c:v mpeg2video -f vob /tmp/UMS-ums/ffmpegvideo_55_1616327971428

Logs

Here are the full trace logs:
ums_10.2.0.log
ums_10.3.0.log

Config

Here is my UMS.conf:

log_level = INFO
logging_filter_console = INFO
#log_level = DEBUG
#logging_filter_console = DEBUG
#log_level = TRACE
#logging_filter_console = TRACE
logging_buffered = true
cred.path = /opt/ums/UMS.cred
uuid = a52e6901-b7e4-4444-aa5a-1dd1e8b7480f
audio_embed_dts_in_pcm = false
encoded_audio_passthrough = false
maximum_bitrate = 0
mpeg2_main_settings = keyint=5:vqscale=1:vqmin=2
hide_advanced_options = false
run_wizard = false
folders = /media/christmas_movies, /media/movies, /media/movies_to_be_tagged, /media/tv_shows, /media/workout
external_network = false
folders_monitored =
show_media_library_folder = false
show_recently_played_folder = false
scan_shared_folders_on_startup = false
fully_played_action = 0
network_interface = eth0
audio_thumbnails_method = 1
thumbnail_seek_position = 60
use_cache = true
audio_subtitles_languages = eng,off
autoload_external_subtitles = false
disable_subtitles = true
audio_use_pcm = true
x264_constant_rate_factor = 16
hide_enginenames = true
hide_extensions = false
mencoder_mux_compatible = false
http_engine_v2 = true
prettify_filenames = true
engines = ffmpegvideo,ffmpegaudio,ffmpegwebvideo,mencoder,tsmuxer,tsmuxeraudio,mencoderwebvideo,vlcwebvideo,vlcvideo,vlcaudio
use_imdb_info = false
resume = false
audio_languages = eng

gpu_acceleration = false
ffmpeg_gpu_decoding_acceleration_method = auto
ffmpeg_available_gpu_acceleration_methods = none,auto,vdpau

[valib]

@mbentley using mpeg2_main_settings = keyint=5:vqscale=1:vqmin=2 in the UMS.conf together with the automatic_maximum_bitrate = true doesn't make sense. We set not only max bitrate automatically but also the mpeg2 setting.
Anyway thanks for info. There is a bug and I will try to solve it.

[valib]

@mbentley I see other problem in your log. The automatic max bitrate doesn't work because the Ping returns error due to permission. See
```DEBUG 11:58:07.715 [pool-4-thread-1] Starting ping -c 5 -s 512 192.168.0.107
DEBUG 11:58:07.724 [pool-4-thread-1] Unix process ID (ping): 144
DEBUG 11:58:07.724 [ping-7-2] ping: permission denied (are you root?)
DEBUG 11:58:07.724 [ping-7-1] PING 192.168.0.107 (192.168.0.107): 512 data bytes
INFO 11:58:07.724 [pool-4-thread-1] Process ping has a return code of 1! Maybe an error occurred... check the log file

[SubJunk]

@valib I will do an urgent deployment when there is a fix for this

[mbentley]

Thanks for taking a look valib! Much appreciated.

@mbentley using mpeg2_main_settings = keyint=5:vqscale=1:vqmin=2 in the UMS.conf together with the automatic_maximum_bitrate = true doesn't make sense. We set not only max bitrate automatically but also the mpeg2 setting.
Anyway thanks for info. There is a bug and I will try to solve it.

Yeah, that makes sense. Previously with automatic_maximum_bitrate defaulting to false, that wasn't the case in 10.2.0 and earlier but with 10.3.0 and later, that would be true since I am not explicitly setting that option in my config. At this point, I don't even recall what all of the settings do - I did a lot of tweaking early on back when I was running PS3MS and trying to stream to my PS3 over wireless. some of those settings might just be left over and maybe not as relevant today...I should probably revalidate some of my settings.

As for ping, I am running the UMS process in my container as a non-root user which could explain why ping does not work as I am in an Alpine Linux container that only has the busybox ping by default which doesn't allow non-root ping. Adding iputils will resolve that on my end.

[valib]

I check the code and it seems to me that the whole problem is made by not working Ping. The mpeg2_main_settings = keyint=5:vqscale=1:vqmin=2 is overriden and not used.

[SubJunk]

@valib I think we should also not allow this to happen:

-maxrate 999000k Automatic (Wireless)

[valib]

@SubJunk yes I agree. I will check the Ping implmentation.

[SubJunk]

@mbentley this fix is deployed to Docker Hub now