Skip to content

FFmpeg version logging and validation #4861

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Oct 2, 2022

Conversation

bastimeyer
Copy link
Member

Motivation

Recently, warning messages were added to the FFMPEGMuxer if muxing streams is unavailable because FFmpeg could not be found on the user's system:
#4781

There are a couple of things which can be further improved though:

  1. The FFmpeg version should be logged on the debug logging level, similar to the Streamlink + Python version and the dependencies:
    This will make debugging issues easier, e.g. stream.ffmpegmux: stream with independent segments (audio+video) cannot be remuxed #4825
  2. The FFmpeg executable should be verified via its version output:
    The user can set arbitrary executables as the --ffmpeg-ffmpeg value, and Streamlink will execute it blindly. Not only is this bad, but if a different executable gets set, or if the ffmpeg executable on the user's system doesn't work, no error messages will be printed.
  3. Muxing certain kinds of streams requires having a certain FFmpeg version in order to work correctly:
    The FFmpeg version should be parsed from the version check output, so that it can be compared against a minimum version. This is currently not implemented, but could be added in the future. Related:
    hls-multi from arte.tv has seconds of hanging video #4520 (comment)

Implementation

  1. Add a generic ProcessOutput utility class which can asynchronously read the subprocess's stdout/stderr streams line-by-line while the process is running, as opposed to waiting for process termination and reading the whole stream data into memory at once via the available high-level stdlib APIs subprocess.run(capture_output=True) or asyncio.create_subprocess_exec().communicate()
  2. Read FFmpeg version after resolving the executable path, log the output and validate.
    Also add the --ffmpeg-no-validation CLI argument for disabling the validation.

Why asyncio?

This makes the implementation and testing way easier compared to running in separate threads and making everything thread-safe. Using asyncio was not possible until last year due to the support for py2. This has changed now, so it should be utilized. Adding it however requires adding two more dev-requirements, namely

  • pytest-asyncio - already a transitive dependency, so nothing will change here
  • mock - for backwards compatibility of unittest.mock on py37 (AsyncMock). mock was already removed in the past (d04767f) after it wasn't required anymore. Just a quick mention, by adding it back, the annoying compatibility of the Mock.call_args args/kwargs could also be solved, but that would require changing imports everywhere, and it's probably not worth it.

In regards to the tests, freezegun is used for simulating subprocess timeouts, and it might be possible that something will change in future freezegun releases in terms of the asyncio module integration. This will need to be kept in mind and checked, but most likely it'll be harmless.

FFmpeg version output

As you can see here (also added as comments to the code)

the FFmpeg version string that gets checked is stable. One issue however could be forks which use a different name, but since we've just dropped avconv in 5.0.0, I don't think this is going to be a problem. I'm also not aware of any actively used FFmpeg forks, and should there be any, users can disable the validation by setting the CLI argument mentioned above.

Only the first stdout line will be checked during the validation. On success, everything else will be logged (with indentation). I wouldn't mind changing this if you don't agree with this and think that it's too much.

Potential issues

Executing FFmpeg introduces a small delay at the beginning while resolving and validating the executable. I don't think this is a problem though, even on weak/limited systems. FFmpeg has to be run anyway when muxing, so loading-wise, I don't see this as an issue. The validation timeout value has been set to a very generous 4 seconds.

On error, the infamous "Unexpected version check" error message (phrased differently) will be shown without any actual error stream outputs. Infamous, because the Twitch GUI also needs to validate Streamlink, and the same logic gets used there, which has caused problems for dozens of users in the past who had broken Streamlink installs or configs. For Streamlink, this shouldn't be an issue though, as it also tells which command it's been running for checking the FFmpeg output, and there are also more error and warning messages.

Example

