Endless transcoding/buffering

Plex Media Server Desktops & Laptops
1

Server Version#: Latest
Player Version#: Latest

Plex transcodes forever and playback never starts. The buffering icon just keeps looping forever and nothing happens.

Using a debian 10 headless server.
It used to work perfectly fine for years. Until today. Worked flawlessly last week and nothing changed since. (No debian updates, no new software installed etc, nothing…)

Things I tried:

  • Multiple PMS versions (1.18.6 -> fail; 1.18.7 -> fail; 1.18.8 -> fail)
  • Different transcoder directories (/dev/shm -> fail; custom path with proper permissions /media/plextrs -> fail)
  • Restarting the plexmediaserver service
  • Rebooting the server
  • Multiple NVidia drivers versions (440.59 -> fail; 440.64 -> fail)
  • Disabling HW transcoding -> Same result whether it’s CPU transcode or HW transcode using NVidia GPU (Quadro P1000); Note: I can see the transcoding occur with nvidia-smi as usual, or with the CPU usage/processes running if HW transcode disabled.
  • Using the Plex App client -> It works because it direct plays, but on Chrome it fails because it attempts to transcode. So the issue clearly lies with transcoding only.
  • Multiple movies/TV shows I already watched and know they work
  • Turning on/off subtitles (SRT, PGS) and various video quality settings (1080p, 720p…)
  • Repairing the database
  • Clearing Chrome cache

One thing I noticed is that the temporary transcoding data just keeps growing bigger and bigger forever, but nothing else happens. No crash, it just won’t start and endlessly transcodes any files I tested, even those I know for a fact used to work, as mentioned above.

I have no idea what else to check at this point… I don’t even understand what can be causing this issue all of a sudden. I never had any problems with PMS on Debian and this machine.

See attached log files.

Plex Media Server Logs_2020-03-15_22-31-36.zip (301.1 KB)

2

What clients have you tried?

Is that the Web Client?

Is that the Web Client for Chrome or a Chromecast device?
Also would be useful if we knew the Versions of the Client OS and Plex Client.

3

No. The official Plex App for Windows 10. (version 1.6.3.1009-57cf57c8)

Web Client for Chrome.

Client OS is Windows 10 1909, build 18363.720. I also tested with another Windows 10 machine on 1809 but it also fails.

Plex Web client for Chrome is 4.22.2

4

I need the DEBUG enabled logs (VERBOSE still off).

(DEBUG on doesn’t use more disk space but does let me see what’s happening).

By the looks of it. the DNS lookup is failing to resolve plex.tv and download codecs.

These logs should be 10M each when full. What this shows is how little is being reported.

Screenshot from 2020-03-15 18-16-08
Screenshot from 2020-03-15 18-16-081013×219 35.1 KB

5

I always had debug disabled prior to having this issue, so I’ve only just enabled it after this started happening and tested a few media files to hopefully write meaningful data into these logs, so I guess that’s why they are so small. Sorry about that.

Is there any way I could run some tests to gather more meaningful data for you?

As for the DNS lookup, I tested both from the client and the server, using different DNS servers and they both resolve plex.tv, returning the same IP addresses, so that looks okay to me.

6

I’d like to add that I just tested from the Plex App for Android on my phone (from Wi-Fi connected to the same LAN where my server is, and with Wi-Fi off to force remote play) and I have the same issue as with the Web App in Chrome. So that’s 3 different clients tested so far.

7

May I have a set of logs, Which has DEBUG enabled from the start and which captures one of these issues you’re reporting?

8

I’m sorry, I thought the original logs I attached already contained all that… Because that’s literally what I aimed to do: Enabled DEBUG, attempted to reproduce my issues so it gets captures in the logs, and attached it here.

Anyways, I’ve been playing around for 15 minutes with various things (different files/quality, different client players such as Edge/Chrome, different DNS settings…). But the log file size doesn’t seem to have increased much… And I couldn’t find most of the things I did, written in the logs. Strange… But maybe you can find the information you need, so, here’s the new logs. Plex Media Server Logs_2020-03-16_00-22-52.zip (314.5 KB)

