Skip to content
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

Skipping Songs While Transcoding Causes Audio Glitches #857

Open
Epsicle opened this issue Aug 28, 2024 · 21 comments
Open

Skipping Songs While Transcoding Causes Audio Glitches #857

Epsicle opened this issue Aug 28, 2024 · 21 comments

Comments

@Epsicle
Copy link

Epsicle commented Aug 28, 2024

Sorry if this shows as a duplicate, my main public account (midwesternrodent) is apparently flagged since I logged into it with a VPN so I have to wait for github support to make my contributions visible again.

Last Updated 8/30/2024

Look at the edit history of this comment to see the original issue report.

Steps to reproduce

  1. Turn on transcoded streams in finamp
  2. Shuffle your entire library and skip songs like a maniac, waiting just a second for a song to start buffering before skipping to the next one.
  3. In the Jellyfin Admin Console, look at your most recent transcoded logs until you find something like below (Note the "[q] command received. Exiting line" It will occur near the bottom. It's important that you see some files were opened for writing prior to that command being issued, and that you see one file opened for writing after it was issued.
size=       0kB time=-577014:32:22.77 bitrate=  -0.0kbits/s speed=N/A    
[hls @ 0x617991b04380] Opening '/var/lib/jellyfin/transcodes/f569acf3f179213107393728c98a234f0.ts' for writing
[hls @ 0x617991b04380] Opening '/var/lib/jellyfin/transcodes/f569acf3f179213107393728c98a234f1.ts' for writing


[q] command received. Exiting.

[hls @ 0x617991b04380] Opening '/var/lib/jellyfin/transcodes/f569acf3f179213107393728c98a234f2.ts' for writing
size=N/A time=00:00:00.00 bitrate=N/A speed=   0x    
video:0kB audio:253kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
  1. Play that song all the way through on the same device you skipped songs on. Listen for a brief cutout in the song (see example videos below)

Known to affect the following versions of Finamp

Version: 0.9.9, 0.9.8, 0.6.23, Debian Flatpak

Server Information

Jellyfin Version: 10.9.8.0

This is where things get unique. I have Jellyfin running in an unprivileged LXC on a proxmox host, I'm passing an Intel 12th gen i5 iGPU to the LXC via mount entries in the node.conf file, and I'm accessing the files for Jellyfin over an NFS share mounted to my proxmox host and passed through to the LXC in a similar manner. In case it's relevant, I've shared my conf below.

arch: amd64  
cores: 2  
features: nesting=1  
hostname: jamjar  
memory: 4096  
mp0: /mnt/pve/jellyshare,mp=/mnt/truenas/jellyshare  
nameserver: [redacted]  
net0: name=eth0,bridge=vmbr0,gw=[redacted],hwaddr=[redacted],ip=[redacted]  
/24,tag=[redacted],type=veth  
ostype: debian  
rootfs: local-lvm:vm-2010-disk-1,size=32G  
swap: 4096  
unprivileged: 1  
lxc.cgroup2.devices.allow: c 226:0 rwm  
lxc.cgroup2.devices.allow: c 226:128 rwm  
lxc.mount.entry: /dev/dri/renderD128 dev/dri/renderD128 none bind,optional,create=fi  
le 0, 0  
lxc.mount.entry: /dev/dri dev/dri none bind,optional,create=dir  
lxc.idmap: u 0 100000 65536  
lxc.idmap: g 0 100000 44  
lxc.idmap: g 44 44 1  
lxc.idmap: g 45 100045 61  
lxc.idmap: g 106 104 1  
lxc.idmap: g 107 100107 65429

Workarounds

  1. Turning off transcoding in finamp solves this issue if the file can be direct-played
  2. Clearing the the transcoding directory in Jellyfin resolves this problem temporarily (though it will reoccur, by default Jellyfin clears this log once daily, it can be increased to run every 15 minutes as a hacky workaround for now)

ScreenRecording on Youtube
Another Example

finamp-logs.txt
Jellyfin-Server-Logs-Using-Finamp.txt
Jellyfin-ServerLogs-Using-Standard-App.txt

Taylor Swift - Question - Before Playing.txt
Taylor Swift - Question - Second File After Playing.txt

@Chaphasilor
Copy link
Collaborator

Finamp doesn't support automatic transcoding yet. Transcoding is not only means for reaching device compatibility, but also for reducing bandwidth (especially for streaming FLAC). So that behavior is correct, although due for some improvement.

I've also noticed tracks skipping, but couldn't pinpoint the issue yet.

Regarding your workarounds, if you say it also happens with the F-Droid version, that means it's not a beta issue, but also in the stable version, right? Since the beta is not available through F-Droid.

The server logs should hopefully give some insight into the issue :)

@Chaphasilor
Copy link
Collaborator

I just checked, the track I had trouble with was an MP3 transcoded to OPUS@96 and downloaded to the device. It always skipped to the next track at a certain timestamp, and seeking beyond that point didn't work. Deleting and redownloading the track fixes the issue though, and transcoded streaming also worked fine.

At which bitrate are you transcoding? Do other bitrates work? Does downloading the transcoded file work? And could you grab the Jellyfin transcode logs for the track that's having issues please?

@Epsicle
Copy link
Author

Epsicle commented Aug 29, 2024

Hey, thanks for the reply. I'll get those logs for you later today.

I did just re-test on the F-Droid version and I have no idea what I was thinking or how I tested it the other day but I (obviously) could not get the beta on F-Droid and the stable version offered there does not have this issue. Sorry for pointing you in the wrong direction, I struck that point from my initial post.

As for my transcoding settings I just pressed the allow transcoding option and didn't adjust the bitrate from the default for my day-to-day usage, but I did adjust the bitrate before I thought to submit this as an issue and it had no effect. I'll re-test this today though since after the F-Droid statement I can't trust what I said in that state . Here are the settings screenshots I meant to attach to the original issue.