$ streamlink -l trace --http-proxy socks5h://localhost:1920 https://www.france.tv/france-2/direct.html
[14:46:21.714633][cli][debug] OS:         Linux-5.19.12-1-git-x86_64-with-glibc2.36
[14:46:21.714714][cli][debug] Python:     3.10.7
[14:46:21.714739][cli][debug] Streamlink: 5.0.1+10.gd5793343
[14:46:21.715182][cli][debug] Dependencies:
[14:46:21.715884][cli][debug]  isodate: 0.6.1
[14:46:21.716145][cli][debug]  lxml: 4.9.1
[14:46:21.716578][cli][debug]  pycountry: 22.3.5
[14:46:21.716795][cli][debug]  pycryptodome: 3.14.1
[14:46:21.717094][cli][debug]  PySocks: 1.7.1
[14:46:21.717354][cli][debug]  requests: 2.28.1
[14:46:21.717618][cli][debug]  websocket-client: 1.3.1
[14:46:21.717834][cli][debug]  importlib-metadata: 4.9.0
[14:46:21.717962][cli][debug] Arguments:
[14:46:21.717988][cli][debug]  url=https://www.france.tv/france-2/direct.html
[14:46:21.718014][cli][debug]  --loglevel=trace
[14:46:21.718039][cli][debug]  --player=mpv
[14:46:21.718074][cli][debug]  --http-proxy=socks5h://localhost:1920
[14:46:21.718238][cli][info] Found matching plugin pluzz for URL https://www.france.tv/france-2/direct.html
[14:46:21.935123][plugins.pluzz][debug] Country: FR
[14:46:22.102771][plugins.pluzz][debug] Video ID: 006194ea-117d-4bcf-94a9-153d999c59ae
[14:46:22.522483][utils.l10n][debug] Language code: en_US
[14:46:22.674536][stream.ffmpegmux][trace] Querying FFmpeg version: ['/usr/bin/ffmpeg', '-version']
[14:46:22.695525][stream.ffmpegmux][debug] ffmpeg version n5.1.2 Copyright (c) 2000-2022 the FFmpeg developers
[14:46:22.695601][stream.ffmpegmux][debug]  built with gcc 12.2.0 (GCC)
[14:46:22.695643][stream.ffmpegmux][debug]  configuration: --prefix=/usr --disable-debug --disable-static --disable-stripping --enable-amf --enable-avisynth --enable-cuda-llvm --enable-lto --enable-fontconfig --enable-gmp --enable-gnutls --enable-gpl --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libdav1d --enable-libdrm --enable-libfreetype --enable-libfribidi --enable-libgsm --enable-libiec61883 --enable-libjack --enable-libmfx --enable-libmodplug --enable-libmp3lame --enable-libopencore_amrnb --enable-libopencore_amrwb --enable-libopenjpeg --enable-libopus --enable-libpulse --enable-librav1e --enable-librsvg --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libsvtav1 --enable-libtheora --enable-libv4l2 --enable-libvidstab --enable-libvmaf --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx264 --enable-libx265 --enable-libxcb --enable-libxml2 --enable-libxvid --enable-libzimg --enable-nvdec --enable-nvenc --enable-opencl --enable-opengl --enable-shared --enable-version3 --enable-vulkan
[14:46:22.695688][stream.ffmpegmux][debug]  libavutil      57. 28.100 / 57. 28.100
[14:46:22.695722][stream.ffmpegmux][debug]  libavcodec     59. 37.100 / 59. 37.100
[14:46:22.695755][stream.ffmpegmux][debug]  libavformat    59. 27.100 / 59. 27.100
[14:46:22.695787][stream.ffmpegmux][debug]  libavdevice    59.  7.100 / 59.  7.100
[14:46:22.695819][stream.ffmpegmux][debug]  libavfilter     8. 44.100 /  8. 44.100
[14:46:22.695850][stream.ffmpegmux][debug]  libswscale      6.  7.100 /  6.  7.100
[14:46:22.695882][stream.ffmpegmux][debug]  libswresample   4.  7.100 /  4.  7.100
[14:46:22.695912][stream.ffmpegmux][debug]  libpostproc    56.  6.100 / 56.  6.100
[14:46:22.695955][stream.hls][debug] Using external audio tracks for stream 144p (language=fr, name=Francais)
[14:46:22.696092][stream.hls][debug] Using external audio tracks for stream 216p (language=fr, name=Francais)
[14:46:22.696201][stream.hls][debug] Using external audio tracks for stream 360p (language=fr, name=Francais)
[14:46:22.696300][stream.hls][debug] Using external audio tracks for stream 540p (language=fr, name=Francais)
[14:46:22.696397][stream.hls][debug] Using external audio tracks for stream 720p (language=fr, name=Francais)
[14:46:22.696495][stream.hls][debug] Using external audio tracks for stream 1080p (language=fr, name=Francais)
Available streams: 144p (worst), 216p, 360p, 540p, 720p, 1080p (best)
$ streamlink -l trace --http-proxy socks5h://localhost:1920 --ffmpeg-ffmpeg /usr/bin/false https://www.france.tv/france-2/direct.html
[14:46:51.375609][cli][debug] OS:         Linux-5.19.12-1-git-x86_64-with-glibc2.36
[14:46:51.375706][cli][debug] Python:     3.10.7
[14:46:51.375736][cli][debug] Streamlink: 5.0.1+10.gd5793343
[14:46:51.376172][cli][debug] Dependencies:
[14:46:51.376845][cli][debug]  isodate: 0.6.1
[14:46:51.377095][cli][debug]  lxml: 4.9.1
[14:46:51.377513][cli][debug]  pycountry: 22.3.5
[14:46:51.377724][cli][debug]  pycryptodome: 3.14.1
[14:46:51.378015][cli][debug]  PySocks: 1.7.1
[14:46:51.378266][cli][debug]  requests: 2.28.1
[14:46:51.378522][cli][debug]  websocket-client: 1.3.1
[14:46:51.378737][cli][debug]  importlib-metadata: 4.9.0
[14:46:51.378869][cli][debug] Arguments:
[14:46:51.378896][cli][debug]  url=https://www.france.tv/france-2/direct.html
[14:46:51.378923][cli][debug]  --loglevel=trace
[14:46:51.378946][cli][debug]  --player=mpv
[14:46:51.378979][cli][debug]  --ffmpeg-ffmpeg=/usr/bin/false
[14:46:51.379001][cli][debug]  --http-proxy=socks5h://localhost:1920
[14:46:51.379167][cli][info] Found matching plugin pluzz for URL https://www.france.tv/france-2/direct.html
[14:46:51.611732][plugins.pluzz][debug] Country: FR
[14:46:51.809546][plugins.pluzz][debug] Video ID: 006194ea-117d-4bcf-94a9-153d999c59ae
[14:46:52.298957][utils.l10n][debug] Language code: en_US
[14:46:52.465542][stream.ffmpegmux][trace] Querying FFmpeg version: ['/usr/bin/false', '-version']
[14:46:52.474301][stream.ffmpegmux][error] Could not validate FFmpeg!
[14:46:52.474372][stream.ffmpegmux][error] Unexpected FFmpeg version output while running ['/usr/bin/false', '-version']
[14:46:52.474417][stream.ffmpegmux][warning] No valid FFmpeg binary was not found. See the --ffmpeg-ffmpeg option.
[14:46:52.474453][stream.ffmpegmux][warning] Muxing streams is unsupported! Only a subset of the available streams can be returned!
Available streams: 144p (worst), 216p, 360p, 540p, 720p, 1080p (best)

@bastimeyer
Copy link
Member Author

The py311 tests are failing because of issues with the logging module:
https://github.com/streamlink/streamlink/actions/runs/3168863166/jobs/5160366442#step:5:260

The log.trace() call for some reason has the logger module name instead of ffmpegmux on py311. Not sure what this is about. A bit annoying.

New utility class for executing a subprocess and asynchronously reading
its stdout and stderr streams line by line while the process is running,
with an optional timeout which kills the process. The output streams
and exit code get passed to callback methods which can control the
process execution and final output result.

This is useful for validating unknown executables, e.g. when querying
a version string output, as it avoids reading the entire stdout/stderr
at once and also avoids waiting for the process to terminate on its own.
Copy link
Member

@gravyboat gravyboat left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good @bastimeyer, the logic note I don't care much about but the log output typo could be a bit confusing. If that can be fixed prior to this being merged it would be great! Thanks for your hard work on this one, hopefully it will benefit users.

and log FFmpeg version output on the debug logging level
@gravyboat gravyboat merged commit d82184a into streamlink:master Oct 2, 2022
@bastimeyer bastimeyer deleted the ffmpeg-validation branch October 2, 2022 19:33
@bastimeyer bastimeyer mentioned this pull request Nov 7, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants