Jellyfin, rffmpeg and confusing error messages
Confusing error messages sent me on a debugging spree because of an interesting Jellyifn quirk.
TL;DR: if you have configured an alternative ffmpeg path in Jellyfin, make sure there's an ffprobe binary in the same location with the same file extension. In my case, this was solved by running:
ln -s `which ffprobe` /usr/local/bin/ffprobe.py
I run an instance of Jellyfin on my server. Today, I tried to connect the Gelli app to my server so I could listen to music more easily, as the native Jellyfin client has trouble playing audio when the screen is off.
Logging in and configuring Gelli all went fine, but the app failed to play any songs. There were no details in the error message itself, and the app logs also weren't very clear.
When I took a look at what the server was doing, the server told me this in the logs:
[2021-04-25 13:26:00.930 +02:00] [ERR] Error in "ffprobe"
System.ComponentModel.Win32Exception (2): No such file or directory
at System.Diagnostics.Process.ForkAndExecProcess(String filename, String[] argv, String[] envp, String cwd, Boolean redirectStdin, Boolean redirectStdout, Boolean redirectStderr, Boolean setCredentials, UInt32 userId, UInt32 groupId, UInt32[] groups, Int32& stdinFd, Int32& stdoutFd, Int32& stderrFd, Boolean usesTerminal, Boolean throwOnNoExec)
at System.Diagnostics.Process.StartCore(ProcessStartInfo startInfo)
at MediaBrowser.MediaEncoding.Encoder.MediaEncoder.StartProcess(ProcessWrapper process)
at MediaBrowser.MediaEncoding.Encoder.MediaEncoder.GetMediaInfoInternal(String inputPath, String primaryPath, MediaProtocol protocol, Boolean extractChapters, String probeSizeArgument, Boolean isAudio, Nullable`1 videoType, Boolean forceEnableLogging, CancellationToken cancellationToken)
at MediaBrowser.Providers.MediaInfo.FFProbeAudioInfo.Probe[T](T item, MetadataRefreshOptions options, CancellationToken cancellationToken)
at MediaBrowser.Providers.Manager.MetadataService`2.RunCustomProvider(ICustomMetadataProvider`1 provider, TItemType item, String logName, MetadataRefreshOptions options, RefreshResult refreshResult, CancellationToken cancellationToken)
[2021-04-25 13:26:00.932 +02:00] [INF] User policy for "emby". EnableAudioPlaybackTranscoding: True
[2021-04-25 13:26:00.937 +02:00] [ERR] Error processing request. URL "GET" "/Audio/5c3aab123975959488b382368c93d22b/universal".
System.NullReferenceException: Object reference not set to an instance of an object.
at MediaBrowser.Model.Dlna.StreamBuilder.GetAudioDirectPlayMethods(MediaSourceInfo item, MediaStream audioStream, AudioOptions options)
at MediaBrowser.Model.Dlna.StreamBuilder.BuildAudioItem(MediaSourceInfo item, AudioOptions options)
at MediaBrowser.Model.Dlna.StreamBuilder.BuildAudioItem(AudioOptions options)
at Jellyfin.Api.Helpers.MediaInfoHelper.SetDeviceSpecificData(BaseItem item, MediaSourceInfo mediaSource, DeviceProfile profile, AuthorizationInfo auth, Nullable`1 maxBitrate, Int64 startTimeTicks, String mediaSourceId, Nullable`1 audioStreamIndex, Nullable`1 subtitleStreamIndex, Nullable`1 maxAudioChannels, String playSessionId, Guid userId, Boolean enableDirectPlay, Boolean enableDirectStream, Boolean enableTranscoding, Boolean allowVideoStreamCopy, Boolean allowAudioStreamCopy, String ipAddress)
at Jellyfin.Api.Controllers.UniversalAudioController.GetUniversalAudioStream(Guid itemId, String[] container, String mediaSourceId, String deviceId, Nullable`1 userId, String audioCodec, Nullable`1 maxAudioChannels, Nullable`1 transcodingAudioChannels, Nullable`1 maxStreamingBitrate, Nullable`1 audioBitRate, Nullable`1 startTimeTicks, String transcodingContainer, String transcodingProtocol, Nullable`1 maxAudioSampleRate, Nullable`1 maxAudioBitDepth, Nullable`1 enableRemoteMedia, Boolean breakOnNonKeyFrames, Boolean enableRedirection)
at lambda_method1005(Closure , Object )
at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location ---
at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
--- End of stack trace from previous location ---
at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
at Jellyfin.Server.Middleware.ServerStartupMessageMiddleware.Invoke(HttpContext httpContext, IServerApplicationHost serverApplicationHost, ILocalizationManager localizationManager)
at Jellyfin.Server.Middleware.WebSocketHandlerMiddleware.Invoke(HttpContext httpContext, IWebSocketManager webSocketManager)
at Jellyfin.Server.Middleware.IpBasedAccessValidationMiddleware.Invoke(HttpContext httpContext, INetworkManager networkManager)
at Jellyfin.Server.Middleware.LanFilteringMiddleware.Invoke(HttpContext httpContext, INetworkManager networkManager, IServerConfigurationManager serverConfigurationManager)
at Microsoft.AspNetCore.Authorization.Policy.AuthorizationMiddlewareResultHandler.HandleAsync(RequestDelegate next, HttpContext context, AuthorizationPolicy policy, PolicyAuthorizationResult authorizeResult)
at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
at Swashbuckle.AspNetCore.ReDoc.ReDocMiddleware.Invoke(HttpContext httpContext)
at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
at Jellyfin.Server.Middleware.RobotsRedirectionMiddleware.Invoke(HttpContext httpContext)
at Jellyfin.Server.Middleware.LegacyEmbyRouteRewriteMiddleware.Invoke(HttpContext httpContext)
at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
at Jellyfin.Server.Middleware.ResponseTimeMiddleware.Invoke(HttpContext context)
at Jellyfin.Server.Middleware.ExceptionMiddleware.Invoke(HttpContext context)
[2021-04-25 13:26:00.990 +02:00] [INF] GetPostedPlaybackInfo profile: DeviceProfile { Name: null, Id: null, Identification: null, FriendlyName: null, Manufacturer: null, ManufacturerUrl: null, ModelName: null, ModelDescription: null, ModelNumber: null, ModelUrl: null, SerialNumber: null, EnableAlbumArtInDidl: False, EnableSingleAlbumArtLimit: False, EnableSingleSubtitleLimit: False, SupportedMediaTypes: "Audio,Photo,Video", UserId: null, AlbumArtPn: null, MaxAlbumArtWidth: 0, MaxAlbumArtHeight: 0, MaxIconWidth: null, MaxIconHeight: null, MaxStreamingBitrate: 8000000, MaxStaticBitrate: 8000000, MusicStreamingTranscodingBitrate: 128000, MaxStaticMusicBitrate: null, SonyAggregationFlags: null, ProtocolInfo: null, TimelineOffsetSeconds: 0, RequiresPlainVideoItems: False, RequiresPlainFolders: False, EnableMSMediaReceiverRegistrar: False, IgnoreTranscodeByteRangeRequests: False, XmlRootAttributes: [], DirectPlayProfiles: [DirectPlayProfile { Container: "flac", AudioCodec: "flac", VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "mp3", AudioCodec: "mp3", VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "opus", AudioCodec: "opus", VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "m4a", AudioCodec: "aac", VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "ogg", AudioCodec: "vorbis", VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "ogg", AudioCodec: "opus", VideoCodec: null, Type: Audio }, DirectPlayProfile { Container: "mka", AudioCodec: "opus", VideoCodec: null, Type: Audio }], TranscodingProfiles: [TranscodingProfile { Container: "ts", Type: Audio, VideoCodec: null, AudioCodec: "aac", Protocol: "hls", EstimateContentLength: False, EnableMpegtsM2TsMode: False, TranscodeSeekInfo: Auto, CopyTimestamps: False, Context: Streaming, EnableSubtitlesInManifest: False, MaxAudioChannels: null, MinSegments: 0, SegmentLength: 0, BreakOnNonKeyFrames: False }], ContainerProfiles: [], CodecProfiles: [], ResponseProfiles: [], SubtitleProfiles: [] }
I first focused on the second part of the log message, because that seemed to have to do with playback directly. A NullReference in the playback code seemed like an excellent reason why Gelli wasn't playing any songs, but this turned out to be a false lead; the true cause was the error message at the top:
[2021-04-25 13:26:00.930 +02:00] [ERR] Error in "ffprobe"
System.ComponentModel.Win32Exception (2): No such file or directory
at System.Diagnostics.Process.ForkAndExecProcess(String filename, String[] argv, String[] envp, String cwd, Boolean redirectStdin, Boolean redirectStdout, Boolean redirectStderr, Boolean setCredentials, UInt32 userId, UInt32 groupId, UInt32[] groups, Int32& stdinFd, Int32& stdoutFd, Int32& stderrFd, Boolean usesTerminal, Boolean throwOnNoExec)
This made it look like there was a problem accessing the ffprobe binary. This is a binary that comes with ffmpeg, the tool that decodes and transcodes media for Jellyfin.
So, the first thing I did was to try and find out if I could add ffprobe to the PATH environment variable. I edited a bunch of profile and bashrc files, adding lines like export PATH=$PATH:/usr/local/bin, but that all didn't change a thing.
Luckily, Jellyfin is open source. The problem originated in a file called MediaEncoder.cs, so I went looking there. After looking back and forth throughout the file, I found the place where the binary that's being called resides is being set: MediaEncoder.cs#L125. This looked pretty simple to me; it takes the path of the ffmpeg binary, replaces the last bit of the command line with ffprobe, and that's about it.
Normally, this path isn't set or it's set to the default ffmpeg location, but I have configured rffmpeg so that I can transcode my media on a device with better hardware transcoding support. This meant that my ffmpeg path was set to this:
/usr/local/bin/rffmpeg.py
So, Jellyfin was trying to find ffprobe in /usr/local/bin/. I already tried putting the file there! What was going on?
Then it hit me; something must be going wrong in that string replace that configures the ffmpeg path. I took another look at the regular expression that determines the ffprobe location.
_ffprobePath = Regex.Replace(_ffmpegPath, @"[^\/\\]+?(\.[^\/\\\n.]+)?$", @"ffprobe$1");
When I noticed the $1 at the end of the regex replace, I threw the entire thing into regexr and found the problem: it's appending the file's extension to the end of the ffprobe command!
This makes sense in the Windows world, I suppose, where you need the .exe at the end of every executable for things to work smoothly. However, because of this extension, it's not looking for ffprobe (as the error message said) or /usr/local/bin/ffprobe (as a simple string replace would mean); it's actually looking for /usr/local/bin/ffprobe.py! Had the error message mentioned this, this would never have been a problem, but alas, the exception it threw was misleading.
I created a symlink to ffprobe with the name ffprobe.py and everything immediately started working! In the end I double checked the rffmpeg manual and it looks like it either was updated since I ran it, or I simply didn't follow it correctly, because it explicitly tells users to make symlinks without the .py extension.
I'm not sure why the Jellyfin developers chose to use a regex instead of using the DirectoryInfo API. I suppose something like
var ffmpegFile = new FileInfo(ffmpegPath);
var ffmpegDirectory = ffmpegFile?.Directory;
String ffprobePath = (ffmpegDirectory?.ToString() ?? "") + "ffprobe" + (ffmpegFile?.Extension ?? "")
is more code than a simple regex replace, but its meaning is a lot clearer in my opinion.
Written by Jeroen on April 25, 2021