To illustrate DEBUG being Enabled:

chrome_16-03-2020_00-23-12
chrome_16-03-2020_00-23-121089×459 486 KB

9

I was able to reproduce the same issue using the Plex App for Windows. (So not using the Chrome web client anymore) By forcing a transcode to occur, by selecting 720p as quality for example, the dashboard does report the transcode happening, and the video turns black, no sound either. Funnily enough, from the dashboard perspective it looks like everything is fine, it even updates the buffer progress and the playback timer, but on the client, it’s clearly not working. I can confirm Direct Play does work however, at least from the Windows app, but on Chrome web, even Direct Play doesn’t seem to work. I’m very confused. Same results with Edge. :confused:

Here are the “updated” logs again, assuming it managed to capture anything meaningful… Plex Media Server Logs_2020-03-16_00-35-40.zip (316.8 KB)

I don’t even know if the issue lies with PMS at this point. It looks more like a client issue now.

10

Here’s the problem:

  1. PMS is attempting to get the codecs
  2. PMS can’t get the codecs.
  3. Transcoder appears to have died. Why? No codecs.

Debug logging – at the start, will tell me this instantly.

the name.
Mar 15, 2020 22:27:12.352 [0x7f208bfff700] INFO - CodecManager: obtaining decoder 'vc1'
Mar 15, 2020 22:27:12.528 [0x7f20527fc700] INFO - AutoUpdate: no updates available
Mar 15, 2020 22:27:12.797 [0x7f208bfff700] INFO - CodecManager: obtaining decoder 'ac3'
Mar 15, 2020 22:27:13.282 [0x7f2088ff9700] INFO - Sync: downloaded 0 sync list(s) with 0 sync items(s): 0 new, 0 updated, 0 deleted
Mar 15, 2020 22:27:13.282 [0x7f201d7fa700] WARN - Sync: local sync directory "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sync+" does not exist
Mar 15, 2020 22:27:13.496 [0x7f208bfff700] INFO - CodecManager: obtaining encoder 'aac'
Mar 15, 2020 22:27:13.868 [0x7f208bfff700] INFO - CodecManager: obtaining decoder 'dca'
Mar 15, 2020 22:27:14.058 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 18899
Mar 15, 2020 22:27:14.371 [0x7f208bfff700] INFO - CodecManager: obtaining decoder 'mp2'
Mar 15, 2020 22:27:14.438 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 18897
Mar 15, 2020 22:27:14.761 [0x7f208bfff700] INFO - CodecManager: obtaining encoder 'libx264'
Mar 15, 2020 22:27:15.009 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 19041
Mar 15, 2020 22:27:16.450 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 18990
Mar 15, 2020 22:27:16.450 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 19095
Mar 15, 2020 22:27:17.339 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 19142
Mar 15, 2020 22:27:17.369 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 19140
Mar 15, 2020 22:27:18.867 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 19188
Mar 15, 2020 22:27:19.788 [0x7f2053fff700] INFO - Refreshing paths watched by LibraryUpdateManager
Mar 15, 2020 22:27:19.791 [0x7f2090e63700] WARN - JobManager: Could not find job for handle 19240
Mar 15, 2020 22:27:21.042 [0x7f2043fff700] ERROR - Unknown metadata type: folder
Mar 15, 2020 22:27:32.700 [0x7f20527fc700] INFO - AutoUpdate: no updates available
Mar 15, 2020 22:27:42.517 [0x7f2052ffd700] ERROR - Unknown metadata type: folder
Mar 15, 2020 22:28:02.223 [0x7f20527fc700] WARN - Transcode runner appears to have died.
Mar 15, 2020 22:28:02.229 [0x7f2052ffd700] WARN - Transcode runner appears to have died.
Mar 15, 2020 22:28:07.164 [0x7f208affd700] WARN - Deleted file "/tmp/logs.zipf8547709-a1bd-489a-ba89-0af6e006bff8" after connection reset
Mar 15, 2020 22:31:07.295 [0x7f1fbf7fe700] ERROR - Unknown metadata type: folder
Mar 15, 2020 22:31:29.605 [0x7f1fcd7fa700] WARN - Transcode runner appears to have died.
Mar 15, 2020 22:31:29.610 [0x7f1fceffd700] WARN - Transcode runner appears to have died.
Mar 15, 2020 22:31:36.202 [0x7f208b7fe700] WARN - Deleted file "/tmp/logs.zip713b1a74-d19c-4de7-962a-23427522ecd3" after connection reset
Mar 15, 2020 22:36:00.922 [0x7f2040ff9700] INFO - AutoUpdate: no updates available
Mar 15, 2020 22:42:19.789 [0x7f20737fe700] INFO - It's been 3695 seconds, so we're starting scheduled library update for section 6 (Anime)
Mar 15, 2020 22:42:19.789 [0x7f20737fe700] INFO - It's been 3694 seconds, so we're starting scheduled library update for section 3 (Films)
Mar 15, 2020 22:42:19.789 [0x7f20737fe700] INFO - It's been 3694 seconds, so we're starting scheduled library update for section 4 (TV Shows)
Mar 15, 2020 22:42:19.887 [0x7f20527fc700] WARN - QueryParser: Invalid field 'sectionID' found, ignoring.
Mar 15, 2020 22:42:19.890 [0x7f20527fc700] WARN - QueryParser: Invalid field 'sectionID' found, ignoring.
Mar 15, 2020 22:42:19.892 [0x7f1fceffd700] ERROR - Unknown metadata type: folder
Mar 15, 2020 22:42:19.894 [0x7f20527fc700] WARN - QueryParser: Invalid field 'sectionID' found, ignoring.

Is this box configured to talk to the internet ?
It doesn’t look it to me

11

Well I will make sure to always leave it on from now on. Not even sure why it was disabled in the first place.

What do you call a “box”? The server? Because yes, it is, no issues from the server to reach the Internet. Any specific tests I could run manually? Domains to resolve or ping? plex.tv appears to drop ping requests.

Anyways, here’s a ping to 8.8.8.8 followed with a traceroute to google.com and a DNS request to resolve plex.tv, all from the Plex server:

debian_16-03-2020_00-50-02
debian_16-03-2020_00-50-02978×511 134 KB
As you can see everything is good… Plex settings also report the server being fully accessible to the internet, under “Remote access”

12

Thanks for confirming.

Please set DEBUG on.
Stop the server.
Wait 2 minutes for all the network sockets to close nornmally
Restart the server
Give it 2 minutes to perform and log startup activities
Please then download the logs ZIP and attach again.

This will let me see what it’s doing and where your codecs are going.

13

Here are the attached logs after performing the requested actions. I also re tried to start a stream (without success). Plex Media Server Logs_2020-03-16_01-17-57.zip (317.1 KB)

14

After you changed the DEBUG setting,

  1. Did you remember to click SAVE ?
  2. Did it say “Your changes could not be saved?”

Your actions are not reflected by the log files.

Mar 16, 2020 01:10:14.583 [0x7f311066c700] INFO - Plex Media Server v1.18.7.2457-77cb9455c - Debian GNU/Linux PC x86_64 - build: linux-x86_64 debian - GMT 01:00
Mar 16, 2020 01:10:14.585 [0x7f311066c700] INFO - Linux version: 10 (buster), language: en-US
Mar 16, 2020 01:10:14.585 [0x7f311066c700] INFO - Processor      Intel(R) Xeon(R) CPU E3-1265L V2 @ 2.50GHz
Mar 16, 2020 01:10:14.585 [0x7f311066c700] INFO - /usr/lib/plexmediaserver/Plex Media Server
Mar 16, 2020 01:10:14.851 [0x7f3111157b80] INFO - OCSP: Successfully retrieved response from cache.
Mar 16, 2020 01:10:17.889 [0x7f30e1ffb700] INFO - Refreshing paths watched by LibraryUpdateManager
Mar 16, 2020 01:10:17.951 [0x7f30a57fa700] INFO - AutoUpdate: no updates available
Mar 16, 2020 01:10:18.324 [0x7f30a77fe700] WARN - QueryParser: Invalid field 'promoted' found, ignoring.
Mar 16, 2020 01:10:18.324 [0x7f30a77fe700] WARN - QueryParser: Invalid field 'libraryHubsOnly' found, ignoring.
Mar 16, 2020 01:10:18.324 [0x7f30a77fe700] WARN - QueryParser: Invalid field 'contentDirectoryID' found, ignoring.
Mar 16, 2020 01:10:18.327 [0x7f30a77fe700] WARN - QueryParser: Invalid field 'promoted' found, ignoring.
Mar 16, 2020 01:10:18.327 [0x7f30a77fe700] WARN - QueryParser: Invalid field 'libraryHubsOnly' found, ignoring.
Mar 16, 2020 01:10:18.327 [0x7f30a77fe700] WARN - QueryParser: Invalid field 'contentDirectoryID' found, ignoring.
Mar 16, 2020 01:10:18.690 [0x7f30cbfff700] INFO - Sync: downloaded 0 sync list(s) with 0 sync items(s): 0 new, 0 updated, 0 deleted
Mar 16, 2020 01:10:18.690 [0x7f3081ffb700] WARN - Sync: local sync directory "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sync+" does not exist
Mar 16, 2020 01:10:21.491 [0x7f310d0d5700] ERROR - Error issuing curl_easy_perform(handle): 7
Mar 16, 2020 01:10:21.491 [0x7f310d0d5700] WARN - HTTP error requesting GET https://90-109-84-18.d8286f8642e045d09a5e85b016784b62.plex.direct:32400/identity (0, No error) (Failed to connect to 90-109-84-18.d8286f8642e045d09a5e85b016784b62.plex.direct port 32400: No route to host)
Mar 16, 2020 01:15:15.229 [0x7f310c8d4700] WARN - Deleted file "/tmp/logs.zip7889111a-160e-410a-89a0-5491dd0b7806" after connection reset
Mar 16, 2020 01:15:27.705 [0x7f30a67fc700] INFO - AutoUpdate: no updates available
Mar 16, 2020 01:15:44.085 [0x7f30a67fc700] ERROR - [Transcoder] [dca @ 0x1d85700] No valid DCA sub-stream found
Mar 16, 2020 01:15:44.085 [0x7f30a67fc700] ERROR - [Transcoder] [dca @ 0x1d85700] No valid DCA sub-stream found
Mar 16, 2020 01:15:44.086 [0x7f30a67fc700] ERROR - [Transcoder] [dca @ 0x1d85700] No valid DCA sub-stream found
15

I did not change the DEBUG settings as it was already Enabled.

As shown previously here:

Just to test, I disabled it, clicked SAVE CHANGES → no issues, “Your changes have been saved.”, enabled it again, saved → no issues “Your changes have been saved.”

Or am I doing it wrong? :confused:

16

Ah!!!

SETTINGS - SERVER - GENERAL

Not WEB player.

OOPS :slight_smile:

17

OMG I’m sorry…

Okay, just found the correct setting this time! Time to run the required actions again! It’s gonna be much better now…! :stuck_out_tongue:

18

Ok, here we go! Plex Media Server Logs_2020-03-16_01-42-45.zip (466.5 KB)

19

From my understanding of the logs it looks like transcoding actually works fine as far as the server is concerned, but whenever the client requests the transcoded data, it gets a 404 error?

20

Sorry for the delay (bit under the weather here).

  1. Thank you. Now I can see it doing as it should.
  2. Crashes are being uploaded. There’ve been problems.
  3. I see the Vmware adapters – No problem
  4. I see PMS decide transcoding is needed but this Xeon does not have Quick Sync Video hardware so the test fails (as it should)
