Playback often hangs / can't play videos after upgrade

Plex Media Server Desktops & Laptops
1

I was on Plex Server 1.13.x for a long time and everything was stable.

I recently upgraded to the latest (1.16.6.1592), and now I am having a major issue. I have Plex installed on FreeNAS.

Some significant percentage of the time, when I go to play a video, it just “hangs” and never starts. This happens in both the web player and in the app, but seems to be more common with the web player. This is both for local playback and remote. Usually I can eventually get the video I want to play by start and stopping a bunch, switching from the web player to the desktop app, messing with conversion settings, etc.

Any ideas as to what might be happening?

I really miss having reliable playback. Having things fail to play some 30% of the time is awful!

1 Like
2

Jails and subnets. Try specifying your local network range in the Plex Settings > Show Advanced > Network > Lan Network

Let me know if it works.

3

Nope - didn’t seem to make any difference.

4

We can try to debug this. I’ll paste a method below.
I’ve also noticed the following come up. If it’s not related to your problem,
it’s worth mentioning for others I suppose.

Note : If running in a FreeBSD “jail”, you’ll want to make sure that VNET is enabled. (For instance, FreeNAS has instructions.

Please create a test case using Plex Media Player.

  1. Settings - General (lower one) - Show Advanced
  2. Check DEBUG logging (set it on)
  3. Uncheck VERBOSE logging (set this off)
  4. Click SAVE
  5. Reboot the PMS hardware, and wait 10min.
  6. Start Playback
  7. Play 30 seconds or until failure
  8. Wait 30 seconds
  9. Settings - Troubleshooting - Download Logs
  10. ZIP the entire folder it gives you, and attach it with your next post
  11. Quit out of Plex Media Player.
  12. Locate the latest PMP Log File, zip that up and attach it too.
5

Thanks for the quick response. I will try that soon when I am able.

For some more info, right now I am remote from my server and this is what I am experiencing trying to play a standard 1080p h.264 mkv file (that I’ve played before without issue):

With Plex desktop app on Windows:

  • Try to play with default 720p conversion. Spins upon attempt to play and then errors out with:
    An unknown error occurred (-17)
    Error code: -17

plex_error

  • Try to play with Original Quality. Works fine.

So it seems like maybe something is wrong with the transcoder.

But then I go and try to play with the web app (https://app.plex.tv), and no quality setting works, neither Original nor any of the conversion options. I don’t get an error but it just spins indefinitely without playing the file.

Previous to upgrading, I had no issues like this.

6

Re: the net stuff, FWIW, I am running in a FreeBSD jail (by way of a FreeNAS plugin). My home network uses 10.0.0.0/22 (10.0.0.0 through 10.0.3.255). The FreeNAS system is using 10.0.1.1 as its primary IP. I have the Plex jail configured to use 10.0.1.2. I can access Plex fine via https://10.0.1.2 on my home network. I have port forwarding set up and Plex reports that remote access is enabled and working.

The problem seems independent of remote access - I have the same issues within my LAN and over the internet, sometimes I can stream but often it will fail. I can triple-check that setup though in case it’s a factor.

7

Sounds good. I look forward to the logs.
I like your creative /22 netmask too.

I should read up on jails. I thought it was for isolation and wouldn’t be on the same subnet.
The reason I asked you to use PMP was it behaves, it can direct play, and there’s good logs.
I wouldn’t worry about the web client at the moment, as it always transcodes.

1 Like
8

Somehow it’s gotten worse - I can’t even play with Original Quality now. That used to be the only thing that worked. Now it plays 1-3 frames and then stops indefinitely :(. I can rapidly click play and pause to advance through the video very slowly, lol. No luck with restarting, etc.

PM’d you the logs. What I did:

  • Rebooted machine
  • Attempted to play show in-progress with Original Quality selected. Played a frame or two. Froze with no loading or error.
  • Attempted to play another from the beginning with Original Quality. Played a frame or two. Froze with no loading or error.
  • Attempted to put it into transcode @ 720p mode. Hung with loading spinner.

–

Re: /22, thanks - been using these kinds of netmasks (/23, /22, occasionally /21) for a long time and it’s really nice for organization with static leases without being so big as to have negative effects. I have 10.0.0.* for network infrastructure (router, wireless APs, UniFi Cloud Key, switches, etc), 10.0.1.* for most of my computers, mobile devices, gaming consoles; 10.0.2.* for house-devices like satellite power reporter, sonos, alarm, etc; 10.0.3.* for dynamic leases.

9

I’m just a user like you. So don’t expect brilliant insight, but I’ll try to make progress. At the least we’ll get the data from you that will help others spot this quickly.

I took a look at the PMS logs. It’s confusing what’s it’s doing because you didn’t let the PMS run for 10min before you started testing, then you did 3 different tests while it was busy. I also asked you to use PMP as the player, but instead you used Plex For Windows that’s got problems I’m trying to avoid.

I’m not a huge fan of the Plex-1.3.1 log, but it said the following a lot of times while you were trying to play.

2019-09-22T00:34:26.328 [ ERROR ] https://10-0-1-2.f1b9ed3ce07f4385907ab5bec2d610bb.plex.direct:32400/media/providers?X-Plex-Product=Plex for Windows&X-Plex-Version=1.3.1.916-1cb2c34d&X-Plex-Client-Identifier=136ho8pnrtq0qt1uqqmmq0n2&X-Plex-Platform=windows&X-Plex-Platform-Version=10&X-Plex-Sync-Version=2&X-Plex-Features=external-media&X-Plex-Model=standalone&X-Plex-Device-Name=kel&X-Plex-Device-Screen-Resolution=1815x1292%2C2560x1600&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en: Server's certificate does not match the URL.-200

Then you get this strange error once:

2019-09-22T00:34:26.356 [ ERROR ] libmpv_render/cuda-nvdec: cuGLGetDevices(&device_count, &display_dev, 1, CU_GL_DEVICE_LIST_ALL) failed -> CUDA_ERROR_OPERATING_SYSTEM: OS call failed or operation not supported on this OS 
2019-09-22T00:34:26.356 [ ERROR ] libmpv_render/cuda-nvdec: cuCtxPopCurrent(&dummy) failed -> CUDA_ERROR_INVALID_CONTEXT: invalid device context

Then you get a transcoder session failure once

2019-09-22T00:35:31.979 [ ERROR ] stream: Failed to open https://10.0.1.2:32400/video/:/transcode/universal/start?hasMDE=1&path=%2Flibrary%2Fmetadata%2F9409&mediaIndex=0&partIndex=0&protocol=http&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&maxVideoBitrate=1500&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&session=haeku41oolrlllgueti6gnke&offset=653&subtitles=auto&copyts=1&Accept-Language=en&X-Plex-Session-Identifier=yxu9x5lr9n4kkxg73yawlnhw&X-Plex-Chunked=1&X-Plex-Product=Plex%20for%20Windows&X-Plex-Version=1.3.1.916-1cb2c34d&X-Plex-Client-Identifier=136ho8pnrtq0qt1uqqmmq0n2&X-Plex-Platform=windows&X-Plex-Platform-Version=10&X-Plex-Sync-Version=2&X-Plex-Features=external-media&X-Plex-Model=standalone&X-Plex-Device-Name=kel&X-Plex-Device-Screen-Resolution=1815x1292%2C2560x1600&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en&X-Plex-Client-Profile-Name=Plex%20Desktop.

When Iooked at the PMS logs, the one thing I did spot was that you have it set to HW acceleration, but it keeps failing back to software transcode. I’m not convinced that the SW Transcode is going off correctly, as it uses -1 as a length from my limited understanding. Then the sw transcode stops.

Please do the tests again, following my instructions and avoiding anything extra.
thank you sir

10

Hey -

Sorry about that, didn’t mean to waste your time. Was looking thru the logs myself with some of the various problems I was having and decided to forward those along since I had them in-hand. But I realize why you made the specific request now.

Sent you new logs following the script exactly:

  • Reboot
  • Wait solid 10min
  • Attempt to play file with convert to 720p
  • Get error message after spinning
  • Waited 30 seconds

Also used PMP instead of Plex for Windows.

I really appreciate the help! I’m tempted to just revert back to my old working PMS version, but the TV Guide and Live Channel Recording no longer works with that version… :frowning:. So hopeful I can get the new one to work.

11

I’ll have a look now. Consider uploading your logs here in your thread.
I only spot the simple things.

EDIT: tl;dr it complains about your network being slow, buffering, empty transcode cache, and it errors out with unrecognized file format. PMS says the transcode session had to fall back to software decoding and gives up. After that I got lost and nothing was obvious. Below are some excerpts for dz_dog, but they won’t have the context others need to help.

The suggestion now is for you attach your logs with your reply.

Going through your PMP.log, I can see you switch to 720p and the app going through the analysis to make that happen. As it’s doing so, one error appears, which could be innocuous, but it did mention TLS that could refer to the security encryption protocol.

2019-09-22 15:39:28 [ ERROR ] PlayerComponent.cpp @ 600 - ffmpeg: tls: Failed to send close message

Then I can see the transcode session start but immediate buffering

transcode start and buffering 
2019-09-22 15:39:28 [ DEBUG ] PlayerComponent.cpp @ 594 - ffmpeg: Opening https://10.0.1.2:32400/video/:/transcode/universal/start?hasMDE=1&path=%2Flibrary%2Fmetadata%2F9298&mediaIndex=0&partIndex=0&protocol=http&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&maxVideoBitrate=4000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&session=wco20ma3iq3u5wwxq207wrk9&offset=1&subtitles=auto&copyts=1&Accept-Language=en&X-Plex-Session-Identifier=0aydhnpgb4kbsrwexxjws1c3&X-Plex-Client-Profile-Extra=append-transcode-target-codec%28type%3DvideoProfile%26context%3Dstreaming%26protocol%3Dhttp%26videoCodec%3D%2A%26audioCodec%3D%2A%29&X-Plex-Chunked=1&X-Plex-Client-Identifier=wyggdt0fmoxqhdmi6zhestt9&X-Plex-Device-Screen-Resolution=1200x1600%2C1200x1600&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%3A2%7D%2Cac3%7Bbitrate%3A800000%26channels%3A2%7D&X-Plex-Product=Plex%20Media%20Player&X-Plex-Platform=Konvergo&X-Plex-Platform-Version=2.42.0.1013-712b8c6f&X-Plex-Device=Windows&X-Plex-Device-Name=kel&X-Plex-Model=10&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en&X-Plex-Client-Profile-Name=Konvergo 
2019-09-22 15:39:30 [ INFO  ] JS: %c[Metrics] Updating session last interaction time 
2019-09-22 15:39:30 [ INFO  ] JS: %c[Metrics] Updating session last interaction time 
2019-09-22 15:39:30 [ DEBUG ] PowerComponent.cpp @ 58 - Disabling OS screensaver 
2019-09-22 15:39:30 [ DEBUG ] PlayerComponent.cpp @ 594 - cplayer: Run command: set, flags=0, args=[pause, no] 
2019-09-22 15:39:30 [ DEBUG ] PlayerComponent.cpp @ 594 - cplayer: Set property: pause=no -> 1 
2019-09-22 15:39:30 [ INFO  ] PlayerComponent.cpp @ 466 - Entering state: buffering 
2019-09-22 15:39:30 [ INFO  ] JS: %c[Player] Timeline, {
  "ratingKey": "9298",
  "key": "/library/metadata/9298",
  "playbackTime": 0,
  "playQueueItemID": "17274",
  "state": "playing",
  "hasMDE": 1,
  "time": 1000,
  "duration": 1293000
} 
2019-09-22 15:39:30 [ INFO  ] JS: %c[Player] Buffering detected by PMP 
2019-09-22 15:39:30 [ INFO  ] JS: %c[Player] Timeline, {
  "ratingKey": "9298",
  "key": "/library/metadata/9298",
  "playbackTime": 0,
  "playQueueItemID": "17274",
  "state": "buffering",
  "hasMDE": 1,
  "time": 1000,
  "duration": 1293000
} 

Here is when PMS.log says
Sep 22, 2019 15:39:30.681 [0x80c3af600] DEBUG - Failed to stream media, client probably disconnected after 95338496 bytes: 32 - Broken pipe



Back to your PMP.log
2019-09-22 15:39:35 [ DEBUG ] PlayerComponent.cpp @ 594 - ffmpeg: Mime-type: 'video/x-matroska' 
2019-09-22 15:39:35 [ DEBUG ] PlayerComponent.cpp @ 594 - ffmpeg: Stream opened successfully. 
2019-09-22 15:39:35 [ DEBUG ] PlayerComponent.cpp @ 594 - cache: Cache size set to 151800 KiB (75000 KiB backbuffer) 
2019-09-22 15:39:35 [ DEBUG ] PlayerComponent.cpp @ 594 - demux: Trying demuxers for level=normal. 
2019-09-22 15:39:36 [ DEBUG ] PlayerComponent.cpp @ 594 - cache: Cache is not responding - slow/stuck network connection?

As it’s trying to deal with that for 30sec (thank you) it then fails in this fashion, where the transcoder cache gets emptied

cache: EOF reached 
2019-09-22 15:40:18 [ INFO  ] JS: %c[Player] Timeline, {
  "ratingKey": "9298",
  "key": "/library/metadata/9298",
  "playbackTime": 71,
  "playQueueItemID": "17274",
  "state": "buffering",
  "hasMDE": 1,
  "time": 1000,
  "duration": 1293000
} 
2019-09-22 15:40:28 [ INFO  ] JS: %c[Player] Timeline, {
  "ratingKey": "9298",
  "key": "/library/metadata/9298",
  "playbackTime": 71,
  "playQueueItemID": "17274",
  "state": "buffering",
  "hasMDE": 1,
  "time": 1000,
  "duration": 1293000
} 
2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - cache: EOF reached. 
2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - lavf: No format found, try lowering probescore or forcing the format. 
2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - demux: Trying demuxers for level=unsafe. 
2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - lavf: No format found, try lowering probescore or forcing the format. 
2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - cache: Terminating cache... 
2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - cache: Cache exiting... 
2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - cplayer: Opening failed or was aborted: https://10.0.1.2:32400/video/:/transcode/universal/start?hasMDE=1&path=%2Flibrary%2Fmetadata%2F9298&mediaIndex=0&partIndex=0&protocol=http&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&maxVideoBitrate=4000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&session=wco20ma3iq3u5wwxq207wrk9&offset=1&subtitles=auto&copyts=1&Accept-Language=en&X-Plex-Session-Identifier=0aydhnpgb4kbsrwexxjws1c3&X-Plex-Client-Profile-Extra=append-transcode-target-codec%28type%3DvideoProfile%26context%3Dstreaming%26protocol%3Dhttp%26videoCodec%3D%2A%26audioCodec%3D%2A%29&X-Plex-Chunked=1&X-Plex-Client-Identifier=wyggdt0fmoxqhdmi6zhestt9&X-Plex-Device-Screen-Resolution=1200x1600%2C1200x1600&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%3A2%7D%2Cac3%7Bbitrate%3A800000%26channels%3A2%7D&X-Plex-Product=Plex%20Media%20Player&X-Plex-Platform=Konvergo&X-Plex-Platform-Version=2.42.0.1013-712b8c6f&X-Plex-Device=Windows&X-Plex-Device-Name=kel&X-Plex-Model=10&X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&X-Plex-Language=en&X-Plex-Client-Profile-Name=Konvergo

And directly below those line leaving out nothing… the kicker:

2019-09-22 15:40:36 [ DEBUG ] PlayerComponent.cpp @ 594 - cplayer: finished playback, unrecognized file format (reason 4) 
2019-09-22 15:40:36 [ ERROR ] PlayerComponent.cpp @ 600 - cplayer: Failed to recognize file format. 
2019-09-22 15:40:36 [ INFO  ] PlayerComponent.cpp @ 596 - cplayer:  
2019-09-22 15:40:36 [ INFO  ] PlayerComponent.cpp @ 480 - "Entering state: error (unrecognized file format)"

And just one more message about it to rub it in:

2019-09-22 15:40:36 [ INFO  ] JS: %c[Player] A critical PMP media error occurred: unrecognized file format; the player cannot recover

Now I’ll look in the pms.log and see what it says is happening:

We get the process and session GUID and see playback starting to initialize 
Sep 22, 2019 15:39:30.730 [0x80dceb000] DEBUG - Streaming Resource: Session 0x80d440dd8:0aydhnpgb4kbsrwexxjws1c3 changed transcode slot usage to used.  Used slots is now 1
Then transcode beings with Easy Audio Encoder EAE_ROOT 
Sep 22, 2019 15:39:30.730 [0x80dceb000] DEBUG - Streaming Resource: Reached Decision id=9298 codes=(General=1001,Direct play not available; Conversion OK. Direct Play=3000,App cannot direct play this item. Direct play is disabled. Transcode=1001,Direct play not available; Conversion OK.) media=(id=10168 part=(id=10601 decision=transcode container=mkv protocol=http streams=(Video=(id=32800 decision=transcode bitrate=3416 encoder=libx264 width=1280 height=720) Audio=(id=32801 decision=transcode bitrate=336 encoder=libopus channels=6 rate=48000))))
Sep 22, 2019 15:39:30.731 [0x80c3af100] DEBUG - Completed: [10.0.1.100:60767] 200 GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F9298&mediaIndex=0&partIndex=0&protocol=http&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&maxVideoBitrate=4000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&session=wco20ma3iq3u5wwxq207wrk9&offset=1&subtitles=auto&copyts=1&Accept-Language=en (9 live) TLS GZIP 42ms 1598 bytes (pipelined: 4)
Sep 22, 2019 15:39:30.795 [0x80bcef400] DEBUG - Request: [10.0.1.100:60769 (Subnet)] GET /video/:/transcode/universal/start?hasMDE=1&path=%2Flibrary%2Fmetadata%2F9298&mediaIndex=0&partIndex=0&protocol=http&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&maxVideoBitrate=4000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&session=wco20ma3iq3u5wwxq207wrk9&offset=1&subtitles=auto&copyts=1&Accept-Language=en (10 live) TLS Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:30.795 [0x80bcef400] DEBUG - TranscodeUniversalRequest: using augmented profile Konvergo
Sep 22, 2019 15:39:30.798 [0x80bcef400] DEBUG - Starting a transcode session wco20ma3iq3u5wwxq207wrk9 at offset -1.0 (state=3)
Sep 22, 2019 15:39:30.841 [0x80bcef400] DEBUG - Job running: EAE_ROOT='/tmp/pms-dc0b7ade-6090-4fb4-9e30-37cb857e7877/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/Plex\ Media\ Server/Codecs/dd95667-2450-freebsd-x86_64/' XDG_CACHE_HOME='/Plex Media Server/Cache' XDG_DATA_HOME='/usr/local/share/plexmediaserver-plexpass/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/local/share/plexmediaserver-plexpass/Plex Transcoder' '-codec:0' 'h264' '-codec:1' 'eac3_eae' '-eae_prefix:1' 'wco20ma3iq3u5wwxq207wrk9_' '-ss' '1' '-analyzeduration' '20000000' '-probesize' '20000000' '-i' '/mnt/he_media/TV/The Goldbergs/Season 6/The.Goldbergs.2013.S06E17.Our.Perfect.Strangers.1080p.AMZN.WEB-DL.DDP5.1.H.264-NTb.mkv' '-filter_complex' '[0:0]scale=w=1280:h=720[0];[0]format=pix_fmts=yuv420p|nv12[1]' '-filter_complex' '[0:1] aresample=async=1:ocl='\''5.1'\'':osr=48000[2]' '-map' '[1]' '-codec:0' 'libx264' '-crf:0' '23' '-maxrate:0' '3416k' '-bufsize:0' '6832k' '-r:0' '23.975999999999999' '-preset:0' 'veryfast' '-x264opts:0' 'subme=0:me_range=4:rc_lookahead=10:me=dia:no_chroma_me:8x8dct=0:partitions=none' '-map' '[2]' '-metadata:s:1' 'language=eng' '-codec:1' 'libopus' '-b:1' '336k' '-f' 'segment' '-segment_format' 'matroska' '-segment_format_options' 'live=1' '-segment_time' '1' '-segment_header_filename' 'header' '-segment_start_number' '0' '-segment_list' 'http://127.0.0.1:32400/video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/seglist' '-segment_list_type' 'csv' '-segment_list_unfinished' '1' '-segment_list_size' '2147483647' '-segment_list_separate_stream_times' '1' '-avoid_negative_ts' 'disabled' '-map_metadata:g' '-1' '-map_metadata:c' '-1' '-map_chapters' '-1' 'chunk-%05d' '-start_at_zero' '-copyts' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress'
The transcoder session gets each track sorted out 
Sep 22, 2019 15:39:32.050 [0x80dceb000] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?status=startup (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.050 [0x80c3af600] DEBUG - Completed: [10.0.1.2:24253] 204 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?status=startup (11 live) 0ms 203 bytes (pipelined: 1) (range: bytes=0-) 
Sep 22, 2019 15:39:32.050 [0x80c89f700] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?status=opening (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.050 [0x80c3af100] DEBUG - Completed: [10.0.1.2:24253] 204 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?status=opening (11 live) 0ms 203 bytes (pipelined: 2) (range: bytes=0-) 
Sep 22, 2019 15:39:32.065 [0x80dceb000] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?status=opened (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.065 [0x80c3af600] DEBUG - Completed: [10.0.1.2:24253] 204 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?status=opened (11 live) 0ms 203 bytes (pipelined: 3) (range: bytes=0-) 
Sep 22, 2019 15:39:32.073 [0x80c89f700] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/stream?index=0&id=0&codec=h264&type=video (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.073 [0x80c3af100] DEBUG - Completed: [10.0.1.2:24253] 200 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/stream?index=0&id=0&codec=h264&type=video (11 live) 0ms 195 bytes (pipelined: 4) (range: bytes=0-) 
Sep 22, 2019 15:39:32.073 [0x80dceb000] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/stream?index=1&id=0&codec=eac3&type=audio (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.073 [0x80c3af100] DEBUG - Completed: [10.0.1.2:24253] 200 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/stream?index=1&id=0&codec=eac3&type=audio (11 live) 0ms 195 bytes (pipelined: 5) (range: bytes=0-) 
Sep 22, 2019 15:39:32.237 [0x80dceb000] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&width=1920&height=1080&interlaced=0&sar=1:1&level=40&frameRate=23.976&disp_default=1 (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.237 [0x80c3af600] DEBUG - Completed: [10.0.1.2:24253] 200 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=0&id=0&codec=h264&type=video&profile=High&width=1920&height=1080&interlaced=0&sar=1:1&level=40&frameRate=23.976&disp_default=1 (11 live) 0ms 195 bytes (pipelined: 6) (range: bytes=0-) 
Sep 22, 2019 15:39:32.237 [0x80c89f700] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=1&id=0&codec=eac3&type=audio&bitrate=640000&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&disp_default=1 (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.238 [0x80c3af100] DEBUG - Completed: [10.0.1.2:24253] 200 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=1&id=0&codec=eac3&type=audio&bitrate=640000&language=eng&channels=6&layout=5.1%28side%29&sampleRate=48000&disp_default=1 (11 live) 0ms 195 bytes (pipelined: 7) (range: bytes=0-) 
Sep 22, 2019 15:39:32.238 [0x80c89f700] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=2&id=0&codec=subrip&type=subtitle&language=eng (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.238 [0x80c3af100] DEBUG - Completed: [10.0.1.2:24253] 200 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=2&id=0&codec=subrip&type=subtitle&language=eng (11 live) 0ms 195 bytes (pipelined: 8) (range: bytes=0-) 
Sep 22, 2019 15:39:32.238 [0x80c89f700] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=3&id=0&codec=subrip&type=subtitle&language=eng (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.238 [0x80c3af100] DEBUG - Completed: [10.0.1.2:24253] 200 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress/streamDetail?index=3&id=0&codec=subrip&type=subtitle&language=eng (11 live) 0ms 195 bytes (pipelined: 9) (range: bytes=0-) 
Sep 22, 2019 15:39:32.252 [0x80c89f700] DEBUG - Request: [10.0.1.2:24253 (Subnet)] PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?duration=1293.568000 (11 live) Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.252 [0x80c3af600] DEBUG - Completed: [10.0.1.2:24253] 204 PUT /video/:/transcode/session/wco20ma3iq3u5wwxq207wrk9/127f9ef9-82c0-489d-989e-c4dad9f29a2a/progress?duration=1293.568000 (11 live) 0ms 203 bytes (pipelined: 10) (range: bytes=0-)
And it starts successfully 
Sep 22, 2019 15:39:32.252 [0x80bcef400] DEBUG - Started session successfully: wco20ma3iq3u5wwxq207wrk9
It sees buffering, then stops because it can't HW Decode 
Sep 22, 2019 15:39:32.478 [0x80dceb000] DEBUG - [Now] Updated play state for /library/metadata/9298.
Sep 22, 2019 15:39:32.478 [0x80dceb000] DEBUG - Statistics: (wyggdt0fmoxqhdmi6zhestt9) Reporting active playback in state 0 of type 4 (scrobble: 0) for account 1
Sep 22, 2019 15:39:32.480 [0x80c3af600] DEBUG - Completed: [10.0.1.100:60767] 200 GET /:/timeline?ratingKey=9298&key=%2Flibrary%2Fmetadata%2F9298&playbackTime=0&playQueueItemID=17274&state=playing&hasMDE=1&time=1000&duration=1293000 (7 live) TLS GZIP 3ms 687 bytes (pipelined: 6)
Sep 22, 2019 15:39:32.491 [0x80c3af100] DEBUG - Auth: authenticated user 1 as dz@dzog.us
Sep 22, 2019 15:39:32.491 [0x80dceb000] DEBUG - Request: [10.0.1.100:60767 (Subnet)] GET /status/sessions (7 live) TLS GZIP Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.491 [0x80dceb000] DEBUG - [Now] Adding 2 sessions.
Sep 22, 2019 15:39:32.492 [0x80c3af600] DEBUG - Completed: [10.0.1.100:60767] 200 GET /status/sessions (7 live) TLS GZIP 0ms 1794 bytes (pipelined: 7)
Sep 22, 2019 15:39:32.551 [0x80c3af100] DEBUG - Auth: authenticated user 1 as dz@dzog.us
Sep 22, 2019 15:39:32.551 [0x80c89f700] DEBUG - Request: [10.0.1.100:60767 (Subnet)] GET /:/timeline?ratingKey=9298&key=%2Flibrary%2Fmetadata%2F9298&playbackTime=0&playQueueItemID=17274&state=buffering&hasMDE=1&time=1000&duration=1293000 (7 live) TLS GZIP Signed-in Token (dz@dzog.us)
Sep 22, 2019 15:39:32.552 [0x80c89f700] DEBUG - Client [0aydhnpgb4kbsrwexxjws1c3] reporting timeline state buffering, progress of 1000/1293000ms for guid=, ratingKey=9298 url=, key=/library/metadata/9298, containerKey=, metadataId=9298, source=
Sep 22, 2019 15:39:32.552 [0x80c89f700] DEBUG - [Now] User is dz@dzog.us (ID: 1)
Sep 22, 2019 15:39:32.552 [0x80c89f700] DEBUG - [Now] Device is Konvergo (kel).
Sep 22, 2019 15:39:32.552 [0x80c89f700] DEBUG - [Now] Profile is Konvergo
Sep 22, 2019 15:39:32.552 [0x80c89f700] DEBUG - [Now] Updated play state for /library/metadata/9298.
Sep 22, 2019 15:39:32.552 [0x80c89f700] DEBUG - Statistics: (wyggdt0fmoxqhdmi6zhestt9) Reporting active playback in state 2 of type 4 (scrobble: 0) for account 1
Sep 22, 2019 15:39:32.554 [0x80c3af100] DEBUG - Completed: [10.0.1.100:60767] 200 GET /:/timeline?ratingKey=9298&key=%2Flibrary%2Fmetadata%2F9298&playbackTime=0&playQueueItemID=17274&state=buffering&hasMDE=1&time=1000&duration=1293000 (7 live) TLS GZIP 2ms 687 bytes (pipelined: 8)
Sep 22, 2019 15:39:32.776 [0x80dceb000] DEBUG - Transcoder: session wco20ma3iq3u5wwxq207wrk9 indicated fallback to software decoding

It stops session wco20ma3iq3u5wwxq207wrk9 then attempts another transcode session. After buffering for a while, we get some TLS handshake fails.

Sep 22, 2019 15:40:18.640 [0x80c3af100] DEBUG - CERT: incomplete TLS handshake: sslv3 alert certificate unknown
Sep 22, 2019 15:40:18.640 [0x80c3af600] DEBUG - CERT: incomplete TLS handshake: sslv3 alert certificate unknown
Sep 22, 2019 15:40:18.664 [0x80c3af100] DEBUG - CERT: incomplete TLS handshake: sslv3 alert certificate unknown

Sorry that the problem is not obvious. Does it have to verify your custom TLS Cert every time it does something? Maybe allow local network without auth?

12

Thanks for the analysis -

FWIW, HW Acceleration is showing as disabled on the server side under transcode settings. I tried disabling secure connections and it did not fix the issue either. Same symptoms. I could try providing logs with secure connections disabled?

I just went back to my 1.13.9.5456 install and it’s still working perfectly. (Except for the Guide/Live feature as mentioned, which I believe is no longer compatible with the servers Plex runs to populate it.). Everything plays great!

For 1.16.6.1592, I had installed it via the FreeNAS plugin system - it seems to be an official package. I duped my database for the new version, which seemed to work fine in terms of Plex upgrading the db and all the content showing up. I guess maybe I’ll try a manual install instead?

The logs seem to point to some network issue. But I can access the jail’s net and the jail can access out no problem. And it can communicate enough to connect and sometimes play media (though never via the transcoder).

13

Secure connections should be set to Preferred as certain things use only http.
You should try allowing local connections without auth at some point.
As I was getting blurry eyed I noticed what you were saying about HW Acceleration,
when I saw it say transcodeHwRequested="0"

<Variant id="127f9ef9-82c0-489d-989e-c4dad9f29a2a" targetBitrate="3940" context="streaming" sourceVideoCodec="h264" sourceAudioCodec="eac3" videoDecision="transcode" audioDecision="transcode" protocol="http" container="mkv" videoCodec="h264" audioCodec="opus" audioChannels="6" transcodeHwRequested="0" transcodeHwFullPipeline="0">

Given that, I’m not sure why it keeps saying it has to fall back to software decode :man_shrugging:

14

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.