Streaming video freezing

General Discussions
1

Been using PLEX for years and for all but the last 2-3 months was simply one HyperV virtual Windows server running it. Since this time I have stood up OpenFlixr and decided to combine a bunch of manual work into that system.

Suddenly, I have been experiencing video freeze about 50-60% through any TV show, regardless of the length. This doesn’t matter what the playing device is, AppleTV, Roku, FireTV, etc. however the source video plays fine using VLC or Windows Media Player.

What is worse is I have since stood up a new Windows server and an Ubuntu system installing PLEX on each of those accessing the same source media. All 3 systems exhibit the same behavior. The Windows and Ubuntu systems are virtual machines on VMware and the OpenFlixr system is running on HyperV. Each system is only behind one update (the most recent at the time of this writing).

Let’s just say it is frustrating to be 60% through about a dozen TV shows.

I don’t mind doing the legwork to track down the issue but with all of the logs PLEX generates, where should my focus be (from a log file perspective) based on the behavior I am reporting and should the verbose mode be enabled to get to the bottom of the issue?

Before anyone asks, I am using a custom transcoding location and it has enough space to transcode about 20 streams simultaneously in all instances. One of the systems is even redirecting the transcoding to a partition on SSD.

Thanks in advance for helping out a long-time PLEXPass member.

2

I can help you with the Linux side of the problem but, having stood up 3 servers, I don’t think the problem can yet be isolated to PMS but we’ll find out.
I would like you to recreate the problem in as quiescent an environment as possible. This makes separating out the non-related streams easier.
You do not need Verbose logging. Verbose would show every single data exchange between every client and the server. The default configuration retains, at best 2 minutes of elapsed time.

After recreating, letting it freeze/stutter for about 30 seconds, and then terminating the playback session, I would like you to give it 10 seconds to let all log information make it to the logs for capture using Settings - Server - Help - Download Logs and attach both that ZIP plus the XML (under Get Info -> View XML) of the item you played.

Please do remember to do this on the Linux instance. I am of no help with Windows

3

Sent the files via PM to you Chuck.

4

I found an interesting problem.

Are you using your own SSL / TLS certificate / have a registered domain name in play here?
If so, did you remember to register it with PMS?

May 03, 2018 06:03:51.273 [0x7f2323bfe700] DEBUG - Auth: authenticated user 1 as durandclan
May 03, 2018 06:03:51.273 [0x7f230aff8700] DEBUG - Request: [192.168.1.23:58523 (Subnet)] GET /status/sessions (10 live) TLS GZIP Signed-in Token (durandclan)
May 03, 2018 06:03:51.273 [0x7f230aff8700] DEBUG - [Now] Adding 1 sessions.
May 03, 2018 06:03:51.274 [0x7f2323bfe700] DEBUG - Completed: [192.168.1.23:58523] 200 GET /status/sessions (10 live) TLS GZIP 1ms 470 bytes (pipelined: 1)
May 03, 2018 06:03:51.290 [0x7f23187ff700] ERROR - Error issuing curl_easy_perform(handle): 35
May 03, 2018 06:03:51.902 [0x7f23243ff700] DEBUG - Auth: authenticated user 5007674 as P-------Room (_obfuscated_)

The specific error is:

CURLE_SSL_CONNECT_ERROR (35)

A problem occurred somewhere in the SSL/TLS handshake. You really want the error buffer and read the message there as it pinpoints the problem slightly more. Could be certificates (file formats, paths, permissions), passwords, and others.

I am not seeing file permissions or path errors for the MP3 files so therefore am directing attention to the SSL/TLS handshake.

To correlate this back to your observed 50-60% mark. Is there a specific amount of elapsed time involved or a wall time (top of the hour perhaps) involved?

5

questions answered in your quote…

@ChuckPA said:
I found an interesting problem.

Are you using your own SSL / TLS certificate / have a registered domain name in play here? > Not knowlingly, the server is on a network where I do have a Windows Root CA but this is an Ubuntu machine and I have not configured specifically with any certificate.
If so, did you remember to register it with PMS? > see reply to previous question