Mar 16, 2020 01:39:58.126 [0x7f2fde7fc700] DEBUG - Selecting best audio stream for part ID 30764 (autoselect: 1 language: en)
Mar 16, 2020 01:39:58.126 [0x7f2fde7fc700] DEBUG - Audio Stream: 94374, Subtitle Stream: 94375
Mar 16, 2020 01:39:58.127 [0x7f2fde7fc700] DEBUG - Codecs: testing h264_vaapi (encoder)
Mar 16, 2020 01:39:58.131 [0x7f2fde7fc700] DEBUG - Codecs: hardware transcoding: testing API vaapi
Mar 16, 2020 01:39:58.131 [0x7f2fde7fc700] DEBUG - Codecs: hardware transcoding: opening hw device failed - probably not supported by this system, error: Input/output error
Mar 16, 2020 01:39:58.131 [0x7f2fde7fc700] DEBUG - Codecs: testing h264_nvenc (encoder)
Mar 16, 2020 01:39:58.131 [0x7f2fde7fc700] DEBUG - Codecs: hardware transcoding: testing API nvenc
Mar 16, 2020 01:39:58.147 [0x7f2fde7fc700] DEBUG - [FFMPEG] - Loaded lib: libcuda.so.1

It did find the Nvidia.

It does start to transcode.

Then it halts here:

Mar 16, 2020 01:40:13.133 [0x7f2fd5ffb700] DEBUG - Killing job.
Mar 16, 2020 01:40:13.133 [0x7f2fd5ffb700] DEBUG - Signalling job ID 2923 with 9
Mar 16, 2020 01:40:13.133 [0x7f2fd5ffb700] DEBUG - Job was already killed, not killing again.
Mar 16, 2020 01:40:13.133 [0x7f2fd5ffb700] DEBUG - Stopping transcode session o85tiecibfm0uj9ky6r7ipyt
Mar 16, 2020 01:40:13.134 [0x7f2fd5ffb700] DEBUG - Transcoder: Cleaning old transcode directories.
Mar 16, 2020 01:40:13.135 [0x7f2fd5ffb700] DEBUG - Transcoder: Cleaning old transcode directory: "/media/plextrs/Transcode/Sessions/plex-transcode-o85tiecibfm0uj9ky6r7ipyt-d574d8cc-f301-4d4d-830c-1fa40b68453e"
Mar 16, 2020 01:40:13.135 [0x7f2f717fe700] DEBUG - Streaming Resource: Terminated session 0x7f2f989720a0:42wayp3ftpgxlc8qn6u44t9i with reason Client stopped playback.
Mar 16, 2020 01:40:13.135 [0x7f2f717fe700] DEBUG - Streaming Resource: Removing session 0x7f2f989720a0:42wayp3ftpgxlc8qn6u44t9i

Is /media/plextrs a remote network mount point?

Also, the CPU has to burn the subtitles.

