Server version 1.9.7.4441 quits playing before the end of the file.

According to the fix notes for the previous version, this was one of the fixes - which was not a problem I had ever encountered. Overnight the server updated to v1.9.7.4441 and the problem started - to be clear - it was not doing this yesterday.

I’m trying to watch Will and Grace - which are MP4 files encoded with MPEG4 for the video and AAC for the audio - they are therefore requiring transcoding to play on the Chromecast. Episodes are ending early and skipping to the next episode around 60 seconds before the end, replaying the episode and seeking to the part where it skipped will let me see the rest but generally skips to the next episode again around 15 seconds before the file finishes. I’ve tried turning HW transcoding off which hasn’t really made any difference to the problem.

I’ve done a cursory test with a Chromecast friendly MP4 (ie doesn’t require transcoding) which appears to play to the end - but I’ve only tested this by seeking to the end - I haven’t tried watching the entire file - I will give it a go in a bit.

Nov 09, 2017 09:31:32.646 [5004] DEBUG - Auth: authenticated user 1 as asjmcguireplex
Nov 09, 2017 09:31:32.646 [3436] DEBUG - Request: [192.168.2.76:41819 (Subnet)] GET /:/timeline?hasMDE=1&ratingKey=2090&key=%2Flibrary%2Fmetadata%2F2090&state=paused&playQueueItemID=25799&time=1248443&duration=1306272 (7 live) TLS GZIP Signed-in Token (asjmcguireplex)
Nov 09, 2017 09:31:32.647 [3436] DEBUG - Client [96nlluze9mix641tum5i48zf] reporting timeline state paused, progress of 1248443/1306272ms for guid=, ratingKey=2090 url=, key=/library/metadata/2090, containerKey=, metadataId=2090
Nov 09, 2017 09:31:32.649 [3436] DEBUG - [Now] User is asjmcguireplex (ID: 1)
Nov 09, 2017 09:31:32.650 [3436] DEBUG - [Now] Device is Chromecast (Chromecast).
Nov 09, 2017 09:31:32.650 [3436] DEBUG - [Now] Profile is Chromecast
Nov 09, 2017 09:31:32.650 [3436] DEBUG - [Now] Updated play state for /library/metadata/2090.
Nov 09, 2017 09:31:32.653 [3436] DEBUG - Statistics: (haex4zkdpy4zdxik4dx38eqp) Reporting active playback in state 1 of type 4 (scrobble: 0) for account 1
Nov 09, 2017 09:31:32.653 [11000] DEBUG - Webhook: Delivering media.pause event for item 2090 by user asjmcguireplex to 1 hooks.
Nov 09, 2017 09:31:32.654 [5004] DEBUG - Completed: [192.168.2.76:41817] 200 GET /photo/:/transcode?url=%2Flibrary%2Fmetadata%2F2091%2Fthumb%2F1510038595%3FX-Plex-Token%3Dxxxxxxxxxxxxxxxxxxxxa93-4ddb-b086-172998112e7e&width=587&height=330&minSize=1 (7 live) TLS GZIP 68ms 12366 bytes (pipelined: 1)
Nov 09, 2017 09:31:32.654 [7084] DEBUG - HTTP requesting POST http://[redacted]
Nov 09, 2017 09:31:32.656 [5004] DEBUG - Completed: [192.168.2.76:41819] 200 GET /:/timeline?hasMDE=1&ratingKey=2090&key=%2Flibrary%2Fmetadata%2F2090&state=paused&playQueueItemID=25799&time=1248443&duration=1306272 (7 live) TLS GZIP 9ms 749 bytes (pipelined: 1)
Nov 09, 2017 09:31:32.767 [7084] DEBUG - HTTP 200 response from POST http://[redacted]