May 03, 2018 06:03:51.273 [0x7f2323bfe700] DEBUG - Auth: authenticated user 1 as durandclan
May 03, 2018 06:03:51.273 [0x7f230aff8700] DEBUG - Request: [192.168.1.23:58523 (Subnet)] GET /status/sessions (10 live) TLS GZIP Signed-in Token (durandclan)
May 03, 2018 06:03:51.273 [0x7f230aff8700] DEBUG - [Now] Adding 1 sessions.
May 03, 2018 06:03:51.274 [0x7f2323bfe700] DEBUG - Completed: [192.168.1.23:58523] 200 GET /status/sessions (10 live) TLS GZIP 1ms 470 bytes (pipelined: 1)
May 03, 2018 06:03:51.290 [0x7f23187ff700] ERROR - Error issuing curl_easy_perform(handle): 35
May 03, 2018 06:03:51.902 [0x7f23243ff700] DEBUG - Auth: authenticated user 5007674 as P-------Room (_obfuscated_)

The specific error is:

CURLE_SSL_CONNECT_ERROR (35)

A problem occurred somewhere in the SSL/TLS handshake. You really want the error buffer and read the message there as it pinpoints the problem slightly more. Could be certificates (file formats, paths, permissions), passwords, and others.

I am not seeing file permissions or path errors for the MP3 files so therefore am directing attention to the SSL/TLS handshake.

To correlate this back to your observed 50-60% mark. Is there a specific amount of elapsed time involved or a wall time (top of the hour perhaps) involved? The time of day or minutes past the hour do not apply here, I can repeat the behavior with ease and each episode has a place it stops but when replaying the episode from the start, it stops in exactly the same place

6

Thanks. I wanted to get that out of the way as there have been several cases recently with domain and TLS conditions. You may want to make an exception in your “IP addresses allowed without auth” for that host if it’s truly incapable of handling TLS/SSL auth correctly. It’ll make life easier in the long run

Tracing the playback session from begging to end, I find:

