Universalmediaserver: 7.4.0: Problems playing mkv files with multiple embedded subtitle tracks with ffmpeg

[esabol]

MacOS X High Sierra 10.13.6 (17G65)
ffmpeg version N-90990-g652b857b94-tessus

This is with UMS 7.4.0, but I had the same issue with 7.3.0 and 7.3.1, fwiw. Just never got around to reporting it until now.

If I try to play an mkv file with multiple embedded subtitle tracks that requires transcoding using ffmpeg on my PS4, it doesn't work. It just times out after a minute or so. The only way to get it to play is to go into the directory's "#TRANSCODE#" menu and explicitly select the FFmpeg option without any subtitles.

This is with the "Defer to MEncoder when transcoding problematic subtitles" option turned off in the ffmpeg Transcoding Settings, by the way. (MEncoder doesn't seem to work either, as I reported in issue #1593.)

Interestingly, when I was testing this to generate the log file, I noticed that, in the #TRANSCODE# menu, the ffmpeg English subtitles option had the wrong flag icon. It showed the Finnish flag with a black border around it instead of the British flag like I would expect. The Finnish subtitles option (the next one after the English subtitles option in the listing) showed the Finnish flag with a white border. Not sure if that's a bug with the PS4 Media Player or UMS.

TRACE log: ffmpeg-trace-log.txt

[SubJunk]

@esabol that's interesting, I wonder when it broke, since I have files like that too. Can you try with v5 and/or v6? It helps me to know when things broke since then I can see what changed and have an idea of where to look in the code

[esabol]

I tested 6.7.4, and it has problems transcoding the same file. The PS4 logos just spin and spin.... Five minutes later, I canceled playback and immediately tried playing it again. This time it started playing right away, but English subtitles were displayed.

In the directory listing, the file name had changed from XXXXXX.mkv [FFmpeg] to XXXXXX.mkv [FFmpeg] {Sub:SubRip/English (English)}. I've seen similar behavior with 7.x.x, fwiw. If it fails to play the file once, subsequent attempts will inexplicably play with subtitles turned on. The problem does seem worse in 7.4.0 though, I think.

[esabol]

Tested 5.3.1: Similar result as 7.4.0. PS4 logos spin for about a minute, and then it says, "Cannot play the media." Using the #--TRANSCODE--# menu to explicitly select the FFmpeg option without any subtitles works fine.

[SubJunk]

I think this might unfortunately be a FFmpeg bug I've seen before where it just takes a very long time to initialize the subtitles. I think it is because in some cases, FFmpeg internally extracts the subtitles for the whole file before it can use them, and that takes a long time. We can see in the logs that we are just waiting for FFmpeg to return something for us.

Please try running this from the command line and see how long it takes to actually start transcoding:

"/Applications/Universal Media Server.app/Contents/Resources/osx/ffmpeg" -y -loglevel info -hwaccel auto -threads 1 -i "/Volumes/Tatooine/TV Shows/Maniac/Maniac.2018.S01E01.PROPER.720p.WEBRip.X264-METCON.mkv" -filter_complex "subtitles=/Volumes/Tatooine/TV Shows/Maniac/Maniac.2018.S01E01.PROPER.720p.WEBRip.X264-METCON.mkv:si=0" -threads 10 -bufsize 31250k -maxrate 31250k -crf 19 -ab 640k -c:a ac3 -c:v libx264 -tune zerolatency -preset ultrafast -level 31 -pix_fmt yuv420p -f mpegts file.ts

You can try newer versions of FFmpeg but I tried one about a month ago and it had the same bug :(
It is why we made the "Defer to MEncoder" setting too so we need to fix that on macOS and make sure it is kicking in in this situation

[esabol]

I'll do some timings and get back to you, but I think this is a different problem. That delay might explain the 5.3.1 behavior I described above, but not the 7.4.0. I used mkvmerge to remove the subtitles tracks from these files, and I could still only play them using the #--TRANSCODE--# menu with 7.4.0.

[SubJunk]

Ok thanks. I did some work on getting MEncoder working on macOS last night and I'm close to having a fix, and then can look into this more

[esabol]

Ran that command. It takes 3-7 seconds for the stream to start streaming. Certainly longer than the 2500 milliseconds that the UMS trace log says it sleeping for. Would increasing the sleeping time help?

If I remove -filter_complex "subtitles=/path/to/file.mkv:si=0" arguments from the command, it starts streaming practically instantly, fwiw. Why is it doing anything with the subtitles in this scenario? Unless I specifically request a subtitle track in "#--TRANSCODE--#", why doesn't it just ignore them? The only time I want to see subtitles is if the file has a "Forced English" subtitles track, which these files do not have.

Just for the record, here's the output:

% "/Applications/Universal Media Server.app/Contents/Resources/osx/ffmpeg" -y -loglevel info -hwaccel auto -threads 1 -i "/Volumes/Tatooine/TV Shows/Maniac/Maniac.2018.S01E01.PROPER.720p.WEBRip.X264-METCON.mkv" -filter_complex "subtitles=/Volumes/Tatooine/TV Shows/Maniac/Maniac.2018.S01E01.PROPER.720p.WEBRip.X264-METCON.mkv:si=0" -threads 10 -bufsize 31250k -maxrate 31250k -crf 19 -ab 640k -c:a ac3 -c:v libx264 -tune zerolatency -preset ultrafast -level 31 -pix_fmt yuv420p -f mpegts file.ts
ffmpeg version N-90990-g652b857b94-tessus Copyright (c) 2000-2018 the FFmpeg developers
  built with Apple LLVM version 9.1.0 (clang-902.0.39.1)
  configuration: --cc=/usr/bin/clang --prefix=/opt/ffmpeg --extra-version=tessus --enable-avisynth --enable-fontconfig --enable-gpl --enable-libaom --enable-libass --enable-libbluray --enable-libfreetype --enable-libgsm --enable-libmodplug --enable-libmp3lame --enable-libopencore-amrnb --enable-libopencore-amrwb --enable-libopus --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libtheora --enable-libvidstab --enable-libvo-amrwbenc --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libx264 --enable-libx265 --enable-libxavs --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-version3 --pkg-config-flags=--static --disable-ffplay
  libavutil      56. 18.100 / 56. 18.100
  libavcodec     58. 19.101 / 58. 19.101
  libavformat    58. 13.101 / 58. 13.101
  libavdevice    58.  4.100 / 58.  4.100
  libavfilter     7. 21.100 /  7. 21.100
  libswscale      5.  2.100 /  5.  2.100
  libswresample   3.  2.100 /  3.  2.100
  libpostproc    55.  2.100 / 55.  2.100
Guessed Channel Layout for Input Stream #0.1 : 5.1
Input #0, matroska,webm, from '/Volumes/Tatooine/TV Shows/Maniac/Maniac.2018.S01E01.PROPER.720p.WEBRip.X264-METCON.mkv':
  Metadata:
    encoder         : libebml v1.3.6 + libmatroska v1.4.9
  Duration: 00:41:12.99, start: 0.000000, bitrate: 2591 kb/s
    Stream #0:0: Video: h264 (High), yuv420p(progressive), 1280x544 [SAR 1:1 DAR 40:17], 23.98 fps, 23.98 tbr, 1k tbn, 47.95 tbc (default)
    Stream #0:1: Audio: eac3, 48000 Hz, 5.1, fltp (default)
    Stream #0:2(eng): Subtitle: subrip
    Metadata:
      title           : English
    Stream #0:3(swe): Subtitle: subrip
    Metadata:
      title           : Swedish
    Stream #0:4(nor): Subtitle: subrip
    Metadata:
      title           : Norwegian
    Stream #0:5(ger): Subtitle: subrip
    Metadata:
      title           : German
    Stream #0:6(fin): Subtitle: subrip
    Metadata:
      title           : Finnish
[Parsed_subtitles_0 @ 0x7fba0651a400] Shaper: FriBidi 0.19.2 (SIMPLE)
[Parsed_subtitles_0 @ 0x7fba0651a400] Using font provider coretext
[h264 @ 0x7fba06819a00] Using auto hwaccel type videotoolbox with new default device.
Stream mapping:
  Stream #0:0 (h264) -> subtitles (graph 0)
  subtitles (graph 0) -> Stream #0:0 (libx264)
  Stream #0:1 -> #0:1 (eac3 (native) -> ac3 (native))
Press [q] to stop, [?] for help
[h264 @ 0x7fba06819a00] Failed setup for format videotoolbox_vld: hwaccel initialisation returned error.
[Parsed_subtitles_0 @ 0x7fba0651b040] Shaper: FriBidi 0.19.2 (SIMPLE)
[Parsed_subtitles_0 @ 0x7fba0651b040] Using font provider coretext
[libx264 @ 0x7fba06832400] using SAR=1/1
[libx264 @ 0x7fba06832400] VBV bitrate (31250) > level limit (14000)
[libx264 @ 0x7fba06832400] VBV buffer (31250) > level limit (14000)
[libx264 @ 0x7fba06832400] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2
[libx264 @ 0x7fba06832400] profile Constrained Baseline, level 3.1
Output #0, mpegts, to 'file.ts':
  Metadata:
    encoder         : Lavf58.13.101
    Stream #0:0: Video: h264 (libx264), yuv420p, 1280x544 [SAR 1:1 DAR 40:17], q=-1--1, 23.98 fps, 90k tbn, 23.98 tbc (default)
    Metadata:
      encoder         : Lavc58.19.101 libx264
    Side data:
      cpb: bitrate max/min/avg: 31250000/0/0 buffer size: 31250000 vbv_delay: -1
    Stream #0:1: Audio: ac3, 48000 Hz, 5.1(side), fltp, 640 kb/s (default)
    Metadata:
      encoder         : Lavc58.19.101 ac3
[Parsed_subtitles_0 @ 0x7fba0651b040] fontselect: (Arial, 400, 0) -> /Library/Fonts/Arial.ttf, -1, ArialMT
frame= 9532 fps=141 q=19.0 Lsize=  284133kB time=00:06:37.59 bitrate=5854.2kbits/s speed=5.88x    
video:231257kB audio:31062kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 8.315587%

Response seems a bit quicker if I remove -hwaccel auto from the arguments also. I'll try disabling the "Enable GPU acceleration" option in the settings.

[SubJunk]

It's adding the subtitles based on your audio/subtitles language settings:

Matched internal subtitles track: id: 0, type: SUBRIP, subtitles track title from metadata: English, lang: en

Because the audio stream has no language specified

[esabol]

Ah, ha! I see! That makes sense and explains a lot. I've edited one of the files so that the audio track is marked as "eng" with mkvmerge. I'll run some tests on that, just out of curiosity.

[esabol]

OK, same video with no subtitle tracks and the audio track set to English (eng). I hit play, and the PS4 logos spin for several minutes.... Nothing happens, as usual. (Looking at the log file, the ffmpeg process, if I'm reading it right, has started streaming within the 2500 millisecond sleep period.) I cancel playback and try to play it again. It starts playing right away. Any idea what's going on here?

I watch for a little while and then stop playback. When I try to play the same file again, it resumes at the point where I left off watching before. This is even though I have the "Enable video resuming" option turned off in Navigation/Share Settings (and "resume = false" is in my UMS.conf). I was going to file an issue on that, but I think it's the PS4 Media Player doing that, assuming I'm reading the log file correctly.

Here's the TRACE log:
ffmpeg-nosub-eng-trace.txt

[SubJunk]

Hmm, the first time it seems to be stuck in some weird loop, pretty strange. Yes the resuming will have been on the PS4. My TV does it too.
Does this bug always happen for you on the first attempt at playing?