Screenshot_20240827-170858
Screenshot_20240827-170902
Screenshot_20240827-170905
Screenshot_20240827-170909
Screenshot_20240827-170913

@Epsicle
Copy link
Author

Epsicle commented Aug 30, 2024

Sorry for the delay. I had an interesting development. All songs except Rockstar suddenly started working again yesterday and Rockstar was skipping in a new area and not skipping in the same place as my example video.

I've found that once daily, Jellyfin clears the transcoding directory which the last time it was fixed for me lines up with when that job was last ran. Running that job manually from the Jellyfin UI cleared up the issue on Rockstar - So this may be an upstream Jellyfin issue but I'm still trying to track down what triggered it and why different versions of Finamp behave differently with what I assume at the moment is the same transcode.

One theory I have with pretty much zero evidence but a gut feeling, is this might be because Finamp is buffering songs that are next in the playlist? Because I'm seeing transcode logs for songs I haven't played yet show up in Jellyfin. I'm wondering if it's stopping right at the buffer limit and not at the end of the song and that's what gives us the skip when Jellyfin resumes transcoding but maybe puts the second part in another file? I'm gonna try and test later and see if I can nail that theory down. Wild speculation at the moment.

I've attached the logs for my broken transcode of Rockstar from 8-29 that was skipping at 0:36, and my working transcode of Rockstar that is not skipping at all. The working transcode of Rockstar appears to be quite a bit larger than the broken version for some reason, not sure why that is.

Rockstar Transcoding Logs 8-29-24.txt
Rockstar Transcoding Logs 8-30-24 - After Clearing Transcode Directory.txt

@Epsicle
Copy link
Author

Epsicle commented Aug 30, 2024

Confirmed! It did not work when I tried to make a playlist and force the issue with one song after another, but I did manage to recreate it through brute force.

