Transcoder errors after updating

@ChuckPa

It’s possible that some log entries weren’t included in the .zip as they are being sent to syslog. I’m attaching the /var/log/plexmediaserver logs in case that is what you are looking for.

plexmediaserver.log (28.2 MB)

Also, I did some testing, and all 1.23.x versions I have appear to be broken (1.23.1.4571, 1.23.1.4602, and 1.23.2.4656). It looks like this may be related to the following issue:

I also have the HW acceleration options checked and am running with an NVIDIA card.

I thought you had. I apologize – it’s been a very long week.

Let’s presume for a moment that it is a network / network resource issue.

I’ll ask the dumb questions and you all can tell me I’m smoking cheap stuff.

  1. Is the server on WiFi ?
  2. If on WiFi, is it on one of those goofy “Mesh” style devices?
  3. Do all players fail? Which ones are they? Which are wired and which are wifi ?

It doesn’t appear to be network related. I was seeing server crashes for any media that needed to be transcoded. I was able to replicate on a Roku Stick when I turned the direct play support off (to force transcoding on the server side). Rolling the server back to 1.22.3.4523 resolved the issue.

1 Like

@SunCat

WTH is the plexmediaserver.log file you’ve attached?

  1. It’s not a linux log
  2. I don’t recognize as any of the normal desktop app logs.

Your PMS log should look like this

