PMS Remote Access - Connects and shows available for about 30 seconds then reverts to not available

Plex Media Server Remote Access
,
1

Server Version#: 1.22.1.4228
Player Version#: Any remote client

Hi,

I have a PMS configured on my NAS running in docker via pfsense, that has worked for years until the last month or so.

I have NAT set up to listen on my WAN address for port 32400 and then route that to my NAS on port 32400 where plex is running on docker listening on that port.

Internally everything is working fine, externally, its not - however everything looks correct.

I can browse to my WAN IP:32400 and reach the NAS:32400 (and got the plex login screen) so i know port forwarding is working AND plex is responding (i also, very briefly, tested this by changing the same rule to translate WAN IP:32400 to RouterIP:80 of my router so i would get my router login screen and it worked). Proving NAT is happening as i expect.

If i click on retry in PMS i get “Fully available outside your network” for about 30 seconds before it then switches back to unavailable again.

The weird thing is, if i connect my Android app on my mobile network to my plex server when it shows as available, it REMAINS working AFTER PMS reports its not available to the outside unless i clear the connections by force closing the android app and connecting again, at this point it only shows Plex provided content and not my stuff.

As a test I also tired disabling/stopping the Plex install on docker and installed native Qnap Plex (version 1.2.1 ( 2021/01/28 )) and started it on my NAS as well with just bare minimum settings. This produced the same issue, so it doesnt feel like a docker issue or a Plex install issue or a Router issue either for that matter.

This just doesnt make any sense. Any suggestions?

2

DEBUG log files please? (VERBOSE OFF)

( recreate , Download Logs ZIP file, Attach the ZIP )

It’s not possible to diagnose without seeing what’s actually happening

4

Logs included - to make this as “clean” as possible, i shut down my docker instance and ran a new instance of the qnap app instead to make it easy wiht no media, then recreated the issue.

It initially tried to use a random external port, then i manually set it to 32400 but the issue happened really quickly so i clicked retry for a 3rd attempt and that seemed to sit for 20 seconds or so before inidcation it was unreachable.

5

Thanks for the logs.

First, to tell you a few things about how this works (which is also seen in your logs)

  1. When you enable Remote Access or just open the Settings page when already enabled – a reachability test is performed. The status showing there is as Plex sees it.

  2. If you tap on Plex.tv too much for a reachability test it will do two things:
    a. Skip the test
    b. Throttle reachability tests (1 hour)
    c. PMS, as reflected by Plex/web does not tolerate being “muscled”. This is done to prevent resource starvation (DDOS) caused by an IP spamming for reachability tests.
    d. The normal case is 1-2 per hour. (1 = Turn it on, 2 = Ooops, I want to change it the other way). Anything else is skipped (throttled) until the next hourly refresh.

  3. Your logs show Plex.tv throttling you for having tapped on it too often.

Mar 26, 2021 21:05:54.740 [0x7f93b71bc700] DEBUG - HTTP requesting POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - HTTP 422 response from POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - MyPlex: Published Mapping State response was 422
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - MyPlex: Got response for b66adc457ce9d8ba87258943857f603f82f0d77d ~ registered :0
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - MyPlex: updating mapped state - current state: 'Mapped - Not Published (Not Reachable)'
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - MyPlex: mapping state set to 'Mapped - Publishing'.
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - MyPlex: async reachability check - current mapped state: 'Mapped - Publishing'.
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - MyPlex: requesting connectivity refresh too soon after the last request, skipping.
Mar 26, 2021 21:05:54.919 [0x7f93b71bc700] DEBUG - MyPlex: mapping state set to 'Unknown'.
Mar 26, 2021 21:05:54.920 [0x7f93b74aa700] DEBUG - Completed: [192.168.254.240:57772] 200 PUT /:/prefs?PublishServerOnPlexOnlineKey=false (5 live) TLS GZIP 5444ms 274 bytes (pipelined: 13)
Mar 26, 2021 21:05:55.117 [0x7f93b74aa700] DEBUG - Auth: authenticated user 1 as ScottishB
  1. At that point, it will declare the host as ‘non-published’ and drop the WAN addresses it has for it. This is why you can’t reopen after it locks up.

