Broken DLNA service since 1.1.4 - when will it be fixed? tons of people have problems.

Plex Media Server Desktops & Laptops
1

Since the other threads don’t seem to get much attention, I’m reiterating the problem: any PMS release after 1.1.4 doesn’t have a working DLNA service for Sony systems. It also seems to affect LG systems.

Threads:

I’m betting there are more, this is just going back through few pages. All of those reported issues affect releases after 1.1.4.

2

Lots of forum topics and posts - can’t see any post with full set of log files including the Plex Media Server.log and Plex DLNA Server.log. Closest provided is just the DLNA Server log or extracts of few lines from log

Could we please get a full set of logs can be provided with Debug Logging enabled
See
https://support.plex.tv/hc/en-us/articles/201643703-Reporting-issues-with-Plex-Media-Server
https://support.plex.tv/hc/en-us/articles/200250417-Plex-Media-Server-Log-Files
and the scope of the issue - what works and what does not

3

Logs will follow with details. However, I believe the scope has been already identified multiple times by other folks already: virtually all media that worked before no longer shows up as available for playback.

Entire DLNA directory structure works, less than 1% of my current media shows up.

4

Attaching logs of a freshly upgraded 1.1.4->1.3.0. Before the upgrade, all media plays.

Logs show starting PMS 1.3.0 and navigating via DLNA on the Bravia TV through the advertised Plex menu -> video -> movies -> All Movies. This should yield over a 1000 entries, instead it just shows one.

5

@ananke said:
Attaching logs of a freshly upgraded 1.1.4->1.3.0. Before the upgrade, all media plays.

Logs show starting PMS 1.3.0 and navigating via DLNA on the Bravia TV through the advertised Plex menu → video → movies → All Movies. This should yield over a 1000 entries, instead it just shows one.

I can see an exception

Dec 04, 2016 21:53:07.937 [0x7ff7ae3fe700] ERROR - Error response for update: 5 (Unhandled exception).

Need to see all the log files including the agents and also if any crash uploader logs

So please restart the server and repeat the test and then use the web interface to zip whole set of logs

And can you see if any crash files get written to the Crash Reports subdirectories?
Normally they get purged - but please check

https://support.plex.tv/hc/en-us/articles/200250417-Plex-Media-Server-Log-Files

Thanks

6

Thank you for your assistance. Unfortunately, there are no crash reports, however, additional logs do seem to contain information about a crashing agent.

Attached is a tarball of the entire Logs directory, which was cleaned up right before starting server. So the sequence of events is:

  • stop PMS 1.1.4
    – upgrade to 1.3.0
    – remove all logs
  • start PMS 1.3.0
    – navigate via DLNA to PMS->video->movies->all movies
    – wait ~10 seconds until only one item is presented (during which time the exception error shows up)
  • stop PMS, collect logs

I’m guessing these log lines are most relevant:

com.plexapp.system.log

