PMP stops playback at exactly the same moment every time, after two and a half minutes and does not resume. All videos are the same. Only this one laptop is affected.
The player is Mac PMP Version 3.104.2
The server is Ubunutu 1.16.5.1554
Connected via 5GHz wifi. DLNA is not enabled. Video is reported as direct play in the dashboard. Have tested ethernet as well, with wifi turned off and same behaviour.
The problem does not occur in a web browser on the same machine, only with PMP. I have tried deleting all of the configuration files and reinstalling PMP and it is still the same. The problem does not occur when testing the same version of PMP on another machine on the same wifi network with the same configuration.
I have also tested Plex Version 1.3.0.910-77ef46d6 and it does the same thing. I have also tested download the video via python web server on port 32400 after turning off PMS and it downloads as expected.
Sep 13, 2019 10:57:56.395 [0x7fc541d7e700] INFO - Plex Media Server v1.16.5.1554-1e5ff713d - Ubuntu PC x86_64 - build: linux-x86_64 debian - GMT 00:00
Sep 13, 2019 10:57:56.395 [0x7fc541d7e700] INFO - Linux version: 18.04.3 LTS (Bionic Beaver), language: C
Sep 13, 2019 10:57:56.395 [0x7fc541d7e700] INFO - Processor Intel(R) Core(TM) i5-8400 CPU @ 2.80GHz
Sep 13, 2019 10:57:56.395 [0x7fc541d7e700] INFO - /usr/lib/plexmediaserver/Plex Media Server
Sep 13, 2019 10:57:56.453 [0x7fc54bc2c740] INFO - OCSP: Successfully retrieved response from cache.
Sep 13, 2019 10:57:58.031 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=1): Cannot begin transaction. database is locked
Sep 13, 2019 10:57:58.094 [0x7fc5117fa700] WARN - [Preferences] No update channels loaded, so showing the previously-selected channel, labelled 'unknown' since we don't really know the name.
Sep 13, 2019 10:57:58.270 [0x7fc513fff700] ERROR - Error response for update: 3 (Agent does not handle the given media type).
Sep 13, 2019 10:57:58.274 [0x7fc53affd700] ERROR - Error response for update: 3 (Agent does not handle the given media type).
Sep 13, 2019 10:57:58.312 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=2): Cannot begin transaction. database is locked
Sep 13, 2019 10:57:58.874 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=3): Cannot begin transaction. database is locked
Sep 13, 2019 10:57:59.245 [0x7fc540d7c700] WARN - Crash: Crash reporting disabled
Sep 13, 2019 10:57:59.360 [0x7fc5117fa700] INFO - AutoUpdate: no updates available
Sep 13, 2019 10:57:59.998 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=4): Cannot begin transaction. database is locked
Sep 13, 2019 10:58:00.638 [0x7fc50a7fc700] INFO - AutoUpdate: no updates available
Sep 13, 2019 10:58:01.246 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=5): Cannot begin transaction. database is locked
Sep 13, 2019 10:58:01.743 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=6): Cannot begin transaction. database is locked
Sep 13, 2019 10:58:02.046 [0x7fc52bfff700] WARN - Sync: Couldn't get sync lists without subscription.
Sep 13, 2019 10:58:02.736 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=7): Cannot begin transaction. database is locked
Sep 13, 2019 10:58:03.722 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=8): Cannot begin transaction. database is locked
Sep 13, 2019 10:58:04.694 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=9): Cannot begin transaction. database is locked
Sep 13, 2019 10:58:05.638 [0x7fc512ffd700] ERROR - Failed to begin transaction (../Library/MetadataCollection.cpp:173) (tries=10): Cannot begin transaction. database is locked
Sep 13, 2019 10:58:05.638 [0x7fc512ffd700] ERROR - Fixup 29DatabaseFixupsSyncCollections threw an exception: Cannot begin transaction. database is locked
Sep 13, 2019 10:58:05.639 [0x7fc538ff9700] INFO - Refreshing paths watched by LibraryUpdateManager
Sep 13, 2019 10:58:09.551 [0x7fc510ff9700] ERROR - Error response for update: 3 (Agent does not handle the given media type).
Sep 13, 2019 10:58:16.175 [0x7fc53bfff700] WARN - PubSub: Received notifyConnectivity event with incorrect async identifier (dc4f8de5-8ff6-4934-81c5-247e11436047, expected a54789ba-08f8-4b79-ba40-02df9856877f)
Sep 13, 2019 10:58:25.857 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 10:58:25.857 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
Sep 13, 2019 10:59:51.087 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 10:59:51.087 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
Sep 13, 2019 11:00:36.284 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 11:00:36.284 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
Sep 13, 2019 11:01:23.393 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 11:01:23.393 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
Sep 13, 2019 11:02:08.859 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 11:02:08.859 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
Sep 13, 2019 11:02:54.121 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 11:02:54.121 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
Sep 13, 2019 11:03:49.856 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 11:03:49.856 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
Sep 13, 2019 11:04:45.134 [0x7fc5297fa700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 11:04:45.134 [0x7fc5297fa700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
The verbose log ends with the following:
{
"type": "log:message",
"level": 4,
"message": "[Player] Timeline, {\n \"ratingKey\": \"39647\",\n \"key\": \"/library/metadata/39647\",\n \"playbackTime\": 94684,\n \"playQueueItemID\": \"10369\",\n \"state\": \"playing\",\n \"hasMDE\": 1,\n \"time\": 99000,\n \"duration\": 2546000\n}",
"time": "2019-09-13T11:28:02.137Z"
},
{
"type": "ajax",
"url": "https://192-168-1-125.080cd58547b88b7a486aa6fe9f5030f5.plex.direct:32400/:/timeline?ratingKey=39647&key=%2Flibrary%2Fmetadata%2F39647&playbackTime=94684&playQueueItemID=10369&state=playing&hasMDE=1&time=99000&duration=2546000&X-Plex-Client-Identifier=0bzgpvte29y3bqzsg3rrwrah&X-Plex-Device-Screen-Resolution=1280x1176%2C2560x1600&X-Plex-Version=3.104.2&X-Plex-Client-Capabilities=protocols%3Dshoutcast%2Chttp-video%3BvideoDecoders%3Dh264%7Bprofile%3Ahigh%26resolution%3A2160%26level%3A52%7D%3BaudioDecoders%3Dmp3%2Caac%2Cdts%7Bbitrate%3A800000%26channels%3A8%7D%2Cac3%7Bbitrate%3A800000%26channels%3A8%7D&X-Plex-Product=Plex%20Media%20Player&X-Plex-Platform=Konvergo&X-Plex-Platform-Version=2.41.0.1010-286e05db&X-Plex-Device=OSX&X-Plex-Device-Name=MacBook&X-Plex-Model=10.14&X-Plex-Token=TOKEN&X-Plex-Language=en&X-Plex-Text-Format=plain&X-Plex-Session-Identifier=0bzgpvte29y3bqzsg3rrwrah",
"status": 200,
"headers": {
"Accept-Language": "en"
},
"response": "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n<MediaContainer size=\"1\" playbackState=\"progress\" skipCount=\"0\" viewCount=\"0\" viewOffset=\"99000\">\n<Bandwidths>\n<Bandwidth time=\"0\" bandwidth=\"11924\" resolution=\"\" />\n</Bandwidths>\n</MediaContainer>\n",
"time": "2019-09-13T11:28:02.778Z"
},
{
"type": "log:message",
"level": 4,
"message": "[Player] Buffering detected by PMP",
"time": "2019-09-13T11:28:47.641Z"
},
{
"type": "log:message",
"level": 4,
"message": "[Player] Timeline, {\n \"ratingKey\": \"39647\",\n \"key\": \"/library/metadata/39647\",\n \"playbackTime\": 140475,\n \"playQueueItemID\": \"10369\",\n \"state\": \"buffering\",\n \"hasMDE\": 1,\n \"time\": 144000,\n \"duration\": 2546000\n}",
"time": "2019-09-13T11:28:47.648Z"
},
{
"type": "ajax",
"url": "https://192-168-1-125.080cd58547b88b7a486aa6fe9f5030f5.plex.direct:32400/:/timeline?ratingKey=39647&key=%2Flibrary%2Fmetadata%2F39647&playbackTime=140475&playQueueItemID=10369&state=buffering&hasMDE=1&time=144000&duration=2546000&X-Plex-Client-Identifier=0bzgpvte29y3bqzsg3rrwrah&X-Plex-Device-Screen-Resolution=1280x1176%2C2560x1600&X-Plex-Version=3.104.2&X-Plex-Client-Capabilities=protocols%3Dshoutcast%2Chttp-video%3BvideoDecoders%3Dh264%7Bprofile%3Ahigh%26resolution%3A2160%26level%3A52%7D%3BaudioDecoders%3Dmp3%2Caac%2Cdts%7Bbitrate%3A800000%26channels%3A8%7D%2Cac3%7Bbitrate%3A800000%26channels%3A8%7D&X-Plex-Product=Plex%20Media%20Player&X-Plex-Platform=Konvergo&X-Plex-Platform-Version=2.41.0.1010-286e05db&X-Plex-Device=OSX&X-Plex-Device-Name=MacBook&X-Plex-Model=10.14&X-Plex-Token=TOKEN&X-Plex-Language=en&X-Plex-Text-Format=plain&X-Plex-Session-Identifier=0bzgpvte29y3bqzsg3rrwrah",
"status": 200,
"headers": {
"Accept-Language": "en"
},
"response": "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n<MediaContainer size=\"1\" playbackState=\"progress\" skipCount=\"0\" viewCount=\"0\" viewOffset=\"144000\">\n<Bandwidths>\n<Bandwidth time=\"0\" bandwidth=\"11924\" resolution=\"\" />\n</Bandwidths>\n</MediaContainer>\n",
"time": "2019-09-13T11:28:48.244Z"
},
{
"type": "log:message",
"level": 4,
"message": "[Player] Timeline, {\n \"ratingKey\": \"39647\",\n \"key\": \"/library/metadata/39647\",\n \"playbackTime\": 145080,\n \"playQueueItemID\": \"10369\",\n \"state\": \"stopped\",\n \"hasMDE\": 1,\n \"time\": 144000,\n \"duration\": 2546000\n}",
"time": "2019-09-13T11:28:58.865Z"
},
{
"type": "log:message",
"level": 3,
"message": "[Metrics] Updating session last interaction time",
"time": "2019-09-13T11:28:58.870Z"
},
{
"type": "log:message",
"level": 3,
"message": "[Metrics] Updating session last interaction time",
"time": "2019-09-13T11:28:58.871Z"
},
{
"type": "log:message",
"level": 1,
"message": "[Player] Player was closed or a new playback session was started; ignoring callback",
"time": "2019-09-13T11:28:59.563Z"
},
{
"type": "ajax",
"url": "https://192-168-1-125.080cd58547b88b7a486aa6fe9f5030f5.plex.direct:32400/:/timeline?ratingKey=39647&key=%2Flibrary%2Fmetadata%2F39647&playbackTime=145080&playQueueItemID=10369&state=stopped&hasMDE=1&time=144000&duration=2546000&X-Plex-Client-Identifier=080cd58547b88b7a486aa6fe9f5030f5&X-Plex-Device-Screen-Resolution=1280x1176%2C2560x1600&X-Plex-Version=3.104.2&X-Plex-Client-Capabilities=protocols%3Dshoutcast%2Chttp-video%3BvideoDecoders%3Dh264%7Bprofile%3Ahigh%26resolution%3A2160%26level%3A52%7D%3BaudioDecoders%3Dmp3%2Caac%2Cdts%7Bbitrate%3A800000%26channels%3A8%7D%2Cac3%7Bbitrate%3A800000%26channels%3A8%7D&X-Plex-Product=Plex%20Media%20Player&X-Plex-Platform=Konvergo&X-Plex-Platform-Version=2.41.0.1010-286e05db&X-Plex-Device=OSX&X-Plex-Device-Name=MacBook&X-Plex-Model=10.14&X-Plex-Token=TOKEN&X-Plex-Language=en&X-Plex-Text-Format=plain&X-Plex-Session-Identifier=0bzgpvte29y3bqzsg3rrwrah",
"status": 200,
"headers": {
"Accept-Language": "en"
},
"response": "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n<MediaContainer size=\"1\" playbackState=\"progress\" skipCount=\"0\" viewCount=\"0\" viewOffset=\"144000\">\n<Bandwidths>\n<Bandwidth time=\"0\" bandwidth=\"11924\" resolution=\"\" />\n</Bandwidths>\n</MediaContainer>\n",
"time": "2019-09-13T11:28:59.563Z"
},
{
"type": "ajax",
"url": "https://analytics.plex.tv/collect/event",
"status": 200,
"params": "{\"deviceIdentifier\":\"0bzgpvte29y3bqzsg3rrwrah\",\"context\":{\"device\":{\"product\":\"Plex Media Player\",\"version\":\"3.104.2\",\"platform\":\"Konvergo\",\"platformVersion\":\"2.41.0.1010-286e05db\",\"device\":\"OSX\",\"model\":\"10.14\",\"screenResolution\":\"1280x1176,2560x1600\",\"layout\":\"desktop\"}},\"userId\":12264824,\"event\":\"playback:itemend\",\"interaction\":true,\"properties\":{\"serverType\":\"owned\",\"connectionType\":\"local\",\"type\":\"episode\",\"identifier\":\"com.plexapp.plugins.library\",\"page\":\"discover\",\"context\":\"home.continue\",\"auto\":false,\"protocol\":\"http\",\"offset\":0,\"container\":\"mkv\",\"duration\":2520,\"bitrate\":5632,\"audioCodec\":\"ac3\",\"audioDecision\":\"direct\",\"videoCodec\":\"h264\",\"videoDecision\":\"direct\",\"subtitleFormat\":\"srt\",\"subtitleDecision\":\"direct\",\"player\":\"mpv\",\"playbackTime\":120,\"status\":\"stopped\"},\"sessionIdentifier\":\"d5f5754b-3b10-4671-8d1f-e5cfd3e5e6ef\"}",
"time": "2019-09-13T11:29:05.124Z"
},
{
"type": "ajax",
"url": "https://analytics.plex.tv/collect/event",
"status": 200,
"params": "{\"deviceIdentifier\":\"0bzgpvte29y3bqzsg3rrwrah\",\"context\":{\"device\":{\"product\":\"Plex Media Player\",\"version\":\"3.104.2\",\"platform\":\"Konvergo\",\"platformVersion\":\"2.41.0.1010-286e05db\",\"device\":\"OSX\",\"model\":\"10.14\",\"screenResolution\":\"1280x1176,2560x1600\",\"layout\":\"desktop\"}},\"userId\":12264824,\"event\":\"playback:sessionend\",\"interaction\":true,\"properties\":{\"serverType\":\"owned\",\"connectionType\":\"local\",\"type\":\"episode\",\"playbackCount\":1,\"playbackTime\":120},\"sessionIdentifier\":\"d5f5754b-3b10-4671-8d1f-e5cfd3e5e6ef\"}",
"time": "2019-09-13T11:29:06.316Z"
}
]
Edit:
This is interesting, while selecting ‘Download’ on that computer, it opens a browser window and starts downloading the video until it reaches about 200MB. This corresponds with the following reference to sloth mode in the log. Weird that it comes up for downloading when there should be no transcoding happening. It does not happen with the other test machine when downloading.
Sep 13, 2019 20:34:17.421 [0x7f3bebfff700] DEBUG - [Now] Profile is Konvergo
Sep 13, 2019 20:34:17.421 [0x7f3bebfff700] DEBUG - [Now] Updated play state for /library/metadata/39647.
Sep 13, 2019 20:34:17.421 [0x7f3bebfff700] DEBUG - Statistics: (p8r5fxovri9bqhfsm9kd9rud) Reporting active playback in state 2 of type 4 (scrobble: 0) for account 1
Sep 13, 2019 20:34:17.422 [0x7f3c1f7fe700] DEBUG - Completed: [192.168.1.118:51658] 200 GET /:/timeline?ratingKey=39647&key=%2Flibrary%2Fmetadata%2F39647&playbackTime=165525&playQueueItemID=10869&state=buffering&hasMDE=1&time=165000&duration=2546000 (44 live) TLS GZIP 8ms 493 bytes (pipelined: 1)
Sep 13, 2019 20:34:17.426 [0x7f3c1f7fe700] DEBUG - Auth: authenticated user 1 as noirmaru
Sep 13, 2019 20:34:17.426 [0x7f3bf1ffb700] DEBUG - Request: [192.168.1.118:51658 (Subnet)] GET /:/timeline?ratingKey=39647&key=%2Flibrary%2Fmetadata%2F39647&playbackTime=165525&playQueueItemID=10869&state=buffering&hasMDE=1&time=165000&duration=2546000 (44 live) TLS GZIP Signed-in Token (noirmaru)
Sep 13, 2019 20:34:17.427 [0x7f3bf1ffb700] DEBUG - Client [8xx1orb5nap1vdxqdwaw3tyb] reporting timeline state buffering, progress of 165000/2546000ms for guid=, ratingKey=39647 url=, key=/library/metadata/39647, containerKey=, metadataId=39647, source=
Sep 13, 2019 20:34:17.428 [0x7f3bf1ffb700] DEBUG - Play progress on 39647 '' - got played 165000 ms by account 1!
Sep 13, 2019 20:34:17.430 [0x7f3bf1ffb700] DEBUG - [Now] User is noirmaru (ID: 1)
Sep 13, 2019 20:34:17.430 [0x7f3bf1ffb700] DEBUG - [Now] Device is Konvergo (MacBook).
Sep 13, 2019 20:34:17.430 [0x7f3bf1ffb700] DEBUG - [Now] Profile is Konvergo
Sep 13, 2019 20:34:17.430 [0x7f3bf1ffb700] DEBUG - [Now] Updated play state for /library/metadata/39647.
Sep 13, 2019 20:34:17.430 [0x7f3bf1ffb700] DEBUG - Statistics: (p8r5fxovri9bqhfsm9kd9rud) Reporting active playback in state 2 of type 4 (scrobble: 0) for account 1
Sep 13, 2019 20:34:17.431 [0x7f3c1f7fe700] DEBUG - Completed: [192.168.1.118:51658] 200 GET /:/timeline?ratingKey=39647&key=%2Flibrary%2Fmetadata%2F39647&playbackTime=165525&playQueueItemID=10869&state=buffering&hasMDE=1&time=165000&duration=2546000 (44 live) TLS GZIP 4ms 493 bytes (pipelined: 2)
Sep 13, 2019 20:34:17.574 [0x7f3b58ff9700] DEBUG - Transcoder segment range: 30 - 55 (55)
Sep 13, 2019 20:34:20.385 [0x7f3bebfff700] DEBUG - Transcoder segment range: 30 - 56 (56)
Sep 13, 2019 20:34:22.224 [0x7f3bf1ffb700] DEBUG - Transcoder segment range: 30 - 57 (57)
Sep 13, 2019 20:34:24.336 [0x7f3c1f7fe700] DEBUG - Completed: [192.168.1.118:51615] 200 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (44 live) TLS GZIP 20000ms 5 bytes (pipelined: 2)
Sep 13, 2019 20:34:25.167 [0x7f3b59ffb700] DEBUG - Transcoder segment range: 30 - 58 (58)
Sep 13, 2019 20:34:25.894 [0x7f3b5b7fe700] DEBUG - Session 43m80qv6kyadqx7cmacval4k (4) is throttling
Sep 13, 2019 20:34:25.895 [0x7f3b58ff9700] DEBUG - [Transcoder] Throttle - Going into sloth mode.
hmmm, what is up with these curl timeouts to 169.254.51.208
Sep 13, 2019 21:08:22.712 [0x7f3552ffd700] ERROR - Error issuing curl_easy_perform(handle): 28
Sep 13, 2019 21:08:22.712 [0x7f3552ffd700] DEBUG - HTTP simulating 408 after curl timeout
Sep 13, 2019 21:08:22.712 [0x7f3552ffd700] ERROR - SSDP: Error parsing device schema for http://169.254.51.208:49152/description.xml
