Posters not loaded - error in plexapp.system.log

Server Version#: 1.18.8.2468 (but also on the older version 1.18.7.2438)
Player Version#: Plex Web 4.26.1

  1. Since about two weeks (roughly) my Plex server won’t really load posters for my movies.
    It starts loading the metadata and it success in loading description, plot and some textual metadata. But loading posters fails and it seems to retry quite often to load them, but never success. I haven’t found any major things in the logs except ONE critical error in the Plex/App Support/PMS/Logs/PMS Plugin Logs/com.plexapp.system.log where it says something like :
2020-02-29 13:49:34,189 (7fec14327700) :  DEBUG (agentservice:1077) - Downloading data for metadata://posters/com.plexapp.agents.imdb_524aeb4ca85a8ebbf0eba43caf19f7e886858d72 (in com.plexapp.agents.imdb) from http://image.tmdb.org/t/p/original/hoqe3leVhHBgboB6G1bv1kB8K4p.jpg
2020-02-29 13:49:34,189 (7fec14327700) :  DEBUG (networking:143) - Requesting 'http://image.tmdb.org/t/p/original/hoqe3leVhHBgboB6G1bv1kB8K4p.jpg'
2020-02-29 13:49:54,402 (7fec14327700) :  CRITICAL (runtime:889) - Exception (most recent call last):
  File "/volume1/@appstore/Plex Media Server/Resources/Plug-ins-5d395aa9d/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/components/runtime.py", line 843, in handle_request
    result = f(**d)
  File "/volume1/@appstore/Plex Media Server/Resources/Plug-ins-5d395aa9d/System.bundle/Contents/Code/agentservice.py", line 1078, in media_get
    data = HTTP.Request(media_url, cacheTime=0).content
  File "/volume1/@appstore/Plex Media Server/Resources/Plug-ins-5d395aa9d/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/components/networking.py", line 242, in content
    return self.__str__()
  File "/volume1/@appstore/Plex Media Server/Resources/Plug-ins-5d395aa9d/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/components/networking.py", line 220, in __str__
    self.load()
  File "/volume1/@appstore/Plex Media Server/Resources/Plug-ins-5d395aa9d/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/components/networking.py", line 162, in load
    self._data = f.read()
  File "/volume1/@appstore/Plex Media Server/Resources/Python/lib/python2.7/socket.py", line 355, in read
    data = self._sock.recv(rbufsize)
  File "/volume1/@appstore/Plex Media Server/Resources/Python/lib/python2.7/httplib.py", line 612, in read
    s = self.fp.read(amt)
  File "/volume1/@appstore/Plex Media Server/Resources/Python/lib/python2.7/socket.py", line 384, in read
    data = self._sock.recv(left)
timeout: timed out

Seems like loading the roster fails (and I don’t know why).
To dig a little deeper here, I connected to my Synology NAS and tried to wget the file from there

which worked fine. So DNS and connection problems shouldn’t be present here.

  1. Im not sure if related, but also the server fails in showing the pictures of actors on the web client (different PCs and browsers are tested) and even is not showing posters from movies I added a long time ago and everything went well.

Problem here is like this:


And it seems like waiting up to 2 minutes will resolve the problem. Debugging console says it tries to get the media from: https://192-168-178-155.59d409a7438a425295178963XXXXXX.plex.direct:32400/photo/:/transcode?width=240&height=361&minSize=1&upscale=1&url=%2Flibrary%2Fmetadata%2F126155%2Fthumb%2F1582460297%3FX-Plex-Token%3D8hYtehVWayUEAXXXXXX&X-Plex-Token=8hYrehWWqyUEAXXXXX

and it took about

- this issue is also quite new.
But even after that calls are sucessfull, actors are not loaded in 80-90% of the cases.


The only two things that changed on MY side were a new router (but configurations were imported) and the updated PMS.

Do you guys have any suggestions what I can try ? :-/

Archiv.zip (7.3 MB)
My server logs are attached.

I have edited your thread title “CRITICAL” (yelling) isn’t necessary.

You’re experiencing timeouts when it’s attempting to pull all the information.

There are several factors in play here

  1. It shows PMS is recovering from a crash (not too important at this point)
  2. The networking is changing just as it’s trying to download codecs and perform other operations.
