Android client causes Plex Media Server to go offline

[knavero]

I’ve tried to follow the instructions on https://support.plex.tv/articles/201643703-reporting-issues-with-plex-media-server/ and I do not believe this is a duplicate. Client and server information, debug-level enabled logs, repro steps all below:

Server Version#: 1.19.5.3112
Player Version#: 8.5.1.19778 (2c9485c3)
OS: Windows 10 Pro, Version 10.0.18362, x64
Plex Media Server Logs_2020-08-24_12-51-57.zip (815.9 KB)

While streaming media remotely using the Android Plex client, the Plex Media Server goes offline. When I try to VPN to the WLAN that the Plex Media Server is supposed to be on, I am unable to ping it. I confirm the disconnect by checking the router’s dashboard. On remotely asking someone else to hard reboot the server, I inspect the system event logs, which seem to suggest no error level entries before the hard reboot. I inspected the Plex Media Server logs (attached with debug level is enabled), and transcoding seems to hit a sudden hard stop, but I couldn’t find anything that suggests the Plex Media Server went offline. I speculate that the server was booted off the network and not allowed back on for some reason, as if the server’s WiFi adapter stops functioning. Alas, I’m remote and can’t investigate what state my server is at when “offline” b.c. it would need to be on the WLAN to RDP to.

WRT reproducibility, I’ve reproduced this three times within the recent month, and zero times before that. In other words, Plex client and server were stable until just recently. I’ve made no major updates to my system AFAIK between the time of stability and instability, except VirtualBox (I run services in a Linux VM concurrently with Plex and Tautulli on the native host). The driver versions have not changed for any hardware. I’ve disabled Plex Media Server and am just running the Linux VM with Tautulli to confirm they are not responsible.

The specifics on reproducibility is complex and unclear. I’ve spent quite the effort trying to nail down the exact reproduction steps to no success. The first time this happened, I reset the playback cursor to earlier points before the Plex Media Server went offline. The second time this happened, I minimized the player, paused playback, expanded the player, and hit play, before the Plex Media Server went offline. The third time this happened, the video was streaming normally with zero interaction, before the Plex Media Server went offline. I have not tried characterizing the behavior using another client type such as web.

I could not find any stacktraces, but I imagine that would be in one of the logs if it’s available.

LMK if I can provide any more information.

[knavero]

After running Tautulli and my Linux VM services for a few days, I’ve convinced myself that it’s most likely Plex Media Server that’s problematic.

I’m going to try to attempt a “release bisect”. Searching the forums, I’ve found that older installers can be located at %LOCALAPPDATA%\Plex Media Server\Updates. I know that 1.19.5.3112 is my current “bad” version, so I’ll try to find a “good” version to start from. From there, I’ll try to converge on the first “bad” version. Since reproduction steps aren’t very well-defined, I imagine this may take a few days if not weeks. Or if I have a good enough version, I may not even continue with the bisect unless there’s a good reason to. I’ll try to start with 1.19.1.2645 as my first “good” version.

[knavero]

Reproduced on server 1.19.1.2645. Debug logs attached: Plex Media Server Logs_2020-08-26_20-14-31.zip (1.0 MB). Going to rollback to 1.18.8.2527-740d4c206 and see if that works.

[sa2000]

The logs show the following:

Version v1.19.5.3112-b23ab3896
Plex Media Server was launched at 03:52 am on August 24
Plex Media Server stopped logging at around 05:00 am on August 24

Plex Media Server was re-launched after this at 12:51 on August 24
Plex Media Server was manually shut down at 12:52 on August 24

Version v1.19.1.2645-ccb6eb67e
Plex Media Server launched at 00:14 am on August 26
Plex Media Server stopped logging at around 03:14 am on August 26

Plex Media Server was re-launched at 20:09:28 on August 26
Plex Media Server was manually shut down at 20:09:35 on August 26

