Subsonic is streaming from server when data should be cached offline

Support
1

Issue description:

This was already discussed within the Discussion area and it was requested to be moved here.

Here is the related discussion: When using Navidrome via Subsonic provider with automatic offline media cache it still seems to connect to navidrome when playing, is that expected behaviour?

As mentioned in there, I have synced with subsonic, there is no offline files to download, but if I am on wifi it will always seem to report the files as uncached as per the logs of Navidrome but if I were to turn off wifi/cell it will play fine without calling up to Subsonic.

An odd experiment I did was to do track playlist while online, I then went offline and skipped about 5 songs ahead playing a bit of each, then went back 5 and went back online. When playing the 5 songs I just played it didnt seem to read from the server, but then on the subsequent one it did.

Happy to provide any logs you require, or confirm settings, it could very well be some user error somewhere but to my knowledge all the correct flags are set for offline usage and as I say when I sync it doesnt queue any more files to DL.

Logs:

Upload description: grofit

Additional information:

 

 

Reproduction steps:

 
Just playing any song from fresh start seems to trigger it to be streamed rather than played locally.
 

Media provider:

Subsonic

Screenshots:

     

2

In the logs 100% of the files are played from the offline cache.

3

Sorry I had to dash after posting this, and I only turned debug on for a short period, BUT I went back and checked the Navidrome logs as I heard it doing something on there in the short period I had debug logs on and I think this was one of the last songs played:

time=“2025-10-02T19:03:18Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008454 title=“Too Shy” user=grofit
time=“2025-10-02T19:03:18Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008456 title=“Too Shy” user=grofit
time=“2025-10-02T19:03:18Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008457 title=“Too Shy” user=grofit
time=“2025-10-02T19:03:18Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008455 title=“Too Shy” user=grofit
time=“2025-10-02T19:03:18Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008459 title=“Too Shy” user=grofit
time=“2025-10-02T19:03:18Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008458 title=“Too Shy” user=grofit
time=“2025-10-02T19:03:18Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008460 title=“Too Shy” user=grofit
time=“2025-10-02T19:03:26Z” level=info msg=“Now Playing” artist=“Now Thats What I Call Music” player=“Symfonium [Symfonium/Android]” position=0 requestId=118b361043e4/hQcjUudxFc-008461 title=“Too Shy” user=grofit
time=“2025-10-02T19:07:16Z” level=info msg=“Streaming file” artist=“Now Thats What I Call Music” bitRate=0 cached=false format=raw originalBitRate=96 originalFormat=opus requestId=118b361043e4/hQcjUudxFc-008471 title=“Too Shy” transcoding=false user=grofit
time=“2025-10-02T19:07:17Z” level=info msg=“Streaming file” artist=“Now Thats What I Call Music” bitRate=0 cached=false format=raw originalBitRate=96 originalFormat=opus requestId=118b361043e4/hQcjUudxFc-008472 title=“Too Shy” transcoding=false user=grofit
time=“2025-10-02T19:07:17Z” level=info msg=“Streaming file” artist=“Now Thats What I Call Music” bitRate=0 cached=false format=raw originalBitRate=96 originalFormat=opus requestId=118b361043e4/hQcjUudxFc-008473 title=“Too Shy” transcoding=false user=grofit
time=“2025-10-02T19:07:17Z” level=info msg=“Streaming file” artist=“Now Thats What I Call Music” bitRate=0 cached=false format=raw originalBitRate=96 originalFormat=opus requestId=118b361043e4/hQcjUudxFc-008474 title=“Too Shy” transcoding=false user=grofit

So that was indicating that it was not cached and streamed it, do the logs from Symfonium say otherwise?

4

I don’t know what Navidrome logs, maybe it’s based on the scrobble @deluan ?

But I can assure you that is was played from the cache.