Segments=1&X-Plex-Session-Identifier=42wayp3ftpgxlc8qn6u44t9i
Mar 16, 2020 01:39:59.499 [0x7f2fdcff9700] DEBUG - Auth: authenticated user 1 as Kyhze
Mar 16, 2020 01:39:59.504 [0x7f2fdcff9700] DEBUG - We're going to try to auto-select an audio stream for account 1.
Mar 16, 2020 01:39:59.504 [0x7f2fdcff9700] DEBUG - Selecting best audio stream for part ID 30764 (autoselect: 1 language: en)
Mar 16, 2020 01:39:59.504 [0x7f2fdcff9700] DEBUG - Audio Stream: 94374, Subtitle Stream: 94375
Mar 16, 2020 01:39:59.505 [0x7f2fdcff9700] DEBUG - Found session GUID of o85tiecibfm0uj9ky6r7ipyt in session start.
Mar 16, 2020 01:39:59.505 [0x7f2fdcff9700] DEBUG - Cleaning directory for session o85tiecibfm0uj9ky6r7ipyt ()
Mar 16, 2020 01:39:59.505 [0x7f2fdcff9700] DEBUG - Starting a transcode session o85tiecibfm0uj9ky6r7ipyt at offset -1.0 (state=3)
Mar 16, 2020 01:39:59.506 [0x7f2fdcff9700] DEBUG - TPU: hardware transcoding: enabled, but no hardware decode accelerator found
Mar 16, 2020 01:39:59.506 [0x7f2fdcff9700] DEBUG - [Universal] Using local file path instead of URL: /media/raid/Library/Anime/Overlord III/[neko-kBaraka] Overlord III - 01 [BD][1080p][FLAC] [A6618C57].mkv
Mar 16, 2020 01:39:59.506 [0x7f2fdcff9700] DEBUG - TPU: hardware transcoding: zero-copy support not present
Mar 16, 2020 01:39:59.506 [0x7f2fdcff9700] DEBUG - TPU: hardware transcoding: final decoder: , final encoder: nvenc
Mar 16, 2020 01:39:59.506 [0x7f2fdcff9700] DEBUG - Job running: EAE_ROOT='/tmp/pms-ebcb294a-54eb-4a46-8f7e-c8a3738537bc/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/0bc617e-2965-linux-x86_64/' XDG_CACHE_HOME='/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache' XDG_DATA_HOME='/usr/lib/plexmediaserver/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/lib/plexmediaserver/Plex Transcoder' '-codec:0' 'h264' '-codec:1' 'flac' '-analyzeduration' '20000000' '-probesize' '20000000' '-i' '/media/raid/Library/Anime/Overlord III/[neko-kBaraka] Overlord III - 01 [BD][1080p][FLAC] [A6618C57].mkv' '-map_inlineass' '0:2' '-filter_complex' '[0:0]scale=w=1920:h=1080[0];[0]format=pix_fmts=yuv420p|nv12[1];[1]inlineass=font_scale=1.000000:font_path=/usr/lib/plexmediaserver/Resources/Fonts/DejaVuSans-Regular.ttf:fontconfig_file=/usr/lib/plexmediaserver/Resources/fonts.conf:language=en[2]' '-filter_complex' '[0:1] aresample=async=1:ocl='\''stereo'\'':osr=48000[3]' '-map' '[2]' '-metadata:s:0' 'language=jpn' '-codec:0' 'h264_nvenc' '-b:0' '14499k' '-maxrate:0' '19332k' '-bufsize:0' '38664k' '-forced-idr:0' '1' '-r:0' '23.975999999999999' '-force_key_frames:0' 'expr:gte(t,0+n_forced*1)' '-map' '[3]' '-metadata:s:1' 'language=jpn' '-codec:1' 'aac' '-b:1' '256k' '-f' 'dash' '-seg_duration' '1' '-init_seg_name' 'init-stream$RepresentationID$.m4s' '-media_seg_name' 'chunk-stream$RepresentationID$-$Number%05d$.m4s' '-window_size' '5' '-delete_removed' 'false' '-skip_to_segment' '1' '-time_delta' '0.0625' '-manifest_name' 'http://127.0.0.1:32400/video/:/transcode/session/o85tiecibfm0uj9ky6r7ipyt/d574d8cc-f301-4d4d-830c-1fa40b68453e/manifest?X-Plex-Http-Pipeline=infinite' '-avoid_negative_ts' 'disabled' '-map_metadata' '-1' '-map_chapters' '-1' 'dash' '-map' '0:2' '-f' 'null' '-codec' 'ass' 'nullfile' '-start_at_zero' '-copyts' '-vsync' 'cfr' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/o85tiecibfm0uj9ky6r7ipyt/d574d8cc-f301-4d4d-830c-1fa40b68453e/progress'
Mar 16, 2020 01:39:59.507 [0x7f2fdcff9700] DEBUG - Jobs: Starting child process with pid 2923
Mar 16, 2020 01:39:59.517 [0x7f2fde7fc700] DEBUG - Request: [10.40.0.23:45276 (WAN)] PUT /video/:

Not very fast of a CPU: 4000 Passmarks
It’s doing

  1. Decode in software
  2. Audio transcode
  3. Subtitle burning
  4. GPU management.