jmshrv / finamp

A Jellyfin music client for mobile
Mozilla Public License 2.0
1.85k stars 121 forks source link

Skipping Songs While Transcoding Causes Audio Glitches #857

Open Epsicle opened 3 weeks ago

Epsicle commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 3 weeks ago

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 commented 2 weeks ago

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 commented 3 days ago

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!