search

navidrome / navidrome

🎧☁️ Modern Music Server and Streamer compatible with Subsonic/Airsonic
https://www.navidrome.org
GNU General Public License v3.0
10.47k stars 798 forks source link

[Bug]: HTTP 416 on Symfonium Offline #2287

Closed vbabiy closed 6 months ago

vbabiy commented 1 year ago

I confirm that:

Version

v0.49.3

Current Behavior

Server is throwing 416 errors on file downloads in Symfonium

Expected Behavior

File to download

Steps To Reproduce

No response

Environment

- OS: Ubuntu 20.04
- Client: Latest Symfonium

How Navidrome is installed?

Binary (from downloads page)

Configuration

MusicFolder = '/nas/Media/Music/Library'
TranscodingCacheSize = '150MiB'
LogLevel = 'DEBUG'
ScanSchedule = '@every 1h'
EnableSharing = true

[Scanner]
Extractor = 'ffmpeg'

[Prometheus]
Enabled = true
MetricsPath = '/metrics_vb_zone_9192010'

Relevant log output

Mar 29 11:45:47 navidrome navidrome[298]: time="2023-03-29T11:45:47Z" level=warning msg="HTTP: GET http://<server>/rest/stream.view?id=037c13627017d1906675f9b877d8111c&u=vbabiy&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime=1ms httpStatus=416 remoteAddr=10.10.100.134 requestId=navidrome/OCuvAPT3s6-238134 responseSize=33 userAgent="Symfonium/4.3.0 (Linux;Android 13)"
Mar 29 11:50:20 navidrome navidrome[298]: time="2023-03-29T11:50:20Z" level=warning msg="HTTP: GET http://<server>/rest/stream.view?id=ee7f8bacccdfd2a6af2cc956414c3602&u=vbabiy&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime=2.1ms httpStatus=416 remoteAddr=10.10.100.134 requestId=navidrome/OCuvAPT3s6-238576 responseSize=33 userAgent="Symfonium/4.3.0 (Linux;Android 13)"

Anything else?

I am get some music but others fail.

Code of Conduct

deluan commented 1 year ago