So we have 2 incidents of Plex Media Server activity stopping
There is no indication of any crashes or network failures

I would like to see the Windows System and Application event logs - if you could Open Event Viewer and save all events for each of the System and Application logs and zip the two saved evtx files and send them to me by Private Message

Whilst there is no evidence of a network issue, it is not advisable to run the Plex Media Server on WiFi.

PS: I suggest you run the latest public release which came out today and get next set of logs for that - and please run with debug logging enabled all the time rather than enabled in-flight.

[knavero]

Understood. Thanks for looking at the debug logs. Yeah, I still have debug logging enabled since opening the issue. I didn’t/don’t plan on turning it off. I will try running the latest public release (1.20.1.3252-a78fef9a9) and report back if I’m able to reproduce the issue.

Indeed, you’re right; I do intend on eventually wiring my server to the AP. WiFi, though sub-optimal, has at least uncovered some bizarre regression that I do not experience on server version 1.18.8.

[knavero]

These logs should have had debug logging enabled from the point of starting the server to where it went offline. I apologize for not having debug logging enabled early enough for the logs in my original post.

[knavero]

I forgot to mention in the original post that one of the first things I did was that I checked %SystemRoot% for any dump files which would indicate a crash. There were no dump files.

[sa2000]

I have been looking at the event log - it is looking like windows / PC stopped

The logs showed these two incidents relating to Plex Media Server

Plex Media Server stopped logging after 04:59:56 am on August 24
Plex Media Server stopped logging after 03:15:58 am on August 26

The event logs do show gaps and unexpected shutdowns at these times

Taking the first - the one where seemed to have a crash / stop some time around / after 04:59:56 am on August 24

The Windows Event logs show a gap between 04:59:17 and 05:53:45

and then looking at the second incident where we appeared to have a crash / stop sometime after 03:15:58 am on August 26
Again the windows event logs show a gap between 03:11:42 am and 20:08:05 when it was rebooted

So i would suggest you actually be in front of the PC when the issues arise and actually see if windows is running and see if it is, if a Plex Media Server.exe process is running in Task Manager. If it is running but not logging anything then dump the process and provide it with the logs zip and event logs files zipped

Other points to note:

Event Logs show the windows time drifting and after few hours it is out by 3 or 4 seconds and gets corrected
I picked here examples where the drift was more than 1 second.
It appears to be both ways - either too fast or too slow

I notice a lot of log entries of
The client has sent an activation request to the key management service machine.
I do not know if this indicates any licensing issues that may affect the operation of windows or if it is normal and I am not sure if this log entry is relevant
The KMS-R@1n service terminated with the following error: The parameter is incorrect.

[knavero]

Yeah, some of that actually makes sense. I’ve noted the “unexpected shutdowns” as aligning with when I asked someone at the remote location to hard reboot the machine so that it’ll be seen on the LAN again for me to RDP to it. I believe the KMS entries can be dismissed; I’ve confirmed under Control Panel\System and Security\System at Windows Activation at the bottom that it says “Windows is activated”. The “windows time drift” is unusual to me; I’m not quite sure what the cause behind that behavior is. Alas, I agree - I definitely should be physically in front of the machine when the problem is next reproduced. I will make that a priority to do that and capture the dump of PMS if it is still on the proc table.

On another note, I am able to repro the issue on 1.20.1.3252. Simply streaming a video without interacting with any UI controls for about 30-40 minutes is enough to reproduce the problem. Again, there is not memory dump within %systemroot% indicating any kernel panic. The debug logs are here: Plex Media Server Logs_2020-08-28_15-41-57.zip (1.3 MB), though I imagine it contains nothing new. Either way, they are here for any further confirmation.

Again, thanks for looking at the data I’ve provided.

[sa2000]

@knavero

