Somewhere a http 404 error causes a http 500 error when browsing the DLNA Playlist
Closed this issue · 6 comments
I'm having difficulty defining exactly what's the culprit.
I've updated Plex to version 1.21.4.4079 this week, I had some trouble importing the iTunes library and playlist but that's fixed now. Probably a bad export from the Music app? Anyway, when I browse the DLNA server I see the Playlists plugin in Plex -> Music -> Music Channels. When I click on the Playlists icon, I see a spinning wheel and the message "access denied" is thrown by the Plex DLNA server.
When I examine the Plex Media Server Log, I see the following:
Feb 27, 2021 18:20:56.722 [0x7f7300ff9700] DEBUG - Request: [127.0.0.1:44512 (Loopback)] GET /music/playlisthost (10 live) GZIP Signed-in Token (blaaat)
Feb 27, 2021 18:20:56.722 [0x7f7300ff9700] DEBUG - Plug-in com.plexapp.plugins.playlisthost has been used 10 times.
Feb 27, 2021 18:20:56.723 [0x7f7300ff9700] DEBUG - [com.plexapp.plugins.playlisthost] Sending command over HTTP (GET): /music/playlisthost
Feb 27, 2021 18:20:56.723 [0x7f7300ff9700] DEBUG - HTTP requesting GET http://127.0.0.1:42381/music/playlisthost
Feb 27, 2021 18:20:56.742 [0x7f73377fe700] DEBUG - Auth: authenticated user 1 as blaaat
Feb 27, 2021 18:20:56.743 [0x7f7301ffb700] DEBUG - Request: [127.0.0.1:44518 (Loopback)] GET /playlists (11 live) GZIP Signed-in Token (blaaat)
Feb 27, 2021 18:20:56.757 [0x7f73377fe700] DEBUG - Completed: [127.0.0.1:44518] 200 GET /playlists (11 live) GZIP 14ms 1516 bytes
Feb 27, 2021 18:20:56.826 [0x7f7301ffb700] DEBUG - Request: [127.0.0.1:44520 (Loopback)] GET /:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMzIKY29tLnBsZXhhcHAucGx1Z2lucy5wbGF5bGlzdGhvc3RzMTAKaWRlbnRpZmllcnIwCg__ (11 live) GZIP Signed-in Token (blaaat)
Feb 27, 2021 18:20:56.826 [0x7f7301ffb700] DEBUG - [com.plexapp.system] Sending command over HTTP (GET): /:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMzIKY29tLnBsZXhhcHAucGx1Z2lucy5wbGF5bGlzdGhvc3RzMTAKaWRlbnRpZmllcnIwCg__
Feb 27, 2021 18:20:56.826 [0x7f7301ffb700] DEBUG - HTTP requesting GET http://127.0.0.1:36779/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMzIKY29tLnBsZXhhcHAucGx1Z2lucy5wbGF5bGlzdGhvc3RzMTAKaWRlbnRpZmllcnIwCg__
Feb 27, 2021 18:20:56.841 [0x7f7301ffb700] DEBUG - HTTP 404 response from GET http://127.0.0.1:36779/:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMzIKY29tLnBsZXhhcHAucGx1Z2lucy5wbGF5bGlzdGhvc3RzMTAKaWRlbnRpZmllcnIwCg__
Feb 27, 2021 18:20:56.841 [0x7f7301ffb700] DEBUG - [com.plexapp.system] HTTP reply status 404, with 0 bytes of content.
Feb 27, 2021 18:20:56.842 [0x7f73377fe700] DEBUG - Completed: [127.0.0.1:44520] 404 GET /:/plugins/com.plexapp.system/messaging/function/X1N0b3JlU2VydmljZTpJc0NoYW5uZWxCcm9rZW4_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMQpzMzIKY29tLnBsZXhhcHAucGx1Z2lucy5wbGF5bGlzdGhvc3RzMTAKaWRlbnRpZmllcnIwCg__ (11 live) GZIP 15ms 261 bytes
Feb 27, 2021 18:20:56.856 [0x7f7300ff9700] DEBUG - HTTP 500 response from GET http://127.0.0.1:42381/music/playlisthost
Feb 27, 2021 18:20:56.857 [0x7f7300ff9700] DEBUG - [com.plexapp.plugins.playlisthost] HTTP reply status 500, with 2335 bytes of content.
Feb 27, 2021 18:20:56.858 [0x7f73377fe700] DEBUG - Completed: [127.0.0.1:44512] 500 GET /music/playlisthost (10 live) GZIP 136ms 1117 bytes
Here's the Plex DLNA Server.log of around that time:
Feb 27, 2021 18:20:49.670 [0x7fbf097fa700] DEBUG - Mapped object 0 to part 0 on server
Feb 27, 2021 18:20:49.670 [0x7fbf097fa700] DEBUG - OnBrowseDirectChildren returning success with 3 objects of 3 total
Feb 27, 2021 18:20:50.762 [0x7fbf097fa700] DEBUG - OnBrowseDirectChildren for 'abe6121c-1731-4683-815c-89e1dcd2bf11' with filter '*' and sort '', paged as 0 + 8
Feb 27, 2021 18:20:50.762 [0x7fbf097fa700] DEBUG - Mapped client to generic profile: Host: 192.168.1.221:32469; User-Agent: Network_Module/1.0 (WX-030) UPnP/1.0 DLNADOC/1.50; Con
tent-Type: text/xml; charset="utf-8"; Content-Length: 486; SOAPACTION: "urn:schemas-upnp-org:service:ContentDirectory:1#Browse"; Cache-Control: no-cache; Pragma: no-cache
Feb 27, 2021 18:20:50.762 [0x7fbf097fa700] DEBUG - Mapped object abe6121c-1731-4683-815c-89e1dcd2bf11 to part 0 on server
Feb 27, 2021 18:20:50.762 [0x7fbf097fa700] DEBUG - Downloading document http://127.0.0.1:32400/library/sections
Feb 27, 2021 18:20:50.763 [0x7fbf097fa700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/library/sections
Feb 27, 2021 18:20:50.770 [0x7fbf097fa700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/library/sections
Feb 27, 2021 18:20:50.771 [0x7fbf097fa700] DEBUG - Caching document http://127.0.0.1:32400/library/sections as 16cbffa1cf5325264cc2f53d1372d009739c44ce
Feb 27, 2021 18:20:50.776 [0x7fbf097fa700] DEBUG - OnBrowseDirectChildren returning success with 8 objects of 8 total
Feb 27, 2021 18:20:50.826 [0x7fbf097fa700] DEBUG - GET for http://192.168.1.221:32469/proxy/8c3261ed135033342c02/albumart.jpg
Feb 27, 2021 18:20:50.826 [0x7fbf097fa700] DEBUG - Mapped client to generic profile: Host: 192.168.1.221:32469; Accept: */*; Accept-Language: nl-nl; Connection: keep-alive; Accept-Encoding: gzip, deflate; User-Agent: MusicCast/4534(iOS)
Feb 27, 2021 18:20:50.826 [0x7fbef97fa700] DEBUG - GET for http://192.168.1.221:32469/proxy/8c3261ed135033342c02/albumart.jpg
Feb 27, 2021 18:20:50.826 [0x7fbef97fa700] DEBUG - Mapped client to generic profile: Host: 192.168.1.221:32469; Accept: */*; Accept-Language: nl-nl; Connection: keep-alive; Accept-Encoding: gzip, deflate; User-Agent: MusicCast/4534(iOS)
Feb 27, 2021 18:20:50.829 [0x7fbf097fa700] DEBUG - Proxied GET to http://127.0.0.1:32400/photo/:/transcode?format=jpg&height=512&url=http%3A%2F%2F127%2E0%2E0%2E1%3A32400%2F%3A%2Fresources%2Fartist%2Epng&width=512&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx: HTTP/1.1 200
Feb 27, 2021 18:20:50.830 [0x7fbf097fa700] DEBUG - Responding HTTP/1.1 200
Feb 27, 2021 18:20:50.829 [0x7fbef97fa700] DEBUG - Proxied GET to http://127.0.0.1:32400/photo/:/transcode?format=jpg&height=512&url=http%3A%2F%2F127%2E0%2E0%2E1%3A32400%2F%3A%2Fresources%2Fartist%2Epng&width=512&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx: HTTP/1.1 200
Feb 27, 2021 18:20:50.830 [0x7fbef97fa700] DEBUG - Responding HTTP/1.1 200
Feb 27, 2021 18:20:51.787 [0x7fbee3fff700] DEBUG - OnBrowseDirectChildren for 'aca21a34-d277-4d9d-9602-687d89765172' with filter '*' and sort '', paged as 0 + 8
Feb 27, 2021 18:20:51.787 [0x7fbee3fff700] DEBUG - Mapped client to generic profile: Host: 192.168.1.221:32469; User-Agent: Network_Module/1.0 (WX-030) UPnP/1.0 DLNADOC/1.50; Content-Type: text/xml; charset="utf-8"; Content-Length: 486; SOAPACTION: "urn:schemas-upnp-org:service:ContentDirectory:1#Browse"; Cache-Control: no-cache; Pragma: no-cache
Feb 27, 2021 18:20:51.787 [0x7fbee3fff700] DEBUG - Mapped object aca21a34-d277-4d9d-9602-687d89765172 to part 0 on server
Feb 27, 2021 18:20:51.787 [0x7fbee3fff700] DEBUG - Downloading document http://127.0.0.1:32400/channels/recentlyViewed
Feb 27, 2021 18:20:51.788 [0x7fbee3fff700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/channels/recentlyViewed
Feb 27, 2021 18:20:51.794 [0x7fbee3fff700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/channels/recentlyViewed
Feb 27, 2021 18:20:51.794 [0x7fbee3fff700] DEBUG - Caching document http://127.0.0.1:32400/channels/recentlyViewed as f326449b428ce95194fa19b5eb8a714233602f4a
Feb 27, 2021 18:20:51.795 [0x7fbee3fff700] DEBUG - [PERF] Slowest insertObjectID in 10.000000 ms.
Feb 27, 2021 18:20:51.797 [0x7fbee3fff700] DEBUG - OnBrowseDirectChildren returning success with 1 objects of 1 total
Feb 27, 2021 18:20:51.831 [0x7fbee3fff700] DEBUG - GET for http://192.168.1.221:32469/proxy/bc7dcad93e5678d9af64/albumart.jpg
Feb 27, 2021 18:20:51.831 [0x7fbee3fff700] DEBUG - Mapped client to generic profile: Host: 192.168.1.221:32469; Accept: */*; Accept-Language: nl-nl; Connection: keep-alive; Accept-Encoding: gzip, deflate; User-Agent: MusicCast/4534(iOS)
Feb 27, 2021 18:20:51.833 [0x7fbee3fff700] DEBUG - Proxied GET to http://127.0.0.1:32400/photo/:/transcode?format=jpg&height=512&url=http%3A%2F%2F127%2E0%2E0%2E1%3A32400%2F%3A%2Fplugins%2Fcom%2Eplexapp%2Eplugins%2Eplaylisthost%2Fresources%2Ficon-default%2Epng%3Ft%3D1612560853&width=512&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx: HTTP/1.1 200
Feb 27, 2021 18:20:51.834 [0x7fbee3fff700] DEBUG - Responding HTTP/1.1 200
Feb 27, 2021 18:20:56.719 [0x7fbef97fa700] DEBUG - OnBrowseDirectChildren for 'c700e44f6c2285385e4f' with filter '*' and sort '', paged as 0 + 8
Feb 27, 2021 18:20:56.719 [0x7fbef97fa700] DEBUG - Mapped client to generic profile: Host: 192.168.1.221:32469; User-Agent: Network_Module/1.0 (WX-030) UPnP/1.0 DLNADOC/1.50; Content-Type: text/xml; charset="utf-8"; Content-Length: 470; SOAPACTION: "urn:schemas-upnp-org:service:ContentDirectory:1#Browse"; Cache-Control: no-cache; Pragma: no-cache
Feb 27, 2021 18:20:56.720 [0x7fbef97fa700] DEBUG - Mapped object c700e44f6c2285385e4f to /music/playlisthost part 0 on server http://127.0.0.1:32400/
Feb 27, 2021 18:20:56.720 [0x7fbef97fa700] DEBUG - Downloading document http://127.0.0.1:32400/music/playlisthost
Feb 27, 2021 18:20:56.720 [0x7fbef97fa700] DEBUG - HTTP requesting GET http://127.0.0.1:32400/music/playlisthost
Feb 27, 2021 18:20:56.858 [0x7fbef97fa700] DEBUG - HTTP 500 response from GET http://127.0.0.1:32400/music/playlisthost
Feb 27, 2021 18:20:56.859 [0x7fbef97fa700] DEBUG - Caching document http://127.0.0.1:32400/music/playlisthost as 729dae2495f5a81dac87bd2a17f611ef4f55772b
Feb 27, 2021 18:20:56.859 [0x7fbef97fa700] ERROR - downloadContainer: expected MediaContainer element, found Response
Feb 27, 2021 18:20:56.859 [0x7fbef97fa700] ERROR - generateForPlexPath - unable to get directory /music/playlisthost
I have attached the PlaylistPlugin log from Plex:
com.plexapp.plugins.playlisthost.log
From what I can tell from the release notes, there haven't been major changes between this version of Plex and the versions from last month. These might be related:
- (Security) Mitigate against potential DDoS amplification by only responding to UDP requests from LAN
- (HTTP) The server could crash when setting up libraries during first run.
- This update contains internal changes in support of upcoming server functionality improvements. (no further comment or whatsoever, so not sure what this means?)
- (Library) Allow deletion of play history again.
I'm not a developer, so I'm kinda lost in between these log files 😇
Not sure what's going on either but this is perhaps related from the log:
2021-02-27 18:20:56,821 (7fb47cff9700) : WARNING (runtime:1065) - Generating a callback path for a function with no route: <function PlaylistMenu at 0x7fb485aced50>
Since plugins are using HTTP "routes" to receive messages, my guess is that something changed that breaks how the route was defined for PlaylistMenu. It looks like Plex sees these warnings, and then attempts to ping the "route" to see if it's valid or not, and then hits the 404. Not sure how fixable it is, or what the expected change is for plugins.
The relevant code is how PlaylistMenu is defined:
#@route(PREFIX +'/playlist')
def PlaylistMenu(title, key):
Unfortunately, with plugins deprecated, the developers of Plex aren't likely to tell us when they make relevant changes here anymore. So it may be under the heading of "internal changes to support upcoming server improvements".
I agree. I recently discovered Plex and like it a lot. It does a lot of what I like to have. Except for playlists in DLNA showing up. I'm very glad I found your plugin 😄 . It made my expectations of Plex complete, good enough for what I want to do with it. Sadly for me this all in one experience lasted about a month.
I've searched for any API documentation on Plex but it's either very old on public sites, or it's hidden behind Plex's walls. It's a company decision of deprecating plugins for some reason. That's it.
Thankfully there are more similar products. I've been eyeing on Emby for a short while. They do playlists in DLNA out of the box. But they don't import iTunes/Music library.xml to create playlists. Plex does, sort of. Still. Until they drop that.
I'm not sure what I'm going to do. I might have a look at the /playlist route in Plex, to see if that's it and what has been changed. But I might also have a go at Emby. For what it's worth, Emby (still) publishes their API documentation and is open to plugin development.
--EDIT--
FWIW: I grabbed a browser to see if Developer Tools would show me a few clues. It didn't. But to my surprise there is something clearly not right. I see quite a lot of calls being made to 127.0.0.1:
http://127.0.0.1:32400/media/providers?X-Plex-Product=Plex%20Web&X-Plex-Version=4.51.3&X-Plex-Client-Identifier=700rg3urvu595vo3cnnz0a9y&X-Plex-Platform=Chrome&X-Plex-Platform-Version=88.0&X-Plex-Sync-Version=2&X-Plex-Features=external-media%2Cindirect-media&X-Plex-Model=bundled&X-Plex-Device=OSX&X-Plex-Device-Name=Chrome&X-Plex-Device-Screen-Resolution=912x937%2C1920x1080&X-Plex-Language=en
I'm running Plex on my NAS; this calling to localhost off course doesn't lead to any result; Plex telling my browser to grab something on my laptop on port 32400? Plex is running somewhere else (NAS), not my laptop...
It might just be that somewhere down the line, something got broken, which causes your plugin to fail.
I rolled back a few versions of PMS, since I'm running docker, that's pretty easy 🤓
On Plex Server version 1.21.3.4046 your plugin works! Release 1.21.4.4054 was only made available to paying Plex Pass users and it wasn't a public release. But changes in that release are obviously also in release 1.21.4.4079.
And to get back on my "--EDIT--" on my previous post about calls being made to 127.0.0.1 while Plex is running on my NAS and not on my laptop: I'm seeing a lot of those messages also on version 1.21.3.4046. So might be not related. Might 😉 .
For now I'll keep that specific docker tag around (1.21.3.4046). If there's an updated release from Plex, I'll try that and see what happens.
Yeah, to be honest, my NAS is setup this way now:
- Run Asset UPnP for Music
- Run Plex for Movies/TV
But I have written a couple tools for producing m3u files from either iTunes or Plex to make it work with Asset UPnP. They only really work on macOS though.
An update: there have been a few new releases in Plex Media Server. I've updated my docker container to the most recent version 1.22.1.4228 and the playlist plugin is working again!
I'll close this issue as it has originated from a Plex update and has been fixed by an update by Plex.