2025-10-02 20:03:19.607 Verbose MediaPrepareManager  getPreparedMedia[W]: From cache PlayableMediaItem(source=MediaItem{externalId='caa0f426a8b4648bdef712df59229db1', mediaType=Song, file='/music/Albums/Now Thats What I Call Music/Now Thats What I Call No. 1s 2006/1-14 Too Shy 1.opus', title='Too Shy', resume=0}, url=file:///%2Fstorage%2F72C8-5C5A%2FAndroid%2Fdata%2Fapp.symfonik.music.player%2Ffiles%2FOfflineMedias%2FC%2FCAA0F426A8B4648BDEF712DF59229DB1.opus, externalThumbnail=, originalUrl=, urlIncludeResumePoint=false, urlIncludeResumePointValue=null, alreadyResolved=true, mimeTypeOverride=, payload=, preparationError=false, preparationErrorMessage=, playlistPosition=49, repeatCount=0, headers=null, mediaFormat=null, lyrics=[], chapters=null, uuid=41cef255-b0f8-4bdd-8920-3fa8727a3831, supportSeeking=true, playsAsAdvertisement=false, isPublicStreamable=false) -> PlayableMediaItem(source=MediaItem{externalId='caa0f426a8b4648bdef712df59229db1', mediaType=Song, file='/music/Albums/Now Thats What I Call Music/Now Thats What I Call No. 1s 2006/1-14 Too Shy 1.opus', title='Too Shy', resume=0}, url=file:///%2Fstorage%2F72C8-5C5A%2FAndroid%2Fdata%2Fapp.symfonik.music.player%2Ffiles%2FOfflineMedias%2FC%2FCAA0F426A8B4648BDEF712DF59229DB1.opus, externalThumbnail=, originalUrl=, urlIncludeResumePoint=false, urlIncludeResumePointValue=null, alreadyResolved=true, mimeTypeOverride=, payload=, preparationError=false, preparationErrorMessage=, playlistPosition=49, repeatCount=0, headers=null, mediaFormat=null, lyrics=[], chapters=null, uuid=41cef255-b0f8-4bdd-8920-3fa8727a3831, supportSeeking=true, playsAsAdvertisement=false, isPublicStreamable=false)


2025-10-02 20:03:19.619 Verbose ExternalPlaylistDataSource  Open [p=0.01s, o=0.01s, t=0.02s, c=0]: 41cef255-b0f8-4bdd-8920-3fa8727a3831/DataSpec[GET file:///%2Fstorage%2F72C8-5C5A%2FAndroid%2Fdata%2Fapp.symfonik.music.player%2Ffiles%2FOfflineMedias%2FC%2FCAA0F426A8B4648BDEF712DF59229DB1.opus, 667, -1, null, 6]
5

Is there any way in the app for me to check the logs? I tried using file browser (on device) to access the app folder to see if I can find the logs directly but it seems to hang the file browser whenever I try to access the app folder (assume its android permissions or something).

I havent bothered posting again incase @deluan was going to chime in but I tried to see if I could dig into things on the Navidrome side, as that seems to still be indicating its not cached, but others have said that may be due to scrobbling, but I confirmed scrobbling isnt enabled or setup on my instance so it cant be that.

As I cant access the logs myself, can you tell me at a high level what the flow is for when it goes to play an audio file linked to subsonic? as it seems to hang for a while on the first play (even when im pretty confident the file is cached) so im wondering if it knows the files locally available but has an async call open to the subsonic server which needs to complete before audio plays.

6

Completely unrelated to the issue and what is happening…

And you can share the logs to your email or file app or whatever but they will show what I’ve shown so if you do not believe me you won’t get more.

Install a proxy and see that /stream.view is not called, check server BW, many other more logical ways to see what happen if you don’t believe me.

7

Its not that I don’t believe what you have said, I am sure Symfonium is playing from the cache as you say, but regardless it takes longer to play tracks when the device can connect to the Navidrome instance and for some reason (possibly nothing to do with Symfonium) its causing reads on the NAS where the music is stored even though it shouldnt be.

So I am in an awkward position as a user here as I am seeing slight lags in this app when the device can connect to the server, but if it cant there isn’t that problem. So if we assume there is a problem on Navidromes end I need to be able to help them diagnose like I have tried to give you logs from their side, so I want to give them some logs from your side.

Also on the point on scrobbling, this isnt information from me it was mentioned by a user in their discord that a scrobble request could possibly trigger a read (I cannot confirm if this is true).

Ultimately I want to gather more data to ascertain where the read is stemming from, so again its not about if I believe you or not, it just getting more information to work out whats happening, as however you spin it, its not a great experience for me when connected to same wifi as server.

8

You never said anything about lag or whatever …

You said the app stream when it should not, no it’s not the case.

Scrobble are sent from Symfonium to Subsonic always if the server is accessible to maintain playcounts and up to date dashboard.

So if you have lags it’s another issue, open a new one with proper details on what you are actually after.

9

Its not consistent or I would raise it, anecdotally it seems to happen more often on the first few plays and only when on wifi, if im not on wifi I never seem to have the issue, so rather than jumping to another issue I just want to follow this up with navidrome people as it could be that the 2 things are linked, it could be that they are not, but either way I want to resolve this and see if that improves things.

10

Just to add more info, the following log from Navidrome means that the server’s /stream (or /download) endpoint was indeed called, and the file was not served from the server’s cache (yes, the server also has its own cache, configurable by TranscodingCacheSize). It has nothing to do with the client cache.
```
requestId=118b361043e4/hQcjUudxFc-008471 title=“Too Shy” transcoding=false user=grofit
time=“2025-10-02T19:07:17Z” level=info msg=“Streaming file” artist=“Now Thats What I Call Music” bitRate=0 cached=false format=raw originalBitRate=96 originalFormat=opus
```

11

Thanks so then @grofit you need to provide matching logs with matching timestamps between Navidrome and Symfonium.

There is 0 call to stream or download in the provided logs for sure.

12

Thanks for the clarification, from the logs provided do you see any reason why there would be reads made to the music volume in the scenario shown in the logs? (the data volume is on a local disk so wouldn’t need to read from the Nas)

13

Sorry I thought this is what was provided originally, I sent you the debug logs from here and the related logs from navidrome that matched the file plays.

I am happy to do same thing again and paste them in here (will have to be later or tomorrow though)

14

Server logs says “2025-10-02T19:07:17Z” The Symfonium logs are between 20:01 and 20:03.

But again in the provided logs there’s no call to /stream or /download only /scrobble and /getLyricsBySongId

And no do not paste logs here, use the upload system as intended.

15

Ah ok, thankfully had a couple of minutes so gave it a try, I cleared all logs and restarted phone so its a fresh run, I played a known cached file heard the read on the NAS, uploaded the support file. Here is the Navidrome logs for this period.

time="2025-10-24T17:41:35Z" level=error msg="Error calling LastFM/artist.getInfo" artist="Min Su Kim (GHSTLOOP)" error="last.fm error(6): The artist you supplied could not be found" requestId=dc88595204c0/rWalE4EA5B-000733
time="2025-10-24T17:41:35Z" level=warning msg="Artist not found in deezer" artist="Min Su Kim (GHSTLOOP)" requestId=dc88595204c0/rWalE4EA5B-000733
time="2025-10-24T17:41:35Z" level=warning msg="HTTP: GET http://my-server/share/img/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6ImFyLTdrcVprcTZFaHk3aW0wZ2NiSTBHd3RfMCIsImlzcyI6Ik5EIn0.uNCoWPQPM3JKoD3qp248tFDWYB6nz5SuN1Iwfyehci4?size=1200&u=grofit&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime=324.7ms httpStatus=404 remoteAddr="192.168.1.143:46538" requestId=dc88595204c0/rWalE4EA5B-000733 responseSize=18
time="2025-10-24T17:41:35Z" level=error msg="Error calling LastFM/artist.getInfo" artist="Min Su Kim (GHSTLOOP)" error="last.fm error(6): The artist you supplied could not be found" requestId=dc88595204c0/rWalE4EA5B-000734
time="2025-10-24T17:41:35Z" level=warning msg="Artist not found in deezer" artist="Min Su Kim (GHSTLOOP)" requestId=dc88595204c0/rWalE4EA5B-000734
time="2025-10-24T17:41:35Z" level=warning msg="HTTP: GET http://my-server/share/img/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpZCI6ImFyLTdrcVprcTZFaHk3aW0wZ2NiSTBHd3RfMCIsImlzcyI6Ik5EIn0.uNCoWPQPM3JKoD3qp248tFDWYB6nz5SuN1Iwfyehci4?size=1200&u=grofit&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime=261.3ms httpStatus=404 remoteAddr="192.168.1.143:46538" requestId=dc88595204c0/rWalE4EA5B-000734 responseSize=18
time="2025-10-24T17:41:44Z" level=info msg="Now Playing" artist=Bethesda player="Symfonium [Symfonium/Android]" position=0 requestId=dc88595204c0/rWalE4EA5B-000736 title="Wings of Kynareth" user=grofit
time="2025-10-24T17:41:44Z" level=info msg="Now Playing" artist=Bethesda player="Symfonium [Symfonium/Android]" position=0 requestId=dc88595204c0/rWalE4EA5B-000737 title="Wings of Kynareth" user=grofit
time="2025-10-24T17:41:44Z" level=info msg="Streaming file" artist=Bethesda bitRate=0 cached=false format=raw originalBitRate=140 originalFormat=opus requestId=dc88595204c0/rWalE4EA5B-000738 title="Wings of Kynareth" transcoding=false user=grofit
time="2025-10-24T17:41:44Z" level=info msg="Now Playing" artist=Bethesda player="Symfonium [Symfonium/Android]" position=0 requestId=dc88595204c0/rWalE4EA5B-000739 title="Wings of Kynareth" user=grofit
time="2025-10-24T17:41:45Z" level=info msg="Streaming file" artist=Bethesda bitRate=0 cached=false format=raw originalBitRate=140 originalFormat=opus requestId=dc88595204c0/rWalE4EA5B-000740 title="Wings of Kynareth" transcoding=false user=grofit
time="2025-10-24T17:41:45Z" level=info msg="Streaming file" artist=Bethesda bitRate=0 cached=false format=raw originalBitRate=140 originalFormat=opus requestId=dc88595204c0/rWalE4EA5B-000741 title="Wings of Kynareth" transcoding=false user=grofit
time="2025-10-24T17:41:45Z" level=info msg="Now Playing" artist=Bethesda player="Symfonium [Symfonium/Android]" position=0 requestId=dc88595204c0/rWalE4EA5B-000742 title="Wings of Kynareth" user=grofit
time="2025-10-24T17:41:45Z" level=info msg="Streaming file" artist=Bethesda bitRate=0 cached=false format=raw originalBitRate=140 originalFormat=opus requestId=dc88595204c0/rWalE4EA5B-000743 title="Wings of Kynareth" transcoding=false user=grofit
time="2025-10-24T17:41:45Z" level=info msg="Now Playing" artist=Bethesda player="Symfonium [Symfonium/Android]" position=0 requestId=dc88595204c0/rWalE4EA5B-000744 title="Wings of Kynareth" user=grofit
time="2025-10-24T17:41:49Z" level=info msg="Now Playing" artist=Bethesda player="Symfonium [Symfonium/Android]" position=0 requestId=dc88595204c0/rWalE4EA5B-000745 title="Wings of Kynareth" user=grofit

What I find odd is that I loaded the app, didnt play anything other than Wings of Kynareth, so no idea why it was requesting some other song, but regardless it did the read when I played Wings of Kynareth, let me know if you need any other data/info.

16

Enable Navidrome debug mode to trace level to see more.

And again do not paste logs here …

17

Sorry I thought you meant Symfonium logs, where do you want me to put the Navidrome logs for your viewing pleasure?

Stand down I have found the upload widget thing in here

18

I restarted device, played Wings of Kynreath from the android widget and it didnt seem to do a read, I loaded up the app and picked a different track that I know is cached “Night on the Plains” and it did the read, I have uploaded the whole navidrome log (its not JSON but your uploader wont allow .txt), let me know if you need anything else.

== Edit ==
Had to reupload the logs as it didnt take ALL the logs since I restarted due to cutoff, re-uploaded with ALL the logs from server booting so you should have everything.
navidrome_logs_all.json (1.6 MB)

19

The actual upload system is https://upload.symfonium.app :wink:

Anyway thanks, so it’s ffmpeg, not related to playback and absolutely not supposed to reach the server. Can you export your settings (not the providers just the settings part) and explain how you offline cache those files and how you start playback.

20

Sorry just to clarify you want the symfonium settings?