search

MediaBrowser / Emby

Emby Server is a personal media server with apps on just about every device.
https://emby.media
GNU General Public License v2.0
4.19k stars 811 forks source link

DLNA DMR (Timeout??) more logging might help #3775

Closed neilstephens closed 1 year ago

neilstephens commented 1 year ago

Gday,

Firstly, thanks for providing a great media server. I have emby-server running on a debian file server. I usually just use my phone to stream my audio tracks using a third party media player (bubble upnp) and send it to a bluetooth speaker or DLNA reciever, and that works great.

But recently, I've been using the "Play on another device" option directly in Emby web and mobile, in an effort to save phone battery and have the ability to remote control the playback from multiple devices. This works great, apart from one very annoying blocker: After a seemingly random number of songs, the playback stops. There doesn't seem to be a pattern that I can see based on track length, format, etc. It might play anywhere from 1 to 10 songs before stopping.

Every time it happens, the logs show pretty much the same thing:

2023-04-09 17:41:37.990 Info SessionManager: Playback stopped reported by app Emby Server DLNA 4.7.11.0 playing Emotion Sickness. Stopped at 0 ms
2023-04-09 17:41:37.994 Info SessionManager: Playback start reported by app Emby Server DLNA 4.7.11.0 playing 40 Miles From the Sun. Started at 0 ms
2023-04-09 17:41:37.997 Info Server: http/1.1 Response 204 to host3. Time: 388ms. http://host2:8096/emby/Sessions/028151b251368263acd852233dd9c37a/Playing/nextTrack?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=43274c7f-ece0-41c9-b266-24b25db3f824&X-Emby-Client-Version=4.7.11.0&X-Emby-Language=en-gb
2023-04-09 17:41:39.771 Info Server: http/1.1 Response 200 to host1. Time: 1889ms. http://10.1.1.6:8096/audio/7096/stream.mp3?DeviceId=uuid:aadd4db2-9035-4c05-84f3-92b764e13fbf&MediaSourceId=0c052684a781c50859f9f3c74104d916&Static=true&PlaySessionId=93d0fbc25079499f9bebd45477738a19
2023-04-09 17:45:20.720 Info SessionManager: Playback stopped reported by app Emby Server DLNA 4.7.11.0 playing 40 Miles From the Sun. Stopped at 211000 ms
2023-04-09 17:45:20.753 Info Server: http/1.1 GET http://10.1.1.6:8096/audio/5738/stream.mp3?DeviceId=uuid:aadd4db2-9035-4c05-84f3-92b764e13fbf&MediaSourceId=4e029768d8ac332a6ba873f1875fafaf&Static=true&PlaySessionId=c05b736e8c82467da084c9de3d1d9783. UserAgent: stagefright/1.2 (Linux;Android 4.2.2)
2023-04-09 17:45:20.914 Info SessionManager: Playback start reported by app Emby Server DLNA 4.7.11.0 playing Miss You Love. Started at 0 ms
2023-04-09 17:45:22.769 Info Server: http/1.1 Response 200 to host1. Time: 2017ms. http://10.1.1.6:8096/audio/5738/stream.mp3?DeviceId=uuid:aadd4db2-9035-4c05-84f3-92b764e13fbf&MediaSourceId=4e029768d8ac332a6ba873f1875fafaf&Static=true&PlaySessionId=c05b736e8c82467da084c9de3d1d9783
2023-04-09 17:46:25.953 Debug NetworkManager: Detected local ip addresses: 10.1.1.6 ...
2023-04-09 17:50:21.906 Info SessionManager: Session 028151b251368263acd852233dd9c37a has gone idle while playing
2023-04-09 17:50:21.906 Info SessionManager: Playback stopped reported by app Emby Server DLNA 4.7.11.0 playing Miss You Love. Stopped at 240000 ms

In this case:

There's always a message from the session manager saying the session went idle. But I assume that's a knock-on effect, because that's delayed from when the music stops. That's not much to go on, even though debug logging was enabled in the DLNA plugin. So I looked at packet captures for the same time:

At this point I'm stuck because there's not quite enough to go on. Is it possible to get some more debugging messages logged? I've tried searching the code, but I can't find any timeouts apart from the session timeout, but my naive reading of the code makes me think that's set to 5 minutes, which doesn't seem to fit my observations. So I'm confused...

Any help or tips appreciated. Thanks.

FYI, the DNLA DMR receiver I'm using is called Air Receiver (android). I've tried Bubble UPnP as well, and there seems to be a similar problem, but in that case it correlates to stopping after short songs (<1min), but I haven't dug into that yet.

LukePulverenti commented 1 year ago

HI, if you're able to try the 4.8 beta server there's a chance this might be resolved there.

Essentially dlna playback is sometimes not recognizing that playback of a file has completed, and as a result, never advances to the next one. Some work was done to resolve that in the 4.8 beta channel, so you need that as well as the updated Dlna plugin. Thanks.

LukePulverenti commented 1 year ago

I would review the testing are of the community for 4.8 beta server issues before jumping up though, and make sure they won't impact you. When I have a chance I'll see if I can backport the updates to 4.7.

neilstephens commented 1 year ago

Great, thanks. I'll go ahead and grab the updates. Have you got a link to the testing results so far?

LukePulverenti commented 1 year ago

This user had a similar issue and reported success: https://emby.media/community/index.php?/topic/117657-issues-playing-to-arylic-up2stream-boards

neilstephens commented 1 year ago

Looks promising. I've got the deb downloaded already. Do I just search through the github issues here for any potential other things to watch out for, or is there a thread somewhere for the beta testing?

LukePulverenti commented 1 year ago

I would check out this section: https://emby.media/community/index.php?/forum/102-emby-server/ Thanks.

neilstephens commented 1 year ago

I tried out the beta in docker. Still looks like the same problem:

2023-04-12 04:49:46.790 Info SessionManager: Playback start reported by app Emby Server DLNA 4.8.0.29 playing Thunderclouds (Feat. Sia, Diplo & Labrinth). Started at 0 ms
2023-04-12 04:49:47.595 Info Server: http/1.1 Response 200 to host1. Time: 1122ms. GET http://10.1.1.215:8096/audio/9/stream.mp3?DeviceId=uuid:aadd4db2-9035-4c05-84f3-92b764e13fbf&MediaSourceId=b62ab6c32c2b485362cfb79fbca639e8&Static=true&PlaySessionId=ab7ff7d0953045a19e8518f793423422&api_key=x_secret2_x
2023-04-12 04:49:51.706 Info HttpClient: GET https://assets.fanart.tv/fanart/music/8d79b49a-143c-4807-bd44-6c985a4655bf/hdmusiclogo/lsd-5d072161e2a56.png
2023-04-12 04:49:51.792 Info HttpClient: GET https://assets.fanart.tv/fanart/music/172e1f1a-504d-4488-b053-6344ba63e6d0/artistbackground/cave-nick--bad-seeds-the-4f8487b17c8c9.jpg
2023-04-12 04:50:33.907 Info Server: http/1.1 POST http://localhost:8096/emby/Sessions/028151b251368263acd852233dd9c37a/Command?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=5de581eb-3251-4dfb-8b06-761e58940c51&X-Emby-Client-Version=4.8.0.29&X-Emby-Token=x_secret1_x&X-Emby-Language=en-us&reqformat=json. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/111.0
2023-04-12 04:50:33.912 Info Server: http/1.1 Response 204 to 127.0.0.1. Time: 5ms. POST http://localhost:8096/emby/Sessions/028151b251368263acd852233dd9c37a/Command?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=5de581eb-3251-4dfb-8b06-761e58940c51&X-Emby-Client-Version=4.8.0.29&X-Emby-Token=x_secret1_x&X-Emby-Language=en-us&reqformat=json
2023-04-12 04:50:43.873 Info Server: http/1.1 POST http://localhost:8096/emby/Sessions/028151b251368263acd852233dd9c37a/Command?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=5de581eb-3251-4dfb-8b06-761e58940c51&X-Emby-Client-Version=4.8.0.29&X-Emby-Token=x_secret1_x&X-Emby-Language=en-us&reqformat=json. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/111.0
2023-04-12 04:50:43.875 Info Server: http/1.1 Response 204 to 127.0.0.1. Time: 2ms. POST http://localhost:8096/emby/Sessions/028151b251368263acd852233dd9c37a/Command?X-Emby-Client=Emby Web&X-Emby-Device-Name=Firefox&X-Emby-Device-Id=5de581eb-3251-4dfb-8b06-761e58940c51&X-Emby-Client-Version=4.8.0.29&X-Emby-Token=x_secret1_x&X-Emby-Language=en-us&reqformat=json
2023-04-12 04:52:58.233 Info SessionManager: Playback stopped reported by app Emby Server DLNA 4.8.0.29 playing Thunderclouds (Feat. Sia, Diplo & Labrinth). Stopped at 181000 ms
2023-04-12 04:52:58.287 Info Server: http/1.1 GET http://10.1.1.215:8096/audio/29/stream.mp3?DeviceId=uuid:aadd4db2-9035-4c05-84f3-92b764e13fbf&MediaSourceId=d65550b379644691ffce24f2f20aa630&Static=true&PlaySessionId=b7985112bf5d4ffd816a643199b713b5&api_key=x_secret2_x. UserAgent: stagefright/1.2 (Linux;Android 4.2.2)
2023-04-12 04:52:58.528 Info SessionManager: Playback start reported by app Emby Server DLNA 4.8.0.29 playing Missing Me. Started at 0 ms
2023-04-12 04:52:59.718 Info Server: http/1.1 Response 200 to host1. Time: 1431ms. GET http://10.1.1.215:8096/audio/29/stream.mp3?DeviceId=uuid:aadd4db2-9035-4c05-84f3-92b764e13fbf&MediaSourceId=d65550b379644691ffce24f2f20aa630&Static=true&PlaySessionId=b7985112bf5d4ffd816a643199b713b5&api_key=x_secret2_x
2023-04-12 04:57:40.609 Info SessionManager: Session 028151b251368263acd852233dd9c37a has gone idle while playing
2023-04-12 04:57:40.609 Info SessionManager: Playback stopped reported by app Emby Server DLNA 4.8.0.29 playing Missing Me. Stopped at 222000 ms
LukePulverenti commented 1 year ago

Can you please attach the complete log file? Thanks.

neilstephens commented 1 year ago

embyserver.txt

LukePulverenti commented 1 year ago

Can you start up all of your dlna software, and then put this url in a browser and attach the response: http://10.1.1.234:1330/ConnectionManager/aadd4db2-9035-4c05-84f3-92b764e13fbf/scpd.xml Please note, depending on the way your software works, that url might not be valid anymore, which means you'll need to try this all again and then obtain the url from your server log.

And please do the same for this url: http://10.1.1.234:1330/

Thanks.

LukePulverenti commented 1 year ago

Nevermind, I can reproduce with Air Receiver Lite.

neilstephens commented 1 year ago

Hey, that's great news if you managed to reproduce the issue. Or did you just mean you were going to try? Those URLs didn't work (probably since I restarted Air Receiver in the meantime). I'll see if I can figure out the new GUID from today's log. But doesn't seem like it's listening on 1330 at all...?

182 2023-04-13 10:06:37.839607793   10.1.1.215  10.1.1.234  49528   1330    74  49528 → 1330 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=1785399657 TSecr=0 WS=1024
184 2023-04-13 10:06:37.868719049   10.1.1.234  10.1.1.215  1330    49528   60  1330 → 49528 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0
LukePulverenti commented 1 year ago

Please try the 1.1 update to the dlna plugin and let me know how that compares. Thanks.

neilstephens commented 1 year ago

Gday, unfortunately I can't figure out where to download the 1.1 dlna plugin. I've tried searching the github repos, going to the emby website etc. The catalog in Emby itself only lists up to 1.0.95. Can you point me in the right direction? Thanks.

LukePulverenti commented 1 year ago

Your server should auto-update to it, but it requires the beta server.

neilstephens commented 1 year ago

ah OK thanks, I'll fire up a docker container with the beta again. Thanks

neilstephens commented 1 year ago

Looking great so far! I've played half-a-dozen short tracks in a row, throwing some longer tracks into the playlist now. But I reckon you've nailed it. The tracks transitions are instant now. It always took a few seconds to change tracks previously. Did you fix something fundamental?

So is the 1.1 plugin an ABI break, or could I theoretically copy it to my 4.7.11 server installation in the meantime to the 4.8 release?

Thanks so much for the awesome support! suffice to say, I'll be putting in a requisition request for a premiere subscription to the household boss ;-)

LukePulverenti commented 1 year ago

Thanks for testing! You can't use it with 4.7 but I'm hoping to publish a 4.7 compatible version the catalog soon.

neilstephens commented 1 year ago

Cool, no worries. Confirming it hasn't skipped a beat in 22 tracks! I'll close this issue and wait with baited breath for the update on the stable branch. Thanks!

LukePulverenti commented 1 year ago

Can you try this version on your 4.7 install? Emby.Dlna.zip

Unzip that under /var/lib/emby/plugins

Thanks.

neilstephens commented 1 year ago

Testing now. All good so far. I'll post back when a few tracks have played through. Cheers

neilstephens commented 1 year ago

Working great (20+ tracks played). Well done, and thanks again for the great support!

LukePulverenti commented 1 year ago

Great, thanks ! You'll see a 1.1.1 update in the catalog which will just be the same thing with a version bump.