Nov 09, 2017 09:53:51.386 [6568] DEBUG - [Now] User is asjmcguireplex (ID: 1)
Nov 09, 2017 09:53:51.387 [6568] DEBUG - [Now] Device is Chromecast (Chromecast).
Nov 09, 2017 09:53:51.387 [6568] DEBUG - [Now] Profile is Chromecast
Nov 09, 2017 09:53:51.387 [6568] DEBUG - [Now] Updated play state for /library/metadata/2091.
Nov 09, 2017 09:53:51.387 [6568] DEBUG - Statistics: (haex4zkdpy4zdxik4dx38eqp) Reporting active playback in state 1 of type 4 (scrobble: 0) for account 1
Nov 09, 2017 09:53:51.390 [5004] DEBUG - Completed: [192.168.2.76:42467] 200 GET /:/timeline?hasMDE=1&ratingKey=2091&key=%2Flibrary%2Fmetadata%2F2091&state=paused&playQueueItemID=25800&time=1240693&duration=1305872 (6 live) TLS GZIP 4ms 751 bytes (pipelined: 1)
Nov 09, 2017 09:54:00.894 [8984] DEBUG - Request: [192.168.2.76:42469 (Subnet)] OPTIONS /:/timeline?hasMDE=1&ratingKey=2091&key=%2Flibrary%2Fmetadata%2F2091&state=stopped&continuing=1&playQueueItemID=25800&time=1240693&duration=1305872 (6 live) TLS GZIP Signed-in
Nov 09, 2017 09:54:00.895 [13476] DEBUG - Completed: [192.168.2.76:42469] 200 OPTIONS /:/timeline?hasMDE=1&ratingKey=2091&key=%2Flibrary%2Fmetadata%2F2091&state=stopped&continuing=1&playQueueItemID=25800&time=1240693&duration=1305872 (6 live) TLS GZIP 1ms 547 bytes (pipelined: 1)
Nov 09, 2017 09:54:00.898 [6568] DEBUG - Request: [192.168.2.76:42470 (Subnet)] OPTIONS /video/:/transcode/universal/stop?session=29mmsfutwyzh9qxi2513p5eg (6 live) TLS GZIP Signed-in
Nov 09, 2017 09:54:00.899 [5004] DEBUG - Completed: [192.168.2.76:42470] 200 OPTIONS /video/:/transcode/universal/stop?session=29mmsfutwyzh9qxi2513p5eg (6 live) TLS GZIP 1ms 521 bytes (pipelined: 1)
Nov 09, 2017 09:54:00.996 [13476] DEBUG - Auth: authenticated user 1 as asjmcguireplex
Nov 09, 2017 09:54:00.996 [7844] DEBUG - Request: [192.168.2.180:49468 (Subnet)] GET /playQueues/394?repeat=0&own=0&includeChapters=1 (5 live) TLS GZIP Signed-in Token (asjmcguireplex)
<snip>
Nov 09, 2017 09:54:01.101 [4944] DEBUG - Webhook: Delivering media.stop event for item 2091 by user asjmcguireplex to 1 hooks.
<snip>
Nov 09, 2017 09:54:01.111 [7844] DEBUG - Request: [192.168.2.76:42473 (Subnet)] GET /video/:/transcode/universal/stop?session=29mmsfutwyzh9qxi2513p5eg (7 live) TLS GZIP Signed-in Token (asjmcguireplex)
Nov 09, 2017 09:54:01.113 [13476] DEBUG - Completed: [192.168.2.76:42473] 200 GET /video/:/transcode/universal/stop?session=29mmsfutwyzh9qxi2513p5eg (7 live) TLS GZIP 2ms 268 bytes (pipelined: 1)

I don’t know if this provides enough information - but you can clearly see the stream is killed before it reaches the end of the duration.

Yes this is happening to me as well. Same pms version. Using IOS to cast to chromecast

It seems to be related to the Chromecast - I tried playing the same file in the web player and it seems to play the entire file (though it may have cut the last 3-5 seconds - I’m not entirely sure).

Verified: Direct Play / Stuff that doesn’t pass through the transcoder - plays right to the end.

EDIT: Optimising - using the transcoder, does transcode the entire file.

Would it be possible to get the full log from above and not just the snippet?

