Platform: Windows 10 x64
PMS version: 1.28.2.6106 (latest)
Plex HTPC version: 1.23.2.3194-7787f5be (latest)
Expected behavior:
Plex Media Server prevents Windows from sleeping when busy - ie. media is playing/scheduled maintenance. This is how it works when accessing PMS using the Android app, the web browser, the Windows app, or the now discontinued ‘Plex Media Player’ app.
Observed behavior:
Having Plex HTPC open and otherwise idle on the ‘Home’ screen appears to be enough to prevent sleep on the machine running PMS. Note this doesn’t happen with the initial Plex HTPC ‘select user’ screen open, PMS only gets ‘insomnia’ once a user is selected. This happens both when PMS and Plex HTPC are running on the same machine, or when Plex HTPC is run on a different machine as well.
This means Plex HTPC needs to be closed after every use as being idle is enough to prevent sleep, which isn’t ideal when running on an HTPC. Returning to the ‘switch user’ screen isn’t enough to prevent it.
Here are the results of powercfg /requests on the system running PMS when Plex HTPC is open and idle on the Home screen:
C:\WINDOWS\system32>powercfg /requests
DISPLAY:
None.
SYSTEM:
[PROCESS] \Device\HarddiskVolume4\Program Files (x86)\Plex\Plex Media Server\Plex Media Server.exe
AWAYMODE:
[PROCESS] \Device\HarddiskVolume4\Program Files (x86)\Plex\Plex Media Server\Plex Media Server.exe
EXECUTION:
None.
PERFBOOST:
None.
ACTIVELOCKSCREEN:
None.
And here are the results after Plex HTPC is closed, and with Plex open in a web browser or the Android web app (but without any media playing).
C:\WINDOWS\system32>powercfg /requests
DISPLAY:
None.
SYSTEM:
None.
AWAYMODE:
None.
EXECUTION:
None.
PERFBOOST:
None.
ACTIVELOCKSCREEN:
None.
Verbose debug logging on PMS appears to show a request for /player/proxy/poll from Plex HPTC that seems to trigger this:
Aug 25, 2022 13:35:29.377 [1872] DEBUG - Request: [xxx.xxx.xxx.xxx:10297 (Subnet)] GET /player/proxy/poll?xxxxx
Aug 25, 2022 13:35:29.378 [1872] DEBUG - [Req#54e3/CompanionProxy] registered new player: xxxxxxxxx (xxx.xxx.xxx.xxx)
Aug 25, 2022 13:35:29.378 [1872] VERBOSE - [IDLE] Adding (0->1) work item http_download - /player/proxy/poll?xxxxx
Aug 25, 2022 13:35:29.378 [1872] VERBOSE - [IDLE] Server is now active
Aug 25, 2022 13:35:29.378 [1872] VERBOSE - [IDLE] * http_download - /player/proxy/poll?xxxxx - 1 active item(s)
The request then keeps PMS ‘active’ for 20s preventing sleep, before going idle and then immediately becoming ‘active’ again as the request is repeated every 20s while Plex HTPC remains open:
Aug 25, 2022 13:39:29.602 [9668] VERBOSE - LongPoll: Sending data...
Aug 25, 2022 13:39:29.602 [9600] VERBOSE - LongPoll: got onDataRequested, closing connection
Aug 25, 2022 13:39:29.602 [0984] DEBUG - Completed: [xxx.xxx.xxx.xxx:10297] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cplayqueues&timeout=1 (4 live) TLS GZIP 20013ms 5 bytes (pipelined: 13)
Aug 25, 2022 13:39:29.602 [0984] VERBOSE - [IDLE] Removing (1->0) work item http_download - /player/proxy/pollxxxx
Aug 25, 2022 13:39:29.602 [0984] VERBOSE - [IDLE] Server is now idle
Aug 25, 2022 13:39:29.606 [0984] VERBOSE - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 25, 2022 13:39:29.606 [0984] DEBUG - Auth: authenticated user 21738586 as xxxxx
Aug 25, 2022 13:39:29.606 [10708] DEBUG - Request: [xxx.xxx.xxx.xxx:10297 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cplayqueues&timeout=1 (4 live) #a25c TLS GZIP
Aug 25, 2022 13:39:29.606 [10708] VERBOSE - [IDLE] Adding (0->1) work item http_download - /player/proxy/poll?xxxx
Aug 25, 2022 13:39:29.606 [10708] VERBOSE - [IDLE] Server is now active
Aug 25, 2022 13:39:29.606 [10708] VERBOSE - [IDLE] * http_download - /player/proxy/poll?xxx - 1 active item(s)
Aug 25, 2022 13:39:29.606 [10708] DEBUG - Content-Length is -1 (of total: -1).
Aug 25, 2022 13:39:33.590 [9600] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:39:39.560 [9600] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:39:43.599 [9600] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:39:49.561 [0984] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:39:49.612 [11100] VERBOSE - LongPoll: Sending data...
Aug 25, 2022 13:39:49.613 [0984] VERBOSE - LongPoll: got onDataRequested, closing connection
Aug 25, 2022 13:39:49.613 [9600] DEBUG - Completed: [xxx.xxx.xxx.xxx:10297] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cplayqueues&timeout=1 (4 live) TLS GZIP 20006ms 5 bytes (pipelined: 14)
Aug 25, 2022 13:39:49.613 [9600] VERBOSE - [IDLE] Removing (1->0) work item http_download - /player/proxy/pollxxxx
Aug 25, 2022 13:39:49.613 [9600] VERBOSE - [IDLE] Server is now idle
Aug 25, 2022 13:39:49.635 [9600] VERBOSE - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 25, 2022 13:39:49.635 [9600] DEBUG - Auth: authenticated user 21738586 as HTPC
Aug 25, 2022 13:39:49.636 [10708] DEBUG - Request: [xxx.xxx.xxx.xxx:10297 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cplayqueues&timeout=1 (4 live) #a25d TLS GZIP
Aug 25, 2022 13:39:49.636 [10708] VERBOSE - [IDLE] Adding (0->1) work item http_download - /player/proxy/poll?xxxx
Aug 25, 2022 13:39:49.636 [10708] VERBOSE - [IDLE] Server is now active
Aug 25, 2022 13:39:49.636 [10708] VERBOSE - [IDLE] * http_download - /player/proxy/poll?xxxx - 1 active item(s)
Aug 25, 2022 13:39:49.636 [10708] DEBUG - Content-Length is -1 (of total: -1).
Aug 25, 2022 13:39:53.611 [0984] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:39:59.576 [9600] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:40:01.440 [9668] DEBUG - EPG[xmltv]: Next thing to start/end is at 2022-08-25 13:45:00 (in 300 seconds)
Aug 25, 2022 13:40:03.626 [9600] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:40:09.581 [9600] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:40:09.653 [11100] VERBOSE - LongPoll: Sending data...
Aug 25, 2022 13:40:09.653 [9600] VERBOSE - LongPoll: got onDataRequested, closing connection
Aug 25, 2022 13:40:09.653 [0984] DEBUG - Completed: [xxx.xxx.xxx.xxx:10297] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cplayqueues&timeout=1 (4 live) TLS GZIP 20017ms 5 bytes (pipelined: 15)
Aug 25, 2022 13:40:09.653 [0984] VERBOSE - [IDLE] Removing (1->0) work item http_download - /player/proxy/poll?xxxx
Aug 25, 2022 13:40:09.653 [0984] VERBOSE - [IDLE] Server is now idle
Aug 25, 2022 13:40:09.658 [0984] VERBOSE - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Aug 25, 2022 13:40:09.658 [0984] DEBUG - Auth: authenticated user 21738586 as xxxx
Aug 25, 2022 13:40:09.658 [10708] DEBUG - Request: [xxx.xxx.xxx.xxx:10297 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cplayqueues&timeout=1 (4 live) #a260 TLS GZIP
Aug 25, 2022 13:40:09.658 [10708] VERBOSE - [IDLE] Adding (0->1) work item http_download - /player/proxy/poll?xxxx
Aug 25, 2022 13:40:09.658 [10708] VERBOSE - [IDLE] Server is now active
Aug 25, 2022 13:40:09.658 [10708] VERBOSE - [IDLE] * http_download - /player/proxy/poll?xxxxx - 1 active item(s)
Aug 25, 2022 13:40:09.658 [10708] DEBUG - Content-Length is -1 (of total: -1).
Once Plex HTPC is closed, and the last request to /player/proxy/poll completes it then returns to an idle state:
Aug 25, 2022 13:40:29.664 [11100] VERBOSE - LongPoll: Sending data...
Aug 25, 2022 13:40:29.664 [0984] VERBOSE - LongPoll: got onDataRequested, closing connection
Aug 25, 2022 13:40:29.664 [9600] DEBUG - Completed: [xxx.xxx.xxx.xxx:10297] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cplayqueues&timeout=1 (3 live) TLS GZIP 20006ms 5 bytes (pipelined: 16)
Aug 25, 2022 13:40:29.664 [9600] VERBOSE - [IDLE] Removing (1->0) work item http_download - /player/proxy/poll?xxxxx
Aug 25, 2022 13:40:29.664 [9600] VERBOSE - [IDLE] Server is now idle
Aug 25, 2022 13:40:29.664 [0984] VERBOSE - Didn't receive a request from xxx.xxx.xxx.xxx:10297: stream truncated
Aug 25, 2022 13:40:33.654 [0984] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:40:34.380 [9668] DEBUG - player xxxx was last refreshed 10 seconds ago
Aug 25, 2022 13:40:43.669 [0984] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:40:44.394 [9668] DEBUG - player xxxx was last refreshed 20 seconds ago
Aug 25, 2022 13:40:53.685 [0984] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:40:54.405 [9668] DEBUG - player xxxx was last refreshed 30 seconds ago
Aug 25, 2022 13:41:03.692 [0984] VERBOSE - WebSocket: processed 1 frame(s)
Aug 25, 2022 13:41:04.410 [9668] DEBUG - player xxxx was last refreshed 40 seconds ago
Aug 25, 2022 13:41:04.410 [9668] DEBUG - player xxxx was not refreshed for over 30 seconds, dropping it.
I’m reluctant to post full debug logs on a public forum as it appears to contain usernames/addresses/library information/machine names etc. Hopefully I’ve picked out enough relevant info though to show whats going wrong.
