Overnight freeze due to plex.tv communications error?!?!?!?

Live TV & DVR
1

Hello. I awoke today to find that Plex decided to stop working overnight. DVR recordings ceased at 5am. When I look in the logs it appears possible that there was a burp in my internet last night. This gave Plex some response errors and instead of gracefully handling them it just…shuts down and goes non-functional without a restart in under ten minutes?!? This is unacceptable. I’m doubtful there was any loss of internet at all however…

Nov 13, 2019 05:06:09.105 [0x7fedf9c62700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:06:09.106 [0x7feddc726700] DEBUG - Request: [192.168.0.21:39918 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:06:09.107 [0x7feddc726700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:06:16.321 [0x7fedf9974700] DEBUG - EventSource: Failure in ReadData (2 - End of file).
Nov 13, 2019 05:06:16.321 [0x7fedf9974700] DEBUG - MyPlex: We appear to have lost Internet connectivity, resetting device URL cache.
Nov 13, 2019 05:06:16.321 [0x7fedf9974700] ERROR - EventSource: Retrying in 15 seconds.
Nov 13, 2019 05:06:29.120 [0x7fedf9c62700] DEBUG - Completed: [192.168.0.21:39918] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (10 live) TLS GZIP 20014ms 5 bytes (pipelined: 1)
Nov 13, 2019 05:06:29.201 [0x7fedf9c62700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:06:29.201 [0x7feddc726700] DEBUG - Request: [192.168.0.21:39924 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:06:29.202 [0x7feddc726700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:06:31.321 [0x7fedf9c62700] DEBUG - EventSource: Resolving 45.33.125.156 port 443
Nov 13, 2019 05:06:31.338 [0x7fedf9c62700] DEBUG - EventSource: Resolved 45.33.125.156 to 45.33.125.156
Nov 13, 2019 05:06:32.777 [0x7fedf9c62700] DEBUG - EventSource: Connected in 425 ms.
Nov 13, 2019 05:06:32.786 [0x7fedf9c62700] DEBUG - EventSource: Wrote data, reading reply.
Nov 13, 2019 05:06:48.944 [0x7fedf9974700] DEBUG - EventSource: Read HTTP reply header.
Nov 13, 2019 05:06:48.944 [0x7fedf9974700] DEBUG - EventSource: Failure in ParseHeader: HTTP/1.1 500 Internal Server Error
Server: nginx
Date: Wed, 13 Nov 2019 11:06:48 GMT
Content-Type: text/html
Content-Length: 186
Connection: close

<html>
<head><title>500 Internal Server Error</title></head>
<body bgcolor="white">
<center><h1>500 Internal Server Error</h1></center>
<hr><center>nginx</center>
</body>
</html>
 (0 - Success).
Nov 13, 2019 05:06:48.967 [0x7fedf9974700] ERROR - EventSource: Retrying in 30 seconds.
Nov 13, 2019 05:06:49.203 [0x7fedf9974700] DEBUG - Completed: [192.168.0.21:39924] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (10 live) TLS GZIP 20002ms 5 bytes (pipelined: 1)
Nov 13, 2019 05:06:49.252 [0x7fedf9974700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:06:49.252 [0x7feddcd02700] DEBUG - Auth: Refreshing tokens inside the token-based authentication filter.
Nov 13, 2019 05:06:49.253 [0x7feddc726700] DEBUG - Request: [192.168.0.21:39926 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:06:49.253 [0x7feddcd02700] DEBUG - HTTP requesting GET https://plex.tv/servers/d10fb0b59e0ec6b6fd123451ba11ee363858d3aa/access_tokens.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1
Nov 13, 2019 05:06:49.254 [0x7feddc726700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:06:54.722 [0x7feddcd02700] ERROR - Error issuing curl_easy_perform(handle): 52
Nov 13, 2019 05:06:54.722 [0x7feddcd02700] WARN - HTTP error requesting GET https://plex.tv/servers/d10fb0b59e0ec6b6fd123451ba11ee363858d3aa/access_tokens.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1 (0, No error) (Empty reply from server)
Nov 13, 2019 05:06:54.728 [0x7feddcd02700] DEBUG - MyPlex: using cached data for request for https://plex.tv/servers/d10fb0b59e0ec6b6fd123451ba11ee363858d3aa/access_tokens.xml?auth_token=xxxxxxxxxxxxxxxxxxxx&includeProfiles=1&includeProviders=1
Nov 13, 2019 05:06:54.731 [0x7feddcd02700] DEBUG - MyPlex: updating with 10 access tokens
Nov 13, 2019 05:06:54.731 [0x7fed7b735700] DEBUG - HTTP requesting GET https://plex.tv/media/providers?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Nov 13, 2019 05:07:00.200 [0x7fed7b735700] ERROR - Error issuing curl_easy_perform(handle): 52
Nov 13, 2019 05:07:00.200 [0x7fed7b735700] WARN - HTTP error requesting GET https://plex.tv/media/providers?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (0, No error) (Empty reply from server)
Nov 13, 2019 05:07:00.206 [0x7fed7b735700] ERROR - Error parsing content.
Nov 13, 2019 05:07:00.224 [0x7fed7b735700] ERROR - Error parsing XML: Error parsing file.
Nov 13, 2019 05:07:00.861 [0x7feddc726700] DEBUG - BPQ: onConsiderProcessing: Idle (true)
Nov 13, 2019 05:07:00.861 [0x7feddc726700] DEBUG - BPQ: [Idle] -> [Processing]
Nov 13, 2019 05:07:00.865 [0x7feddc726700] DEBUG - BPQ: generating queue items from 0 generator(s)
Nov 13, 2019 05:07:00.865 [0x7feddc726700] DEBUG - BPQ: generated 0 item(s) for queue
Nov 13, 2019 05:07:00.905 [0x7feddc726700] DEBUG - PlayQueue: 0 generated IDs compressed down to a 20 byte blob.
Nov 13, 2019 05:07:00.906 [0x7feddc726700] DEBUG - PlayQueue: 0 generated IDs compressed down to a 20 byte blob.
Nov 13, 2019 05:07:00.907 [0x7feddc726700] DEBUG - BPQ: [Processing] -> [Idle]
Nov 13, 2019 05:07:00.907 [0x7feddc726700] DEBUG - BPQ: garbageCollect - sync - forced - 1
Nov 13, 2019 05:07:00.907 [0x7feddc726700] DEBUG - Sync: starting Sync garbage collection: 1, forced
Nov 13, 2019 05:07:00.907 [0x7feddc726700] DEBUG - Sync: finished Sync garbage collection: 1
Nov 13, 2019 05:07:00.907 [0x7feddc726700] DEBUG - BPQ: garbageCollect - version - forced - -1
Nov 13, 2019 05:07:00.907 [0x7feddc726700] DEBUG - Versions: garbage collecting
Nov 13, 2019 05:07:00.914 [0x7feddc726700] DEBUG - Versions: garbage collected in 0.0 seconds
Nov 13, 2019 05:07:09.255 [0x7fedf9c62700] DEBUG - Completed: [192.168.0.21:39926] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (10 live) TLS GZIP 20002ms 5 bytes (pipelined: 1)
Nov 13, 2019 05:07:09.318 [0x7fedf9c62700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:07:09.318 [0x7fed7a5a1700] DEBUG - Request: [192.168.0.21:39928 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:07:09.319 [0x7fed7a5a1700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:07:18.967 [0x7fedf9974700] DEBUG - EventSource: Resolving 45.33.125.156 port 443
Nov 13, 2019 05:07:18.968 [0x7fedf9974700] DEBUG - EventSource: Resolved 45.33.125.156 to 45.33.125.156
Nov 13, 2019 05:07:19.454 [0x7fedf9c62700] DEBUG - EventSource: Connected in 466 ms.
Nov 13, 2019 05:07:19.454 [0x7fedf9c62700] DEBUG - EventSource: Wrote data, reading reply.
Nov 13, 2019 05:07:29.320 [0x7fedf9c62700] DEBUG - Completed: [192.168.0.21:39928] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (10 live) TLS GZIP 20001ms 5 bytes (pipelined: 1)
Nov 13, 2019 05:07:29.369 [0x7fedf9974700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:07:29.370 [0x7fed6b735700] DEBUG - Request: [192.168.0.21:39944 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:07:29.370 [0x7fed6b735700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:07:35.744 [0x7fedf9974700] DEBUG - EventSource: Read HTTP reply header.
Nov 13, 2019 05:07:35.745 [0x7fedf9974700] DEBUG - EventSource: Failure in ParseHeader: HTTP/1.1 500 Internal Server Error
Server: nginx
Date: Wed, 13 Nov 2019 11:07:35 GMT
Content-Type: text/html
Content-Length: 186
Connection: close

<html>
<head><title>500 Internal Server Error</title></head>
<body bgcolor="white">
<center><h1>500 Internal Server Error</h1></center>
<hr><center>nginx</center>
</body>
</html>
 (0 - Success).
Nov 13, 2019 05:07:36.355 [0x7fedf9974700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:07:36.355 [0x7fedf9974700] DEBUG - PubsubServerManager: Switching to next host in region: 45.33.119.35
Nov 13, 2019 05:07:36.388 [0x7fedf9974700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:07:36.388 [0x7fedf9974700] DEBUG - EventSource: Resolving 45.33.119.35 port 443
Nov 13, 2019 05:07:36.389 [0x7fedf9974700] DEBUG - EventSource: Resolved 45.33.119.35 to 45.33.119.35
Nov 13, 2019 05:07:37.009 [0x7fedf9c62700] DEBUG - EventSource: Connected in 601 ms.
Nov 13, 2019 05:07:37.009 [0x7fedf9c62700] DEBUG - EventSource: Wrote data, reading reply.
Nov 13, 2019 05:07:49.371 [0x7fedf9c62700] DEBUG - Completed: [192.168.0.21:39944] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (10 live) TLS GZIP 20002ms 5 bytes (pipelined: 1)
Nov 13, 2019 05:07:49.397 [0x7fedf9974700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:07:49.398 [0x7fed7a5a1700] DEBUG - Request: [192.168.0.21:39946 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:07:49.398 [0x7fed7a5a1700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:07:56.389 [0x7fedf9974700] DEBUG - EventSource: Failure in IdleTimeout (0 - Success).
Nov 13, 2019 05:07:56.389 [0x7fedf9974700] ERROR - EventSource: Retrying in 15 seconds.
Nov 13, 2019 05:08:09.399 [0x7fedf9974700] DEBUG - Completed: [192.168.0.21:39946] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (10 live) TLS GZIP 20001ms 5 bytes (pipelined: 1)
Nov 13, 2019 05:08:09.495 [0x7fedf9974700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:08:09.496 [0x7fed6b735700] DEBUG - Request: [192.168.0.21:39950 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:08:09.497 [0x7fed6b735700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:08:11.389 [0x7fedf9c62700] DEBUG - EventSource: Resolving 45.33.119.35 port 443
Nov 13, 2019 05:08:11.390 [0x7fedf9c62700] DEBUG - EventSource: Resolved 45.33.119.35 to 45.33.119.35
Nov 13, 2019 05:08:26.980 [0x7fedf9974700] DEBUG - EventSource: Connected in 551 ms.
Nov 13, 2019 05:08:26.981 [0x7fedf9974700] DEBUG - EventSource: Wrote data, reading reply.
Nov 13, 2019 05:08:29.498 [0x7fedf9974700] DEBUG - Completed: [192.168.0.21:39950] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (10 live) TLS GZIP 20002ms 5 bytes (pipelined: 1)
Nov 13, 2019 05:08:29.556 [0x7fedf9974700] DEBUG - Auth: authenticated user 1 as NDInnovations
Nov 13, 2019 05:08:29.557 [0x7fed6b735700] DEBUG - Request: [192.168.0.21:39956 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Token (NDInnovations)
Nov 13, 2019 05:08:29.558 [0x7fed6b735700] DEBUG - Content-Length is -1 (of total: -1).
Nov 13, 2019 05:08:31.389 [0x7fedf9c62700] DEBUG - EventSource: Failure in IdleTimeout (0 - Success).
Nov 13, 2019 05:08:36.574 [0x7fedf9c62700] DEBUG - HTTP requesting GET https://plex.tv/services/pubsub/servers
Nov 13, 2019 05:08:42.051 [0x7fedf9c62700] ERROR - Error issuing curl_easy_perform(handle): 52
Nov 13, 2019 05:08:42.051 [0x7fedf9c62700] WARN - HTTP error requesting GET https://plex.tv/services/pubsub/servers (0, No error) (Empty reply from server)
Nov 13, 2019 05:08:47.134 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 45.56.115.195 was 100 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 173.255.237.43 was 152 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 184.105.148.113 was 208 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 176.58.127.172 was 255 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 139.162.120.52 was 328 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 139.162.40.38 was 449 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 82.94.168.21 was 514 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 172.105.99.32 was 535 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Time to connect to 45.33.119.35 was 698 ms.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] WARN - PubSubManager: Connection to 139.162.170.32 failed: Connection timed out.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] WARN - PubSubManager: Connection to 45.33.125.156 failed: Connection timed out.
Nov 13, 2019 05:08:47.135 [0x7fedf9c62700] DEBUG - PubSubManager: Another server (45.56.115.195) beat the current one (45.33.119.35).
Nov 13, 2019 05:08:47.178 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.179 [0x7fedf9c62700] DEBUG - EventSource: Resolving 45.56.115.195 port 443
Nov 13, 2019 05:08:47.179 [0x7fedf9c62700] DEBUG - PubSubManager: Updating best host to 45.56.115.195.
Nov 13, 2019 05:08:47.179 [0x7fedf9974700] DEBUG - EventSource: Resolved 45.56.115.195 to 45.56.115.195
Nov 13, 2019 05:08:47.179 [0x7fedf9c62700] DEBUG - PubSubManager: Updating best ping time for 45.56.115.195 to 100 ms.
Nov 13, 2019 05:08:47.179 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.180 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.180 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.180 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.180 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.180 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.180 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.180 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:08:47.181 [0x7fedf9c62700] DEBUG - EventSource: Stopping.
Nov 13, 2019 05:30:04.005 [0x7fed799e9700] DEBUG - Putting plug-in com.plexapp.agents.thetvdb to sleep.
Nov 13, 2019 05:30:04.005 [0x7fed799e9700] DEBUG - Stopping [com.plexapp.agents.thetvdb].
Nov 13, 2019 05:30:04.005 [0x7fed799e9700] DEBUG - [com.plexapp.agents.thetvdb] Killing.
Nov 13, 2019 05:30:04.010 [0x7fedfa23e700] WARN - JobManager: Could not find job for handle 31249
Nov 13, 2019 05:30:14.006 [0x7fed799e9700] DEBUG - Stopping file watcher for com.plexapp.agents.thetvdb
2

While it might be useful for PMS to have a watchdog timer, I’m guessing that most people would run a cron job that checks connectivity that often.

3

If Plex is going to decide to just go idle on bad network communication back home, they should have a watch dog or gracefully handle the error. Like I said I doubt this had anything to do with my network. This is an http 501 error from Plex. How am I supposed to watchdog that myself? Query every single possible plex url constantly? This didn’t even crash Plex completely, it just went to sleep and stopped doing anything. I still had to manually stop and then restart the service, so it’s not like I can occasionally check if Plex died. And even if I did that why would “most people” decide to just live with that and not point out to Plex that they should be more resilient in cases of their own servers burping. A communication error with their pubsub server should not crash me.

4

I’m not disagreeing with you when I mentioned an external watchdog timer.
My suggestion was not going to work 100% of the time.

If you’d like to investigate the failure, we could gather some log files.
Any information you can provide would be the best way to get a fix in place.

https://support.plex.tv/articles/201869908-log-files

If you want Plex to put in place an internal watchdog in their server, please open a Feature Request topic so it can be voted on by the community.

Thanks.

5

Another Plex freeze due to miscommunication with gracenote (what?!?!?) causing recordings to stop immediately and nothing else happen but logs generated until I force restart.

2019-12-10 20:38:12,675 (7ff020432700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=4&force=1&respectTags=0&parentGUID=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%3Flang%3Den&parentID=4942&guid=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%2F1%3Flang%3Den&id=7888&agent=com.plexapp.agents.localmedia&async=0
2019-12-10 20:38:12,703 (7ff020432700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:12,775 (7ff020432700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:12,817 (7feff0a5f700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=4&force=1&respectTags=0&parentGUID=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%3Flang%3Den&parentID=4942&guid=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%2F2%3Flang%3Den&id=8000&agent=com.plexapp.agents.localmedia&async=0
2019-12-10 20:38:12,820 (7feff0a5f700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:12,990 (7ff020432700) :  DEBUG (agentservice:326) - Adding com.plexapp.agents.thetvdb://280494/4/1?lang=en to the update list
2019-12-10 20:38:12,992 (7ff020432700) :  DEBUG (agentservice:400) - Acquiring GUID mutex for com.plexapp.agents.thetvdb://280494/4/1?lang=en (7888) (count is now 1)
2019-12-10 20:38:12,993 (7ff020432700) :  DEBUG (agentservice:402) - Acquired GUID mutex for com.plexapp.agents.thetvdb://280494/4/1?lang=en (7888)
2019-12-10 20:38:12,993 (7ff020432700) :  INFO (agentservice:404) - Preparing metadata for TV_Show in com.plexapp.agents.thetvdb (280494)
2019-12-10 20:38:12,991 (7feff0a5f700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:12,995 (7ff020432700) :  DEBUG (runtime:1117) - Created a thread named 'notify_processing'
2019-12-10 20:38:13,004 (7ff020432700) :  DEBUG (model:32) - Loading model with GUID com.plexapp.agents.thetvdb://280494/4/1?lang=en
2019-12-10 20:38:13,009 (7feff0a5f700) :  DEBUG (agentservice:326) - Adding com.plexapp.agents.thetvdb://280494/4/2?lang=en to the update list
2019-12-10 20:38:13,009 (7feff0a5f700) :  DEBUG (agentservice:400) - Acquiring GUID mutex for com.plexapp.agents.thetvdb://280494/4/2?lang=en (8000) (count is now 1)
2019-12-10 20:38:13,010 (7feff0a5f700) :  DEBUG (agentservice:402) - Acquired GUID mutex for com.plexapp.agents.thetvdb://280494/4/2?lang=en (8000)
2019-12-10 20:38:13,010 (7feff0a5f700) :  INFO (agentservice:404) - Preparing metadata for TV_Show in com.plexapp.agents.thetvdb (280494)
2019-12-10 20:38:13,013 (7feff0a5f700) :  DEBUG (runtime:1117) - Created a thread named 'notify_processing'
2019-12-10 20:38:13,014 (7feff0a5f700) :  DEBUG (model:32) - Loading model with GUID com.plexapp.agents.thetvdb://280494/4/2?lang=en
2019-12-10 20:38:13,014 (7fefa3447700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/metadata/processing?id=7888'
2019-12-10 20:38:13,059 (7ff020432700) :  ERROR (model:205) - Cannot read model from /mnt/HD/HD_a2/Nas_Prog/plex_conf/Plex Media Server/Metadata/TV Shows/7/6e75e7690cd470984617e748b1c329439e53cd9.bundle/Contents/com.plexapp.agents.thetvdb
2019-12-10 20:38:13,069 (7fefa3fff700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/metadata/processing?id=8000'
2019-12-10 20:38:13,087 (7ff020432700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:13,099 (7feff0a5f700) :  ERROR (model:205) - Cannot read model from /mnt/HD/HD_a2/Nas_Prog/plex_conf/Plex Media Server/Metadata/TV Shows/a/9d40fb55177dbe5e9d6df2fdde0cc9b1c3aedfb.bundle/Contents/com.plexapp.agents.thetvdb
2019-12-10 20:38:13,112 (7feff0a5f700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:13,132 (7ff020432700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.agents.localmedia/messaging/function/X0FnZW50S2l0OlNlYXJjaA__/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmVuczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M3ClRWX1Nob3dzMTAKbWVkaWFfdHlwZTUKczQKNDk0MnM4CnBhcmVudElEczQ3CmNvbS5wbGV4YXBwLmFnZW50cy50aGV0dmRiOi8vMjgwNDk0LzQvMT9sYW5nPWVuczQKZ3VpZGIxczUKZm9yY2VzMjYKY29tLnBsZXhhcHAuYWdlbnRzLnRoZXR2ZGJzMTMKcHJpbWFyeV9hZ2VudHM0Cjc4ODhzMgppZHIwCg__'
2019-12-10 20:38:13,139 (7fefa3447700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=4&force=1&respectTags=0&parentGUID=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%3Flang%3Den&parentID=4942&guid=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%2F1%3Flang%3Den&id=7888&agent=com.plexapp.agents.localmedia&async=0
2019-12-10 20:38:13,142 (7fefa3447700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:13,143 (7fefa3447700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:13,200 (7feff0a5f700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.agents.localmedia/messaging/function/X0FnZW50S2l0OlNlYXJjaA__/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmVuczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M3ClRWX1Nob3dzMTAKbWVkaWFfdHlwZTUKczQKNDk0MnM4CnBhcmVudElEczQ3CmNvbS5wbGV4YXBwLmFnZW50cy50aGV0dmRiOi8vMjgwNDk0LzQvMj9sYW5nPWVuczQKZ3VpZGIxczUKZm9yY2VzMjYKY29tLnBsZXhhcHAuYWdlbnRzLnRoZXR2ZGJzMTMKcHJpbWFyeV9hZ2VudHM0CjgwMDBzMgppZHIwCg__'
2019-12-10 20:38:13,258 (7fefa3447700) :  DEBUG (agentservice:357) - Not adding com.plexapp.agents.thetvdb://280494/4/1?lang=en to the update list because it already exists
2019-12-10 20:38:13,260 (7fefa3447700) :  DEBUG (runtime:924) - Response: [200] InitiateUpdateResponse, 161 bytes
2019-12-10 20:38:14,353 (7fefa3447700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=4&force=1&respectTags=0&parentGUID=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%3Flang%3Den&parentID=4942&guid=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%2F2%3Flang%3Den&id=8000&agent=com.plexapp.agents.localmedia&async=0
2019-12-10 20:38:14,355 (7fefa3447700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:14,357 (7fefa3447700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:14,365 (7fefa3447700) :  DEBUG (agentservice:357) - Not adding com.plexapp.agents.thetvdb://280494/4/2?lang=en to the update list because it already exists
2019-12-10 20:38:14,367 (7fefa3447700) :  DEBUG (runtime:924) - Response: [200] InitiateUpdateResponse, 161 bytes
2019-12-10 20:38:15,500 (7fefa3447700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=4&force=1&respectTags=0&parentGUID=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%3Flang%3Den&parentID=4942&guid=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F280494%2F4%2F3%3Flang%3Den&id=8001&agent=com.plexapp.agents.localmedia&async=0
2019-12-10 20:38:15,502 (7fefa3447700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:15,504 (7fefa3447700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:15,520 (7fefa3447700) :  DEBUG (agentservice:326) - Adding com.plexapp.agents.thetvdb://280494/4/3?lang=en to the update list
2019-12-10 20:38:15,521 (7fefa3447700) :  DEBUG (agentservice:400) - Acquiring GUID mutex for com.plexapp.agents.thetvdb://280494/4/3?lang=en (8001) (count is now 1)
2019-12-10 20:38:15,521 (7fefa3447700) :  DEBUG (agentservice:402) - Acquired GUID mutex for com.plexapp.agents.thetvdb://280494/4/3?lang=en (8001)
2019-12-10 20:38:15,522 (7fefa3447700) :  INFO (agentservice:404) - Preparing metadata for TV_Show in com.plexapp.agents.thetvdb (280494)
2019-12-10 20:38:15,525 (7fefa3447700) :  DEBUG (runtime:1117) - Created a thread named 'notify_processing'
2019-12-10 20:38:15,527 (7fefa3447700) :  DEBUG (model:32) - Loading model with GUID com.plexapp.agents.thetvdb://280494/4/3?lang=en
2019-12-10 20:38:15,542 (7fefa3fff700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/metadata/processing?id=8001'
2019-12-10 20:38:15,574 (7fefa3447700) :  ERROR (model:205) - Cannot read model from /mnt/HD/HD_a2/Nas_Prog/plex_conf/Plex Media Server/Metadata/TV Shows/2/e8e8278482eb6adeb94a863c7b065090d6e5f28.bundle/Contents/com.plexapp.agents.thetvdb
2019-12-10 20:38:15,579 (7fefa3447700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:15,666 (7fefa3447700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.agents.localmedia/messaging/function/X0FnZW50S2l0OlNlYXJjaA__/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoyCmRpY3QKZGljdAo2CnMyCmVuczQKbGFuZ2IwczYKbWFudWFsYjBzNwpwcmltYXJ5aTAKczcKdmVyc2lvbnIxCnM2Cmt3YXJnc3M3ClRWX1Nob3dzMTAKbWVkaWFfdHlwZTUKczQKNDk0MnM4CnBhcmVudElEczQ3CmNvbS5wbGV4YXBwLmFnZW50cy50aGV0dmRiOi8vMjgwNDk0LzQvMz9sYW5nPWVuczQKZ3VpZGIxczUKZm9yY2VzMjYKY29tLnBsZXhhcHAuYWdlbnRzLnRoZXR2ZGJzMTMKcHJpbWFyeV9hZ2VudHM0CjgwMDFzMgppZHIwCg__'
2019-12-10 20:38:18,891 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /system/messaging/clear_events/com.plexapp.agents.localmedia
2019-12-10 20:38:18,894 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /system/messaging/clear_events/com.plexapp.agents.localmedia
2019-12-10 20:38:18,896 (7fefa3fff700) :  DEBUG (runtime:88) - Sending packed state data (99 bytes)
2019-12-10 20:38:18,897 (7fefa3fff700) :  DEBUG (runtime:924) - Response: [200] str, 0 bytes
2019-12-10 20:38:19,401 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.system/resourceHashes
2019-12-10 20:38:19,406 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.system/resourceHashes
2019-12-10 20:38:19,409 (7fefa3fff700) :  DEBUG (runtime:88) - Sending packed state data (99 bytes)
2019-12-10 20:38:19,409 (7fefa3fff700) :  DEBUG (runtime:924) - Response: [200] str, 13276 bytes
2019-12-10 20:38:19,496 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /:/plugins/com.plexapp.system/messaging/function/X0J1bmRsZVNlcnZpY2U6QWxsU2VydmljZXM_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMApyMAo_
2019-12-10 20:38:19,498 (7fefa3fff700) :  DEBUG (runtime:49) - Received packed state data (80 bytes)
2019-12-10 20:38:19,501 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /:/plugins/com.plexapp.system/messaging/function/X0J1bmRsZVNlcnZpY2U6QWxsU2VydmljZXM_/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMApyMAo_
2019-12-10 20:38:19,575 (7fefa3fff700) :  DEBUG (runtime:88) - Sending packed state data (99 bytes)
2019-12-10 20:38:19,576 (7fefa3fff700) :  DEBUG (runtime:924) - Response: [200] str, 59982 bytes
2019-12-10 20:38:21,464 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=2&force=1&respectTags=0&guid=com%2Eplexapp%2Eagents%2Ethetvdb%3A%2F%2F345868%3Flang%3Den&id=24
2019-12-10 20:38:21,468 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:21,469 (7fefa3fff700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins'
2019-12-10 20:38:21,507 (7fefa3fff700) :  DEBUG (agentservice:326) - Adding com.plexapp.agents.thetvdb://345868?lang=en to the update list
2019-12-10 20:38:21,510 (7ff021ce2700) :  DEBUG (agentservice:400) - Acquiring GUID mutex for com.plexapp.agents.thetvdb://345868?lang=en (24) (count is now 1)
2019-12-10 20:38:21,510 (7ff021ce2700) :  DEBUG (agentservice:402) - Acquired GUID mutex for com.plexapp.agents.thetvdb://345868?lang=en (24)
2019-12-10 20:38:21,511 (7ff021ce2700) :  INFO (agentservice:404) - Preparing metadata for TV_Show in com.plexapp.agents.thetvdb (345868)
2019-12-10 20:38:21,537 (7fefa3fff700) :  DEBUG (runtime:924) - Response: [200] InitiateUpdateResponse, 161 bytes
2019-12-10 20:38:21,549 (7ff021ce2700) :  DEBUG (runtime:1117) - Created a thread named 'notify_processing'
2019-12-10 20:38:21,559 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=2&force=1&respectTags=0&guid=com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F363648&id=87
2019-12-10 20:38:21,563 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:21,575 (7fefa3d11700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/metadata/processing?id=24'
2019-12-10 20:38:21,609 (7ff021ce2700) :  DEBUG (networking:143) - Requesting 'http://127.0.0.1:32400/:/plugins/com.plexapp.agents.thetvdb/messaging/function/X0FnZW50S2l0OlVwZGF0ZU1ldGFkYXRh/Y2VyZWFsMQoxCmxpc3QKMApyMAo_/Y2VyZWFsMQoxCmRpY3QKMTAKczIKZW5zNApsYW5nYjFzNQpmb3JjZWIwczgKcGVyaW9kaWNzMgoyNHM0CmRiaWRpMApzNwp2ZXJzaW9ubnMxMApwYXJlbnRHVUlEbnM4CnBhcmVudElEczcKVFZfU2hvd3MxMAptZWRpYV90eXBlczQzCmNvbS5wbGV4YXBwLmFnZW50cy50aGV0dmRiOi8vMzQ1ODY4P2xhbmc9ZW5zNApndWlkczYKMzQ1ODY4czIKaWRyMAo_'
2019-12-10 20:38:21,621 (7fefa3fff700) :  CRITICAL (agentservice:369) - Exception in update request handler (most recent call last):
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 301, in update
    version = self.agent_get_version(libraryAgent or identifier, 'Artist' if media_type == 'Album' else media_type)
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 1226, in agent_get_version
    for agent in self.agent_info[identifier]:
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/code/sandbox.py", line 108, in <lambda>
    _getitem_           = lambda x, y: x.__getitem__(y),
KeyError: 'com.gracenote.onconnect'

2019-12-10 20:38:21,624 (7fefa3fff700) :  DEBUG (runtime:924) - Response: [200] InitiateUpdateResponse, 975 bytes
2019-12-10 20:38:21,656 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=2&force=1&respectTags=0&guid=plex%3A%2F%2Fshow%2F5d79804e525a0b0020d7b150&id=10454
2019-12-10 20:38:21,661 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:21,662 (7fefa3fff700) :  CRITICAL (agentservice:369) - Exception in update request handler (most recent call last):
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 301, in update
    version = self.agent_get_version(libraryAgent or identifier, 'Artist' if media_type == 'Album' else media_type)
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 1226, in agent_get_version
    for agent in self.agent_info[identifier]:
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/code/sandbox.py", line 108, in <lambda>
    _getitem_           = lambda x, y: x.__getitem__(y),
KeyError: 'plex'

2019-12-10 20:38:21,664 (7fefa3fff700) :  DEBUG (runtime:924) - Response: [200] InitiateUpdateResponse, 956 bytes
2019-12-10 20:38:21,679 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=2&force=1&respectTags=0&guid=com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F8965051&id=4490
2019-12-10 20:38:21,682 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:21,683 (7fefa3fff700) :  CRITICAL (agentservice:369) - Exception in update request handler (most recent call last):
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 301, in update
    version = self.agent_get_version(libraryAgent or identifier, 'Artist' if media_type == 'Album' else media_type)
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 1226, in agent_get_version
    for agent in self.agent_info[identifier]:
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/code/sandbox.py", line 108, in <lambda>
    _getitem_           = lambda x, y: x.__getitem__(y),
KeyError: 'com.gracenote.onconnect'

2019-12-10 20:38:21,686 (7fefa3fff700) :  DEBUG (runtime:924) - Response: [200] InitiateUpdateResponse, 975 bytes
2019-12-10 20:38:21,698 (7fefa3fff700) :  DEBUG (runtime:717) - Handling request GET /system/agents/update?mediaType=2&force=1&respectTags=0&guid=plex%3A%2F%2Fshow%2F5db547667d0cdb001f2c8f2b&id=11327
2019-12-10 20:38:21,705 (7fefa3fff700) :  DEBUG (runtime:814) - Found route matching /system/agents/update
2019-12-10 20:38:21,707 (7fefa3fff700) :  CRITICAL (agentservice:369) - Exception in update request handler (most recent call last):
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 301, in update
    version = self.agent_get_version(libraryAgent or identifier, 'Artist' if media_type == 'Album' else media_type)
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/System.bundle/Contents/Code/agentservice.py", line 1226, in agent_get_version
    for agent in self.agent_info[identifier]:
  File "/mnt/HD/HD_a2/Nas_Prog/plexmediaserver/binaries/Resources/Plug-ins-5a96726d0/Framework.bundle/Contents/Resources/Versions/2/Python/Framework/code/sandbox.py", line 108, in <lambda>
    _getitem_           = lambda x, y: x.__getitem__(y),
KeyError: 'plex'
6

It probably won’t be much fun to read this other thread I helped a guy solve that had a similar error with gracenotedb.

That thread is an example where the user got an error like yours, and it took several attempts to get the full logs of what occurred. Once I had those, I found he had a bad HDHomerun device.

I’m not saying you have that, but when debugging Plex, the developers seem to want everything Plex gives when you use Settings - Troubleshooting - Download Logs. You would zip and attach the folder.

Personally I wouldn’t wait for Plex to fix this. I’d make a cron job or a Raspberry Pi Zero into an external watchdog.

I hope you all have a happy holidays and get some smooth recordings!

7

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.