Full log attached. Please note any messages about the Chromecast seeking - are where I was having to replay the last part of the file to try and get as far as the credits.

For info - having optimised several seasons - Plex is now sending the optimised versions to the Chromecast and they play right to the end - it only seems to be when the transcoder is used in combination with the Chromecast as far as I have been able to test this far. Though I imagine the optimising process probably works in a different way to transcoding on the fly - because optimising probably doesn’t need to bother with chunking?

Same problem with the latest beta. Running on Ubuntu 17.10 with Roku clients (2015 models, hardwired).

Looks like there’s another thread reporting the same problems as well… http://forums.plex.tv/discussion/295230/1-9-7-4441-jumping-to-next-episode-before-current-episode-finishes-playing-on-chromecast

Is there an update to this issue? I’m only able to watch about 4 minutes of a 20 minute show before it stops and I have to restart the show. Just started with the update today.

Having the same issue

Add my voice to this complaint. PMS 1.9.7.4441 on Windows 2016 Server, Roku Premium+ client.

OKay, there’s definitely a problem with 1.9.7.4441. I am too experiencing crashes at the end of a episode, and it only seems to be on episodes where transcoding is taking place, in my case converting eac5.1. I rolled back my server to 1.9.6.4429 and the episode played fine all the way to the end. Attached are my logs.

Having the same issue with 1.9.7.4441 on Ubuntu 16.04.3 with Roku. Happy to provide logs if the ones already provided aren’t sufficient.

me too. i need to stop updating as soon as i see the stupid messages. seems like the last 2 updates have broke stuff.

@Dystaxia said:
OKay, there’s definitely a problem with 1.9.7.4441. I am too experiencing crashes at the end of a episode, and it only seems to be on episodes where transcoding is taking place, in my case converting eac5.1. I rolled back my server to 1.9.6.4429 and the episode played fine all the way to the end. Attached are my logs.

Can’t see any server crashes. What time? what was being played ? which video? what crashed? and where? Is it the plex app on the device ? or server ? transcoder crash?

I see server running from Nov 09, 2017 20:12:48 until you shut it down at 08:05:48 Nov 10, 2017
and restarted and again shut down at 08:16:29
and restarted and logs captured at 08:20

@sa2000 said:

@Dystaxia said:
OKay, there’s definitely a problem with 1.9.7.4441. I am too experiencing crashes at the end of a episode, and it only seems to be on episodes where transcoding is taking place, in my case converting eac5.1. I rolled back my server to 1.9.6.4429 and the episode played fine all the way to the end. Attached are my logs.

Can’t see any server crashes. What time? what was being played ? which video? what crashed? and where? Is it the plex app on the device ? or server ? transcoder crash?

I see server running from Nov 09, 2017 20:12:48 until you shut it down at 08:05:48 Nov 10, 2017
and restarted and again shut down at 08:16:29
and restarted and logs captured at 08:20

Should be that last timeframe of 8:16 to 8:20 - i grabbed the logs right after it crashed. Was playing The Blacklist s5e07. Roku 3.

@jondhoughton said:
Having the same issue with 1.9.7.4441 on Ubuntu 16.04.3 with Roku. Happy to provide logs if the ones already provided aren’t sufficient.

Please do and details of the problem and at what time and when streaming what

I think clarification is needed as to whether dsytaxia really means the transcoder crashed, or did the file just end prematurely? In my case (and others here) - the transcoder appears to complete it’s job successfully and then Plex skips to the next episode pretty much as soon as the transcoder has completed, so the last 60 seconds or so - may well have been transcoded - but is not sent to the Chromecast / other client.

@asjmcguireplex said:
I think clarification is needed as to whether dsytaxia really means the transcoder crashed, or did the file just end prematurely? In my case (and others here) - the transcoder appears to complete it’s job successfully and then Plex skips to the next episode pretty much as soon as the transcoder has completed, so the last 60 seconds or so - may well have been transcoded - but is not sent to the Chromecast / other client.

Sorry for the confusion; yes. Transcoder finishes, however the play abruptly stops, not at the end of the file.