Feb 29, 2020 13:46:46.246 [0x7fd1b1fc3700] DEBUG - HTTP requesting GET https://downloads.plex.tv/codecs/0bc617e-2974/linux-x86_64-standard/libaac_decoder.so
Feb 29, 2020 13:46:46.364 [0x7fd1665a1700] DEBUG - NetworkInterface: received Netlink message len=1096, type=RTM_NEWLINK, flags=0x0
Feb 29, 2020 13:46:46.364 [0x7fd1665a1700] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=18, flags=0x1002, change=0xffffffff
Feb 29, 2020 13:46:46.364 [0x7fd1665a1700] DEBUG - Network change.
Feb 29, 2020 13:46:46.364 [0x7fd1665a1700] DEBUG - NetworkInterface: Notified of network changed (force=0)
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - Network change notification but nothing changed.
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - NetworkInterface: received Netlink message len=1100, type=RTM_NEWLINK, flags=0x0
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=18, flags=0x1043, change=0x1
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - Network change.
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - NetworkInterface: Notified of network changed (force=0)
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - Network change notification but nothing changed.
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - NetworkInterface: received Netlink message len=1100, type=RTM_NEWLINK, flags=0x0
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=18, flags=0x1003, change=0x0
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - Network change.
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - NetworkInterface: Notified of network changed (force=0)
Feb 29, 2020 13:46:46.365 [0x7fd1665a1700] DEBUG - Network change notification but nothing changed.
Feb 29, 2020 13:46:46.998 [0x7fd166e6b700] DEBUG - HTTP 200 response from GET https://plex.tv/servers/c1be2c82682aa8819c50225e96095bed684ea0eb/sync_lists?auth_token=xxxxxxxxxxxxxxxxxxxx

one second later

Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: received Netlink message len=1108, type=RTM_NEWLINK, flags=0x0
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=18, flags=0x11043, change=0x0
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - Network change.
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: Notified of network changed (force=0)
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - Network change notification but nothing changed.
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: received Netlink message len=1108, type=RTM_NEWLINK, flags=0x0
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=18, flags=0x11043, change=0x0
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - Network change.
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: Notified of network changed (force=0)
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - Network change notification but nothing changed.
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: received Netlink message len=1108, type=RTM_NEWLINK, flags=0x0
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: Netlink information message family=0, type=1, index=18, flags=0x11043, change=0x0
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - Network change.
Feb 29, 2020 13:46:47.484 [0x7fd1665a1700] DEBUG - NetworkInterface: Notified of network changed (force=0)
Feb 29, 2020 13:46:47.485 [0x7fd1665a1700] DEBUG - Network change notification but nothing changed.
Feb 29, 2020 13:46:48.010 [0x7fd1a3259700] DEBUG - Auth: authenticated user 18644668 as Svolpic
Feb 29, 2020 13:46:48.010 [0x7fd16511f700] DEBUG - Request: [95.157.57.157:59254 (WAN)] GET / (8 live) TLS G

I find further discrepancy in that:

  1. The CPU doesn’t match the product and DSM is not current.
Feb 29, 2020 13:46:35.153 [0x7fd1b259f700] INFO - Plex Media Server v1.18.8.2468-5d395aa9d - Synology DS3617xs x86_64 - build: linux-x86_64 synology - GMT 01:00
Feb 29, 2020 13:46:35.153 [0x7fd1b259f700] INFO - Linux version: DSM 6.1.4.15217-5, language: en-US
Feb 29, 2020 13:46:35.153 [0x7fd1b259f700] INFO - Processor Intel(R) Xeon(R) CPU E3-1245 v6 @ 3.70GHz

with the official listed as:

DS3617xs	Intel Xeon D-1527	Quad Core	8	Yes	Broadwell	DDR4 ECC SO-DIMM 16 GB

Ref: https://www.synology.com/en-us/knowledgebase/DSM/tutorial/Compatibility_Peripherals/What_kind_of_CPU_does_my_NAS_have

What can you tell me about what’s really happening here?

Hi @ChuckPa, thanks for your reply.
Sorry for the headline - i was just copying the original message from the log I found.

To bring some light in here - and I know I brought myself in this situation by myself and I’m working on a solution on this… but currently beeing in a lock-in situation … : This is a xpenology box, running synology with custom hardware.

It started with a test and ended up too big to fail. Now it failed and i already worked on a migration concept - but currently there is no easy exit from this setup … :frowning:

So this is in fact a Intel(R) Xeon(R) CPU E3-1245 v6 @ 3.70GHz with 16GB of RAM, and a Supermicro X11SSH-CTF Mainboard with a Intel® X550 10GBase-T Ethernet Controller.

This setup worked finde the last 3 years (round about) and I think this has to do something with my router change.

I can understand if you guys are not willing to give more support on that setup since its absolutely out of the box - and believe me - this is not the first time I regret this setup and since one year I plan a migration - but with no easy outcome so far.

Since your post I did a few steps to change this behaviour:

  • I installed a older Plex server version (1.18.5.2309)
  • deleted the cache folder for the plugins
  • disabled ipv6 completely
  • I disabled IPMI which was running the last 2 years shared on this nic port
  • I took a different port on my router (switched from the 2,5G NBase-T-Ethernet-Port back to a 1G port like before) [i wasn’t sure if my cable this crappy xpenology setup can handle 2,5g )

No changes so far.

Maybe in a general way: Does anybody has a hint what can cause this kind of network change?

Thanks

It’s not a problem to help but knowing truth makes it much easier.
Given the adapters are going up & down heavily implies the link status is flipping state.

Link status flipping comes from:

  1. Loose/faulty cable or connector or not latched in completely (most common)
  2. DHCP server gone wild and sending IP address assignments (forcing DSM to take the interface down momentarily while it sets the commanded IP address)
  3. External (IPMI) managment forcing changes – which you’ve disabled.

Does the configuration have static or DHCP addressing?

On a separate thought train,

Exiting from XPEnology back to native linux is actually pretty easy.
You’ve already done the hard part with the HDD connectivity.

Synology disk partitioning is very simple and makes it easy to take volumes elsewhere

  1. DSM root partition
  2. Swap partition
  3. Data storage parition

Given this, mdadm --assemble /dev/sd*3 (listing each device found by the native host Linux (e.g. Fedora)) will re-instantiate the volume as /dev/md0 which you can then mount in complete emulation of Synology mount /dev/md0 /volume1

I would suggest proving this out yourself using the live usb method first after we resolve the networking issue.

Thanks for giving some tips and help here. Appreciated!

So the setup WAS on DHCP, but since your reply right now, i changed it in DSM to static. This had no impact in the behaviour of the poster download and the error message in com.plexapp.system.log (CRITICAL etc).

I try the cable in the next hour.
Also trying a different IPMI setup again since I didnt deactivated it completly - only switched it to dedicated mode on nic port 2.

It’s a really interesting error anyway since watching movies and shows still works really well. no problems no stuttering etc.
Shouldn’t this flipping not be a problem here too?


is there any way of watching the network switching back and forth somehow? Because yes, in the plex starting log i can see the network thing you mentioned in post 1, but after that warmup phase it seems to be gone, right? Or maybe I didn’t look at the right places.

– on that extra thought : didn’t know it will be so easy to import that volume in for e.g. in ubuntu as well o.O . I thought this stuff is highly bound to Synology since all the OS files are also on this partitions etc.

PMS relies on the host’s network connections.
There is no “warm up phase” in PMS for network. It is there or it is not. PMS does not wait.

Monitoring link state is trivial in a script if [ "$(ifconfig ethX | grep UP)" = "" ]; then
– it’s down

The challenge is catching it.

Moving on to where the root cause of not getting posters is the next task.

I do need see updated logs in light of the changes.

  1. Shut down PMS
  2. Wait 2 minutes for socket to be fully closed in DSM
  3. Start PMS
  4. Wait 2 minutes for PMS to talk to Plex.tv
  5. Perform Forced metadata refresh
  6. Download Logs & Attach

Re ‘bound to synology’,

It’s a regular Linux box to me. I see the package manager (Package Center), reserved names for the storage areas (/volume1, /volume2, etc) on a large storage space, and the hardware transcoding inodes (if present).

@ChuckPa
thanks again for your help.
I did as you described. Shuting down , waiting at least 5 minutes, then starting up again. Waiting 5 minutes and than do a forced refresh of one of my libraries (i have a small one with only 12 movies in it and took that one).

Waited at least 15 minutes (because it took endless of loading some data o.O ) and attached it here:
Plex Media Server Logs_2020-03-02_07-44-19.zip (4.2 MB)

Yesterday evening my wife watched Lord or Rings with Plex and it worked like charm - expect new library entries (newer than 2 weeks or so) have no poster etc. :wink:

Thanks in advance

@bwestpha

I’m seeing it again just as I previously saw with HTTPcookies and CRLF vs CR.

I have no idea what has changed in 1.18.8 in this regard. Nothing should have been changed.

Regardless, I would like to clean out the data caches.

  1. Stop PMS
  2. Open File Station
  3. Navigate to Plex/Library/Application Support/Plex Media Server/Plug-in Support/Caches
  4. Delete all you see here.
  5. Navigate to Plex/Library/Application Support/Plex Media Server/Plug-in Support/Data (do not mistake with Databases)
  6. Delete all you see in the Data directory
  7. Start PMS
  8. Force Refresh All Metadata for the problem section.
  9. Advise of the progress when complete

@ChuckPa

Sounds really strange o.O .
And as I said, i even installed an OLD version of plex since that error occured - but no changed behaviour even I’m pretty sure this bug is not never than mid january 2020.

Stange.

I did the steps you wrote here (I already deleted the cache oonce or twice, but the Data folder was quite new to me :smiley: ).
The boot time of the server was a lot longer than the times before and it looks like plex loaded a bunch of data on starting up (netIO was quite high).

After that I again took my small movie library and force-loaded the meta-data.


and 10 minutes later:

(and again 10 minutes later some of the loading spinners gone away but the cover still is missing - I’m not bringing up another screenshot for this.

remarkable is, that there seems to be a lot of load on the line due to the “downloading” of metadata but nothin is changed.

Logfiles after 20 minutes of waiting are attached again … :-S

:`(

// tomorrow evening i have some more time and no double shift to try out a plex server fresh install on a different machine to exclude network issues and after that maybe installing a plex server on a VM hosted on that Synology/Xpenology machine. Maybe this will bring up some light?

Thanks a LOT

Plex Media Server Logs_2020-03-02_23-11-13.zip (4.6 MB)

I will be unavailable for a day or two due to another higher priority issue.
I am bookmarking this so I don’t forget.

Please do ping me @ChuckPa in a few days if I’ve not responded.

I have exactly the same problems. Posters for movies can’t be downloaded and images for actors and similar movies are missing. The error in the log files is also the same.
Already tried deleting the Plug-In Support Caches and Data folder and also disabling IPv6.
I included log files trying to update the metadata for a problematic movie after a fresh start of the media server.

Plex Media Server Logs_2020-03-07_14-51-51.zip (987.9 KB)

@ChuckPa any news on that :frowning: ?
Seems like I’m maybe not the only one …

1 Like

I just noticed I can fix all the problems (posters not downloading, pictures for cast and similar movies not showing) when I connect my server to a VPN. But like @bwestpha I can manually download media via curl that Plex fails to download when not using a VPN, so it does not seem to be a general network problem. I’d really appreciate @ChuckPa having a look at this again, as having my server connected to a VPN is no permanent solution for me.

I’m working with a few other German users.

I spent 3+ hours yesterday with @reap over Facetime talking this through since I’m in the US.

A few questions come up.

  1. How many of you have the new Fritzbox ?
  2. How many of you signed up for the new Gigabit service with that (as I am told) “less than friendly” ISP ?
2 Likes

I have been using their gigabit service for about a year now and have always been happy with it. But it is true that the quality of this ISP depends heavily on the area where you live in.
And yes I have also been using the latest Cable FritzBox (6591) since its release in May 2019. It was bought by me and is not provided by the ISP and therefore runs unmodified firmware.

@reap

Would you have time to update here please as to any progress you’ve made with the ISP?

All:
What we discovered on Reap’s systems.

  1. MacOS PMS ran flawlessly
  2. Syno PMS (same version) would not
  3. We did a traceroute from his location to plex.tv
  4. The Mac succeeded
  5. The Synology did not.
  6. Implication - MAC address based trunking / routing in their gigabit service at his node.
  7. We found other portions of their infrastructure exposed to the public. OOPS

Yes, exactly this.

I recently changed my network device from an „fritz box 6490“ and a Vodafone isp line of 500mbit down/50 Mbit up to a newer and cheaper offer with 1000/50.

I can not 100% be sure this issue came up in the exact same timeframe but yes.

My thoughts Were ok the new fritz box , but yes … it’s also a new rate.

Im really interested in what they may have changed on their isp site o.O

||| Just as a note: last 3-4 years it worked fine with 500/50 and with lower rates.

Whatever happened,

It happened around the time of the new gigabit service setup & launch on 1 March 2020

It does take time to configure infrastructure. We might have been seeing this creeping problem for some time now but masked because it was so isolated.

With the effort we put into it and my additional research on enterprise routing tables, it does make sense as to why this is happening.

Sure. I’m gonna copy my post out of my thread:
So I called my ISP (Unitymedia/Vodafone Germany) yesterday and told them what we discovered. And by them I mean three different people. The whole story. None of them seemed to get what I was talking about. One of them just replied “So you can’t receive E-Mails?” WHAT?! :rofl: The third person passed my topic to her supervisor which called me today. He knew what I meant and passed the information to the technicians, they will call me back as soon as they figured out what is going wrong here.

Sadly no progress and no expected reaction on the login screen for the Frankfurt main node :grinning:

@bwestpha Any chance you’re living in the area of Frankfurt or in Hessen? I’m trying to delimit the variables.