Jun 06, 2021 21:10:15.718 [0x7f5c831a3b38] INFO - Plex Media Server v1.23.1.4528-c0513eb4c - Ubuntu PC x86_64 - build: linux-x86_64 debian - GMT -04:00
Jun 06, 2021 21:10:15.718 [0x7f5c831a3b38] INFO - Linux version: 16.04.7 LTS (Xenial Xerus), language: en-US
Jun 06, 2021 21:10:15.718 [0x7f5c831a3b38] INFO - Processor Intel(R) Xeon(R) Silver 4116 CPU @ 2.10GHz
Jun 06, 2021 21:10:15.718 [0x7f5c831a3b38] INFO - Compiler is - Clang 11.0.1 (https://plex.tv e0c29d5827bc4eaaa2ceb882cbeed224b0960173)
Jun 06, 2021 21:10:15.718 [0x7f5c831a3b38] INFO - /usr/lib/plexmediaserver/Plex Media Server

What you shared is:

Jun  6 03:55:40 schitzo PlexMediaServer[15523]:[warning] QueryParser: Invalid field 'pinnedContentDirectoryID' found, ignoring.
Jun  6 03:55:41 schitzo PlexMediaServer[15523]:[err] SQLITE3:0x80000001, 28, double-quoted string literal: "1969-12-31 23:00:00"
Jun  6 03:55:41 schitzo PlexMediaServer[15523]:[err] SQLITE3:0x80000001, 28, double-quoted string literal: "1969-12-31 23:00:00"
Jun  6 03:55:41 schitzo PlexMediaServer[15523]:[warning] QueryParser: Invalid field 'contentDirectoryID' found, ignoring.
Jun  6 03:55:41 schitzo PlexMediaServer[15523]:[warning] QueryParser: Invalid field 'contentDirectoryID' found, ignoring.
Jun  6 03:55:41 schitzo PlexMediaServer[15523]:[warning] QueryParser: Invalid field 'pinnedContentDirectoryID' found, ignoring.
Jun  6 03:55:41 schitzo PlexMediaServer[15523]:[warning] QueryParser: Invalid field 'pinnedContentDirectoryID' found, ignoring.
Jun  6 03:55:41 schitzo PlexMediaServer[15523]:[warning] QueryParser: Invalid field 'contentDirectoryID' found, ignoring.
  1. Turn DEBUG logging back on please

  2. Please do not edit / shorten the file. too many mistakes happen that way.

  3. I am challenging this:

Jun  6 03:39:22 schitzo PlexMediaServer[15523]:[warning] QueryParser: Invalid field 'pinnedContentDirectoryID' found, ignoring.
Jun  6 03:39:22 schitzo PlexMediaServer[15523]:[warning]

What is it from? Which system?

Some NAS systems do use the name PlexMediaServer

Regaring going back to 1.22.3 ----

  1. Going back means stagnating.
  2. That toolchain & its binaries are frozen. No new development
  3. If there is an issue, we do need to resolve it.
  4. Help is really appreciated here so I can make things right

@ChuckPa

At the moment I’m stuck on 1.22.1 since anything newer but before 1.23.x is already removed from the internet lol.

I have only one device on my network that uses Wi-Fi and it’s my phone.

My latest log should show my PC using the web app manually setting media to a lower quality to force the error.

@ChuckPa

Stand by a bit. I need to re-update to the broken release to re-gather logs.

For context, my server is running on a linux server with the main logs going to syslog:

[Service]
Environment=“PLEX_MEDIA_SERVER_USE_SYSLOG=true”

Since the logs I attached have been written by syslog, they will look a bit different from what you are used to.

A re-test and new upload coming soon…

@SunCat

Thank you for explaining the source of the logs.

We can’t use syslog captured logs.
I request you flip back to standard until we’re done.

Done. Here are the logs after switching back to standard logging, re-installing 1.23.2.4656, and replicating the transcode crash.
Plex Media Server Logs_2021-06-11_11-44-46.zip (1.5 MB)

I’m seeing a few of these in your log

WARN - HTTP error requesting GET https://192-168-0-195.6f8b033c81da412b9a2547fe7f3bbc0c.plex.direct:32400 (7, Couldn't connect to server) (Failed to connect to 192-168-0-195.6f8b033c81da412b9a2547fe7f3bbc0c.plex.direct port 32400: Connection refused)

The cannot connect errors are unrelated to the transcode errors we are currently chasing. The code always wants to try direct connecting to internal server IP addresses it may not have direct access to.

I re-ran a test with HW acceleration turned off. The server no longer crashes, but still spins when asked to transcode the media.

Plex Media Server Logs_2021-06-11_11-51-54.zip (1.6 MB)

Reviewing now. Not too worried about plex.direct at this time. Let’s get the big stuff first :slight_smile:

@SunCat

Please open a terminal window.
get into "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Crash Reports"

Drill down into this version directory and then into “PLEX MEDIA SERVER”

There will be a .dmp (or more) there.

Please ZIP up whatever you find and attach it.

This is my log after switching the episode from direct play to transcode. Chrome web player, wired connection on LAN.

Jun 07, 2021 07:36:12.136 [0x7f5c7264eb38] DEBUG - Request: [192.168.0.39:50873 (Allowed Network (Subnet))] GET /video/:/transcode/universal/decision?hasMDE=1&path=%2Flibrary%2Fmetadata%2F561089&mediaIndex=0&partIndex=0&protocol=dash&fastSeek=1&directPlay=0&directStream=1&subtitleSize=100&audioBoost=100&location=lan&maxVideoBitrate=2000&addDebugOverlay=0&autoAdjustQuality=0&directStreamAudio=1&mediaBufferSize=102400&session=23nzx5euqyokxdjt2xl1uot1&subtitles=burn&Accept-Language=en (43 live) TLS GZIP Signed-in Token (kazz3r24)
Jun 07, 2021 07:36:12.136 [0x7f5c7264eb38] DEBUG - [Transcode] Found session GUID of 23nzx5euqyokxdjt2xl1uot1 in session start.
Jun 07, 2021 07:36:12.136 [0x7f5c7264eb38] DEBUG - [Transcode] TranscodeUniversalRequest: using augmented profile Web
Jun 07, 2021 07:36:12.136 [0x7f5c7264eb38] DEBUG - [Transcode] Downloading document http://127.0.0.1:32400/library/metadata/561089?includeBandwidths=1&offset=-1&X-Plex-Incomplete-Segments=1&X-Plex-Session-Identifier=rwllybl07pr55f3uusjixykk
Jun 07, 2021 07:36:12.136 [0x7f5c7264eb38] DEBUG - [Transcode] Auth: authenticated user 1 as kazz3r24
Jun 07, 2021 07:36:12.148 [0x7f5c7264eb38] DEBUG - [Transcode] We're going to try to auto-select an audio stream for account 1.
Jun 07, 2021 07:36:12.148 [0x7f5c7264eb38] DEBUG - [Transcode] Selecting best audio stream for part ID 1538420 (autoselect: 1 language: en)
Jun 07, 2021 07:36:12.148 [0x7f5c7264eb38] DEBUG - [Transcode] We're going to try to auto-select a subtitle.
Jun 07, 2021 07:36:12.148 [0x7f5c7264eb38] DEBUG - [Transcode] Audio Stream: 3480892, Subtitle Stream: -1
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled up video bitrate to 13054Kbps based on 4.500000x fudge factor.
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Selected protocol dash; container: mp4
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: analyzing media item 1473214
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: Direct Play is disabled
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: media must be transcoded in order to use the dash protocol
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: no direct play video profile exists for http/mkv/hevc
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: no direct play video profile exists for http/mkv/hevc/eac3
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] Broken Trust - video.bitDepth limitation applies: 10 > 8
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: no remuxable profile found, so video stream will be transcoded
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Cannot direct stream video stream due to profile or setting limitations
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled up video bitrate to 13054Kbps based on 4.500000x fudge factor.
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Cannot direct stream audio stream due to codec eac3 when profile only allows aac
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Superman and Lois - S1 E6 - Broken Trust: selected media 0 / 1473214
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] Streaming Resource: Calculated bandwidth of 2369kbps exceeds bandwidth limit. Changing decision parameters provided by client to fit bandwidth limit of 2000kbps
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] Streaming Resource: Determining preferred transcode encoders through transcode only decision.
Jun 07, 2021 07:36:12.149 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled up video bitrate to 13054Kbps based on 4.500000x fudge factor.
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled up video bitrate to 13054Kbps based on 4.500000x fudge factor.
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Streaming Resource: Reducing playback quality for 1904kbps stream bitrate: video resolution to 720x328, audio channels to 2, quality to 60
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled up video bitrate to 13054Kbps based on 4.500000x fudge factor.
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled maximum bitrate for resolution reduction to 1830Kbps.
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Selected protocol dash; container: mp4
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: analyzing media item 1473214
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: Direct Play is disabled
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: media must be transcoded in order to use the dash protocol
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: no direct play video profile exists for http/mkv/hevc
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: no direct play video profile exists for http/mkv/hevc/eac3
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Broken Trust - video.bitDepth limitation applies: 10 > 8
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Broken Trust - audio.channels limitation applies: 6 > 2
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: E6 - Broken Trust: no remuxable profile found, so video stream will be transcoded
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Cannot direct stream video stream due to profile or setting limitations
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled up video bitrate to 13054Kbps based on 4.500000x fudge factor.
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Scaled maximum bitrate for resolution reduction to 1830Kbps.
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] Broken Trust - audio.channels limitation applies: 6 > 2
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Cannot direct stream audio stream due to profile or setting limitations
Jun 07, 2021 07:36:12.150 [0x7f5c7264eb38] DEBUG - [Transcode] MDE: Superman and Lois - S1 E6 - Broken Trust: selected media 0 / 1473214
Jun 07, 2021 07:36:12.150 [0x7f5c733bbb38] DEBUG - [Transcode] Killing job.
Jun 07, 2021 07:36:12.150 [0x7f5c733bbb38] DEBUG - [Transcode] Signalling job ID 41959 with 9
Jun 07, 2021 07:36:12.151 [0x7f5c733bbb38] DEBUG - [Transcode] Job was already killed, not killing again.