2016-12-05 07:05:06,117 (7f5c317fa700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=1&force=1&guid=tt0014429&id=355969&agent=com.plexapp.agents.localmedia&async=0                                                                                                                                                                 2016-12-05 07:05:06,119 (7f5c317fa700) :  DEBUG (runtime:814) - Found route matching /system/agents/update                                                                        2016-12-05 07:05:06,120 (7f5c317fa700) :  CRITICAL (agentservice:364) - Exception in update request handler (most recent call last):                                                File "/usr/lib/plexmediaserver/Resources/Plug-ins-6277334/System.bundle/Contents/Code/agentservice.py", line 291, in update                                                         (root_type, identifier, id, lang, base_guid) = self.parse_guid(int(mediaType), guid)                                                                                            File "/usr/lib/plexmediaserver/Resources/Plug-ins-6277334/System.bundle/Contents/Code/agentservice.py", line 1073, in parse_guid                                                    (identifier, parts) = guid.split('://')                                                                                                                                       ValueError: need more than 1 value to unpack

com.plexapp.agents.localmedia.log

2016-12-05 07:04:10,881 (7fbc99e51700) :  CRITICAL (sandbox:298) - Function named 'Start' couldn't be found in the current environment

Cheers!

7

Thank you.

I have raised this now with the development team

8

Thanks! Please let us know if there’s any progress, or a bug number assigned.

Cheers!

9

@ananke said:
Thanks! Please let us know if there’s any progress, or a bug number assigned.

Cheers!

Do you know if it is always getting the exception on the same item?

http://127.0.0.1:32400/system/agents/update?mediaType=1&force=1&guid=tt0014429&id=355969&agent=com.plexapp.agents.localmedia&async=0
Dec 05, 2016 07:05:06.123 [0x7f612cff8700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/system/agents/update?mediaType=1&force=1&guid=tt0014429&id=355969&agent=com.plexapp.agents.localmedia&async=0
Dec 05, 2016 07:05:06.123 [0x7f612cff8700] ERROR - Error response for update: 5 (Unhandled exception).

The metadata item id is I believe 355969
I tried DLNA on a Samsung TV with home videos which would be using local media agent and I could not get it to give an error. I am just wondering if there is one bad media file that is stopping the processing - or is this a general problem ?

Could you get me the xml you get back from this request when put in a browser on the server
http://localhost:32400/library/metadata/355969?X-Plex-Token=xxxxxxxxxxxxxx
See this support page for how to find your token string
https://support.plex.tv/hc/en-us/articles/204059436-Finding-your-account-token-X-Plex-Token
It is also in Preferences.xml

10

I’ll get the logs shortly; however, it’s worth noting that DLNA is broken for all of the libraries, and their respective sections. This would imply a larger general issue.

11

XML data for item in question

<MediaContainer size="1" allowSync="1" identifier="com.plexapp.plugins.library" librarySectionID="1" librarySectionTitle="Movies" librarySectionUUID="b046f867577c25e8e4242de832563bdfd7f8996d" mediaTagPrefix="/system/bundle/media/flags/" mediaTagVersion="1473718680">
<Video ratingKey="355969" key="/library/metadata/355969" guid="tt0014429" librarySectionID="1" type="movie" title="Safety Last!" summary="" year="2013" thumb="/library/metadata/355969/thumb/1448289709" art="/library/metadata/355969/art/1448289709" duration="4432695" addedAt="1448289484" updatedAt="1448289709" chapterSource="">
<Media videoResolution="720" id="419399" duration="4432695" bitrate="8472" width="992" height="720" aspectRatio="1.33" audioChannels="2" audioCodec="flac" videoCodec="h264" container="mkv" videoFrameRate="24p" videoProfile="high">
<Part id="431468" key="/library/parts/431468/1378352797/file.mkv" duration="4432695" file="/storage/archive/movies/Safety Last! (1923).mkv" size="4694440535" container="mkv" deepAnalysisVersion="1" indexes="sd" requiredBandwidths="13484,11208,10121,9583,9355,9199,8531,8531" videoProfile="high">
<Stream id="587835" streamType="1" default="1" codec="h264" index="0" bitrate="8472" language="English" languageCode="eng" bitDepth="8" cabac="1" chromaSubsampling="4:2:0" codecID="V_MPEG4/ISO/AVC" duration="4432683" frameRate="23.976" frameRateMode="cfr" hasScalingMatrix="0" height="720" level="41" pixelFormat="yuv420p" profile="high" refFrames="5" requiredBandwidths="11575,9299,8137,7599,7335,7171,6531,6531" scanType="progressive" width="992"/>
<Stream id="587836" streamType="2" selected="1" default="1" codec="flac" index="1" channels="2" language="Not Applicable" languageCode="zxx" audioChannelLayout="stereo" bitDepth="24" bitrateMode="vbr" codecID="A_FLAC" duration="4432695" requiredBandwidths="1357,1350,1350,1350,1350,1350,1350,1350" samplingRate="48000"/>
<Stream id="587837" streamType="2" codec="flac" index="2" channels="1" language="Not Applicable" languageCode="zxx" audioChannelLayout="mono" bitDepth="24" bitrateMode="vbr" codecID="A_FLAC" duration="4432695" requiredBandwidths="663,653,653,653,653,653,653,653" samplingRate="48000"/>
</Part>
</Media>
</Video>
</MediaContainer>
12

Additional data: the item in question, 355969, plays just fine via DLNA on that device under 1.1.4. Similar errors show up:

2016-12-06 07:14:01,846 (7f6eaa7fc700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=1&force=1&guid=tt0014429&id=355969&agent=com.plexapp.agents.localmedia&async=0
2016-12-06 07:14:01,847 (7f6eaa7fc700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2016-12-06 07:14:01,848 (7f6eaa7fc700) :  CRITICAL (agentservice:364) - Exception in update request handler (most recent call last):
  File "/usr/lib/plexmediaserver/Resources/Plug-ins-24ffd60/System.bundle/Contents/Code/agentservice.py", line 291, in update
    (root_type, identifier, id, lang, base_guid) = self.parse_guid(int(mediaType), guid)
  File "/usr/lib/plexmediaserver/Resources/Plug-ins-24ffd60/System.bundle/Contents/Code/agentservice.py", line 1073, in parse_guid
    (identifier, parts) = guid.split('://')
ValueError: need more than 1 value to unpack

2016-12-06 07:14:01,849 (7f6eaa7fc700) :  DEBUG (runtime:924) - Response: [200] InitiateUpdateResponse, 628 bytes
13

Thank you @ananke - so do we also get the unhandled exception in the Plex Media Server.log on 1.1.4 to correspond with the localmedia agent error?

http://127.0.0.1:32400/system/agents/update?mediaType=1&force=1&guid=tt0014429&id=355969&agent=com.plexapp.agents.localmedia&async=0
Dec 05, 2016 07:05:06.123 [0x7f612cff8700] DEBUG - HTTP 200 response from GET http://127.0.0.1:32400/system/agents/update?mediaType=1&force=1&guid=tt0014429&id=355969&agent=com.plexapp.agents.localmedia&async=0
Dec 05, 2016 07:05:06.123 [0x7f612cff8700] ERROR - Error response for update: 5 (Unhandled exception
14

Indeed, same unhandled exception takes place:

With 1.3.0 yesterday:

Plex Media Server.2.log:Dec 05, 2016 07:05:06.123 [0x7f612cff8700] ERROR - Error response for update: 5 (Unhandled exception).

This morning with 1.1.4:

Plex Media Server.log:Dec 06, 2016 06:39:53.274 [0x7f9ba7fff700] ERROR - Error response for update: 5 (Unhandled exception).
Plex Media Server.log:Dec 06, 2016 06:40:23.219 [0x7f9ba8fff700] ERROR - Error response for update: 5 (Unhandled exception).
Plex Media Server.log:Dec 06, 2016 07:11:58.564 [0x7f9bafbf8700] ERROR - Error response for update: 5 (Unhandled exception).
Plex Media Server.log:Dec 06, 2016 07:14:01.851 [0x7f9b96bf7700] ERROR - Error response for update: 5 (Unhandled exception).
Plex Media Server.log:Dec 06, 2016 07:15:24.358 [0x7f9bafbf8700] ERROR - Error response for update: 5 (Unhandled exception).

Looks like that exception error may be a wild goose chase. It’s as if Plex simply did not see any media that matches what’s accepted by the profile of the DLNA client. Or more precisely: anything that would be a candidate for transcoding, suddenly is not offered to the clients.

Considering that most of the people having this issue are experiencing it on older Sony/LG systems, which did not have native support for MKV/AVI/etc, vast majority of the media would be transcoded. This subsystem has worked flawlessly for years now, so it is very much a regression bug introduced past 1.1.4.

Not sure if that would help narrow down the culprit.

15

@ananke said:
Indeed, same unhandled exception takes place:

With 1.3.0 yesterday:

Plex Media Server.2.log:Dec 05, 2016 07:05:06.123 [0x7f612cff8700] ERROR - Error response for update: 5 (Unhandled exception).

This morning with 1.1.4:

Dec 06, 2016 06:39:53.274 [0x7f9ba7fff700] ERROR - Error response for update: 5 (Unhandled exception).
Dec 06, 2016 06:40:23.219 [0x7f9ba8fff700] ERROR - Error response for update: 5 (Unhandled exception).
Dec 06, 2016 07:11:58.564 [0x7f9bafbf8700] ERROR - Error response for update: 5 (Unhandled exception).
Dec 06, 2016 07:14:01.851 [0x7f9b96bf7700] ERROR - Error response for update: 5 (Unhandled exception).
Dec 06, 2016 07:15:24.358 [0x7f9bafbf8700] ERROR - Error response for update: 5 (Unhandled exception).

Looks like that exception error may be a wild goose chase.

So it is.

@ananke said:
It’s as if Plex simply did not see any media that matches what’s accepted by the profile of the DLNA client. Or more precisely: anything that would be a candidate for transcoding, suddenly is not offered to the clients.

Considering that most of the people having this issue are experiencing it on older Sony/LG systems, which did not have native support for MKV/AVI/etc, vast majority of the media would be transcoded. This subsystem has worked flawlessly for years now, so it is very much a regression bug introduced past 1.1.4.

Thank you for all the information. Would like now to compare the two sets of logs from 1.1.4 and 1.3.0. Any chance of the logs from 1.1.4 including the Plex DLNA Server log and corresponding Plex Media Server logs. Best to do t he same as before - but on 1.1.4

So of these videos

Dec 05, 2016 07:05:08.530 [0x7f33273ff700] DEBUG - MDE: received PLEX_PROTOCOL_ANY from client, selected protocol http
Dec 05, 2016 07:05:08.530 [0x7f33273ff700] DEBUG - MDE: analyzing media item 179196
Dec 05, 2016 07:05:08.530 [0x7f33273ff700] DEBUG - MDE: Franklin and the Green Knight (2000): DirectPlay
Dec 05, 2016 07:05:08.530 [0x7f33273ff700] DEBUG - MDE: Franklin and the Green Knight (2000): selected media 0 / 179196

Dec 05, 2016 07:05:08.533 [0x7f33273ff700] DEBUG - MDE: received PLEX_PROTOCOL_ANY from client, selected protocol http
Dec 05, 2016 07:05:08.533 [0x7f33273ff700] DEBUG - MDE: analyzing media item 111473
Dec 05, 2016 07:05:08.533 [0x7f33273ff700] DEBUG - MDE: 101 Dalmatians (1961): no direct play video profile exists for http/mkv/h264
Dec 05, 2016 07:05:08.533 [0x7f33273ff700] DEBUG - MDE: 101 Dalmatians (1961): no direct play video profile exists for http/mkv/h264/dca
Dec 05, 2016 07:05:08.533 [0x7f33273ff700] DEBUG - MDE: 101 Dalmatians (1961): selected media 0 / 111473

Dec 05, 2016 07:05:08.535 [0x7f33273ff700] DEBUG - MDE: received PLEX_PROTOCOL_ANY from client, selected protocol http
Dec 05, 2016 07:05:08.535 [0x7f33273ff700] DEBUG - MDE: analyzing media item 418978
Dec 05, 2016 07:05:08.535 [0x7f33273ff700] DEBUG - MDE: 12 O’Clock Boys (2014): no direct play video profile exists for http/mkv/h264
Dec 05, 2016 07:05:08.535 [0x7f33273ff700] DEBUG - MDE: 12 O’Clock Boys (2014): no direct play video profile exists for http/mkv/h264/ac3
Dec 05, 2016 07:05:08.535 [0x7f33273ff700] DEBUG - MDE: 12 O’Clock Boys (2014): selected media 0 / 418978
etc

which showed up and played ok and which did not?

The profile it is was using on 1.3.0.3095 is showing in the Plex DLNA Server log

Dec 05, 2016 07:05:00.741 [0x7f33273ff700] DEBUG - Mapped client to profile Sony Bravia 2012 using device description of type 'urn:schemas-upnp-org:device:MediaRenderer:1'
Dec 05, 2016 07:05:00.742 [0x7f33273ff700] DEBUG - Mapped object e89a1f1f9abcf472924a to /library/sections/1/all part 0 on server http://127.0.0.1:32400/
16

All of them show up and play on 1.1.4. Attached are logs of PMS starting up, navigating through DLNA and viewing few seconds of each of those media items.

Please let me if any other data could be of use. On the surface it appears that PMS simply doesn’t consider media to be suitable for playback. Considering there have been no changes in DLNA profiles between the versions, this has to be internal to PMS.

17

Oops, I don’t think previous comment contained the logs. Here they are.

18

@ananke thanks for taking one for the team and going through all of this. Looking forward to the resolution.

19

Thanks @ananke -

20

Thanks a lot @ananke !
Let’s hope there’s a fix soon.