Metadata no longer being applied to Movies (confirmed as ipv6 timeout delays)

server-windows

#1

Kind of been stumped with this lately, new movies are not having metadata attached/updated, but my TV show library does.
If anyone more knowledgeable about where to look in the logs would take a look, I would appreciate it.
Things I have tried:
1. Unmatch/Rematch both using auto and manual.
2. Disable ipv6
3. Add new directory
4. Moved local media assets to the bottom of all agents
5. Updated to current 1.9.7.4460 version

Any input would be greatly appreciated.


#2

Your logs are in ‘Verbose’ mode. They are almost unusable because of this.
See the notice to the right -->

  1. activate debug logging (disable ‘verbose’ mode!)
  2. quit Plex Server
  3. wait 1 minute
  4. start Plex Server
  5. wait 2 minutes
  6. either refresh one movie or add one movie into your library
  7. wait 3 minutes
  8. fetch log files and attach them here

#3

Have you ever started Plex Server ‘As Administrator’ ? (you should never)

Did you install a new anti virus/personal firewall/privacy guard etc pp?

Which anti virus is in use?


#4

Thank you for the reply!
No new AV/Firewall has been installed.
I only run Windows Defender on this machine since day one.
I do not run as admin.
I have attached the non-verbose logs.


#5

After disabling IPv6 support within Plex , did you restart the Plex server?
Is this a Windows Server edition?
Are Windows updates activated?