If I may comment about how you’ve implemented this?

  1. I also have pfSense.

  2. I’ve enabled both UPnP and NAT-PMP

  3. Given Netgate implemented both very well , Plex loves it.

  4. I run 3 docker containers and 4 VMs (QA & development)

  5. pfSense maps them all (automatic port mapping mode) without fail. This provides the normal Plex brokered server sharing via Plex/web or apps.

  6. I also have a FQDN which my pfSense maintains the DHCP WAN address of for me.

  7. I created one static port forwarding rule in pfSense to forward to 32400 of my main server. I turn this on only when I am performing certain tests.

I’m going to send you a few things via DM.
I think it will help you understand better how this works.

6

To summarize for anyone else who might read this and think I lost my mind (which is always possible)

  1. Hover over Remote Access on the left side
  2. Give it the chance to make a reachability test.
  3. If you had remote access before, it will go green again.
7

Hi ChuckPa,
Firstly - many thanks for all the info, however, i think the issue was that my repeated attempts to check set off that issue that you found in the logs, but it does not appear to the the root cause here. That is, after leaving it overnight and checking again this morning i am still unable to connect remotely.

Now knowing what you are looking at in the logs i can hopefully provide the section you need here showing what i hope is the section where is shows as not published:-

Mar 27, 2021 10:23:25.301 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:62755] 200 OPTIONS /myplex/refreshReachability (7 live) TLS GZIP 0ms 384 bytes (pipelined: 5)
Mar 27, 2021 10:23:25.313 [0x7fbc7f7fe700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 10:23:25.313 [0x7fbc27fff700] DEBUG - Request: [192.168.254.241:62755 (Allowed Network (Subnet))] PUT /myplex/refreshReachability (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 10:23:25.313 [0x7fbc27fff700] DEBUG - MyPlex: async reachability check - current mapped state: 'Mapped - Not Published'.
Mar 27, 2021 10:23:25.313 [0x7fbc27fff700] DEBUG - MyPlex: Requesting reachability check.
Mar 27, 2021 10:23:25.313 [0x7fbc27fff700] DEBUG - HTTP requesting PUT https://plex.tv/api/servers/4a85a4d49cef8ee61d7906044e41aab0a1585a46/connectivity?X-Plex-Token=ScottishBScottishBxxxxxx&asyncIdentifier=fe747020-eeeb-483d-a17e-597ed9391818
Mar 27, 2021 10:23:25.541 [0x7fbc27fff700] DEBUG - HTTP 200 response from PUT https://plex.tv/api/servers/4a85a4d49cef8ee61d7906044e41aab0a1585a46/connectivity?X-Plex-Token=ScottishBScottishBxxxxxx&asyncIdentifier=fe747020-eeeb-483d-a17e-597ed9391818
Mar 27, 2021 10:23:25.542 [0x7fbc7f7fe700] DEBUG - Completed: [192.168.254.241:62755] 200 PUT /myplex/refreshReachability (7 live) TLS GZIP 229ms 328 bytes (pipelined: 6)
Mar 27, 2021 10:23:27.496 [0x7fbc7effd700] DEBUG - EventSource: Got event [data] '<Message address="xx.xxx.xx.xx" port="32400" asyncIdentifier="fe747020-eeeb-483d-a17e-597ed9391818" connectivity="0" command="notifyConnectivity"/>'
Mar 27, 2021 10:23:27.496 [0x7fbc7effd700] DEBUG - PubSub: Got notified of reachability for async identifier fe747020-eeeb-483d-a17e-597ed9391818: 0 for xx.xxx.xx.xx:32400 (responded in 1954 ms)
Mar 27, 2021 10:23:27.496 [0x7fbc7effd700] DEBUG - MyPlex: reachability check - current mapping state: 'Mapped - Not Published'.
Mar 27, 2021 10:23:27.496 [0x7fbc7effd700] DEBUG - MyPlex: mapping state set to 'Mapped - Not Published (Not Reachable)'.
Mar 27, 2021 10:23:27.500 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 10:23:27.500 [0x7fbc27fff700] DEBUG - Request: [192.168.254.241:62755 (Allowed Network (Subnet))] GET /myplex/account (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 10:23:27.501 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:62755] 200 GET /myplex/account (7 live) TLS GZIP 0ms 3428 bytes (pipelined: 7)
Mar 27, 2021 10:23:36.688 [0x7fbc5b7fe700] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.254.22:80/description.xml
Mar 27, 2021 10:23:36.688 [0x7fbc5b7fe700] DEBUG - HTTP requesting GET http://192.168.254.22:80/description.xml
Mar 27, 2021 10:23:36.695 [0x7fbc5b7fe700] DEBUG - HTTP 200 response from GET http://192.168.254.22:80/description.xml
Mar 27, 2021 10:23:36.695 [0x7fbc5b7fe700] DEBUG - NetworkServiceBrowser: found 1 SSDP devices via http://192.168.254.22:80/description.xml
Mar 27, 2021 10:23:36.695 [0x7fbc5b7fe700] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.254.22 (Philips hue (192.168.254.22))

Can you have a quick look at this please?

With regards to my setup, i’ll try to give you an insight -

I’ve enabled both UPnP and NAT-PMP - I only have uPnP configured, but that does seem to be working for my needs anyway - i’ll look into NAT-PMP but its not something i’ve needed until maybe now.

I run 3 docker containers and 4 VMs (QA & development) - I used to have a Esxi Server all set up with multiple VM’s including PfSense, FreeNAS etc and (144GB of RAM) - long story but i got the server for an absolute steal off ebay. However, i found that the power requirements, not to mention the noise, were a bit off putting. So i broke it up and sold it for much more than i paid for it. With that i bought a dedicated box (not Netgate) for PfSense and a nice NAS. I then used docker on the NAS for pretty much all my apps and restricted each to the minimum they needed to run. No VM’s are used - i dont need any that require to be on 24/7 so for anything that needs a bit more grunt i fire that up in VMware Workstation on my PC for the times that i need it.

PfSense maps them all (automatic port mapping mode) without fail. This provides the normal Plex brokered server sharing via Plex/web or apps. I have mine configured for manual port mapping mode, but as i’ve proved above, it is working, and things like my PS4 etc all work fine also and they need uPnP to work.

I also have a FQDN which my pfSense maintains the DHCP WAN address of for me. - Yup - same here, but mainly for OpenVPN access so that i have a permanent FQDN i can connect to rather than hunting for an ip address.

I created one static port forwarding rule in pfSense to forward to 32400 of my main server. I turn this on only when I am performing certain tests.- I have the same, well 1 NAT rule, which also automatically creates a WAN Firewall rule, but its on permanently. I wouldn’t remember to turn this on before i need it. I have watchtower configured on docker to keep Plex updated to the latest version every morning so it should help with any security risk.

Hope that helps and as mentioned, thanks for the help again.

8

Another one several hours later:-

Mar 27, 2021 14:25:06.152 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:06.152 [0x7fbc25ffb700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (6 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:06.153 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (6 live) TLS GZIP 0ms 3230 bytes (pipelined: 54)
Mar 27, 2021 14:25:06.528 [0x7fbc7f7fe700] DEBUG - EventSource: Got event [data] '<Message host="139.162.247.112" port="443" command="startRelay"/>'
Mar 27, 2021 14:25:06.529 [0x7fbc7f7fe700] DEBUG - Relay: reused an existing key for https://downloads.plex.tv/relay/relay_v1.pub
Mar 27, 2021 14:25:06.529 [0x7fbc7f7fe700] DEBUG - Relay: starting relay.
Mar 27, 2021 14:25:06.529 [0x7fbc7f7fe700] DEBUG - [JobRunner] Job running: PLEXTOKEN=xxxxxxxxxxxxxxxxxxxxd' '/usr/lib/plexmediaserver/Plex Relay' '-p' '443' '-N' '-R' '0:127.0.0.1:32401' '-o' 'StrictHostKeyChecking=yes' '-o' 'UserKnownHostsFile=/config/Library/Application Support/Plex Media Server/Cache/relayHostKey.txt' '-o' 'LogLevel=VERBOSE' '-o' 'PreferredAuthentications=password' '-o' 'PubkeyAuthentication=no' '-l' 'ScottishB' '-F' '/dev/null' '139.162.247.112'
Mar 27, 2021 14:25:06.529 [0x7fbc7f7fe700] DEBUG - [JobRunner] Jobs: Starting child process with pid 13702
Mar 27, 2021 14:25:06.652 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:06.653 [0x7fbc7d7fa700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (6 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:06.653 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (6 live) TLS GZIP 0ms 3230 bytes (pipelined: 55)
Mar 27, 2021 14:25:06.765 [0x7fbc25ffb700] DEBUG - [PlexRelay] Authenticated to 139.162.247.112 ([139.162.247.112]:443).
Mar 27, 2021 14:25:06.877 [0x7fbbf37fe700] INFO - [PlexRelay] Allocated port 13417 for remote forward to 127.0.0.1:32401
Mar 27, 2021 14:25:07.152 [0x7fbc7f7fe700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:07.152 [0x7fbc7d7fa700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:07.152 [0x7fbc7f7fe700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (7 live) TLS GZIP 0ms 3230 bytes (pipelined: 56)
Mar 27, 2021 14:25:07.525 [0x7fbc7f7fe700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:07.525 [0x7fbbf37fe700] DEBUG - Request: [127.0.0.1:44462 (WAN)] GET /:/websockets/notifications (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:07.525 [0x7fbbf37fe700] DEBUG - WebSocket: Performing handshake from origin 
Mar 27, 2021 14:25:07.525 [0x7fbbf37fe700] DEBUG - Beginning read from WebSocket
Mar 27, 2021 14:25:07.651 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:07.651 [0x7fbc25ffb700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:07.652 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (7 live) TLS GZIP 0ms 3230 bytes (pipelined: 57)
Mar 27, 2021 14:25:08.151 [0x7fbc7f7fe700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:08.152 [0x7fbc7d7fa700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:08.152 [0x7fbc7f7fe700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (7 live) TLS GZIP 0ms 3230 bytes (pipelined: 58)
Mar 27, 2021 14:25:08.651 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:08.652 [0x7fbc7d7fa700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:08.652 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (7 live) TLS GZIP 0ms 3230 bytes (pipelined: 59)
Mar 27, 2021 14:25:09.151 [0x7fbc7f7fe700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:09.152 [0x7fbc25ffb700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:09.152 [0x7fbc7f7fe700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (7 live) TLS GZIP 0ms 3230 bytes (pipelined: 60)
Mar 27, 2021 14:25:09.371 [0x7fbc6ffff700] DEBUG - NAT: UPnP, found device <http://192.168.254.22:80/description.xml> with private address <192.168.254.2>
Mar 27, 2021 14:25:09.371 [0x7fbc6ffff700] DEBUG - NAT: UPnP, not an IGD: <http://192.168.254.22:80/description.xml>.
Mar 27, 2021 14:25:09.384 [0x7fbc6ffff700] DEBUG - NAT: UPnP, found device <http://192.168.254.22:80/description.xml> with private address <192.168.254.2>
Mar 27, 2021 14:25:09.384 [0x7fbc6ffff700] DEBUG - NAT: UPnP, not an IGD: <http://192.168.254.22:80/description.xml>.
Mar 27, 2021 14:25:09.398 [0x7fbc6ffff700] DEBUG - NAT: UPnP, found device <http://192.168.254.22:80/description.xml> with private address <192.168.254.2>
Mar 27, 2021 14:25:09.398 [0x7fbc6ffff700] DEBUG - NAT: UPnP, not an IGD: <http://192.168.254.22:80/description.xml>.
Mar 27, 2021 14:25:09.399 [0x7fbc6ffff700] DEBUG - NAT: UPnP, found device <http://192.168.254.1:2189/rootDesc.xml> with private address <192.168.254.2>
Mar 27, 2021 14:25:09.400 [0x7fbc6ffff700] DEBUG - NAT: UPnP, usable device <http://192.168.254.1:2189/rootDesc.xml> with private address <192.168.254.2>.
Mar 27, 2021 14:25:09.401 [0x7fbc6ffff700] DEBUG - NAT: UPnP, public address is xx.xxx.xx.xx
Mar 27, 2021 14:25:09.401 [0x7fbc6ffff700] DEBUG - HTTP requesting GET https://86-153-46-90.1acfff95d08d469d9b880c03d8788626.plex.direct:32400/identity
Mar 27, 2021 14:25:09.414 [0x7fbc7f7fe700] DEBUG - Request came in with unrecognized domain / IP 'xx.xxx.xx.xx' in header Host; treating as non-local
Mar 27, 2021 14:25:09.414 [0x7fbc25ffb700] DEBUG - Request: [192.168.254.1:39353 (Allowed Network (Subnet))] GET /identity (8 live) TLS GZIP Signed-in
Mar 27, 2021 14:25:09.456 [0x7fbc6ffff700] DEBUG - HTTP 200 response from GET https://86-153-46-90.1acfff95d08d469d9b880c03d8788626.plex.direct:32400/identity
Mar 27, 2021 14:25:09.456 [0x7fbc6ffff700] DEBUG - MyPlex: mapping state set to 'Mapped - Not Published'.
Mar 27, 2021 14:25:09.456 [0x7fbc6ffff700] DEBUG - MyPlex: sendMapping resetting state - previous mapping state: 'Mapped - Not Published'.
Mar 27, 2021 14:25:09.456 [0x7fbc6ffff700] DEBUG - MyPlex: mapping state set to 'Unknown'.
Mar 27, 2021 14:25:09.456 [0x7fbc7f7fe700] DEBUG - Completed: [192.168.254.1:39353] 200 GET /identity (8 live) TLS GZIP 42ms 449 bytes
Mar 27, 2021 14:25:09.458 [0x7fbc6ffff700] DEBUG - MyPlex: Sending Server Info to myPlex (user=scott@x.x.x, ip=, port=32400)
Mar 27, 2021 14:25:09.458 [0x7fbc6ffff700] DEBUG - HTTP requesting POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx
Mar 27, 2021 14:25:09.652 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:09.652 [0x7fbbf37fe700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (7 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:09.652 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (7 live) TLS GZIP 0ms 3229 bytes (pipelined: 61)
Mar 27, 2021 14:25:09.695 [0x7fbc6ffff700] DEBUG - HTTP 201 response from POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx
Mar 27, 2021 14:25:09.695 [0x7fbc6ffff700] DEBUG - MyPlex: Published Mapping State response was 201
Mar 27, 2021 14:25:09.696 [0x7fbc6ffff700] DEBUG - MyPlex: Got response for 4a85a4d49cef8ee61d7906044e41aab0a1585a46 ~ registered xx.xxx.xx.xx:32400
Mar 27, 2021 14:25:09.696 [0x7fbc6ffff700] DEBUG - MyPlex: updating mapped state - current state: 'Mapped - Not Published'
Mar 27, 2021 14:25:09.696 [0x7fbc6ffff700] DEBUG - MyPlex: mapping state set to 'Mapped - Publishing'.
Mar 27, 2021 14:25:09.696 [0x7fbc6ffff700] DEBUG - MyPlex: async reachability check - current mapped state: 'Mapped - Publishing'.
Mar 27, 2021 14:25:09.696 [0x7fbc6ffff700] DEBUG - MyPlex: Requesting reachability check.
Mar 27, 2021 14:25:09.696 [0x7fbc6ffff700] DEBUG - HTTP requesting PUT https://plex.tv/api/servers/4a85a4d49cef8ee61d7906044e41aab0a1585a46/connectivity?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&asyncIdentifier=d4f4570b-de1f-4f64-8cdd-12f2372ecb84
Mar 27, 2021 14:25:09.834 [0x7fbc6ffff700] DEBUG - HTTP 200 response from PUT https://plex.tv/api/servers/4a85a4d49cef8ee61d7906044e41aab0a1585a46/connectivity?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&asyncIdentifier=d4f4570b-de1f-4f64-8cdd-12f2372ecb84
Mar 27, 2021 14:25:09.835 [0x7fbc6ffff700] DEBUG - MyPlex: Updating device connections (from timer: 0)
Mar 27, 2021 14:25:09.835 [0x7fbc6ffff700] DEBUG - HTTP requesting PUT https://plex.tv/devices/4a85a4d49cef8ee61d7906044e41aab0a1585a46?Connection[][uri]=http://192.168.254.2:32400&Connection[][uri]=http://192.168.254.2:32400&httpsEnabled=1&httpsRequired=0&dnsRebindingProtection=0&natLoopbackSupported=1&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Mar 27, 2021 14:25:09.977 [0x7fbc6ffff700] DEBUG - HTTP 200 response from PUT https://plex.tv/devices/4a85a4d49cef8ee61d7906044e41aab0a1585a46?Connection[][uri]=http://192.168.254.2:32400&Connection[][uri]=http://192.168.254.2:32400&httpsEnabled=1&httpsRequired=0&dnsRebindingProtection=0&natLoopbackSupported=1&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Mar 27, 2021 14:25:10.029 [0x7fbc7effd700] DEBUG - Request came in with unrecognized domain / IP 'xx.xxx.xx.xx' in header Host; treating as non-local
Mar 27, 2021 14:25:10.029 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:10.030 [0x7fbc7d7fa700] DEBUG - Request: [192.168.254.1:58376 (Allowed Network (Subnet))] GET /media/providers (8 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:10.032 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.1:58376] 200 GET /media/providers (8 live) TLS GZIP 2ms 4935 bytes (pipelined: 1)
Mar 27, 2021 14:25:10.152 [0x7fbc7f7fe700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:10.152 [0x7fbc25ffb700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (8 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:10.153 [0x7fbc7f7fe700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (8 live) TLS GZIP 0ms 3286 bytes (pipelined: 62)
Mar 27, 2021 14:25:11.215 [0x7fbc7effd700] DEBUG - EventSource: Got event [data] '<Message address="xx.xxx.xx.xx" port="32400" asyncIdentifier="d4f4570b-de1f-4f64-8cdd-12f2372ecb84" connectivity="0" command="notifyConnectivity"/>'
Mar 27, 2021 14:25:11.215 [0x7fbc7effd700] DEBUG - PubSub: Got notified of reachability for async identifier d4f4570b-de1f-4f64-8cdd-12f2372ecb84: 0 for xx.xxx.xx.xx:32400 (responded in 1380 ms)
Mar 27, 2021 14:25:11.215 [0x7fbc7effd700] DEBUG - MyPlex: reachability check - current mapping state: 'Mapped - Publishing'.
Mar 27, 2021 14:25:11.215 [0x7fbc7effd700] DEBUG - MyPlex: mapping state set to 'Mapped - Not Published (Not Reachable)'.
Mar 27, 2021 14:25:11.217 [0x7fbc7effd700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:11.217 [0x7fbc25ffb700] DEBUG - Request: [192.168.254.241:52695 (Allowed Network (Subnet))] GET /myplex/account (8 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:11.217 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:52695] 200 GET /myplex/account (8 live) TLS GZIP 0ms 3295 bytes (pipelined: 63)
Mar 27, 2021 14:25:13.496 [0x7fbc7effd700] DEBUG - Completed: [192.168.254.241:52678] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (8 live) TLS GZIP 20000ms 5 bytes (pipelined: 47)
Mar 27, 2021 14:25:13.506 [0x7fbc7f7fe700] DEBUG - Auth: authenticated user 1 as ScottishB
Mar 27, 2021 14:25:13.506 [0x7fbbf37fe700] DEBUG - Request: [192.168.254.241:52678 (Allowed Network (Subnet))] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (8 live) TLS GZIP Signed-in Token (ScottishB)
Mar 27, 2021 14:25:13.506 [0x7fbbf37fe700] DEBUG - Content-Length is -1 (of total: -1).
Mar 27, 2021 14:25:14.401 [0x7fbc257fa700] DEBUG - HTTP requesting GET https://plex.tv/services/pubsub/servers
Mar 27, 2021 14:25:14.555 [0x7fbc257fa700] DEBUG - HTTP 200 response from GET https://plex.tv/services/pubsub/servers
9 
Mar 27, 2021 14:25:09.400 [0x7fbc6ffff700] DEBUG - NAT: UPnP, usable device <http://192.168.254.1:2189/rootDesc.xml> with private address <192.168.254.2>.
Mar 27, 2021 14:25:09.401 [0x7fbc6ffff700] DEBUG - NAT: UPnP, public address is xx.xxx.xx.xx

This does look good to me.

What does Pfsense show?

This is my current table. Notice there is one non-expired entry at this moment.

Screenshot from 2021-03-27 11-15-22
Screenshot from 2021-03-27 11-15-221160×417 40.8 KB

10

I don’t remember why these were created. They might be obsolete now in pfSense 2.5.

Screenshot from 2021-03-27 11-19-21
Screenshot from 2021-03-27 11-19-21882×389 36.4 KB

14

Hey ChuckPa.
I found the issue. After a lot of mucking around i tried to use an open port checker (https://portchecker.co/) which told me that my port 32400 on my WAN IP was closed. I found that weird as my pfsense was telling me it was open.

So i changed the NAT to point to routerip:80 and then checked the port again - open… WTF?

Flipped the NAT back and thought why is this and i remembered that, due to Qnap having that qsnatch issue they recommended blocking access to the server via an ACL to anything other than Local IP’s.

And here’s where i forgot about Plex. So my plex was being blocked on my NAS by an ACL preventing the external IP hitting it. As soon as i cleared that i checked if the port was open again and - it was.

Plex popped back into life moments later.

Thank you very much for all your help however, really appreciated your input.

Many Thanks

15

Thank you for letting me know about that one.

I never saw the announcement from QNAP.

(what I get for being behind a pfsense for such a long time)

16

I am having the same problem. It started basically around the first of June. I hadn’t made any changes to my configuration and it had worked for over a year.

I have tried everything I could read on the forums including assigning a static IP to the NAS and enabling port forwarding.

I thought the issue might be the My Cloud Home I was using, so I got a new NAS Synology DS920+ (I needed the capacity anyway, so it was a good excuse).

I set up the new NAS and loaded some files, and it still is doing the same behavior.

I’ve uploaded the logs, and I am sure it is way more than what is needed, but I am not sure what exactly is helpful.

Help??

Thanks,
Paul
Plex Media Server Logs_2021-06-22_09-18-52.zip (954.8 KB)

17

Did you try the portchecker website to see if the port is open?

If not do that first.

Then if its closed, change the NAT on your router to point to your Routers IP address (internal) and port 80 as opposed to your Plex IP and port 32400.

That should then allow you to brose to your public IP and get your routers login page as if you were browsing to it internally.

Obviously you do NOT want that left up so only do this for testing but it’ll be fine for 5 mins or so as you test.

If that works then your router is NAT’ing properly so that points to your NAS as the issue, maybe a firewall etc, so change your NAT to your NAS IP and port 80 so you get the NAS login page etc.

Find out what you can get to and where the access stops.

18

I actually can’t figure out how to change the NAT on the router. I have an Orbi. I did try portchecker and it said every port I tried was closed.

I can say that every other service works, except Plex. Meaning my PS4 works; I can access the NAS remotely and browse files. It really seems to be limited to Plex not working

19

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