Network problems, closed sockets, and a bit of plex relay
fail
Oct 06, 2019 18:37:15.198 [6100] DEBUG - PublicAddressManager: Mapping failed.
Oct 06, 2019 18:45:29.926 [1604] DEBUG - Failed to stream media, client probably disconnected after 103972864 bytes: 10054 - An existing connection was forcibly closed by the remote host
Oct 06, 2019 18:53:38.373 [2076] DEBUG - EventSource: Failure in ReadData (53 - The network path was not found).
Oct 06, 2019 18:53:38.415 [2552] DEBUG - Jobs: 'C:\Program Files (x86)\Plex\Plex Media Server\PlexRelay.exe' exit code for process 12316 is 255 (failure)
Oct 06, 2019 18:55:57.231 [2076] DEBUG - Failed to stream media, client probably disconnected after 7405568 bytes: 10054 - An existing connection was forcibly closed by the remote host
Oct 06, 2019 18:59:39.714 [8688] DEBUG - Jobs: 'C:\Program Files (x86)\Plex\Plex Media Server\PlexRelay.exe' exit code for process 11296 is 255 (failure)
Oct 06, 2019 19:08:33.225 [2076] DEBUG - Failed to stream media, client probably disconnected after 5324800 bytes: 10054 - An existing connection was forcibly closed by the remote host
Oct 06, 2019 19:10:12.718 [2076] DEBUG - Failed to stream media, client probably disconnected after 1458176 bytes: 10054 - An existing connection was forcibly closed by the remote host
Oct 07, 2019 00:34:00.965 [1604] DEBUG - Failed to stream media, client probably disconnected after 4980736 bytes: 10054 - An existing connection was forcibly closed by the remote host
Oct 07, 2019 00:34:30.991 [2076] DEBUG - Failed to stream media, client probably disconnected after 82509824 bytes: 10054 - An existing connection was forcibly closed by the remote host
Oct 07, 2019 21:03:50.487 [1604] DEBUG - Failed to stream media, client probably disconnected after 3735552 bytes: 10054 - An existing connection was forcibly closed by the remote host
Oct 07, 2019 21:04:02.024 [1604] DEBUG - Failed to stream media, client probably disconnected after 147456 bytes: 10054 - An existing connection was forcibly closed by the remote host
relay
Oct 06, 2019 18:53:38.397 [7560] INFO - [PlexRelay] Connection reset by 172.105.99.147 port 443
Oct 06, 2019 18:53:38.415 [2552] DEBUG - Jobs: 'C:\Program Files (x86)\Plex\Plex Media Server\PlexRelay.exe' exit code for process 12316 is 255 (failure)
Oct 06, 2019 18:54:37.023 [2076] DEBUG - EventSource: Got event [data] '<Message host="172.105.6.176" port="443" command="startRelay"/>'
Oct 06, 2019 18:54:37.024 [2076] DEBUG - Relay: reused an existing key for https://downloads.plex.tv/relay/relay_v1.pub
Oct 06, 2019 18:54:37.024 [2076] DEBUG - Relay: starting relay.
Oct 06, 2019 18:54:37.025 [2076] DEBUG - Job running: PLEXTOKEN='xxxxxxxxxxxxxxxxxxxx' C:\Program Files (x86)\Plex\Plex Media Server\PlexRelay.exe -p 443 -N -R 0:127.0.0.1:32401 -o StrictHostKeyChecking=yes -o "UserKnownHostsFile=C:\Users\ajarr\AppData\Local\Plex Media Server\Cache\relayHostKey.txt" -o NoneSwitch=yes -o NoneEnabled=yes -o LogLevel=VERBOSE -o PreferredAuthentications=password -o PubkeyAuthentication=no -l ajarrell1029 172.105.6.176
Oct 06, 2019 18:54:38.225 [6728] DEBUG - [PlexRelay] Authenticated to 172.105.6.176 ([172.105.6.176]:443).
Oct 06, 2019 18:54:38.420 [13408] ERROR - [PlexRelay] kex protocol error: type 7 seq 11
Oct 06, 2019 18:54:38.899 [6728] INFO - [PlexRelay] Allocated port 13243 for remote forward to 127.0.0.1:32401
Oct 06, 2019 18:57:17.285 [12964] DEBUG - Relay: cleaning up inactive relay connection to 172.105.99.147
Oct 06, 2019 18:59:39.692 [11688] DEBUG - [PlexRelay] Transferred: sent 2872, received 3972 bytes, in 301.5 seconds
Oct 06, 2019 18:59:39.706 [10648] DEBUG - [PlexRelay] Bytes per second: sent 9.5, received 13.2
Oct 06, 2019 18:59:39.714 [8688] DEBUG - Jobs: 'C:\Program Files (x86)\Plex\Plex Media Server\PlexRelay.exe' exit code for process 11296 is 255 (failure)
completed after connection closed
Oct 07, 2019 21:01:17.794 [2076] DEBUG - NotificationStream: Removing because of error
Oct 07, 2019 21:03:58.984 [2076] DEBUG - NotificationStream: Removing because of error
Oct 07, 2019 21:01:17.794 [2076] DEBUG - Completed after connection close: [127.0.0.1:61728] -3 GET /:/websockets/notifications (4 live) GZIP 5ms 0 bytes
Oct 07, 2019 21:02:32.006 [1604] DEBUG - Completed after connection close: [192.168.1.12:51698] 200 GET /playlists (13 live) TLS GZIP Page 0-89 6ms 0 bytes (pipelined: 2)
Oct 07, 2019 21:03:27.186 [1604] DEBUG - Completed after connection close: [192.168.1.12:51764] 200 GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (13 live) TLS GZIP 12ms 0 bytes (pipelined: 12)
Oct 07, 2019 21:03:37.186 [1604] DEBUG - Completed after connection close: [192.168.1.12:51772] 200 GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (14 live) TLS GZIP 22ms 0 bytes (pipelined: 4)
Oct 07, 2019 21:03:47.169 [1604] DEBUG - Completed after connection close: [192.168.1.12:51766] 200 GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (13 live) TLS GZIP 10ms 0 bytes (pipelined: 11)
Oct 07, 2019 21:03:50.487 [1604] DEBUG - Completed after connection close: [192.168.1.12:51776] 206 GET /library/parts/5122/1566132984/file.mp4?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (15 live) TLS 52087ms 3735552 bytes (range: bytes=0-)
Oct 07, 2019 21:03:57.106 [2076] DEBUG - Completed after connection close: [192.168.1.12:51778] 200 GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (21 live) TLS GZIP 9ms 0 bytes (pipelined: 2)
Oct 07, 2019 21:03:58.984 [2076] DEBUG - Completed after connection close: [127.0.0.1:62213] -3 GET /:/websockets/notifications (20 live) GZIP 7978ms 863 bytes
Oct 07, 2019 21:04:02.025 [1604] DEBUG - Completed after connection close: [192.168.1.12:51790] 206 GET /library/parts/5122/1566132984/file.mp4?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (16 live) TLS 1332ms 147456 bytes (range: bytes=3331729-)
Oct 07, 2019 21:04:07.214 [2076] DEBUG - Completed after connection close: [192.168.1.12:51780] 200 GET /:/timeline?bandwidth=608&bufferedTime=-1&containerKey=%2FplayQueues%2F70&duration=4914443&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (13 live) TLS GZIP 10ms 0 bytes (pipelined: 2)
Oct 07, 2019 21:04:09.788 [2076] DEBUG - Completed after connection close: [192.168.1.12:51784] 200 GET /:/timeline?bandwidth=608&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914443&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=playing&time=1194743&timeToFirstFrame=71 (13 live) TLS GZIP 14ms 0 bytes (pipelined: 2)
Oct 07, 2019 21:04:17.188 [1604] DEBUG - Completed after connection close: [192.168.1.12:51788] 200 GET /:/timeline?bandwidth=517&bufferedTime=2&containerKey=%2FplayQueues%2F70&duration=4914443&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=7326&playQueueItemID=69&ratingKey=5213&state=playing&time=1195247 (12 live) TLS GZIP 14ms 0 bytes (pipelined: 2)
- those repeat -
The request to play on the Fire TV occurs here
Oct 07, 2019 21:02:57.913 [7748] DEBUG - Request: [192.168.1.12:51764 (Subnet)] GET /video/:/transcode/universal/decision?audioBoost=100&autoAdjustQuality=0&directPlay=1&directStream=1&directStreamAudio=1&fastSeek=1&hasMDE=1&location=lan&maxVideoBitrate=200000&mediaBufferSize=74944&mediaIndex=0&partIndex=0&path=%2Flibrary%2Fmetadata%2F5213&protocol=*&session=5905531bf5f53743-com-plexapp-android&subtitleSize=100&videoBitrate=200000&videoQuality=100&videoResolution=3840x2160 (15 live) TLS GZIP Signed-in Token (ajarrell1029)
Oct 07, 2019 21:02:57.925 [7748] DEBUG - Streaming Resource: Reached Decision id=5213 codes=(MDE=1000,Direct play OK.) media=(id=5085 part=(id=5122 decision=direct play protocol=* streams=(Video=(id=10241 decision= width=1280 height=714) Audio=(id=10242 decision= channels=0 rate=0))))
Oct 07, 2019 21:02:57.926 [2076] DEBUG - Completed: [192.168.1.12:51764] 200 GET /video/:/transcode/universal/decision?audioBoost=100&autoAdjustQuality=0&directPlay=1&directStream=1&directStreamAudio=1&fastSeek=1&hasMDE=1&location=lan&maxVideoBitrate=200000&mediaBufferSize=74944&mediaIndex=0&partIndex=0&path=%2Flibrary%2Fmetadata%2F5213&protocol=*&session=5905531bf5f53743-com-plexapp-android&subtitleSize=100&videoBitrate=200000&videoQuality=100&videoResolution=3840x2160 (15 live) TLS GZIP 13ms 2031 bytes (pipelined: 11)
Oct 07, 2019 21:02:58.400 [1604] DEBUG - Auth: authenticated user 1 as ajarrell1029
Oct 07, 2019 21:02:58.401 [7296] DEBUG - Request: [192.168.1.12:51776 (Subnet)] GET /library/parts/5122/1566132984/file.mp4?autoAdjustQuality=0&hasMDE=1&location=lan&mediaBufferSize=74944 (16 live) TLS Signed-in Token (ajarrell1029) (range: bytes=0-)
Oct 07, 2019 21:02:58.504 [7296] DEBUG - Content-Length of Z:\Movies\Horror\D\Darker Than Night (2018)\Darker Than Night.mp4 is 706298102 (of total: 706298102).
Oct 07, 2019 21:03:07.133 [2076] DEBUG - Auth: authenticated user 1 as ajarrell1029
Oct 07, 2019 21:03:07.135 [10264] DEBUG - Request: [192.168.1.12:51772 (Subnet)] GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&location=lan&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (16 live) TLS GZIP Signed-in Token (ajarrell1029)
Oct 07, 2019 21:03:07.139 [10264] DEBUG - Client [5905531bf5f53743-com-plexapp-android] reporting timeline state buffering, progress of 1194743/4914452ms for guid=com.plexapp.agents.imdb://tt5845440?lang=en, ratingKey=5213 url=, key=/library/metadata/5213, containerKey=/playQueues/70, metadataId=5213, source=
Oct 07, 2019 21:03:07.141 [10264] DEBUG - Library item 5224 'The Dead Don't Die' got skipped for account ID 1.
Oct 07, 2019 21:03:07.144 [10264] DEBUG - Play progress on 5213 'Darker Than Night' - got played 1194743 ms by account 1!
Oct 07, 2019 21:03:07.144 [10264] DEBUG - HubCache: Expiring '1/home.continue/1/hubs/en-us/' because event plex.event.play.session.state.update referenced an item the hub contained
Oct 07, 2019 21:03:07.144 [10264] DEBUG - HubCache: Expiring '1/home.continue/1/hubs/en/count=17&excludeFields=summary&excludePlaylists=1&includeEmpty=1&includeExternalMetadata=1&includeFeaturedTags=1&includeStations=1' because event plex.event.play.session.state.update referenced an item the hub contained
Oct 07, 2019 21:03:07.147 [10264] DEBUG - We're going to try to auto-select an audio stream for account 1.
Oct 07, 2019 21:03:07.147 [10264] DEBUG - Selecting best audio stream for part ID 5122 (autoselect: 1 language: en)
Oct 07, 2019 21:03:07.148 [10264] DEBUG - Audio Stream: 10242, Subtitle Stream: -1
Oct 07, 2019 21:03:07.148 [10264] DEBUG - [Now] User is ajarrell1029 (ID: 1)
Oct 07, 2019 21:03:07.149 [10264] DEBUG - [Now] Device is Android (AFTMM).
Oct 07, 2019 21:03:07.150 [10264] DEBUG - [Now] Profile is Android
Oct 07, 2019 21:03:07.150 [10264] DEBUG - [Now] Updated play state for /library/metadata/5213.
Oct 07, 2019 21:03:07.150 [10264] DEBUG - Statistics: (5905531bf5f53743-com-plexapp-android) Reporting active playback in state 2 of type 1 (scrobble: 0) for account 1
Oct 07, 2019 21:03:07.154 [2076] DEBUG - Completed: [192.168.1.12:51772] 200 GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&location=lan&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (16 live) TLS GZIP 20ms 496 bytes (pipelined: 3)
Oct 07, 2019 21:03:07.156 [1604] DEBUG - Auth: authenticated user 1 as ajarrell1029
Oct 07, 2019 21:03:07.156 [7748] DEBUG - Request: [127.0.0.1:62041 (Loopback)] GET /status/sessions (13 live) GZIP Signed-in Token (ajarrell1029)
Oct 07, 2019 21:03:07.156 [7748] DEBUG - [Now] Adding 1 sessions.
Oct 07, 2019 21:03:07.157 [2076] DEBUG - Completed: [127.0.0.1:62041] 200 GET /status/sessions (13 live) GZIP 1ms 350 bytes (pipelined: 1)
Oct 07, 2019 21:03:17.181 [1604] DEBUG - Auth: authenticated user 1 as ajarrell1029
Oct 07, 2019 21:03:17.183 [10264] DEBUG - Request: [192.168.1.12:51766 (Subnet)] GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (13 live) TLS GZIP Signed-in Token (ajarrell1029)
Oct 07, 2019 21:03:17.187 [10264] DEBUG - Client [5905531bf5f53743-com-plexapp-android] reporting timeline state buffering, progress of 1194743/4914452ms for guid=com.plexapp.agents.imdb://tt5845440?lang=en, ratingKey=5213 url=, key=/library/metadata/5213, containerKey=/playQueues/70, metadataId=5213, source=
Oct 07, 2019 21:03:17.191 [10264] DEBUG - Play progress on 5213 'Darker Than Night' - got played 1194743 ms by account 1!
Oct 07, 2019 21:03:17.191 [10264] DEBUG - [Now] User is ajarrell1029 (ID: 1)
Oct 07, 2019 21:03:17.191 [10264] DEBUG - [Now] Device is Android (AFTMM).
Oct 07, 2019 21:03:17.192 [10264] DEBUG - [Now] Profile is Android
Oct 07, 2019 21:03:17.192 [10264] DEBUG - [Now] Updated play state for /library/metadata/5213.
Oct 07, 2019 21:03:17.192 [10264] DEBUG - Statistics: (5905531bf5f53743-com-plexapp-android) Reporting active playback in state 2 of type 1 (scrobble: 0) for account 1
Oct 07, 2019 21:03:17.195 [1604] DEBUG - Auth: authenticated user 1 as ajarrell1029
Oct 07, 2019 21:03:17.195 [2076] DEBUG - Completed: [192.168.1.12:51766] 200 GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (13 live) TLS GZIP 12ms 496 bytes (pipelined: 10)
Oct 07, 2019 21:03:17.196 [8408] DEBUG - Request: [127.0.0.1:62041 (Loopback)] GET /status/sessions (13 live) GZIP Signed-in Token (ajarrell1029)
Oct 07, 2019 21:03:17.196 [8408] DEBUG - [Now] Adding 1 sessions.
Oct 07, 2019 21:03:17.196 [2076] DEBUG - Completed: [127.0.0.1:62041] 200 GET /status/sessions (13 live) GZIP 0ms 350 bytes (pipelined: 2)
Oct 07, 2019 21:03:27.173 [2076] DEBUG - Auth: authenticated user 1 as ajarrell1029
Oct 07, 2019 21:03:27.175 [10264] DEBUG - Request: [192.168.1.12:51764 (Subnet)] GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (13 live) TLS GZIP Signed-in Token (ajarrell1029)
Oct 07, 2019 21:03:27.179 [10264] DEBUG - Client [5905531bf5f53743-com-plexapp-android] reporting timeline state buffering, progress of 1194743/4914452ms for guid=com.plexapp.agents.imdb://tt5845440?lang=en, ratingKey=5213 url=, key=/library/metadata/5213, containerKey=/playQueues/70, metadataId=5213, source=
Oct 07, 2019 21:03:27.183 [10264] DEBUG - Play progress on 5213 'Darker Than Night' - got played 1194743 ms by account 1!
Oct 07, 2019 21:03:27.183 [10264] DEBUG - [Now] User is ajarrell1029 (ID: 1)
Oct 07, 2019 21:03:27.183 [10264] DEBUG - [Now] Device is Android (AFTMM).
Oct 07, 2019 21:03:27.184 [10264] DEBUG - [Now] Profile is Android
Oct 07, 2019 21:03:27.184 [10264] DEBUG - [Now] Updated play state for /library/metadata/5213.
Oct 07, 2019 21:03:27.184 [10264] DEBUG - Statistics: (5905531bf5f53743-com-plexapp-android) Reporting active playback in state 2 of type 1 (scrobble: 0) for account 1
Oct 07, 2019 21:03:27.186 [1604] DEBUG - Completed after connection close: [192.168.1.12:51764] 200 GET /:/timeline?bandwidth=976&bufferedTime=0&containerKey=%2FplayQueues%2F70&duration=4914452&guid=com.plexapp.agents.imdb%3A%2F%2Ftt5845440%3Flang%3Den&key=%2Flibrary%2Fmetadata%2F5213&machineIdentifier=21b8b684f68243eae4b34ed489ad8764218c361b&playbackTime=0&playQueueItemID=69&ratingKey=5213&state=buffering&time=1194743 (13 live) TLS GZIP 12ms 0 bytes (pipelined: 12)
Oct 07, 2019 21:03:27.187 [1604] DEBUG - Auth: authenticated user 1 as ajarrell1029
Oct 07, 2019 21:03:27.187 [8408] DEBUG - Request: [127.0.0.1:62041 (Loopback)] GET /status/sessions (12 live) GZIP Signed-in Token (ajarrell1029)
Oct 07, 2019 21:03:27.188 [8408] DEBUG - [Now] Adding 1 sessions.
Oct 07, 2019 21:03:27.188 [2076] DEBUG - Completed: [127.0.0.1:62041] 200 GET /status/sessions (13 live) GZIP 0ms 350 bytes (pipelined: 3)
It seems to only be able to send 350 bytes at time before buffering. I’m sorry I don’t know why, and the log doesn’t give an error there.