I don’t see any attempts to match a movie in your logs within the last 2 days.
Please go to the video that doesn’t get any metadata and copy its Plex XML info and paste it into here (please enclose the XML with triple backticks ` above and below it).

Then perform the Plex Dance with the movie, wait 3 minutes, then grab fresh logs and post them again please.


#6

I have restarted the machine several times since disabling IPv6 within Plex.
Windows 10 Pro 64 Bit.
Windows Updates are activated.

XML info for one of the files that will not update metadata:

<MediaContainer size="1" allowSync="1" identifier="com.plexapp.plugins.library" librarySectionID="1" librarySectionTitle="Movies" librarySectionUUID="cc3d7986-1311-4bf7-b97e-2e0348a92d70" mediaTagPrefix="/system/bundle/media/flags/" mediaTagVersion="1510645826">

<Video ratingKey="82573" key="/library/metadata/82573" guid="com.plexapp.agents.imdb://tt0338348?lang=en" librarySectionID="1" librarySectionKey="/library/sections/1" type="movie" title="The Polar Express" titleSort="Polar Express" summary="" thumb="/library/metadata/82573/thumb/1512106474" art="/library/metadata/82573/art/1512106474" duration="5996693" addedAt="1512106466" updatedAt="1512106474">

<Media videoResolution="720" id="389865" duration="5996693" bitrate="968" width="1280" height="528" aspectRatio="2.35" audioChannels="2" audioCodec="aac" videoCodec="h264" container="mp4" videoFrameRate="24p" optimizedForStreaming="0" audioProfile="lc" has64bitOffsets="0" videoProfile="main">

<Part accessible="1" exists="1" id="391732" key="/library/parts/391732/1512106270/file.mp4" duration="5996693" file="D:\Movies\The Polar Express (2004).mp4" size="725691631" audioProfile="lc" container="mp4" has64bitOffsets="0" optimizedForStreaming="0" videoProfile="main">

<Stream id="764359" streamType="1" default="1" codec="h264" index="0" bitrate="803" bitDepth="8" chromaSubsampling="4:2:0" colorRange="tv" colorSpace="bt709" frameRate="23.975" hasScalingMatrix="0" height="528" level="31" profile="main" refFrames="4" streamIdentifier="1" width="1280" />

<Stream id="764360" streamType="2" selected="1" default="1" codec="aac" index="1" channels="2" bitrate="165" audioChannelLayout="stereo" profile="lc" samplingRate="48000" streamIdentifier="2" />

</Part>

</Media>

<Extras size="0">

</Extras>

</Video>

</MediaContainer>

The thumbnail preview for the movie just sits with the animated spinning tag icon on it in perpetuity. Waited 10 minutes before downloading new logs.


#7

I have the same problem new movie don’t get new data


#8

same problem here with windows 10 Pro 64 Bit and 1.10.0.4523


#9

The update request in your server produces an error or times out.

2017-12-02 08:59:22,404 (2158) :  ERROR (networking:219) - Error opening URL 'http://127.0.0.1:32400/:/plugins/com.plexapp.agents.imdb/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZW5zNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzNQo4MjU3NHM0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczUKTW92aWVzMTAKbWVkaWFfdHlwZXM0Mwpjb20ucGxleGFwcC5hZ2VudHMuaW1kYjovL3R0MDMzODM0OD9sYW5nPWVuczQKZ3VpZHM5CnR0MDMzODM0OHMyCmlkcjAK'
2017-12-02 08:59:22,405 (2158) :  CRITICAL (core:579) - Exception in update for com.plexapp.agents.imdb://tt0338348?lang=en (most recent call last):
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-a39b25852\System.bundle\Contents\Code\agentservice.py", line 407, in update_task
    self.agent_update_metadata(identifier, media_type, guid, id, lang, dbid, parentGUID, force, version, parentID, periodic)
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-a39b25852\System.bundle\Contents\Code\agentservice.py", line 1236, in agent_update_metadata
    kwargs=kwargs
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-a39b25852\Framework.bundle\Contents\Resources\Versions\2\Python\Framework\components\messaging.py", line 86, in call_external_function
    packed_result = self._core.networking.http_request(url, cacheTime=0, timeout=None, immediate=True).content
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-a39b25852\Framework.bundle\Contents\Resources\Versions\2\Python\Framework\components
etworking.py", line 370, in http_request
    return HTTPRequest(self._core, url, data, h, url_cache, encoding, errors, timeout, immediate, sleep, opener, follow_redirects, method)
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-a39b25852\Framework.bundle\Contents\Resources\Versions\2\Python\Framework\components
etworking.py", line 141, in __init__
    self.load()
  File "C:\Program Files (x86)\Plex\Plex Media Server\Resources\Plug-ins-a39b25852\Framework.bundle\Contents\Resources\Versions\2\Python\Framework\components
etworking.py", line 181, in load
    f = self._opener.open(req, timeout=self._timeout)
  File "C:\Program Files (x86)\Plex\Plex Media Server\python27.zip\urllib2.py", line 435, in open
    response = meth(req, response)
  File "C:\Program Files (x86)\Plex\Plex Media Server\python27.zip\urllib2.py", line 548, in http_response
    'http', request, response, code, msg, hdrs)
  File "C:\Program Files (x86)\Plex\Plex Media Server\python27.zip\urllib2.py", line 473, in error
    return self._call_chain(*args)
  File "C:\Program Files (x86)\Plex\Plex Media Server\python27.zip\urllib2.py", line 407, in _call_chain
    result = func(*args)
  File "C:\Program Files (x86)\Plex\Plex Media Server\python27.zip\urllib2.py", line 556, in http_error_default
    raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
HTTPError: HTTP Error 500: Internal Server Error

I think I need help with this one.
@sa2000 could you take a look?


#10

Same Probleme
Win 10 family
plex server 1.10.0.4523


#11

@OttoKerner said:
I think I need help with this one.
@sa2000 could you take a look?

There seem to be slow processing of requests to fetch images -

2017-12-02 08:49:22,703 (1938) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/mXPoxiRny3VPH0iXJWXlyTq1mjo.jpg'
2017-12-02 08:51:02,921 (1938) :  DEBUG (networking:198) - Not caching 'http://image.tmdb.org/t/p/w300/mXPoxiRny3VPH0iXJWXlyTq1mjo.jpg' (content type 'image/jpeg' not cacheable in Agent plug-ins)

2017-12-02 08:51:03,003 (1938) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/v7aFwIIgUk5I38IhygcOYYhJbO6.jpg'
2017-12-02 08:52:43,168 (1938) :  DEBUG (networking:198) - Not caching 'http://image.tmdb.org/t/p/w300/v7aFwIIgUk5I38IhygcOYYhJbO6.jpg' (content type 'image/jpeg' not cacheable in Agent plug-ins)

2017-12-02 08:52:43,226 (1938) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/hGHCwdqgvJiOa8Np5tmp9Bb4WN6.jpg'
2017-12-02 08:54:24,855 (1938) :  DEBUG (networking:198) - Not caching 'http://image.tmdb.org/t/p/w300/hGHCwdqgvJiOa8Np5tmp9Bb4WN6.jpg' (content type 'image/jpeg' not cacheable in Agent plug-ins)

2017-12-02 08:54:24,901 (1938) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/gd2LTTrtkWOA3SYk6UPKZsr7uAr.jpg'
2017-12-02 08:56:05,661 (1938) :  DEBUG (networking:198) - Not caching 'http://image.tmdb.org/t/p/w300/gd2LTTrtkWOA3SYk6UPKZsr7uAr.jpg' (content type 'image/jpeg' not cacheable in Agent plug-ins)

2017-12-02 08:56:05,716 (1938) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/AcXCaPRB037DZoZZ2cJzRSxrNBP.jpg'
2017-12-02 08:57:45,993 (1938) :  DEBUG (networking:198) - Not caching 'http://image.tmdb.org/t/p/w300/AcXCaPRB037DZoZZ2cJzRSxrNBP.jpg' (content type 'image/jpeg' not cacheable in Agent plug-ins)

2017-12-02 08:57:46,058 (1938) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/3AuJ43BY8pCQHKTTGE9lWmRbEjU.jpg'
2017-12-02 09:00:15,351 (1938) :  DEBUG (networking:198) - Not caching 'http://image.tmdb.org/t/p/w300/3AuJ43BY8pCQHKTTGE9lWmRbEjU.jpg' (content type 'image/jpeg' not cacheable in Agent plug-ins)

Each request seems to take 100 seconds to complete. Either something is slowing the responses or we are missing notifications

It is all http and https so can capture with wireshark easily and compare times to logs

Suggest first is to try these url’s in browser on the server and see if the images come back immediately

If they do, then need to look into using wireshark and then comparing times of when the requests go out and images come back from image.tmdb.org with what gets logged in the com.plexapp.agents.imdb.log file


#12

Those image links load instantly using Chrome on the machine running the Plex server.


#13

Began capturing packets with Wireshark right before adding Dunkirk to Movies folder. Got two 200 codes for jpegs received right away, and continued to let it run until Plex notified me it was done processing Dunkirk 9 minutes later. No metadata was added to the entry in Plex. I hope some of the attached files might help.
Exported captured frames as XML, and an HTTP export.


#14

Bump if anyone else would mind taking a look.


#15

Sorry - will have a look at your captured info later today


#16

The wireshark captures do not give me absolute date/time to allow me to match to log entries in the plex logs

Do you still have the actual wireshark pcap file?

I need to know what times these were

<packet>
<section>21201</section>
<section>186.661994</section>
<section>10.0.1.37</section>
<section>104.16.57.155</section>
<section>HTTP</section>
<section>307</section>
<section>GET /t/p/w300/4yjJNAgXBmzxpS6sogj4ftwd270.jpg HTTP/1.1 </section>
</packet>

<packet>
<section>21227</section>
<section>186.726171</section>
<section>104.16.57.155</section>
<section>10.0.1.37</section>
<section>HTTP</section>
<section>462</section>
<section>HTTP/1.1 200 OK  (JPEG JFIF image)</section>
</packet>

I noticed this error - I am not sure if it is relevant

    mkdir(name, mode)
WindowsError: [Error 5] Access is denied: u'\\\\?\\C:\\Users\\Sean\\AppData\\Local\\Plex Media Server\\Metadata\\Movies\\8\\bbccbee97bfbad9a9fbb9deb3d49cc19ffb7e03.bundle\\Contents\\com.plexapp.agents.imdb\\art'

It is creating a directory and failing

The path was C:\Users\Sean\AppData\Local\Plex Media Server\Metadata\Movies\8\bbccbee97bfbad9a9fbb9deb3d49cc19ffb7e03.bundle\Contents\com.plexapp.agents.imdb\art

can you check permissions for the user account Plex Media Server runs in. Also disk space
Anything special about the filesystem ? Is it NTFS ?
Any symbolic links used?


#17

I’m also having the same issue. Seems that recently, my agent setting were automatically changed.
Movies is set to Personal Media. However, I am unable to change the setting. There is no save button and it just reverts when I leave settings. All new movies are unable to get metadata.


#18

Thanks again for taking a look.

  • A single user account on the system, with administrator privileges.
  • Normal NTFS formatting for the C:\ drive, with ~170GB of free space available on the SSD.
  • D:\ drive is a parity Windows Storage Spaces disk, with four 3TB WD Reds.
  • No symbolic links used beyond what Windows may use in Storage Spaces virtual disk.

I no longer have the pcap for the original Wireshark capture, so I will complete another one.
Here is a quick synopsis of my capture:
2:57 Start Wireshark capture and add mother! (2017).mkv to Movies directory.
2:58 Plex notices file change and adds it to recently added movies list.
3:05? (post deleted so I’m not positive on time) I force refresh metadata on mother!.
3:10? Plex notifies processing complete on mother!, end Wireshark capture.

Attached in the .zip are Plex Server Logs, Wireshark pcap file, and a screenshot of Plex home.
Notice in the screenshot that after a few days, some of the movies have had their metadata attached, while others which were added at the same time (Cocoon) have not, and still have a spinning tag icon on them.


#19

@sdownes said:
Thanks again for taking a look.

  • A single user account on the system, with administrator privileges.
  • Normal NTFS formatting for the C:\ drive, with ~170GB of free space available on the SSD.
  • D:\ drive is a parity Windows Storage Spaces disk, with four 3TB WD Reds.
  • No symbolic links used beyond what Windows may use in Storage Spaces virtual disk.

I no longer have the pcap for the original Wireshark capture, so I will complete another one.
Here is a quick synopsis of my capture:
2:57 Start Wireshark capture and add mother! (2017).mkv to Movies directory.
2:58 Plex notices file change and adds it to recently added movies list.
3:05? (post deleted so I’m not positive on time) I force refresh metadata on mother!.
3:10? Plex notifies processing complete on mother!, end Wireshark capture.

Attached in the .zip are Plex Server Logs, Wireshark pcap file, and a screenshot of Plex home.
Notice in the screenshot that after a few days, some of the movies have had their metadata attached, while others which were added at the same time (Cocoon) have not, and still have a spinning tag icon on them.

Many Thanks - Good evidence.

So the delay is on transmitting the request out
It shows the request not going out till 100 seconds later

2017-12-09 02:58:44,469 (19d0) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/uuQpQ8VDOtVL2IO4y2pR58odkS5.jpg'

and captured in wireshark

1	2017-12-09 09:00:24.577753	0.000000	HTTP	10.0.1.37	63911	104.16.59.155	80	GET /t/p/w300/uuQpQ8VDOtVL2IO4y2pR58odkS5.jpg HTTP/1.1 	369

The time showing as 09:00:24.577753 is because of my timezone - it is actually 03:00:24.577753

I will continue to look into this

What you could establish is if there was a lot of queued requests at the time - so repeat with another movie. But before adding the movie check with wireshark to see if there are a lot of queued requests being sent


#20

I have done a test with a dummy file named mother! (2017).mkv in a test library to see what we can get in terms of more diagnostics

In my test - first image.tmdb.org jpg request

2017-12-09 17:22:36,269 (3cdc) :  DEBUG (networking:166) - Requesting 'http://image.tmdb.org/t/p/w300/uuQpQ8VDOtVL2IO4y2pR58odkS5.jpg'
125 2017-12-09 17:22:36,628 (3cdc) :  DEBUG (networking:198) - Not caching 'http://image.tmdb.org/t/p/w300/uuQpQ8VDOtVL2IO4y2pR58odkS5.jpg' (content type 'image/jpeg' not cacheable in Agent plug-ins)

Matching wireshark

143689	2017-12-09 17:22:36.588664	265.301957	HTTP	192.168.0.152	53262	104.16.61.155	80	GET /t/p/w300/uuQpQ8VDOtVL2IO4y2pR58odkS5.jpg HTTP/1.1 	307

Just a 320ms delay compared to your 100 second delay

As you are now very good at getting the perfect diagnostics, I would like to take it one step deeper - just to see what was happening on your system in the 100 seconds

I am thinking of adding to wireshark and the logs, SysInternals Process Monitor

The procmon capture would record when the request goes out - in my case it was captured like this

147625	17:22:36.5885248	PlexScriptHost.exe	5724	0	TCP Connect	AML-SA-LT\plex	AML-SA-LT:53262 -> 104.16.61.155:http	SUCCESS	Length: 0, mss: 1460, sackopt: 1, tsopt: 0, wsopt: 1, rcvwin: 65700, rcvwinscale: 8, sndwinscale: 10, seqnum: 0, connid: 0	09/12/2017 17:22:36

147626	17:22:36.6164412	PlexScriptHost.exe	5724	0	TCP Send	AML-SA-LT\plex	AML-SA-LT:53262 -> 104.16.61.155:http	SUCCESS	Length: 253, startime: 378742, endtime: 378745, seqnum: 0, connid: 0	09/12/2017 17:22:36

So download procmon and run it as admin - do not start running it until you are ready.
Launch wireshark and add this filter display in the filter bar http.host contains "image.tmdb.org"

So suggest a test library and just one movie added and start procmon capture and wireshark just before you add the path folder to the test library to pick the movie file you place there.

As soon as you see a GET /t/p/xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx entry in wireshark, stop procmon capture andn stop wireshark capture

Save procmon without filtering into PML file (clear all filters before saving all as PML)
Save wireshark without filtering as pcap file (Clear the display filter and let that change complete - then save all captured packets)
Zip both and upload in your dropbox or other personal space and send me link by private message
and attach the logs that go with it