I just changed my buffer to 285 (probably not important, it's the length of rockstar + 30 seconds from when I was trying to force the issue) and started skipping around my entire library giving it just enough time to start but not finish buffering the entire song before skipping on to the next. Then I dug through my transcode logs until I found one that looked messed up (Question...? by Taylor Swift), and then played it and BAM! We've got a skip right at 7 seconds!

So the issue seems to be caused by frequent skipping before it can fully buffer the song into the player, and then jellyfin stops the transcode but keeps the partial transcode in the cache and the skip is the jump to the second portion of the song's transcode maybe caused by searching? Seems like something to take up with the Jellyfin project upstream, do you agree?

Taylor Swift - Question - Before Playing.txt
Taylor Swift - Question - Second File After Playing.txt

Youtube Video (Apparently It's a Short for some reason)

EDIT: After looking at the log it seems like the write to the transcode file was interrupted which causes the skip, not that Jellyfin takes a second to search for the next file in the transcode.

@Chaphasilor
Copy link
Collaborator

Interesting! Thanks for digging so deep :D

Interrupted transcode jobs due to skipping seem like a reasonable explanation, but I'm not sure it's just the fault of he server.
Do you have throttled transcodes enabled in Jellyfin?

While the default buffer duration for the beta version is much longer, the stable version should pre-cache upcoming tracks as well. So I'm not yet understanding why it would behave differently. Can you try streaming one of the broken tracks with the stable version again? If they still work in the stable version, then something with the transcoding setup is probably different.

I'll take a more thorough look at the logs in a bit.

@Chaphasilor
Copy link
Collaborator

Hmm, if I interpret the logs correctly it might be that skipping ahead in the current track will move the end of the buffer forward as well, leaving a gap. Normally the buffer should just stay where it is and then continue pre-caching, but maybe there was an update to Android's built-in media player (Exoplayer, not Media3) with Android 14, or the audio library we're using to handle playback introduced a bug in a recent version?
I'll see if I can find anything...

@Epsicle
Copy link
Author

Epsicle commented Aug 30, 2024

Interesting! Thanks for digging so deep :D

Interrupted transcode jobs due to skipping seem like a reasonable explanation, but I'm not sure it's just the fault of he server. Do you have throttled transcodes enabled in Jellyfin?

No problem! Glad I can finally be of help to a project I love! And no, I do not have throttled transcodes enabled for Jellyfin. The examples I've sent so far are from local streams over Wifi 6 so about a gigabit to my server over the network. My upload speed over my VPN is much lower, something like 50mbs so that could play a role when I'm out and about.

While the default buffer duration for the beta version is much longer, the stable version should pre-cache upcoming tracks as well. So I'm not yet understanding why it would behave differently. Can you try streaming one of the broken tracks with the stable version again? If they still work in the stable version, then something with the transcoding setup is probably different.

Yep, I was once again incorrect, this does happen on the stable version after I followed my steps to recreate. I just started mashing skipped songs and within the first four or five transcode logs there was a log that looked broken and once again, the skip happens at the same spot.

To make it simple you don't even need to wait for the song to start buffering, just mash next over and over and you'll see plenty of broken examples you can look at in your transcode logs. Just clear the directory when you're done testing to fix everything.

Also just to clarify - it's not that there are broken tracks, it seems any track is capable of becoming broken if it is skipped at just the right time while transcoding, and then it is only broken until you clear the transcode directory.

Oddly enough, the flaptak version on my debian 12 laptop seems to be triggering a new transcode and not utilizing the cache. I'll see if I can recreate the issue on the flaptak version. Do you know what android version the flatpak is built from?

@Epsicle
Copy link
Author

Epsicle commented Aug 30, 2024

The issue is happening on the flatpak version on debian 12 as well, it's just triggering a new transcode rather than utilizing the transcode created by my Pixel 8. Let me grab my Android 13 phone and see if the same song has issues on that one or if I can recreate it with another song.

@Epsicle Epsicle changed the title Android 14: some .mp3s skipping while transcoding is enabled Skipping Songs While Transcoding Causes Audio Glitches Aug 30, 2024
@Epsicle
Copy link
Author

Epsicle commented Aug 30, 2024

Changed the title to better match the issue. This is also happening on the Android 13 phone, but like I found with the flatpak finamp client, it's creating it's own transcode for some reason so that specific track is fine on other devices.

EDIT:
As a temporary workaround I'm changing the scheduled time to clear my transcode logs in Jellyfin from once per day to every 15 minutes.

We'll see if I have any ill effects from that

@Chaphasilor
Copy link
Collaborator

Okay. Network speed is probably not an issue, the transcoded tracks become broken on your server before getting streamed to your device. Basically, JF seems to transcode the original file into the new format, but leaves some gaps in-between.
I'm not sure why new transcodes would be created per-device. Maybe take a look at the transcode directory to check if subdirectories are created? And you could also check if the same target codec and bitrate are used in all cases.

@Epsicle
Copy link
Author

Epsicle commented Aug 31, 2024

No subdirectories, they do seem to be the same codec and bitrate but I'm going to enable debug logging and see if I can get more information on what's going on.

No rush cause I know you've got other things to do and there's a weekend and everything. But were you able to replicate the issue on your machine? If not I can close this and keep troubleshooting on my own since at least to my eyes it seems like we're heading towards either a Jellyfin issue or a server misconfiguration on my side. If that's the case and I find a solution I can come back and edit the first comment with the solution for anyone else who pops up on this in the future. Just don't want to take any more of your valuable time if this is just me being a dunce, lol.

@Chaphasilor
Copy link
Collaborator

Sorry for not getting back to you! I saw your message but never replied for some reason...

I mean I've experienced a very similar issue before, and I'm interested in the cause as well ^^

Haven't tried to reproduce it yet, might try that tomorrow. Anything interesting in the logs?

@Epsicle
Copy link
Author

Epsicle commented Sep 18, 2024

Hey, also sorry for not getting back to you! Work got crazy.

No nothing concrete yet other than what I've already shared. I'm going to dig deeper over the weekend and let you know if I find anything. I'm going to try to reproduce the issue with FFMPEG directly, feed that transcode into my jellyfin transcode folder, and see if I have the same issue. I'm very suspicious of the transcode logs showing the transcode is briefly continuing after it's been killed via the "q" key but again - just a hunch and as this thread has shown those are not always reliable with me!

@midwesternrodent
Copy link

midwesternrodent commented Oct 6, 2024

(tldr at bottom)

Epsicle here, my main account for contributions got unbanned.

The issue is still happening predictably on the latest version of Jellyfin and Finamp with the same steps to reproduce referenced above. (just for clarity, I'm posting them again below).

  1. Turn on transcoded streams in finamp, stop and start the app for the change take affect.
  2. For ease of reading the results, delete the transcodes in your current transcode directory, also delete the logs in your log directory.
  3. Shuffle your entire library on finamp like a maniac, skipping one song before it even starts playing. Do this several times.
  4. Go through your transcode logs until you find "[q] command received. Exiting." in one of your logs
  5. Check the name of that song and try to play it. Eventually you will hear the song skip.

I confirmed this was still happening, made a copy of the broken transcodes, and then deleted the transcode directory. The issue resolved itself immediately on the broken song I had created with these steps. After restoring the backup of the bad transcodes the issue returned at the exact same spot.

The command that triggered this corrupted transcode on the jellyfin server was the following

/usr/lib/jellyfin-ffmpeg/ffmpeg -analyzeduration 200M -probesize 1G  -i file:"/mnt/truenas/jellyshare/Music/Twenty One Pilots/2009 - Twenty One Pilots/02 - fall away.mp3" -map_metadata -1 -map_chapters -1 -threads 0   -vn -acodec libfdk_aac -ab 256000 -ac 2 -ar 44100 -copyts -avoid_negative_ts disabled -max_muxing_queue_size 2048 -f hls -max_delay 5000000 -hls_time 3 -hls_segment_type mpegts -start_number 0 -hls_segment_filename "/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d39%d.ts" -hls_playlist_type vod -hls_list_size 0 -y "/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d39.m3u8"

I replayed this command exactly on my server and received the following output (note: I manually triggered the "q" command)

jamjar@jamjar:/mnt/truenas/jellyshare$ /usr/lib/jellyfin-ffmpeg/ffmpeg -analyzeduration 200M -probesize 1G  -i file:"/mnt/truenas/jellyshare/Music/Twenty One Pilots/2009 - Twenty One Pilots/02 - fall away.mp3" -map_metadata -1 -m  
ap_chapters -1 -threads 0   -vn -acodec libfdk_aac -ab 256000 -ac 2 -ar 44100 -copyts -avoid_negative_ts disabled -max_muxing_queue_size 2048 -f hls -max_delay 5000000 -hls_time 3 -hls_segment_type mpegts -start_number 0 -hls_seg  
ment_filename "/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d39%d.ts" -hls_playlist_type vod -hls_list_size 0 -y "/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d39.m3u8"  
ffmpeg version 6.0.1-Jellyfin Copyright (c) 2000-2023 the FFmpeg developers  
 built with gcc 12 (Debian 12.2.0-14)  
 configuration: --prefix=/usr/lib/jellyfin-ffmpeg --target-os=linux --extra-version=Jellyfin --disable-doc --disable-ffplay --disable-ptx-compression --disable-static --disable-libxcb --disable-sdl2 --disable-xlib --enable-lto -  
-enable-gpl --enable-version3 --enable-shared --enable-gmp --enable-gnutls --enable-chromaprint --enable-opencl --enable-libdrm --enable-libxml2 --enable-libass --enable-libfreetype --enable-libfribidi --enable-libfontconfig --en  
able-libbluray --enable-libmp3lame --enable-libopus --enable-libtheora --enable-libvorbis --enable-libopenmpt --enable-libdav1d --enable-libsvtav1 --enable-libwebp --enable-libvpx --enable-libx264 --enable-libx265 --enable-libzvb  
i --enable-libzimg --enable-libfdk-aac --arch=amd64 --enable-libshaderc --enable-libplacebo --enable-vulkan --enable-vaapi --enable-amf --enable-libvpl --enable-ffnvcodec --enable-cuda --enable-cuda-llvm --enable-cuvid --enable-n  
vdec --enable-nvenc  
 libavutil      58.  2.100 / 58.  2.100  
 libavcodec     60.  3.100 / 60.  3.100  
 libavformat    60.  3.100 / 60.  3.100  
 libavdevice    60.  1.100 / 60.  1.100  
 libavfilter     9.  3.100 /  9.  3.100  
 libswscale      7.  1.100 /  7.  1.100  
 libswresample   4. 10.100 /  4. 10.100  
 libpostproc    57.  1.100 / 57.  1.100  
Input #0, mp3, from 'file:/mnt/truenas/jellyshare/Music/Twenty One Pilots/2009 - Twenty One Pilots/02 - fall away.mp3':  
 Metadata:  
   album           : Twenty One Pilots  
   artist          : Twenty One Pilots  
   genre           : Electronic Rock Hip Hop  
   title           : Fall Away  
   track           : 02  
   date            : 2009  
 Duration: 00:03:02.47, start: 0.025057, bitrate: 320 kb/s  
 Stream #0:0: Audio: mp3, 44100 Hz, stereo, fltp, 320 kb/s  
   Metadata:  
     encoder         : LAME3.98r  
   Side data:  
     replaygain: track gain - -8.200000, track peak - unknown, album gain - unknown, album peak - unknown,    
Stream mapping:  
 Stream #0:0 -> #0:0 (mp3 (mp3float) -> aac (libfdk_aac))  
Press [q] to stop, [?] for help  
[mpegts @ 0x64aff2b76dc0] frame size not set  
Output #0, hls, to '/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d39.m3u8':  
 Metadata:  
   encoder         : Lavf60.3.100  
 Stream #0:0: Audio: aac, 44100 Hz, stereo, s16, 256 kb/s  
   Metadata:  
     encoder         : Lavc60.3.100 libfdk_aac  
   Side data:  
     replaygain: track gain - -8.200000, track peak - unknown, album gain - unknown, album peak - unknown,    
[hls @ 0x64aff2b10500] Opening '/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d390.ts' for writing  
[hls @ 0x64aff2b10500] Opening '/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d391.ts' for writing  
[hls @ 0x64aff2b10500] Opening '/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d392.ts' for writing  
  
  
[q] command received. Exiting.  
  
[hls @ 0x64aff2b10500] Opening '/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d393.ts' for writing  
size=N/A time=00:00:00.00 bitrate=N/A speed=   0x       
video:0kB audio:366kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown

I then played the selected song through finamp and experienced a skip in the song, but at a different location. Once again, clearing the transcode directory fixed the issue.

Since I haven't (yet) observed this with video content. I decided to give it a shot with Stargate and see what happens in the client if I copy the FFMPEG command and cancel it part way through.

The command for this attempt was the following much beefier command. I once again cleared my transcoding directory before attempting this. I also had to enter the root user to run this command (I believe because I have hardware acceleration enabled). I then once again, immediately pressed "q" and then played the video on the web client to see what happens.

/usr/lib/jellyfin-ffmpeg/ffmpeg -analyzeduration 200M -probesize 1G -ss 00:06:48.000 -noaccurate_seek -init_hw_device vaapi=va:,kernel_driver=i915,driver=iHD -init_hw_device qsv=qs@va -filter_hw_device qs -hwaccel vaapi -hwaccel_output_format vaapi -noautorotate -i file:"/mnt/truenas/jellyshare/movies/Stargate (1994)/Stargate (1994).mp4" -noautoscale -map_metadata -1 -map_chapters -1 -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_qsv -preset veryfast -look_ahead 0 -b:v 6668200 -maxrate 6668200 -bufsize 13336400 -profile:v:0 high -level 51 -g:v:0 72 -keyint_min:v:0 72 -vf "setparams=color_primaries=bt709:color_trc=bt709:colorspace=bt709,scale_vaapi=format=nv12:extra_hw_frames=24,hwmap=derive_device=qsv,format=qsv" -codec:a:0 libfdk_aac -ac 2 -ab 256000 -ar 48000 -af "volume=2" -copyts -avoid_negative_ts disabled -max_muxing_queue_size 2048 -f hls -max_delay 5000000 -hls_time 3 -hls_segment_type fmp4 -hls_fmp4_init_filename "4b895d819a09870f767bcf911656a7ac-1.mp4" -start_number 136 -hls_segment_filename "/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a7ac%d.mp4" -hls_playlist_type vod -hls_list_size 0 -y "/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a7ac.m3u8"

This time the issue did not replicate within the first few minutes of the movie on the Jellyfin client.

When I ran the command as the root user, this was the output:

root@jamjar:/var/log/jellyfin# /usr/lib/jellyfin-ffmpeg/ffmpeg -analyzeduration 200M  
-probesize 1G -ss 00:06:48.000 -noaccurate_seek -init_hw_device vaapi=va:,kernel_dr  
iver=i915,driver=iHD -init_hw_device qsv=qs@va -filter_hw_device qs -hwaccel vaapi -  
hwaccel_output_format vaapi -noautorotate -i file:"/mnt/truenas/jellyshare/movies/St  
argate (1994)/Stargate (1994).mp4" -noautoscale -map_metadata -1 -map_chapters -1 -t  
hreads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_qsv -preset veryfast -look_ahea  
d 0 -b:v 6668200 -maxrate 6668200 -bufsize 13336400 -profile:v:0 high -level 51 -g:v  
:0 72 -keyint_min:v:0 72 -vf "setparams=color_primaries=bt709:color_trc=bt709:colors  
pace=bt709,scale_vaapi=format=nv12:extra_hw_frames=24,hwmap=derive_device=qsv,format  
=qsv" -codec:a:0 libfdk_aac -ac 2 -ab 256000 -ar 48000 -af "volume=2" -copyts -avoid  
_negative_ts disabled -max_muxing_queue_size 2048 -f hls -max_delay 5000000 -hls_tim  
e 3 -hls_segment_type fmp4 -hls_fmp4_init_filename "4b895d819a09870f767bcf911656a7ac  
-1.mp4" -start_number 136 -hls_segment_filename "/mnt/truenas/jellyshare/transcodes/  
4b895d819a09870f767bcf911656a7ac%d.mp4" -hls_playlist_type vod -hls_list_size 0 -y "  
/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a7ac.m3u8"  
ffmpeg version 6.0.1-Jellyfin Copyright (c) 2000-2023 the FFmpeg developers  
 built with gcc 12 (Debian 12.2.0-14)  
 configuration: --prefix=/usr/lib/jellyfin-ffmpeg --target-os=linux --extra-version  
=Jellyfin --disable-doc --disable-ffplay --disable-ptx-compression --disable-static  
--disable-libxcb --disable-sdl2 --disable-xlib --enable-lto --enable-gpl --enable-ve  
rsion3 --enable-shared --enable-gmp --enable-gnutls --enable-chromaprint --enable-op  
encl --enable-libdrm --enable-libxml2 --enable-libass --enable-libfreetype --enable-  
libfribidi --enable-libfontconfig --enable-libbluray --enable-libmp3lame --enable-li  
bopus --enable-libtheora --enable-libvorbis --enable-libopenmpt --enable-libdav1d --  
enable-libsvtav1 --enable-libwebp --enable-libvpx --enable-libx264 --enable-libx265  
--enable-libzvbi --enable-libzimg --enable-libfdk-aac --arch=amd64 --enable-libshade  
rc --enable-libplacebo --enable-vulkan --enable-vaapi --enable-amf --enable-libvpl -  
-enable-ffnvcodec --enable-cuda --enable-cuda-llvm --enable-cuvid --enable-nvdec --e  
nable-nvenc  
 libavutil      58.  2.100 / 58.  2.100  
 libavcodec     60.  3.100 / 60.  3.100  
 libavformat    60.  3.100 / 60.  3.100  
 libavdevice    60.  1.100 / 60.  1.100  
 libavfilter     9.  3.100 /  9.  3.100  
 libswscale      7.  1.100 /  7.  1.100  
 libswresample   4. 10.100 /  4. 10.100  
 libpostproc    57.  1.100 / 57.  1.100  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'file:/mnt/truenas/jellyshare/movies/Stargat  
e (1994)/Stargate (1994).mp4':  
 Metadata:  
   major_brand     : isom  
   minor_version   : 512  
   compatible_brands: isomiso2mp41  
   creation_time   : 2020-03-26T20:27:07.000000Z  
   title           : Stargate.1994.EXTENDED.1080p.BluRay.x265-RARBG  
   encoder         : Lavf58.20.100  
   comment         : Stargate.1994.EXTENDED.1080p.BluRay.x265-RARBG  
 Duration: 02:09:53.67, start: 0.000000, bitrate: 2231 kb/s  
 Stream #0:0[0x1](und): Video: hevc (Main 10) (hev1 / 0x31766568), yuv420p10le(tv),  
1920x800 [SAR 1:1 DAR 12:5], 2000 kb/s, 23.98 fps, 23.98 tbr, 1200k tbn (default)  
   Metadata:  
     creation_time   : 2020-03-26T20:27:07.000000Z  
     handler_name    : VideoHandler  
     vendor_id       : [0][0][0][0]  
 Stream #0:1[0x2](eng): Audio: aac (LC) (mp4a / 0x6134706D), 48000 Hz, 5.1, fltp, 2  
24 kb/s (default)  
   Metadata:  
     creation_time   : 2020-03-26T20:27:07.000000Z  
     handler_name    : SoundHandler  
     vendor_id       : [0][0][0][0]  
Stream mapping:  
 Stream #0:0 -> #0:0 (hevc (native) -> h264 (h264_qsv))  
 Stream #0:1 -> #0:1 (aac (native) -> aac (libfdk_aac))  
Press [q] to stop, [?] for help  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
[hls @ 0x5b42732392c0] Opening '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f7  
67bcf911656a7ac-1.mp4' for writing  
Output #0, hls, to '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a  
7ac.m3u8':  
 Metadata:  
   encoder         : Lavf60.3.100  
 Stream #0:0: Video: h264, qsv(tv, bt709, progressive), 1920x800 [SAR 1:1 DAR 12:5]  
, q=2-31, 6668 kb/s, 23.98 fps, 24k tbn (default)  
   Metadata:  
     encoder         : Lavc60.3.100 h264_qsv  
   Side data:  
     cpb: bitrate max/min/avg: 6668200/0/6668200 buffer size: 13336400 vbv_delay: N  
/A  
 Stream #0:1: Audio: aac, 48000 Hz, stereo, s16, 256 kb/s (default)  
   Metadata:  
     encoder         : Lavc60.3.100 libfdk_aac  
[hls @ 0x5b42732392c0] Opening '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f7  
67bcf911656a7ac136.mp4' for writing  
[mp4 @ 0x5b4276093f00] Packet duration: -16 / dts: 19672040 is out of range  
  
  
[q] command received. Exiting.  
  
[hls @ 0x5b42732392c0] Opening '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f7  
67bcf911656a7ac137.mp4' for writing  
frame=   83 fps=0.0 q=20.0 Lsize=N/A time=00:00:03.37 bitrate=N/A dup=2 drop=0 speed  
=7.41x       
video:2957kB audio:111kB subtitle:0kB other streams:0kB global headers:0kB muxing ov  
erhead: unknown  
root@jamjar:/var/log/jellyfin# ls  
FFmpeg.Transcode-2024-10-06_16-27-14_2da02e2fc71a1a63af6023aa9447fdfd_f1ab44ad.log  
root@jamjar:/var/log/jellyfin# ls  
FFmpeg.Transcode-2024-10-06_16-27-14_2da02e2fc71a1a63af6023aa9447fdfd_f1ab44ad.log  
root@jamjar:/var/log/jellyfin# lsls  
bash: lsls: command not found  
root@jamjar:/var/log/jellyfin# ls  
FFmpeg.Transcode-2024-10-06_16-27-14_2da02e2fc71a1a63af6023aa9447fdfd_f1ab44ad.log  
root@jamjar:/var/log/jellyfin# rm -rf *  
root@jamjar:/var/log/jellyfin# ls  
root@jamjar:/var/log/jellyfin# /usr/lib/jellyfin-ffmpeg/ffmpeg -analyzeduration 200M  
-probesize 1G -ss 00:06:48.000 -noaccurate_seek -init_hw_device vaapi=va:,kernel_dr  
iver=i915,driver=iHD -init_hw_device qsv=qs@va -filter_hw_device qs -hwaccel vaapi -  
hwaccel_output_format vaapi -noautorotate -i file:"/mnt/truenas/jellyshare/movies/St  
argate (1994)/Stargate (1994).mp4" -noautoscale -map_metadata -1 -map_chapters -1 -t  
hreads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_qsv -preset veryfast -look_ahea  
d 0 -b:v 6668200 -maxrate 6668200 -bufsize 13336400 -profile:v:0 high -level 51 -g:v  
:0 72 -keyint_min:v:0 72 -vf "setparams=color_primaries=bt709:color_trc=bt709:colors  
pace=bt709,scale_vaapi=format=nv12:extra_hw_frames=24,hwmap=derive_device=qsv,format  
=qsv" -codec:a:0 libfdk_aac -ac 2 -ab 256000 -ar 48000 -af "volume=2" -copyts -avoid  
_negative_ts disabled -max_muxing_queue_size 2048 -f hls -max_delay 5000000 -hls_tim  
e 3 -hls_segment_type fmp4 -hls_fmp4_init_filename "4b895d819a09870f767bcf911656a7ac  
-1.mp4" -start_number 136 -hls_segment_filename "/mnt/truenas/jellyshare/transcodes/  
4b895d819a09870f767bcf911656a7ac%d.mp4" -hls_playlist_type vod -hls_list_size 0 -y "  
/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a7ac.m3u8"  
ffmpeg version 6.0.1-Jellyfin Copyright (c) 2000-2023 the FFmpeg developers  
 built with gcc 12 (Debian 12.2.0-14)  
 configuration: --prefix=/usr/lib/jellyfin-ffmpeg --target-os=linux --extra-version  
=Jellyfin --disable-doc --disable-ffplay --disable-ptx-compression --disable-static  
--disable-libxcb --disable-sdl2 --disable-xlib --enable-lto --enable-gpl --enable-ve  
rsion3 --enable-shared --enable-gmp --enable-gnutls --enable-chromaprint --enable-op  
encl --enable-libdrm --enable-libxml2 --enable-libass --enable-libfreetype --enable-  
libfribidi --enable-libfontconfig --enable-libbluray --enable-libmp3lame --enable-li  
bopus --enable-libtheora --enable-libvorbis --enable-libopenmpt --enable-libdav1d --  
enable-libsvtav1 --enable-libwebp --enable-libvpx --enable-libx264 --enable-libx265  
--enable-libzvbi --enable-libzimg --enable-libfdk-aac --arch=amd64 --enable-libshade  
rc --enable-libplacebo --enable-vulkan --enable-vaapi --enable-amf --enable-libvpl -  
-enable-ffnvcodec --enable-cuda --enable-cuda-llvm --enable-cuvid --enable-nvdec --e  
nable-nvenc  
 libavutil      58.  2.100 / 58.  2.100  
 libavcodec     60.  3.100 / 60.  3.100  
 libavformat    60.  3.100 / 60.  3.100  
 libavdevice    60.  1.100 / 60.  1.100  
 libavfilter     9.  3.100 /  9.  3.100  
 libswscale      7.  1.100 /  7.  1.100  
 libswresample   4. 10.100 /  4. 10.100  
 libpostproc    57.  1.100 / 57.  1.100  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'file:/mnt/truenas/jellyshare/movies/Stargat  
e (1994)/Stargate (1994).mp4':  
 Metadata:  
   major_brand     : isom  
   minor_version   : 512  
   compatible_brands: isomiso2mp41  
   creation_time   : 2020-03-26T20:27:07.000000Z  
   title           : Stargate.1994.EXTENDED.1080p.BluRay.x265-RARBG  
   encoder         : Lavf58.20.100  
   comment         : Stargate.1994.EXTENDED.1080p.BluRay.x265-RARBG  
 Duration: 02:09:53.67, start: 0.000000, bitrate: 2231 kb/s  
 Stream #0:0[0x1](und): Video: hevc (Main 10) (hev1 / 0x31766568), yuv420p10le(tv),  
1920x800 [SAR 1:1 DAR 12:5], 2000 kb/s, 23.98 fps, 23.98 tbr, 1200k tbn (default)  
   Metadata:  
     creation_time   : 2020-03-26T20:27:07.000000Z  
     handler_name    : VideoHandler  
     vendor_id       : [0][0][0][0]  
 Stream #0:1[0x2](eng): Audio: aac (LC) (mp4a / 0x6134706D), 48000 Hz, 5.1, fltp, 2  
24 kb/s (default)  
   Metadata:  
     creation_time   : 2020-03-26T20:27:07.000000Z  
     handler_name    : SoundHandler  
     vendor_id       : [0][0][0][0]  
Stream mapping:  
 Stream #0:0 -> #0:0 (hevc (native) -> h264 (h264_qsv))  
 Stream #0:1 -> #0:1 (aac (native) -> aac (libfdk_aac))  
Press [q] to stop, [?] for help  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
libva info: VA-API version 1.22.0  
libva info: Trying to open /usr/lib/jellyfin-ffmpeg/lib/dri/iHD_drv_video.so  
libva info: Found init function __vaDriverInit_1_22  
libva info: va_openDriver() returns 0  
[hls @ 0x5ee36dcdfc00] Opening '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f7  
67bcf911656a7ac-1.mp4' for writing  
Output #0, hls, to '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a  
7ac.m3u8':  
 Metadata:  
   encoder         : Lavf60.3.100  
 Stream #0:0: Video: h264, qsv(tv, bt709, progressive), 1920x800 [SAR 1:1 DAR 12:5]  
, q=2-31, 6668 kb/s, 23.98 fps, 24k tbn (default)  
   Metadata:  
     encoder         : Lavc60.3.100 h264_qsv  
   Side data:  
     cpb: bitrate max/min/avg: 6668200/0/6668200 buffer size: 13336400 vbv_delay: N  
/A  
 Stream #0:1: Audio: aac, 48000 Hz, stereo, s16, 256 kb/s (default)  
   Metadata:  
     encoder         : Lavc60.3.100 libfdk_aac  
[hls @ 0x5ee36dcdfc00] Opening '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f7  
67bcf911656a7ac136.mp4' for writing  
[mp4 @ 0x5ee371748b00] Packet duration: -16 / dts: 19672040 is out of range  
  
  
[q] command received. Exiting.  
  
[hls @ 0x5ee36dcdfc00] Opening '/mnt/truenas/jellyshare/transcodes/4b895d819a09870f7  
67bcf911656a7ac137.mp4' for writing  
frame=   83 fps=0.0 q=20.0 Lsize=N/A time=00:00:03.37 bitrate=N/A dup=2 drop=0 speed  
=7.55x       
video:2957kB audio:111kB subtitle:0kB other streams:0kB global headers:0kB muxing ov  
erhead: unknown

When I went to play the file in the jellyfin web client, there was no skip. I then attempted to recreate the issue manually by starting the ffmpeg command, manually killing it, and copying the files over to my desktop. I then ran the command again but stopped it a little later. I grabbed the new m3u8 file overwriting the one on my local machine and all the mp4s except for those generated by the previous transcode.

Playing this monstrosity in VLC resulted in this very noticable skip occuring.

I then replicated this by trying to grab the files that I triggered from a web player. What I found is that I could see the "[q]" command being sent in the logs for the video content, but once the session ends, Jellyfin is deleting the transcodes entirely for video content.

The issue seems to be that Jellyfin is not doing the same for the audio only transcodes that are triggered through finamp, leading to the broken transcodes remaining on the system. I also found that when I re-ran the ffmpeg transcode from the CLI, jellyfin overwrote the corrupted .mp4 on the video content, but this did not happen for audio content when I ran that command on the CLI.

I'm going to compare the options between the two commands and see if I can find a flag that works to overwrite the corrupted transcodes for audio. Just figured I'd post my work so far.

tldr;

  1. Video content is deleted after the user session ends in Jellyfin, audio content that is transcoded via finamp, is not.
  2. There are wildly different commands for transcoding audio vs video they are below.
  3. Video transcodes also overwrite bad sections of a transcode even when done manually via the CLI. This does not happen with the command being used by finamp.

I believe there is a flag in ffmpeg that may mitigate this since I'm seeing different behavior on video vs. audio transcodes. I just need to take some time to figure out what it is.

Command for Video Transcoding

/usr/lib/jellyfin-ffmpeg/ffmpeg -analyzeduration 200M -probesize 1G -ss 00:06:48.000 -noaccurate_seek -init_hw_device vaapi=va:,kernel_driver=i915,driver=iHD -init_hw_device qsv=qs@va -filter_hw_device qs -hwaccel vaapi -hwaccel_output_format vaapi -noautorotate -i file:"/mnt/truenas/jellyshare/movies/Stargate (1994)/Stargate (1994).mp4" -noautoscale -map_metadata -1 -map_chapters -1 -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_qsv -preset veryfast -look_ahead 0 -b:v 6668200 -maxrate 6668200 -bufsize 13336400 -profile:v:0 high -level 51 -g:v:0 72 -keyint_min:v:0 72 -vf "setparams=color_primaries=bt709:color_trc=bt709:colorspace=bt709,scale_vaapi=format=nv12:extra_hw_frames=24,hwmap=derive_device=qsv,format=qsv" -codec:a:0 libfdk_aac -ac 2 -ab 256000 -ar 48000 -af "volume=2" -copyts -avoid_negative_ts disabled -max_muxing_queue_size 2048 -f hls -max_delay 5000000 -hls_time 3 -hls_segment_type fmp4 -hls_fmp4_init_filename "4b895d819a09870f767bcf911656a7ac-1.mp4" -start_number 136 -hls_segment_filename "/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a7ac%d.mp4" -hls_playlist_type vod -hls_list_size 0 -y "/mnt/truenas/jellyshare/transcodes/4b895d819a09870f767bcf911656a7ac.m3u8"

Command for Audio Transcoding Through Finamp

/usr/lib/jellyfin-ffmpeg/ffmpeg -analyzeduration 200M -probesize 1G  -i file:"/mnt/truenas/jellyshare/Music/Twenty One Pilots/2009 - Twenty One Pilots/02 - fall away.mp3" -map_metadata -1 -map_chapters -1 -threads 0   -vn -acodec libfdk_aac -ab 256000 -ac 2 -ar 44100 -copyts -avoid_negative_ts disabled -max_muxing_queue_size 2048 -f hls -max_delay 5000000 -hls_time 3 -hls_segment_type mpegts -start_number 0 -hls_segment_filename "/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d39%d.ts" -hls_playlist_type vod -hls_list_size 0 -y "/mnt/truenas/jellyshare/transcodes/89230d82729c85bc61702e25da605d39.m3u8"

@midwesternrodent
Copy link

Looking at the two commands, there isn't a significant amount of difference other than the extra flags for video. The -y flag is even specified to overwrite existing output already. But for some reason, FFMPEG is seeing the 0.ts and 1.ts files already present, and starting at 2.ts rather than re-transcode over files 0 and 1.

I think this is probably upstream, as that would make sense to hang onto that cache for something larger like a TV show or movie that probably always has a partial transcode, and the skips are likely less noticeable if they happen at all / maybe they're large enough they trigger a jellyfin cleanup script that the audio transcodes just aren't large enough to trigger?

Big I don't know. But let me know if you want me to dig into anything else.

In the meantime, I've made a hacky script, and installed it in my crontab on the jellyfin server to workaround this for now. This searches through every transcode log, finds those that aborted early (and have .ts extensions), and deletes all of the transcode segments for that audio file from the transcode directory. This seems to get me what I need, but it is VERY hacky as you can tell.

#!/bin/bash
# Author: MidwesternRodent
# Date: 10/11/2024
#
# Description: Search the Jellyfin transcode logs for an aborted audio transcode
# indicated by the phrase "[q] command received. Exiting". When found, determine
# the names of the relevant HLS segments produced by ffmpeg, and delete them in
# the jellyfin transcode directory.
#
# This is designed as a temporary workaround (famous last words) to finamp issue #857
#
# https://github.com/jmshrv/finamp/issues/857

# Change to the location of your logs and transcode folders
# You can find this information with your admin user at
# https://yourjellyfinserver.tld/web/#/dashboard

jellyfin_log_path=/var/log/jellyfin/
jellyfin_transcode_path=/mnt/truenas/jellyshare/transcodes/

# We're going to use this to search for the transcode segement name.
string_before_transcode_segment_name="-hls_segment_filename \"$jellyfin_transcode_path"

for file in $(find $jellyfin_log_path -type f); do
    while IFS= read -r line; do
        if [[ $line == *"[q] command received. Exiting"* ]]; then
            # Change /mnt/truenas/jellyshare/transcodes/ to your transcode directory.
            bad_transcode_segment=$(cat $file | grep -o -P "(?<=$string_before_transcode_segment_name).*(?=%d.ts)")

            # if this is null, then the file didn't have ".ts" in it, meaning it's likely a non-finamp generated transcode (like a movie)
            if [[ $bad_transcode_segment == "" ]]; then
                echo "NULL"
                continue
            else
                # Delete the bad transcode files and the log file, now that we're done with them.
                # Note: Deleting the log file requires sudo permissions
                rm $jellyfin_transcode_path$bad_transcode_segment*
                rm $file
                continue
            fi
        fi

    done < $file
done

And I've just got it installed in my crontab like so to run every 5 minutes.

*/5 * * * * /home/jamjar/DeletePartialTranscodes.sh

@Chaphasilor
Copy link
Collaborator

Hey @midwesternrodent, it's amazing how much effort you're putting into this!
One obvious thing that I haven't seen you attempt yet (or did I miss it?) is trying to reproduce this issue somehow in the official Jellyfin client, or any other Jellyfin music client for that matter.
It's starting to sound like this really is an upstream issue, and the only thing we could do in Finamp are some hacky workarounds.

I'll reproduce this in an hour or so and respond back!

@Chaphasilor
Copy link
Collaborator

Chaphasilor commented Oct 16, 2024

Just managed to reproduce it with Finamp following your steps above. Although I do have the quit message followed by writes in all of the transcode logs, but only noticed the skipping with some tracks so far...

Edit: Seems like maybe I just missed the gaps for the first couple tracks. Every other track so far has had a gap.

@Chaphasilor
Copy link
Collaborator

Okay, so after quickly skipping through about 50 tracks at first, getting the quit message for every transcode, and then listening to that queue from the start, I can say that indeed all tracks have a short skip (likely one missing segment) somewhere in the middle.

I also tried reproducing it with the stock app, but while I got the expected logs, the server always re-transcodes and doesn't use existing transcodes, so the gaps are not present...
Now I need to figure out why in Finamp's case the old files are used.

@Chaphasilor
Copy link
Collaborator

Also, the only difference between the ffmpeg commands logged by Finamp vs. Jellyfin Web/Android was the -ar 44100 option (which specifies sampling rate). It of course makes no sense at all that this is the issue, but that doesn't mean that it really isn't the issue.
I'll try removing the sampling rate from Finamp's transcode request and seeing what happens...

@midwesternrodent
Copy link

Hey, thanks! I'm just glad I'm not crazy, lol. I was going to spin up a server in docker to see if I could recreate it there if I hadn't heard from you or someone else. I did try the stock jellyfin app but I'm not sure if I mentioned it here explicitly, I wasn't able to get it to reliably transcode all the time since a lot of my stuff could just direct-play through it.

If it is upstream, I'm happy to take the info I've gathered and put in an issue with Jellyfin, or if you'd prefer to open it I can make sure I follow it and provide any logs and background info from my server. Let me know if changing the sampling rate does anything. Thanks for investigating!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants