Remote access failing and dvr recordings failing....

General Discussions Plex Features
1

What is the correlation here? I keep seeing this over and over. I built a new plex and new firewall and it worked great for several weeks. All of the sudden the problem popped back up. Nothing changed on my end. I saw someone in another forum that mentioned a correlation and that idea was quickly shot down and being out of the realm of possibility.

I think they are absolutely related. The DVR crash always follows when Plex can’t manage to find my static public IP because the URL it is trying to communicate with has issues on the Plex company end.

I don’t believe this is a network or firewall issue on my side because other far more sensitive systems on my network never indicate any network/dns/firewall issue. I have run packet captures to the internet that don’t fail when this problem occurs. The internet didn’t go down, firewall shows no such occurrence. But Plex seems to have a problem and this problem just started in the last 2 days. I have been on version Version 1.9.1.4272 since it was release a couple weeks ago and it has been rock solid.

How does Plex use this process to determine my public IP? DEBUG - MyPlex: We appear to have lost Internet connectivity, resetting device URL cache. What is it connecting to on Plex’s side? And is that service having issues again on their side?

ep 30, 2017 14:48:44.566 [0x7f570effe700] DEBUG - PublicAddressManager: Obtaining public address and mapping port.
Sep 30, 2017 14:48:44.566 [0x7f56e3bf6700] DEBUG - MyPlex: Updating device connections (from timer: 0)
Sep 30, 2017 14:48:44.567 [0x7f570effe700] DEBUG - EventSource: Failure in IdleTimeout (0 - Success).
Sep 30, 2017 14:48:44.567 [0x7f56e3bf6700] DEBUG - HTTP requesting PUT https://plex.tv/devices/096062add0e1f005240dd7eef8cd0a227faf9997?Connection[][uri]=http://10.10.10.6:32400&httpsEnabled=1&httpsRequired=0&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Sep 30, 2017 14:48:44.567 [0x7f570effe700] DEBUG - MyPlex: We appear to have lost Internet connectivity, resetting device URL cache.
Sep 30, 2017 14:48:44.567 [0x7f570effe700] ERROR - EventSource: Retrying in 15 seconds.
Sep 30, 2017 14:48:44.567 [0x7f56f77fe700] DEBUG - PublicAddressManager: Obtaining public IP.
Sep 30, 2017 14:48:44.567 [0x7f56f77fe700] DEBUG - HTTP requesting GET http://plex.tv/pms/:/ip
Sep 30, 2017 14:48:44.567 [0x7f570effe700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Sep 30, 2017 14:48:44.567 [0x7f570effe700] DEBUG - Auth: Came in with the master token, authorization succeeded.
Sep 30, 2017 14:48:44.567 [0x7f56fd7ff700] DEBUG - Request: [127.0.0.1:34738 (Loopback)] PUT /video/:/transcode/session/6f8f3290-2e9c-451d-918e-891019d3c9b6/0bde8ab4-8c61-4528-ba8f-d9346a9f5429/progress?progress=-1.0&size=-22&remaining=-1&speed=1.1 (26 live) Signed-in Token (jreiter1975)
Sep 30, 2017 14:48:44.568 [0x7f56e73fd700] DEBUG - buildLiveM3U8: min 0 max 934
Sep 30, 2017 14:48:44.568 [0x7f570effe700] DEBUG - Completed after connection close: [127.0.0.1:34738] 206 PUT /video/:/transcode/session/6f8f3290-2e9c-451d-918e-891019d3c9b6/0bde8ab4-8c61-4528-ba8f-d9346a9f5429/progress?progress=-1.0&size=-22&remaining=-1&speed=1.1 (25 live) 0ms 0 bytes
Sep 30, 2017 14:48:44.588 [0x7f570effe700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Sep 30, 2017 14:48:44.588 [0x7f570effe700] DEBUG - Auth: Came in with the master token, authorization succeeded.
Sep 30, 2017 14:48:44.588 [0x7f56e9bfe700] DEBUG - Request: [127.0.0.1:35656 (Loopback)] PUT /video/:/transcode/session/332c0f3a-9266-4d15-836f-32207f4f3f15/4fb509c8-f7ee-4e6a-8d7c-91f8db1b6480/progress?progress=-1.0&size=1940909932&remaining=-1&speed=0.0 (25 live) Signed-in Token (jreiter1975)
Sep 30, 2017 14:48:44.589 [0x7f570f7ff700] DEBUG - Completed: [127.0.0.1:35656] 206 PUT /video/:/transcode/session/332c0f3a-9266-4d15-836f-32207f4f3f15/4fb509c8-f7ee-4e6a-8d7c-91f8db1b6480/progress?progress=-1.0&size=1940909932&remaining=-1&speed=0.0 (25 live) 0ms 326 bytes
Sep 30, 2017 14:48:44.590 [0x7f56ffbff700] DEBUG - buildLiveM3U8: min 0 max 934
Sep 30, 2017 14:48:44.593 [0x7f56e53f9700] DEBUG - Request: [127.0.0.1:35660 (Loopback)] GET /livetv/sessions/6f8f3290-2e9c-451d-918e-891019d3c9b6/332c0f3a-9266-4d15-836f-32207f4f3f15/00865.ts (26 live) Signed-in
Sep 30, 2017 14:48:44.594 [0x7f56e53f9700] DEBUG - Content-Length of /plex/cache/Transcode/Sessions/plex-transcode-6f8f3290-2e9c-451d-918e-891019d3c9b6/media-00865.ts is 2006148.
Sep 30, 2017 14:48:44.596 [0x7f570f7ff700] DEBUG - Completed: [127.0.0.1:35660] 200 GET /livetv/sessions/6f8f3290-2e9c-451d-918e-891019d3c9b6/332c0f3a-9266-4d15-836f-32207f4f3f15/00865.ts (25 live) 3ms 2006148 bytes
Sep 30, 2017 14:48:44.597 [0x7f570f7ff700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Sep 30, 2017 14:48:44.597 [0x7f570f7ff700] DEBUG - Auth: authenticated user 1 as jreiter1975
Sep 30, 2017 14:48:44.597 [0x7f570f7ff700] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Sep 30, 2017 14:48:44.598 [0x7f56f7fff700] DEBUG - Request: [10.10.10.9:56670 (Subnet)] GET /status/sessions/background (24 live) TLS GZIP Signed-in Token (jreiter1975)
Sep 30, 2017 14:48:44.599 [0x7f570f7ff700] DEBUG - Completed: [10.10.10.9:56670] 200 GET /status/sessions/background (24 live) TLS GZIP 1ms 470 bytes (pipelined: 4)
Sep 30, 2017 14:48:44.624 [0x7f570f7ff700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Sep 30, 2017 14:48:44.624 [0x7f570f7ff700] DEBUG - Auth: Came in with the master token, authorization succeeded.
Sep 30, 2017 14:48:44.624 [0x7f56e63fb700] DEBUG - Request: [127.0.0.1:35662 (Loopback)] PUT /video/:/transcode/session/332c0f3a-9266-4d15-836f-32207f4f3f15/4fb509c8-f7ee-4e6a-8d7c-91f8db1b6480/progress?progress=-1.0&size=1940916136&remaining=-1&speed=0.0 (25 live) Signed-in Token (jreiter1975)
Sep 30, 2017 14:48:44.625 [0x7f570f7ff700] DEBUG - Completed: [127.0.0.1:35662] 206 PUT /video/:/transcode/session/332c0f3a-9266-4d15-836f-32207f4f3f15/4fb509c8-f7ee-4e6a-8d7c-91f8db1b6480/progress?progress=-1.0&size=1940916136&remaining=-1&speed=0.0 (24 live) 0ms 326 bytes
Sep 30, 2017 14:48:44.627 [0x7f570cfff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 9781 is 0
Sep 30, 2017 14:48:44.628 [0x7f56e23f3700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 9781 is 0
Sep 30, 2017 14:48:44.628 [0x7f56e23f3700] DEBUG - DVR:Recorder: Asked to stop recording ‘College Football - Georgia at Tennessee’.
Sep 30, 2017 14:48:44.628 [0x7f570cfff700] DEBUG - Jobs: ‘/usr/lib/plexmediaserver/Plex Transcoder’ exit code for process 9781 is 0
Sep 30, 2017 14:48:44.628 [0x7f56e23f3700] DEBUG - DVR:Recorder: Stopping transcode session.
Sep 30, 2017 14:48:44.628 [0x7f56e23f3700] DEBUG - Killing job.
Sep 30, 2017 14:48:44.628 [0x7f56e23f3700] DEBUG - Signalling job ID 9780 with 9
Sep 30, 2017 14:48:44.628 [0x7f56e23f3700] DEBUG - Job was already killed, not killing again.

2

To add:
Static external IP address.
Static internal IP address.
Manually specified public port
UPnP is off.
1 router / firewall (Untangle) Internal IP traffic outbound is not filtered going out. Traffic coming in is not filtered to Plex.
No vlan in use.
No double NAT

3

I see this after a manual restart of remote access. It is up and down today.

Sep 30, 2017 17:45:52.211 [0x7f18a83fe700] DEBUG - PubSubManager: Time to connect to 184.105.148.98 was 122 ms.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] DEBUG - PubSubManager: Time to connect to 184.105.148.108 was 122 ms.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] DEBUG - PubSubManager: Time to connect to 45.79.11.43 was 177 ms.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] DEBUG - PubSubManager: Time to connect to 45.79.198.112 was 224 ms.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] DEBUG - PubSubManager: Time to connect to 50.116.49.5 was 235 ms.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] DEBUG - PubSubManager: Time to connect to 139.162.117.249 was 503 ms.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] WARN - PubSubManager: Connection to 139.162.7.93 failed: Connection timed out.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] WARN - PubSubManager: Connection to 139.162.164.202 failed: Connection timed out.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] WARN - PubSubManager: Connection to 139.162.200.94 failed: Connection timed out.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] WARN - PubSubManager: Connection to 82.94.168.52 failed: Connection timed out.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] WARN - PubSubManager: Connection to 65.52.235.203 failed: Connection timed out.
Sep 30, 2017 17:45:52.212 [0x7f18a83fe700] DEBUG - PubSubManager: Updating best ping time for 184.105.148.108 to 122 ms.
Sep 30, 2017 17:45:56.590 [0x7f18c73ff700] DEBUG - EventSource: Connecting to 184.105.148.108
Sep 30, 2017 17:45:56.590 [0x7f18c73ff700] DEBUG - EventSource: Resolved to 184.105.148.108
Sep 30, 2017 17:45:56.733 [0x7f18c6bfe700] DEBUG - EventSource: Connected in 95 ms.
Sep 30, 2017 17:45:56.733 [0x7f18c6bfe700] DEBUG - EventSource: Wrote data, reading reply.
Sep 30, 2017 17:45:57.365 [0x7f18c73ff700] DEBUG - EventSource: Read HTTP reply header.
Sep 30, 2017 17:45:57.365 [0x7f18c73ff700] DEBUG - MyPlex: We appear to have regained Internet connectivity.

4

Please always upload complete zip files of all the logs.

What would have had some relevance from the snippets you pasted was what happened 15 seconds before and 15 seconds after this log entry, for example

Sep 30, 2017 14:48:44.567 [0x7f570effe700] DEBUG - EventSource: Failure in IdleTimeout (0 - Success

When all logs are provided, one can get a better understanding about what was happening. It may not have the answer but at least it would allow an investigation

So please, restart the server, and get the logs as soon as the issue arises again and attach the zip

There may have been an issue with communicating with one of the pubsub servers
I do not know which one was the selected one before 14:48:44

5

Logs attached

6

This issue is still occuring. Plex server keep saying I am losing internet, when infact it seems to be there server(s) that are having a problem resolving my public IP in a timely fashion. How do I fix this?

7

Thanks for all the logs

The problem is that something is blocking periodic messages from the pubsub server that the Plex Media Server is connecting to.

This shows successful connection to the pubsub server on and initial communication successful but the periodic messages from the pubsub server did not get seen by the Plex Media Server. These would be approx every 10 seconds -

Oct 08, 2017 09:21:18.374 [0x7f002cfff700] DEBUG - EventSource: Connecting to 65.52.235.203
Oct 08, 2017 09:21:18.374 [0x7f002cfff700] DEBUG - EventSource: Resolved to 65.52.235.203
Oct 08, 2017 09:21:18.512 [0x7f002c7fe700] DEBUG - EventSource: Connected in 99 ms.
Oct 08, 2017 09:21:18.513 [0x7f002c7fe700] DEBUG - EventSource: Wrote data, reading reply.
Oct 08, 2017 09:21:19.034 [0x7f002cfff700] DEBUG - EventSource: Read HTTP reply header.

Oct 08, 2017 09:23:14.189 [0x7f002cfff700] DEBUG - EventSource: Failure in IdleTimeout (0 - Success).
Oct 08, 2017 09:23:14.189 [0x7f002cfff700] ERROR - EventSource: Retrying in 15 seconds.

Are you going through any https proxy that may be affecting this?

The IdleTimeout debug log is logged if we do not receive the keep-alive regular messages from the EventSource pubsub server a connection was established with. There are several pubsub servers and the one PMS gets fastest connection to is the one that is used

8

Maybe a switch is bootlooping?

9

@sa2000 said:
Thanks for all the logs

The problem is that something is blocking periodic messages from the pubsub server that the Plex Media Server is connecting to.

This shows successful connection to the pubsub server on and initial communication successful but the periodic messages from the pubsub server did not get seen by the Plex Media Server. These would be approx every 10 seconds -

Oct 08, 2017 09:21:18.374 [0x7f002cfff700] DEBUG - EventSource: Connecting to 65.52.235.203
Oct 08, 2017 09:21:18.374 [0x7f002cfff700] DEBUG - EventSource: Resolved to 65.52.235.203
Oct 08, 2017 09:21:18.512 [0x7f002c7fe700] DEBUG - EventSource: Connected in 99 ms.
Oct 08, 2017 09:21:18.513 [0x7f002c7fe700] DEBUG - EventSource: Wrote data, reading reply.
Oct 08, 2017 09:21:19.034 [0x7f002cfff700] DEBUG - EventSource: Read HTTP reply header.

Oct 08, 2017 09:23:14.189 [0x7f002cfff700] DEBUG - EventSource: Failure in IdleTimeout (0 - Success).
Oct 08, 2017 09:23:14.189 [0x7f002cfff700] ERROR - EventSource: Retrying in 15 seconds.

Are you going through any https proxy that may be affecting this?

The IdleTimeout debug log is logged if we do not receive the keep-alive regular messages from the EventSource pubsub server a connection was established with. There are several pubsub servers and the one PMS gets fastest connection to is the one that is used

No, not going through an https proxy. Going through an Untangle firewall. Plex is running as a VM on Ubuntu 16.04 LTS. Plex is set to bypass all the rules in Untangle. NAT is setup and port 32400 is forwarded. Bot LAN and WAN IPs are static. What log is that snippet from?

10

@jreiter1975 said:

@sa2000 said:
Thanks for all the logs

The problem is that something is blocking periodic messages from the pubsub server that the Plex Media Server is connecting to.

This shows successful connection to the pubsub server on and initial communication successful but the periodic messages from the pubsub server did not get seen by the Plex Media Server. These would be approx every 10 seconds -

Oct 08, 2017 09:21:18.374 [0x7f002cfff700] DEBUG - EventSource: Connecting to 65.52.235.203
Oct 08, 2017 09:21:18.374 [0x7f002cfff700] DEBUG - EventSource: Resolved to 65.52.235.203
Oct 08, 2017 09:21:18.512 [0x7f002c7fe700] DEBUG - EventSource: Connected in 99 ms.
Oct 08, 2017 09:21:18.513 [0x7f002c7fe700] DEBUG - EventSource: Wrote data, reading reply.
Oct 08, 2017 09:21:19.034 [0x7f002cfff700] DEBUG - EventSource: Read HTTP reply header.

Oct 08, 2017 09:23:14.189 [0x7f002cfff700] DEBUG - EventSource: Failure in IdleTimeout (0 - Success).
Oct 08, 2017 09:23:14.189 [0x7f002cfff700] ERROR - EventSource: Retrying in 15 seconds.

Are you going through any https proxy that may be affecting this?

The IdleTimeout debug log is logged if we do not receive the keep-alive regular messages from the EventSource pubsub server a connection was established with. There are several pubsub servers and the one PMS gets fastest connection to is the one that is used

No, not going through an https proxy. Going through an Untangle firewall. Plex is running as a VM on Ubuntu 16.04 LTS. Plex is set to bypass all the rules in Untangle. NAT is setup and port 32400 is forwarded. Bot LAN and WAN IPs are static. What log is that snippet from?

That snippet is repeated over and over again - it is in the Plex Media Server.log files (.1.log, .2.log etc)
It shows successful write message / read reply but after that there would be periodic messages and these are not being received, This is nothing to do with port 32400 being open / forwarded and is specific communctions between the selected pubsub server and Plex Media Server

Could you do some network packet tracing to see that it is coming in and being dropped

11

I can do some packet sniffing and see what is going on. Is there a specific set of pubsub servers? What type of traffic do they pass? Http? Https?

12

@jreiter1975 said:
I can do some packet sniffing and see what is going on. Is there a specific set of pubsub servers? What type of traffic do they pass? Http? Https?

The IP addresses may change - this request gives the total list
https://plex.tv/services/pubsub/servers?X-Plex-Token=xxxxxxxxxxxxxxx
See this article for finding out the server security token https://support.plex.tv/hc/en-us/articles/204059436-Finding-an-authentication-token-X-Plex-Token

Plex Media Server checks all of them if there are connection failures and then sticks to using the one it got fastest connection to - until there is a failure to connect.

These are geographically aligned

Have you blocked any traffic in the firewall / router ?

I believe it is https traffic

The currently selected PubSub server IP Address can be found in logs or in the Preferences.xml in field PubSubServer