@kazz3r24

From that excerpt.

  1. HEVC HDR → H264
  2. Audio from 5.1 → stereo

what’s bothering me is I’m not seeing the transcoder invocation line.

That line would tell me exactly how it was launched.

Would you mind running this little jewel? ( i do have a swoopier way if you want it)

[chuck@lizum ~/bin.504]$ cat set-transcoder-debug 
#!/bin/sh
Token="$(cat "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Preferences.xml" | tail -1 | sed -e 's/.*PlexOnlineToken="//' | sed -e 's/".*//')"
curl http://127.0.0.1:32400/:/prefs/set\?TranscoderLogLevel=debug\&X-Plex-Token=$Token
echo Token=$Token
[chuck@lizum ~/bin.505]$

It sets the transcoder to DEBUG logging level :smiling_imp:

other values are error or verbose. I do not advise using either of those at this time.

OK. I was working on the previous request related to trying with the web player, so here is data from that experiment:

Fri Jun 11 ~12:05 PDT 2021 - plex web test
Fri Jun 11 ~12:06 PDT 2021 - Roku test (server HW accel unchecked)
Fri Jun 11 ~12:08 PDT 2021 - Roku test (server HW accel checked)

Plex Media Server Logs_2021-06-11_12-11-56.zip (1.8 MB)

I also looked for some dump files, but am unable to find any for the current 1.23.2.4656 release. I’m attaching the most recent dump from my test with 1.23.1.4602 in case it helps.

6a7958fe-31db-4445-e1a2cba6-e1ec4577.dmp.gz (156.2 KB)

I think I have what I need for the server stuff.

Is the Roku app still open?
Is logging enabled?

If so, would you please grab its logs too?

I’ll take the PMS logs and the Roku logs to the dev

OK. I tried your recommendation for enabling the transcoder debug, and enabled the Roku remote logging for the test at ~ Fri Jun 11 12:34: PDT 2021 (user SunCat / plex@solgatos.com). I’m also attaching the latest log file dump from that test.

Plex Media Server Logs_2021-06-11_12-37-18.zip (1.9 MB)

Video is just HEVC 10-bit, not sure why the audio would be transcoding - my PC it was playing on has 5.1 sound, it should have just brought the video down to 720p… so that’s weird.

I can run script, but I’m going to have to spin up a VM or something and install Plex on it, see if I can reproduce the error that way, my server is almost always busy.

Ah, perfect! Hopefully you find what you need in @SunCat’s log

@SunCat

Did you also grab the Roku log files as it instructed in the Support page?