Thank you Tolriq! I woke up the next morning take a look at some Jellyfin logs. I just grabbed a representative one that more or less lines up with the yatse logs I sent. I haven’t correlated the two. However, I can clearly see a problem with jellyfin in regards to transcoding. It calls ffmpeg repeatedly, but it exists with “code 1” and ends up failing to transcode.
[2019-12-20 22:27:59.334 -08:00] [WRN] HTTP Response 200 to "192.168.0.3". Time (slow): 0:00:00.7662454. "http://192.168.0.20:8096/Items/a868394753c1784b72c26bcd9a99ba03/Images/Primary"
[2019-12-20 22:28:01.602 -08:00] [WRN] HTTP Response 200 to "192.168.0.3". Time (slow): 0:00:00.6009514. "http://192.168.0.20:8096/Items/4b6c4a2890ab2bea460cc72101d7ea47/Images/Primary"
[2019-12-20 22:28:04.766 -08:00] [INF] User policy for "craig". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True
[2019-12-20 22:28:04.766 -08:00] [INF] Bitrate exceeds DirectPlay limit: media bitrate: 7041275, max bitrate: 2000000
[2019-12-20 22:28:04.766 -08:00] [INF] Bitrate exceeds DirectStream limit: media bitrate: 7041275, max bitrate: 2000000
[2019-12-20 22:28:04.766 -08:00] [INF] Profile: "Unknown Profile", Path: "/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv", isEligibleForDirectPlay: False, isEligibleForDirectStream: False
[2019-12-20 22:28:04.766 -08:00] [INF] RemoteClientBitrateLimit: 10000000, RemoteIp: "192.168.0.3", IsInLocalNetwork: True
[2019-12-20 22:28:04.766 -08:00] [INF] Bitrate exceeds DirectPlay limit: media bitrate: 7041275, max bitrate: 2000000
[2019-12-20 22:28:04.766 -08:00] [INF] Bitrate exceeds DirectStream limit: media bitrate: 7041275, max bitrate: 2000000
[2019-12-20 22:28:04.766 -08:00] [INF] Profile: "Unknown Profile", Path: "/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv", isEligibleForDirectPlay: False, isEligibleForDirectStream: False
[2019-12-20 22:28:04.766 -08:00] [INF] RemoteClientBitrateLimit: 10000000, RemoteIp: "192.168.0.3", IsInLocalNetwork: True
[2019-12-20 22:28:04.766 -08:00] [INF] Bitrate exceeds DirectPlay limit: media bitrate: 7041275, max bitrate: 2000000
[2019-12-20 22:28:04.766 -08:00] [INF] Bitrate exceeds DirectStream limit: media bitrate: 7041275, max bitrate: 2000000
[2019-12-20 22:28:04.766 -08:00] [INF] Profile: "Unknown Profile", Path: "/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv", isEligibleForDirectPlay: False, isEligibleForDirectStream: False
[2019-12-20 22:28:04.835 -08:00] [INF] Playback stopped reported by app "Android" "9" playing "Ad Astra". Stopped at "0" ms
[2019-12-20 22:28:05.961 -08:00] [INF] /usr/lib/jellyfin-ffmpeg/ffmpeg -i file:"/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv" -map_metadata -1 -map_chapters -1 -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_nvenc -pix_fmt yuv420p -preset default -b:v 1616000 -maxrate 1616000 -bufsize 3232000 -force_key_frames:0 "expr:gte(t,0+n_forced*3)" -vf "scale=trunc(min(max(iw\,ih*dar)\,720)/2)*2:trunc(ow/dar/2)*2" -copyts -vsync -1 -codec:a:0 ac3 -ac 6 -ab 384000 -f hls -max_delay 5000000 -avoid_negative_ts disabled -start_at_zero -hls_time 3 -individual_header_trailer 0 -hls_segment_type mkv -start_number 0 -hls_segment_filename "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b145%d.mkv" -hls_playlist_type vod -hls_list_size 0 -y "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b145.m3u8"
[2019-12-20 22:28:06.473 -08:00] [ERR] FFMpeg exited with code 1
[2019-12-20 22:28:06.499 -08:00] [WRN] cannot serve "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b1450.mkv" as transcoding quit before we got there
[2019-12-20 22:28:06.500 -08:00] [ERR] Error processing request: "Could not find file '/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b1450.mkv'."
[2019-12-20 22:28:06.500 -08:00] [WRN] HTTP Response 404 to "192.168.0.3". Time (slow): 0:00:00.5403174. "http://192.168.0.20:8096/videos/7eca936e-2cd8-7fb2-b7b4-ae69a808b01c/hls1/main/0.mkv?DeviceId=7b4894ab73e9586a&MediaSourceId=7eca936e2cd87fb2b7b4ae69a808b01c&VideoCodec=h264&AudioCodec=ac3,eac3&AudioStreamIndex=1&VideoBitrate=1616000&AudioBitrate=384000&PlaySessionId=8f6be6a6d306492b81eed307bd1fc8e8&TranscodingMaxAudioChannels=6&CopyTimestamps=true&RequireAvc=false&Tag=0e9639f8e0ec8e385c8cae660a30f006&SegmentContainer=mkv&BreakOnNonKeyFrames=False&TranscodeReasons=ContainerBitrateExceedsLimit"
[2019-12-20 22:28:06.623 -08:00] [INF] /usr/lib/jellyfin-ffmpeg/ffmpeg -ss 00:00:03.000 -noaccurate_seek -i file:"/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv" -map_metadata -1 -map_chapters -1 -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_nvenc -pix_fmt yuv420p -preset default -b:v 1616000 -maxrate 1616000 -bufsize 3232000 -force_key_frames:0 "expr:gte(t,3+n_forced*3)" -vf "scale=trunc(min(max(iw\,ih*dar)\,720)/2)*2:trunc(ow/dar/2)*2" -copyts -vsync -1 -codec:a:0 ac3 -ac 6 -ab 384000 -f hls -max_delay 5000000 -avoid_negative_ts disabled -start_at_zero -hls_time 3 -individual_header_trailer 0 -hls_segment_type mkv -start_number 1 -hls_segment_filename "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b145%d.mkv" -hls_playlist_type vod -hls_list_size 0 -y "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b145.m3u8"
[2019-12-20 22:28:07.223 -08:00] [ERR] FFMpeg exited with code 1
[2019-12-20 22:28:07.250 -08:00] [WRN] cannot serve "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b1451.mkv" as transcoding quit before we got there
[2019-12-20 22:28:07.251 -08:00] [ERR] Error processing request: "Could not find file '/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b1451.mkv'."
[2019-12-20 22:28:07.251 -08:00] [WRN] HTTP Response 404 to "192.168.0.3". Time (slow): 0:00:00.6298277. "http://192.168.0.20:8096/videos/7eca936e-2cd8-7fb2-b7b4-ae69a808b01c/hls1/main/1.mkv?DeviceId=7b4894ab73e9586a&MediaSourceId=7eca936e2cd87fb2b7b4ae69a808b01c&VideoCodec=h264&AudioCodec=ac3,eac3&AudioStreamIndex=1&VideoBitrate=1616000&AudioBitrate=384000&PlaySessionId=8f6be6a6d306492b81eed307bd1fc8e8&TranscodingMaxAudioChannels=6&CopyTimestamps=true&RequireAvc=false&Tag=0e9639f8e0ec8e385c8cae660a30f006&SegmentContainer=mkv&BreakOnNonKeyFrames=False&TranscodeReasons=ContainerBitrateExceedsLimit"
[2019-12-20 22:28:07.351 -08:00] [INF] /usr/lib/jellyfin-ffmpeg/ffmpeg -ss 00:00:06.000 -noaccurate_seek -i file:"/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv" -map_metadata -1 -map_chapters -1 -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_nvenc -pix_fmt yuv420p -preset default -b:v 1616000 -maxrate 1616000 -bufsize 3232000 -force_key_frames:0 "expr:gte(t,6+n_forced*3)" -vf "scale=trunc(min(max(iw\,ih*dar)\,720)/2)*2:trunc(ow/dar/2)*2" -copyts -vsync -1 -codec:a:0 ac3 -ac 6 -ab 384000 -f hls -max_delay 5000000 -avoid_negative_ts disabled -start_at_zero -hls_time 3 -individual_header_trailer 0 -hls_segment_type mkv -start_number 2 -hls_segment_filename "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b145%d.mkv" -hls_playlist_type vod -hls_list_size 0 -y "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b145.m3u8"
[2019-12-20 22:28:07.840 -08:00] [ERR] FFMpeg exited with code 1
[2019-12-20 22:28:07.899 -08:00] [WRN] cannot serve "/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b1452.mkv" as transcoding quit before we got there
[2019-12-20 22:28:07.899 -08:00] [ERR] Error processing request: "Could not find file '/config/data/transcoding-temp/transcodes/transcodes/transcodes/b36e931c6b79161ffd0160614492b1452.mkv'."
[2019-12-20 22:28:07.899 -08:00] [WRN] HTTP Response 404 to "192.168.0.3". Time (slow): 0:00:00.5511975. "http://192.168.0.20:8096/videos/7eca936e-2cd8-7fb2-b7b4-ae69a808b01c/hls1/main/2.mkv?DeviceId=7b4894ab73e9586a&MediaSourceId=7eca936e2cd87fb2b7b4ae69a808b01c&VideoCodec=h264&AudioCodec=ac3,eac3&AudioStreamIndex=1&VideoBitrate=1616000&AudioBitrate=384000&PlaySessionId=8f6be6a6d306492b81eed307bd1fc8e8&TranscodingMaxAudioChannels=6&CopyTimestamps=true&RequireAvc=false&Tag=0e9639f8e0ec8e385c8cae660a30f006&SegmentContainer=mkv&BreakOnNonKeyFrames=False&TranscodeReasons=ContainerBitrateExceedsLimit"
Anyway, I tried playing around with Yatse again and… well… I can’t reproduce the issue anymore. Which is great - because transcoding works! I tried playing the same movie, at 1M, for 30 seconds. Here’s the jellyfish log:
[2019-12-21 11:13:15.260 -08:00] [INF] User policy for "craig". EnablePlaybackRemuxing: True EnableVideoPlaybackTranscoding: True EnableAudioPlaybackTranscoding: True
[2019-12-21 11:13:15.260 -08:00] [INF] Bitrate exceeds DirectPlay limit: media bitrate: 7041275, max bitrate: 1000000
[2019-12-21 11:13:15.260 -08:00] [INF] Bitrate exceeds DirectStream limit: media bitrate: 7041275, max bitrate: 1000000
[2019-12-21 11:13:15.260 -08:00] [INF] Profile: "Unknown Profile", Path: "/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv", isEligibleForDirectPlay: False, isEligibleForDirectStream: False
[2019-12-21 11:13:15.260 -08:00] [INF] RemoteClientBitrateLimit: 10000000, RemoteIp: "192.168.0.3", IsInLocalNetwork: True
[2019-12-21 11:13:15.260 -08:00] [INF] Bitrate exceeds DirectPlay limit: media bitrate: 7041275, max bitrate: 1000000
[2019-12-21 11:13:15.260 -08:00] [INF] Bitrate exceeds DirectStream limit: media bitrate: 7041275, max bitrate: 1000000
[2019-12-21 11:13:15.260 -08:00] [INF] Profile: "Unknown Profile", Path: "/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv", isEligibleForDirectPlay: False, isEligibleForDirectStream: False
[2019-12-21 11:13:15.260 -08:00] [INF] RemoteClientBitrateLimit: 10000000, RemoteIp: "192.168.0.3", IsInLocalNetwork: True
[2019-12-21 11:13:15.260 -08:00] [INF] Bitrate exceeds DirectPlay limit: media bitrate: 7041275, max bitrate: 1000000
[2019-12-21 11:13:15.261 -08:00] [INF] Bitrate exceeds DirectStream limit: media bitrate: 7041275, max bitrate: 1000000
[2019-12-21 11:13:15.261 -08:00] [INF] Profile: "Unknown Profile", Path: "/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv", isEligibleForDirectPlay: False, isEligibleForDirectStream: False
[2019-12-21 11:13:15.836 -08:00] [INF] /usr/lib/jellyfin-ffmpeg/ffmpeg -i file:"/movies/Ad Astra (2019)/Ad Astra (2019) Bluray-1080p.mkv" -map 0:0 -map 0:1 -map 0:3 -codec:v:0 h264_nvenc -force_key_frames "expr:gte(t,n_forced*5)" -vf "scale=trunc(min(max(iw\,ih*dar)\,640)/2)*2:trunc(ow/dar/2)*2" -copyts -avoid_negative_ts disabled -start_at_zero -pix_fmt yuv420p -preset default -b:v 616000 -maxrate 616000 -bufsize 1232000 -vsync -1 -map_metadata -1 -map_chapters -1 -threads 0 -codec:a:0 ac3 -ac 6 -ab 384000 -codec:s:0 copy -disposition:s:0 default -y "/config/data/transcoding-temp/transcodes/transcodes/transcodes/90634235d094751070abce670b66392d.mkv"
[2019-12-21 11:13:51.944 -08:00] [INF] Stopping ffmpeg process with q command for "/config/data/transcoding-temp/transcodes/transcodes/transcodes/90634235d094751070abce670b66392d.mkv"
[2019-12-21 11:13:51.955 -08:00] [INF] Playback stopped reported by app "Android" "9" playing "Ad Astra". Stopped at "31" ms
[2019-12-21 11:13:52.067 -08:00] [INF] FFMpeg exited with code 0
[2019-12-21 11:13:52.067 -08:00] [INF] Deleting partial stream file(s) "/config/data/transcoding-temp/transcodes/transcodes/transcodes/90634235d094751070abce670b66392d.mkv"
[2019-12-21 11:13:52.192 -08:00] [INF] Playback stopped reported by app "Android" "9" playing "Ad Astra". Stopped at "31000" ms
[2019-12-21 11:13:52.766 -08:00] [ERR] Error processing request: "The operation was canceled."
[2019-12-21 11:13:52.766 -08:00] [WRN] HTTP Response 200 to "192.168.0.3". Time (slow): 0:00:36.9313548. "http://192.168.0.20:8096/videos/7eca936e-2cd8-7fb2-b7b4-ae69a808b01c/stream.mkv?DeviceId=7b4894ab73e9586a&MediaSourceId=7eca936e2cd87fb2b7b4ae69a808b01c&VideoCodec=h264&AudioCodec=ac3,dts,aac,eac3&AudioStreamIndex=1&SubtitleStreamIndex=3&VideoBitrate=616000&AudioBitrate=384000&PlaySessionId=fd7718c19b1448e49d41b67bfbcdc49b&SubtitleMethod=Embed&TranscodingMaxAudioChannels=6&CopyTimestamps=true&RequireAvc=false&Tag=0e9639f8e0ec8e385c8cae660a30f006&SubtitleCodec=subrip&TranscodeReasons=ContainerBitrateExceedsLimit"
[2019-12-21 11:13:53.567 -08:00] [INF] Playback stopped reported by app "Android" "9" playing "Ad Astra". Stopped at "unknown" ms
[2019-12-21 11:13:53.641 -08:00] [WRN] HTTP Response 204 to "192.168.0.3". Time (slow): 0:00:01.6976872. "http://192.168.0.20:8096/Sessions/Playing/Stopped"
[2019-12-21 11:13:54.074 -08:00] [ERR] Error processing request: "The operation was canceled."
[2019-12-21 11:13:54.074 -08:00] [WRN] HTTP Response 200 to "192.168.0.3". Time (slow): 0:00:36.3912704. "http://192.168.0.20:8096/videos/7eca936e-2cd8-7fb2-b7b4-ae69a808b01c/stream.mkv?DeviceId=7b4894ab73e9586a&MediaSourceId=7eca936e2cd87fb2b7b4ae69a808b01c&VideoCodec=h264&AudioCodec=ac3,dts,aac,eac3&AudioStreamIndex=1&SubtitleStreamIndex=3&VideoBitrate=616000&AudioBitrate=384000&PlaySessionId=fd7718c19b1448e49d41b67bfbcdc49b&SubtitleMethod=Embed&TranscodingMaxAudioChannels=6&CopyTimestamps=true&RequireAvc=false&Tag=0e9639f8e0ec8e385c8cae660a30f006&SubtitleCodec=subrip&TranscodeReasons=ContainerBitrateExceedsLimit"
And here’s the Yatse log:
debug-20191221_111408.zip (31.7 KB)
Do you see anything special in the Yatse log this time other than success?
I’m not sure what changed… because I even had this problem with Yatse going to my Plex server. I haven’t set up hardware-accelerated transcoding on Plex and so I just figured my server was choking on the request. Now, curiously, even Plex is working now!