On another note, I am able to repro the issue on 1.20.1.3252. Simply streaming a video without interacting with any UI controls for about 30-40 minutes is enough to reproduce the problem. Again, there is not memory dump within %systemroot% indicating any kernel panic. The debug logs are here: Plex Media Server Logs_2020-08-28_15-41-57.zip (1.3 MB), though I imagine it contains nothing new. Either way, they are here for any further confirmation.

So similar to earlier cases

An issue arose after Aug 27, 2020 22:59:55.134
and the re-launch was at Aug 28, 2020 15:41:28.157

For each of these issues, one needs to look closely at the windows system and application event logs to look for gaps in time and unexpected shutdowns close to the time

Is this a laptop or a desktop ?

[knavero]

An issue arose after Aug 27, 2020 22:59:55.134

I brought up my Tautulli service to inspect the streaming history. Here’s what I got:

The order of events is something like

1. streaming starts
2. plex media server unexpectedely goes offline in the middle of streaming
3. tautulli is still waiting for events
4. hard reboot, so where it says “unexpected shutdown” in the system event logs, it’s actually, from what I found so far at least, expected
5. RDP to server
6. plex media server starts up automatically
7. exit plex media server
8. tautulli is started again
9. tautulli shows the history as shown above where it thinks streaming has never stopped

and the re-launch was at Aug 28, 2020 15:41:28.157

yeah, that makes sense. I requested someone to hard reboot the server, and I RDP’d to the server a few seconds before that timestamp as shown here:

which gives plex media server some time to start up the service and write the log entry.

That’s as far as I got. Like you mentioned earlier, I do need to inspect the state of the server at the point of repro and before doing a hard reboot. It’d be convenient if when I’m physically near the machine, I can minimally repro the problem within the same LAN. Otherwise, I’ll have to find another network to repro it the way I know how - remote streaming. I’ll report again when I gather information WRT that.

Is this a laptop or a desktop ?

desktop

[knavero]

A quick update on the “release bisect”: currently, I’m convinced 1.18.8.2527 is fine. I’m going to try 1.18.9.2571 to see if that’s stable for me. If it is, then I’ll stay on it for the time being until I’m able to be physically near my server to investigate the problem further (which unfortunately, may not be for awhile). The next release ahead in my %localappdata%\plex media server\updates folder is 1.19.1.2645 which reproduces the “unexpectedly going offline” behavior. If anyone else aside from myself is able to repro this behavior (as seemingly difficult as it is), the git bisect range is between 740d4c206..ccb6eb67e assuming the hashes next to the release name are indeed commit SHAs.

[sa2000]

@knavero

A quick update on the “release bisect”: currently, I’m convinced 1.18.8.2527 is fine. I’m going to try 1.18.9.2571 to see if that’s stable for me.

Until you know why Windows is seizing up - there is no benefit from bisecting versions of Plex Media Server. Even if you come to the conclusion that it is version x of Plex Media Server that is leading to this - this won’t help without knowing why and how Windows is failing

The evidence at the moment is that windows is stopping to run.
For your last failures, see the gaps in time in the consecutive event log entries i highlighted - you will need to subtract 8 hours to match your timezone since Event Viewer resets all times to local timezone

This may be unrelated but I was intrigued by seeing flip-flopping consecutive log entries like these

• The system time has changed to ‎2020‎-‎08‎-‎28T22:58:15.000791000Z from ‎2020‎-‎08‎-‎28T22:58:14.986917600Z.

• The system time has changed to ‎2020‎-‎08‎-‎28T22:58:13.549000000Z from ‎2020‎-‎08‎-‎28T22:58:15.314964100Z.

we went from 22:58:14 to 22:58:15 and back to 22:58:13
Looking to see what it is leading to these adjustments
One came from Program Files\KMSpico\AutoPico.exe' and the other from Windows\System32\svchost.exe'

Found references to AutoPico.exe here AutoPico.exe Windows process - What is it?

Anyway - you need to look into why Windows is ceasing up. If it not a legal copy then anything can happen

[knavero]