I need more logs, with information about the streaming request (probably a few lines before the lines you sent.

vbabiy commented 1 year ago 
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="Streaming RAW file" id=fd615085809df26209e5841ac9dbe221 originalBitrate=632 originalFormat=flac path="/nas/Media/Music/Library/Yu-Peng Chen & HOYO-MiX/Genshin Impact - The Shimmering Voyage/4-18 Ominous Monolith.flac" requestBitrate=0 requestFormat= requestId=navidrome/OCuvAPT3s6-239909 selectedBitrate=0 selectedFormat=raw username=vbabiy
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=info msg="Streaming file" artist="Yu-Peng Chen & HOYO-MiX" bitRate=0 cached=false format=raw originalBitRate=632 originalFormat=flac requestId=navidrome/OCuvAPT3s6-239909 title="Ominous Monolith" transcoding=false user=vbabiy username=vbabiy
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=warning msg="HTTP: GET http://<server>/rest/stream.view?id=fd615085809df26209e5841ac9dbe221&u=vbabiy&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime=1.3ms httpStatus=416 remoteAddr=10.10.100.134 requestId=navidrome/OCuvAPT3s6-239909 responseSize=33 userAgent="Symfonium/4.3.0 (Linux;Android 13)"
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="Streaming RAW file" id=5fe9d65706e12aef9d27009839c1129f originalBitrate=642 originalFormat=flac path="/nas/Media/Music/Library/Yu-Peng Chen & HOYO-MiX/Genshin Impact - Jade Moon Upon a Sea of Clouds/1-07 Call It a Day in Liyue.flac" requestBitrate=0 requestFormat= requestId=navidrome/OCuvAPT3s6-239910 selectedBitrate=0 selectedFormat=raw username=vbabiy
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=info msg="Streaming file" artist="Yu-Peng Chen & HOYO-MiX" bitRate=0 cached=false format=raw originalBitRate=642 originalFormat=flac requestId=navidrome/OCuvAPT3s6-239910 title="Call It a Day in Liyue" transcoding=false user=vbabiy username=vbabiy
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=warning msg="HTTP: GET http://<server>/rest/stream.view?id=5fe9d65706e12aef9d27009839c1129f&u=vbabiy&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime=1.5ms httpStatus=416 remoteAddr=10.10.100.134 requestId=navidrome/OCuvAPT3s6-239910 responseSize=33 userAgent="Symfonium/4.3.0 (Linux;Android 13)"
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="API: New request /rest/getSong.view" client=Symfonium requestId=navidrome/OCuvAPT3s6-239911 username=vbabiy version=1.13.0
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="Found matching player" client=Symfonium id=d2a48712-6f02-4c55-8ce0-445322415a0d requestId=navidrome/OCuvAPT3s6-239911 type=Symfonium/Android username=vbabiy
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="API: Successful response" endpoint=/rest/getSong.view requestId=navidrome/OCuvAPT3s6-239911 status=OK username=vbabiy
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="HTTP: GET http://<server>/rest/getSong.view?id=7ada350f442db91392b57dde38955f53&u=vbabiy&t=[REDACTED]&s=[REDACTED]&v=1.13.0&c=Symfonium&f=json" elapsedTime="936.053µs" httpStatus=200 remoteAddr=10.10.100.134 requestId=navidrome/OCuvAPT3s6-239911 responseSize=739 userAgent="Symfonium/4.3.0 (Linux;Android 13)"
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="API: New request /rest/stream.view" client=Symfonium requestId=navidrome/OCuvAPT3s6-239912 username=vbabiy version=1.13.0
Mar 29 14:28:44 navidrome navidrome[298]: time="2023-03-29T14:28:44Z" level=debug msg="Found matching player" client=Symfonium id=d2a48712-6f02-4c55-8ce0-445322415a0d requestId=navidrome/OCuvAPT3s6-239912 type=Symfonium/Android username=vbabiy
deluan commented 1 year ago

I talked to @Tolriq from Symfonium. It would be helpful if you could open an issue in Symfonium forum with the app logs, so he can also take a look at this.

vbabiy commented 1 year ago

@deluan posted https://support.symfonium.app/t/416-error-on-offline-download/1741/1

vbabiy commented 1 year ago

No Range works fine:

http  -pHh "http://<server-skipping-caddy>:4533/rest/stream.view?id=xx&u=vbabiy&t=xxx&s=xx&v=1.13.0&c=Symfonium&f=json"
GET /rest/stream.view?id=xxx&u=vbabiy&t=xxx&s=xxx&v=1.13.0&c=Symfonium&f=json HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: <server-skipping-caddy>:4533
User-Agent: HTTPie/3.2.1

HTTP/1.1 200 OK
Accept-Ranges: bytes
Content-Length: 8415401
Content-Type: audio/mpeg
Date: Thu, 30 Mar 2023 15:45:05 GMT
Last-Modified: Thu, 23 Feb 2023 20:14:32 GMT
Permissions-Policy: autoplay=(), camera=(), microphone=(), usb=()
Referrer-Policy: same-origin
Set-Cookie: nd-player-766261626979=c371d798-7244-40c8-8aab-72fe3d088a4b; Path=/; Max-Age=31536000; HttpOnly; SameSite=Strict
Vary: Origin
X-Content-Duration: 348.37
X-Content-Type-Options: nosniff
X-Frame-Options: DENY

With Range:

http  -pHh "http://<server-skipping-caddy>:4533/rest/stream.view?id=xxx&u=vbabiy&t=xxx&s=xxx&v=1.13.0&c=Symfonium&f=json" Range:"bytes=8415401-"
GET /rest/stream.view?id=xxx&u=vbabiy&t=xxx&s=xxx&v=1.13.0&c=Symfonium&f=json HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: <server-skipping-caddy>:4533
Range: bytes=8415401-
User-Agent: HTTPie/3.2.1

HTTP/1.1 416 Requested Range Not Satisfiable
Content-Encoding: gzip
Content-Length: 57
Content-Range: bytes */8415401
Content-Type: text/plain; charset=utf-8
Date: Thu, 30 Mar 2023 15:46:25 GMT
Last-Modified: Thu, 23 Feb 2023 20:14:32 GMT
Permissions-Policy: autoplay=(), camera=(), microphone=(), usb=()
Referrer-Policy: same-origin
Set-Cookie: nd-player-766261626979=c371d798-7244-40c8-8aab-72fe3d088a4b; Path=/; Max-Age=31536000; HttpOnly; SameSite=Strict
Vary: Origin
Vary: Accept-Encoding
X-Content-Duration: 348.37
X-Content-Type-Options: nosniff
X-Frame-Options: DENY
deluan commented 1 year ago

Is this happening with just one file? AFAIK, ranges are handled correctly in Navidrome and I never saw this issue before. Maybe Caddy is messing with headers? Can you try removing Caddy from the equation?

vbabiy commented 1 year ago

@deluan the above is with the caddy removed.

deluan commented 1 year ago

Correct me if I'm wrong, but reading the headers returned by the server, I think the error 416 is pertinent: The file has 8415401 bytes and you are requesting Range: bytes=8415401-, which is out-of-range (the index for the last byte should be 8415400).

vbabiy commented 1 year ago

@deluan this is on many files.

vbabiy commented 1 year ago

@deluan yeah I think this is a bug in the Symfonium client

Tolriq commented 1 year ago

On resume Symfonium restart at the current file size. This means there was an error before leaving the file complete but with a failure. I'd need logs when this happens, so clear the queue to delete the temp files and have logs enabled before the first 416 happen.

Enable the option slower downloads to disable http/2 with caddy it's reported to fix a few issues with Navidrome so could workaround that but it would be better to find the root cause.

vbabiy commented 1 year ago

@Tolriq I cleared the download queue and then try to redownload and it worked great.

Tolriq commented 1 year ago

Yes but we can't know what happened the first time :(

vbabiy commented 1 year ago

@Tolriq I will keep debug logging on and see if it happens again.

vbabiy commented 1 year ago

I just went through and cached over 12GB with no issue.

Tolriq commented 1 year ago

Without Caddy ?

vbabiy commented 1 year ago

@Tolriq with caddy, but I just hit the bug again.

photo_2023-03-30_14-36-42 debug-20230330_143405.zip

Tolriq commented 1 year ago

Ok so 

2023-03-30 14:32:48.637 Error/DownloaderService: Error downloading
qn.f0: stream was reset: CANCEL
    at qn.y.o(Unknown Source:38)
    at nn.d.o(Unknown Source:10)
    at vn.y.o(Unknown Source:29)
    at vn.m.o(Unknown Source:2)
    at mg.a.o(Unknown Source:28)
    at vn.y.o(Unknown Source:29)
    at vn.x.j(Unknown Source:6)
    at app.symfonik.core.download.DownloaderService.e(Unknown Source:3572)
    at g4.q0.i(Unknown Source:14)
    at em.a.j(Unknown Source:5)
    at um.j0.run(Unknown Source:110)
    at kotlinx.coroutines.internal.g.run(Unknown Source:11)
    at kotlinx.coroutines.scheduling.i.run(Unknown Source:2)
    at kotlinx.coroutines.scheduling.a.run(Unknown Source:76)

The connection is reset by Caddy or Navidrome should check at that time stamp what happen on both. Looks like an HTTP2 issue where the connection is closed before Symfonium request it at the end of the file leading to the file being complete but the error coming back before making Symfonium think the file is incomplete. Then since it's complete the attempt to resume fails as it request a too large range.

I'll add a workaround on Symfonium that will clear the temporary file on error 416 to force a restart fresh. And there's the slower download option to avoid HTTP/2.

But would be nice to find out why caddy reset with Navidrome. I have plenty of users with caddy and Jellyfin and never had any report.

deluan commented 1 year ago

I personally use Caddy with Navidrome, and have being using it since I started Navidrome (3 years), without this kind of issues. So it may be something in your configuration?

vbabiy commented 1 year ago 
                    {
                            "match": [
                                {
                                    "host": [
                                        "music.vb.zone"
                                    ]
                                }
                            ],
                            "handle": [
                                {
                                    "handler": "reverse_proxy",
                                    "upstreams": [
                                        {
                                            "dial": "navidrome.vb.zone:4533"
                                        }
                                    ]
                                }
                            ]
                        },

I have a really basic config for navidrome. Let me see if I can find those errors in the log

vbabiy commented 1 year ago

Not the exact time but maybe this helps:

Mar 30 15:36:50 navidrome navidrome[298]: time="2023-03-30T15:36:50Z" level=debug msg="API: New request /rest/stream.view" client=Symfonium requestId=navidrome/OCuvAPT3s6-249691 username=vbabiy version=1.13.0
Mar 30 15:36:50 navidrome navidrome[298]: time="2023-03-30T15:36:50Z" level=info msg="Registering new player" client=Symfonium id=d1127612-9c60-4704-911d-a4ffe8478d7f requestId=navidrome/OCuvAPT3s6-249691 type=Chrome/Linux usernam>
Mar 30 15:36:50 navidrome navidrome[298]: time="2023-03-30T15:36:50Z" level=debug msg="Streaming RAW file" id=626118c27222ca6621234614720b45b5 originalBitrate=821 originalFormat=flac path="/nas/Media/Music/Library/HOYO‐MiX/Genshin>
Mar 30 15:36:50 navidrome navidrome[298]: time="2023-03-30T15:36:50Z" level=info msg="Streaming file" artist="HOYO‐MiX" bitRate=0 cached=false format=raw originalBitRate=821 originalFormat=flac requestId=navidrome/OCuvAPT3s6-24969>
Mar 30 15:36:50 navidrome navidrome[298]: time="2023-03-30T15:36:50Z" level=warning msg="Request was interrupted" endpoint=/rest/stream.view error="context canceled" requestId=navidrome/OCuvAPT3s6-249691 username=vbabiy
github-actions[bot] commented 7 months ago

This issue has been automatically marked as stale because it has not had recent activity. The resources of the Navidrome team are limited, and so we are asking for your help. If this is a bug and you can still reproduce this error on the master branch, please reply with all of the information you have about it in order to keep the issue open. If this is a feature request, and you feel that it is still relevant and valuable, please tell us why. This issue will automatically be closed in the near future if no further activity occurs. Thank you for all your contributions.

github-actions[bot] commented 2 months ago

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.