May 03, 2018 11:03:21.704 [0x7f23047ff700] DEBUG - [Transcoder] Throttle - Getting back to work.
May 03, 2018 11:03:21.785 [0x7f23097f5700] DEBUG - Request: [192.168.1.98:56662 (Subnet)] GET /video/:/transcode/universal/dash/9hq1nuzhytiwtfvjn26l88pn/1/145.m4s (15 live) TLS GZIP Signed-in
May 03, 2018 11:03:21.786 [0x7f23097f5700] DEBUG - Asked for segment 145 from session.
May 03, 2018 11:03:21.786 [0x7f23097f5700] DEBUG - Returning segment 145 from session: "/mnt/plextrans/Transcode/Sessions/plex-transcode-9hq1nuzhytiwtfvjn26l88pn-015dbd86-1c62-4ddf-ae84-09617e7513a5/chunk-stream1-00146.m4s"
May 03, 2018 11:03:21.786 [0x7f23097f5700] DEBUG - Content-Length of /mnt/plextrans/Transcode/Sessions/plex-transcode-9hq1nuzhytiwtfvjn26l88pn-015dbd86-1c62-4ddf-ae84-09617e7513a5/init-stream1.m4s,/mnt/plextrans/Transcode/Sessions/plex-transcode-9hq1nuzhytiwtfvjn26l88pn-015dbd86-1c62-4ddf-ae84-09617e7513a5/chunk-stream1-00146.m4s is 151742.
May 03, 2018 11:03:21.787 [0x7f2323bfe700] DEBUG - Completed: [192.168.1.98:56662] 200 GET /video/:/transcode/universal/dash/9hq1nuzhytiwtfvjn26l88pn/1/145.m4s (15 live) TLS GZIP 1ms 151742 bytes (pipelined: 3)
May 03, 2018 11:03:21.854 [0x7f2323bfe700] DEBUG - Completed: [192.168.1.98:56553] 200 GET /video/:/transcode/universal/dash/9hq1nuzhytiwtfvjn26l88pn/0/145.m4s (15 live) TLS GZIP 219ms 2546382 bytes (pipelined: 70)
May 03, 2018 11:03:21.932 [0x7f23057ed700] ERROR - [Transcoder] [matroska,webm @ 0x2b79880] Read error at pos. 504970590 (0x1e193d5e)
May 03, 2018 11:03:23.758 [0x7f23243ff700] DEBUG - Auth: authenticated user 1 as durandclan
May 03, 2018 11:03:23.758 [0x7f2308ff4700] DEBUG - Request: [127.0.0.1:44590 (Loopback)] GET /status/sessions (14 live) Signed-in Token (durandclan)
May 03, 2018 11:03:23.758 [0x7f2308ff4700] DEBUG - [Now] Adding 2 sessions.
May 03, 2018 11:03:23.760 [0x7f23243ff700] DEBUG - Completed: [127.0.0.1:44590] 200 GET /status/sessions (14 live) 1ms 5804 bytes (pipelined: 1)
May 03, 2018 11:03:25.826 [0x7f22fdfff700] DEBUG - Request: [127.0.0.1:44598 (Loopback)] PUT /video/:/transcode/session/9hq1nuzhytiwtfvjn26l88pn/015dbd86-1c62-4ddf-ae84-09617e7513a5/progress?progress=61.4&size=-22&remaining=1132&speed=0.7 (15 live) Signed-in Token (durandclan)
May 03, 2018 11:03:25.827 [0x7f2323bfe700] DEBUG - Completed: [127.0.0.1:44598] 206 PUT /video/:/transcode/session/9hq1nuzhytiwtfvjn26l88pn/015dbd86-1c62-4ddf-ae84-09617e7513a5/progress?progress=61.4&size=-22&remaining=1132&speed=0.7 (15 live) 1ms 326 bytes
May 03, 2018 11:03:25.844 [0x7f23187ff700] DEBUG - Request: [127.0.0.1:44600 (Loopback)] POST /video/:/transcode/session/9hq1nuzhytiwtfvjn26l88pn/015dbd86-1c62-4ddf-ae84-09617e7513a5/manifest (15 live) Signed-in
May 03, 2018 11:03:25.849 [0x7f23187ff700] DEBUG - Transcoder segment range: 0 - 157
May 03, 2018 11:03:25.850 [0x7f23243ff700] DEBUG - Completed: [127.0.0.1:44600] 200 POST /video/:/transcode/session/9hq1nuzhytiwtfvjn26l88pn/015dbd86-1c62-4ddf-ae84-09617e7513a5/manifest (15 live) 6ms 166 bytes
May 03, 2018 11:03:25.881 [0x7f2305fee700] DEBUG - Request: [127.0.0.1:44602 (Loopback)] POST /video/:/transcode/session/9hq1nuzhytiwtfvjn26l88pn/015dbd86-1c62-4ddf-ae84-09617e7513a5/manifest (17 live) Signed-in
May 03, 2018 11:03:25.881 [0x7f23047ff700] DEBUG - Request: [127.0.0.1:44604 (Loopback)] PUT /video/:/transcode/session/9hq1nuzhytiwtfvjn26l88pn/015dbd86-1c62-4ddf-ae84-09617e7513a5/progress?progress=61.4&size=-22&remaining=3525&speed=0.1 (16 live) Signed-in Token (durandclan)

Does this coincide with your recreation?

May 03, 2018 11:03:21.932 [0x7f23057ed700] ERROR - [Transcoder] [matroska,webm @ 0x2b79880] Read error at pos. 504970590 (0x1e193d5e)

May 03, 2018 11:03:21.786 [0x7f23097f5700] DEBUG - Returning segment 145 from session: "/mnt/plextrans/Transcode/Sessions/plex-transcode-9hq1nuzhytiwtfvjn26l88pn-015dbd86-1c62-4ddf-ae84-09617e7513a5/chunk-stream1-00146.m4s"

You have the transcoder temp on a network share or is this the SSD? If network, the race condition which inevitably happens catches up. The eac3 codec, because it is licensed and external to the transcoder itself, requires file locking and iNotify support which a network share cannot provide in order to work together. Locking is easy to provide but iNotify does not exist for any network protocol.

Subsequent to this error, you will see the collapse of the session ( speed= entries) show transcode speed plummet from the norm of being well ahead of demand.

To verify this is indeed the root cause, can you temporarily assign the transcoder temp to a machine-local directory? I use /home/plexdir/transcode to avoid the exact same race condition.