Noted. I was going to temporarily stick to an older version of PMS, but 1.18.9 crashed on me several days ago. Which means, despite how useless the release bisect was, it seems, to the best of my knowledge, 1.18.8 was the last release to have behaved without suddenly going offline during streaming (taking into account the nondeterministic OS behavior you’ve mentioned above).

Hm, you bring up a good point. I’ve been overlooking the possibility of KMSpico being an indirect cause to PMS going offline and was convinced that everything was probably fine since, up until recently, PMS was not giving me any major show stopper problems (huh. Unintended pun…). Thanks for reminding me to seriously revisit that thought. Removing KMSpico is easy and will certainly simplify the event logs. Here, I’ll remove it for now to eliminate the log complexity/verbosity.

I appreciate your insights. Thanks again.

[knavero]

Ok, I’m back on 1.20.1.3252. Uninstalled KMSpico which removed the automated daily task off of the scheduler. Going to attempt to break PMS with hopefully some cleaner, less sketchy log history. I’ve cleared both Windows event viewer app/sys logs and %localappdata%\plex media server\logs. I expect zero suspicious log entries and rather something like the “OS just stopped, but nothing in any of the logs is particularly useful” maybe. Which in any case, would obviously still require me to be physically near my machine to investigate what kind of state my machine transitioned to. I guess the point of this exercise is to reduce complexity to exclude out some (KMSpico related, datetime stamp related) speculation. Yeah, we’ll see.

[knavero]

Ok, problem reproduced again on 1.20.1.3252. It took awhile this time (maybe 2 hours) before the problem was reproduced. Windows stopped. Before running the repro steps, I uninstalled KMSpico/autopico and cleared the event/PMS logs before collecting data. Here are the usual logs:

event_logs.zip (133.7 KB)
Plex Media Server Logs_2020-09-02_17-28-15.zip (332.9 KB)

Feel free to take a look, but I imagine it’ll lead to more speculation until I’m physically near the machine.

I noted svchost changing the time again in the event logs, not by much, and not as frequent. The PID it gives in the event description is useless b.c. it’s the PID of the parent process (svchost.exe) composed of several child processes. Also, the nearby logged system events, point to expected time synchronization with time.windows.com at the same timestamp, down to the seconds at least. Also, at the point of the time adjustment, the system is still up for at least 1.5 hours indicated by the alignment to the application events, before stopping with a followup time gap then hard reboot. I think the time gaps are a red herring of sorts. And I’m not really convinced just yet that the OS is operating so non-deterministically that it’s the OS at fault (rather than PMS) for at least several reasons:

1. I’ve proved to, at least myself, this behavior is consistently reproducible and only happens when I’m streaming from PMS from an Android client
2. I’ve left my server running with all my other usual apps, with PMS inactive, for several days, and no problems at the higher application level
3. I was capable of running older versions of PMS (for several years) without this behavior, which most likely should have never worked

I’d obviously very much prefer not to go through the exercise of reapplying backups on a fresh OS. I’ll be very surprised if it comes down to that. Probably won’t even do that for some time.

Huh. I still have some KMS services that still exist in the registry. Let me delete those too. Though, they’ve been in the stopped state.

[knavero]

Alright, I’m finally physically near my machine. I’ve made the change to wire my server to the AP and am running 1.20.1.3252 again. I’m going to try to reproduce the problem locally. If I cannot, I’ll try to use it remotely again hoping everything’s fine. If I’m unable to reproduce it anymore, I’ll let the topic close.

[knavero]

Good news. PMS hasn’t crashed yet on 1.20.1.3252 ever since wiring it in to the AP. I’ve been unable to repro the original issue. My speculation is that PMS 1.20.1.3252 is exposing a bug in my wifi adapter driver, but again, that’s just speculation, so not much value there. Anyway, since it works for me, I guess I’ll just let this ticket close. Thanks for all the help.

[sa2000]

Interesting - thank you for all the feedback. Glad it is ok now