Wrong time used to determine idle sessions

Plex Media Server Desktops & Laptops
1

Server Version: 1.15.3.858
Player Version: 3.83.1

For the past few days I’ve been having some issues which made Plex unusable on my PC.
A stream would start, it would fill the buffer and start playing, but then all follow up requests would fail with a 404 and the stream would eventually stop, once the buffer was played back. You can refresh the page and get a new buffer, but again it wouldn’t go beyond that initial buffer.

After checking that:

  • restarting the Plex Media Server
  • getting the latest Docker image
  • restarting the Docker host
  • restarting the router
  • logout and login again
  • trying different browsers
  • trying different connections (remote, local network, localhost)
  • enable/disable HW accelerated transcoding

I spent some time understanding the server logs and realized that the server is doing something really weird with the logged timestamp, where it would jump into the future by roughly an hour and then come back again.
Aligning this with how Plex will kill idle sessions after 120s, it seems that the Plex Media Server thinks the just recently started stream is idle, due to the time-traveling and will kill it basically on the spot, letting every follow-up request run into 404 and not provide further stream sections.

Here’s the relevant log snippet, notice the time stamp!

Apr 04, 2019 22:05:09.316 [0x7f00cdffb711] DEBUG - Request: [127.0.0.1:48438 (Loopback)] GET /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/0/569.m4s (27 live) GZIP Signed-in
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] DEBUG - Asked for segment 569 from session.
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] DEBUG - Returning segment 569 from session
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] VERBOSE - [IDLE] Adding (0->1) work item http_download - /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/0/569.m4s
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] VERBOSE - [IDLE] * http_download - /:/eventsource/notifications?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx - 5 active item(s)
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] VERBOSE - [IDLE] * http_download - /player/proxy/poll?deviceClass=pc&protocolVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.83.1&X-Plex-Client-Identifier=n2stnznbjxoxlaqgi4q1kd46&X-Plex-Platform=Chrome&X-Plex-Platform-Version=73.0&X-Plex-Sync-Version=2&X-Plex-Device=Windows&X-Plex-Device-Name=Chrome&X-Plex-Device-Screen-Resolution=1920x888%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en - 1 active item(s)
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] VERBOSE - [IDLE] * http_download - /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.93.1&X-Plex-Client-Identifier=shd242hkc4yqkpycn19fdmgr&X-Plex-Platform=Chrome&X-Plex-Platform-Version=73.0&X-Plex-Sync-Version=2&X-Plex-Model=hosted&X-Plex-Device=Windows&X-Plex-Device-Name=Chrome&X-Plex-Device-Screen-Resolution=1920x937%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en - 1 active item(s)
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] VERBOSE - [IDLE] * http_download - /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/0/569.m4s - 1 active item(s)
Apr 04, 2019 22:05:09.317 [0x7f00cdffb711] VERBOSE - [IDLE] * transcoder - h4p8t74asp5agmijh4n5cjas - 1 active item(s)
Apr 04, 2019 22:05:09.318 [0x7f00cdffb711] DEBUG - Content-Length of /transcode/Transcode/Sessions/plex-transcode-h4p8t74asp5agmijh4n5cjas-8701affd-77aa-4d58-ad02-d375eaba9d36/init-stream0.m4s,/transcode/Transcode/Sessions/plex-transcode-h4p8t74asp5agmijh4n5cjas-8701affd-77aa-4d58-ad02-d375eaba9d36/chunk-stream0-00570.m4s is 540527.
Apr 04, 2019 23:02:04.632 [0x7f0121ffb700] DEBUG - Shutting down idle session h4p8t74asp5agmijh4n5cjas (idle time is 180 seconds)
Apr 04, 2019 23:02:04.632 [0x7f0121ffb700] DEBUG - Killing job.
Apr 04, 2019 23:02:04.632 [0x7f0121ffb700] DEBUG - Signalling job ID 4903 with 9
Apr 04, 2019 23:02:04.632 [0x7f0121ffb700] DEBUG - Job was already killed, not killing again.
Apr 04, 2019 23:02:04.632 [0x7f0121ffb700] DEBUG - Stopping transcode session h4p8t74asp5agmijh4n5cjas
Apr 04, 2019 23:02:04.633 [0x7f013ad4f700] DEBUG - Completed: [127.0.0.1:48438] 200 GET /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/0/569.m4s (25 live) GZIP 7ms 540527 bytes (pipelined: 16)
Apr 04, 2019 23:02:04.633 [0x7f013ad4f700] VERBOSE - [IDLE] Removing (1->0) work item http_download - /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/0/569.m4s
Apr 04, 2019 23:02:04.633 [0x7f013ad4f700] VERBOSE - [IDLE] * http_download - /:/eventsource/notifications?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx - 5 active item(s)
Apr 04, 2019 23:02:04.633 [0x7f013ad4f700] VERBOSE - [IDLE] * http_download - /player/proxy/poll?deviceClass=pc&protocolVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.83.1&X-Plex-Client-Identifier=n2stnznbjxoxlaqgi4q1kd46&X-Plex-Platform=Chrome&X-Plex-Platform-Version=73.0&X-Plex-Sync-Version=2&X-Plex-Device=Windows&X-Plex-Device-Name=Chrome&X-Plex-Device-Screen-Resolution=1920x888%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en - 1 active item(s)
Apr 04, 2019 23:02:04.633 [0x7f013ad4f700] VERBOSE - [IDLE] * http_download - /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1&X-Plex-Product=Plex%20Web&X-Plex-Version=3.93.1&X-Plex-Client-Identifier=shd242hkc4yqkpycn19fdmgr&X-Plex-Platform=Chrome&X-Plex-Platform-Version=73.0&X-Plex-Sync-Version=2&X-Plex-Model=hosted&X-Plex-Device=Windows&X-Plex-Device-Name=Chrome&X-Plex-Device-Screen-Resolution=1920x937%2C1920x1080&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en - 1 active item(s)
Apr 04, 2019 23:02:04.633 [0x7f013ad4f700] VERBOSE - [IDLE] * transcoder - h4p8t74asp5agmijh4n5cjas - 1 active item(s)
Apr 04, 2019 23:02:04.634 [0x7f013bd51700] VERBOSE - JobManager: child process with handle 4903 exited
Apr 04, 2019 23:02:04.634 [0x7f013bd51700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 4903 is -9 (signal: Killed)
Apr 04, 2019 23:02:04.635 [0x7f00cdffb711] DEBUG - Cleaning directory for session h4p8t74asp5agmijh4n5cjas (/transcode/Transcode/Sessions/plex-transcode-h4p8t74asp5agmijh4n5cjas-8701affd-77aa-4d58-ad02-d375eaba9d36)
Apr 04, 2019 23:02:04.641 [0x7f0121ffb700] DEBUG - Transcoder: Cleaning old transcode directories.
Apr 04, 2019 23:02:04.644 [0x7f0121ffb700] DEBUG - Transcoder: Cleaning old transcode directory: "/transcode/Transcode/Sessions/plex-transcode-h4p8t74asp5agmijh4n5cjas-8701affd-77aa-4d58-ad02-d375eaba9d36"
Apr 04, 2019 23:02:04.645 [0x7f0121ffb700] DEBUG - Transcoder: Cleaning old transcode directory: "/transcode/Transcode/Sessions/plex-transcode-h4p8t74asp5agmijh4n5cjas-93f4acfe-f32d-4195-b51e-b4e619e0642f"
Apr 04, 2019 23:02:04.645 [0x7f00cdffb711] ERROR - Failed to delete session directory (boost::filesystem::remove: No such file or directory: "/transcode/Transcode/Sessions/plex-transcode-h4p8t74asp5agmijh4n5cjas-8701affd-77aa-4d58-ad02-d375eaba9d36")
Apr 04, 2019 23:02:04.647 [0x7f0121ffb700] DEBUG - Whacked session h4p8t74asp5agmijh4n5cjas, 0 remaining.
Apr 04, 2019 23:02:04.647 [0x7f0121ffb700] DEBUG - Killed 1 idle sessions out of a total of 1.
Apr 04, 2019 23:02:04.655 [0x7f00ed7fa700] DEBUG - Request: [127.0.0.1:48442 (Loopback)] GET /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/1/565.m4s (23 live) GZIP Signed-in
Apr 04, 2019 23:02:04.657 [0x7f013ad4f700] DEBUG - Completed: [127.0.0.1:48442] 404 GET /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/1/565.m4s (23 live) GZIP 1ms 458 bytes (pipelined: 17)
Apr 04, 2019 23:02:04.678 [0x7f00ed7fa700] DEBUG - Request: [127.0.0.1:48438 (Loopback)] GET /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/0/570.m4s (23 live) GZIP Signed-in
Apr 04, 2019 23:02:04.679 [0x7f013ad4f700] DEBUG - Completed: [127.0.0.1:48438] 404 GET /video/:/transcode/universal/dash/h4p8t74asp5agmijh4n5cjas/0/570.m4s (23 live) GZIP 1ms 458 bytes (pipelined: 17)

Am I the only one with this issue? Any ideas how to fix this?

Edit: Potentially related topics:

1 Like
2

I’m quite surprised that no ones else has this issue. :frowning:

In the meantime I have tried additional steps:

  • Setting timezone to UTC in the host didn’t help
  • Reverting to an older Docker image
  • Updating Docker to the latest version
  • Trying the LinuxServer image

Given that two different Docker images show the same issue, rules out that it’s an issue with Docker or the image. Which either leaves the software or the host.

One of the next steps will be to rebuild the VM, maybe even switch from Debian to Ubuntu, just to be sure. I really want this to work again, as Plex is currently unusable to me.
Another route I might investigate a bit are the CIFS share. I read somewhere that those had caused some problems in the past.

Hopefully someone more knowledgeable can help me in figuring out what is going on here.

3

Switched from Docker to native Linux installation, but I’m still experiencing the same issue. Quite frustrating that this only seems to happen to me…

Apr 22, 2019 09:53:40.443 [0x7fa02effd700] DEBUG - NetworkServiceBrowser: found 3 SSDP devices via http://192.168.1.1:5000/rootDesc.xml
Apr 22, 2019 09:53:40.443 [0x7fa02effd700] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.1.1 (Compal Broadband Networks, Inc CH7465LG)
Apr 22, 2019 09:53:40.443 [0x7fa02effd700] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.1.1 (Compal Broadband Networks, Inc CH7465LG)
Apr 22, 2019 09:53:40.443 [0x7fa02effd700] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.1.1 (Compal Broadband Networks, Inc CH7465LG)
Apr 22, 2019 10:49:45.068 [0x7fa02effd700] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://123.45.0.1:32469/DeviceDescription.xml
Apr 22, 2019 10:49:45.068 [0x7fa02effd700] DEBUG - HTTP requesting GET http://123.45.0.1:32469/DeviceDescription.xml
Apr 22, 2019 10:49:45.072 [0x7fa02effd700] DEBUG - HTTP 200 response from GET http://123.45.0.1:32469/DeviceDescription.xml
Apr 22, 2019 10:49:45.073 [0x7fa02effd700] DEBUG - NetworkServiceBrowser: found 1 SSDP devices via http://123.45.0.1:32469/DeviceDescription.xml
Apr 22, 2019 10:49:45.073 [0x7fa02effd700] DEBUG - NetworkServiceBrowser: SSDP arrived: 192.168.1.6 (Plex Media Server: DueNet)
Apr 22, 2019 09:53:41.062 [0x7fa062ffd700] DEBUG - DVR:Grabber: Cleaning up orphaned grabs.
Apr 22, 2019 09:53:41.063 [0x7fa062ffd700] DEBUG - DVR:Grabber: Cleaned up 0 decrepit directories in 0.0 sec.
Apr 22, 2019 09:53:41.064 [0x7fa062ffd700] DEBUG - Activity: registered new activity 5fedb73f-2242-4d10-8c02-ef346df36ac3 - Processing subscriptions
Apr 22, 2019 09:53:41.064 [0x7fa062ffd700] DEBUG - DVR:Subscription: Scheduling subscriptions.
Apr 22, 2019 09:53:41.065 [0x7fa062ffd700] DEBUG - DVR:Subscription: Initialized 0 schedulers.
4

It took me way too long and tried way too many things only to figure out, that my VM host had a wrong time set. Thus the CPU timer sync in the VM sometimes briefly jumped to that time and then self-corrected it back, causing those time jumps. :roll_eyes:

Well I hope that if anyone has a similar issue, they at least will find my post now and don’t have to spend hours searching…

5

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