Receiving transcoding error without config changes

Plex Media Server NAS & Devices
1

Server Version#: 1.21.2.3943 running on a Synology DS218play using DSM 6.2.3-25426 Update 3
Player Version#: 1.20.0.1406-f47a81b7 on Windows 10 Pro 1909 and Plex Web 4.51.1 on Chrome 88.0.4324.104 x64

With (to my knowledge) no config changes whatsoever, today I went from being able to play back all of the videos on my server to being able to play only older and/or smaller ones. Having tested it with all of the available variations, it looks like this primarily - if not solely - affects files that are both from the past three-or-so months and larger than around 1 GB.

Both the desktop player and the web version of the Plex player produce the message “Conversion failed. The transcoder exited due to an error.” The corresponding system log shows “ERROR - [Transcode] Error creating directory “/Plex/tmp_transcoding”: Permission denied” when the video attempts to play back. That directory already exists with all of the correct permissions; I’ve verified this by applying this fix and then completely uninstalling and reinstalling the server software (with a reboot in between and with an upgrade from the last published Synology-specific package to the latest version downloaded from the main Plex website) when that didn’t work. However, even after that the issue persists with identical symptoms.

The connection speed is definitely not the problem here, nor is the processor resource availability for the transcoder, since all of the affected videos played without issue with the same configuration as recently as earlier today. During my troubleshooting attempts I’ve disabled or changed a number of settings - transcoding on and off, maximum bitrate, etc. - but since none of them appeared to have any impact on the issue I reverted them to their previous states.

Here are the logs I’ve extracted. The most recent Plex Media Server.log file reflects the issue as of my latest attempt, but I’ve included the zip with all of them just in case any of the rest is useful. I’ve got it set to debug level, so hopefully there isn’t too much chaff in there.

Plex Media Server Logs_2021-02-04_23-25-59.zip (1.5 MB)

Does anyone know what else to do with this beyond what I’ve already tried? Please let me know if there’s anything I can do to speed along the process of getting this sorted out.

3

Those steps were all part of my initial troubleshooting attempts, but as a good-faith attempt I’ve followed again to the letter. After finishing them I’ve restarted PMS and the exact same symptoms persist.

That said, I think there are two issues here. First, obviously, the fact that the Plex account is missing permissions to its own folders (again, explicitly asserted to no apparent effect), but also that the transcoder is kicking in when it shouldn’t. The bandwidth limit has been fully disabled for all clients during this process, and it’s sending over the LAN instead of an external connection. The need to transcode 6-channel audio down to 2-channel is legitimate though audio direct streaming is (to my knowledge) fully enabled, but even still that shouldn’t demand a transcode down to 480p.

So, where do we go from here, since explicitly asserting those permissions again didn’t work? Is there something else that needs to happen after the steps you provided but before spinning the Plex server back up again?

4

@cogthecat

Trumpy and I have been looking at your logs.

One thing which bothers me is that your PMS files are being modified as PMS is trying to use them.

In this case, the SubZero agent is being modifed.
Please notice the date-time stamps are altered.

Do you have your media in the Plex shared folder?
Do you have anything which “reaches into” the Plex share and modifies permissions or anything else?

1 23:25:23.605 [0x7f846031a0] DEBUG - Completed: [10.0.1.100:56878] 200 GET /:/prefs (10 live) TLS GZIP 1535ms 6861 bytes (pipelined: 5)
Feb 04, 2021 23:25:23.991 [0x7f5fa231a0] DEBUG - HTTP 200 response from GET http://127.0.0.1:35147/system/:/prefs
Feb 04, 2021 23:25:23.991 [0x7f5fa231a0] DEBUG - [com.plexapp.system] HTTP reply status 200, with 418 bytes of content.
Feb 04, 2021 23:25:23.992 [0x7f846031a0] DEBUG - Completed: [10.0.1.100:56892] 200 GET /system/:/prefs (10 live) TLS GZIP 1267ms 734 bytes (pipelined: 1)
Feb 04, 2021 23:25:24.043 [0x7f843151a0] DEBUG - Auth: authenticated user 1 as cogthecat
Feb 04, 2021 23:25:24.044 [0x7f7fc901a0] DEBUG - Request: [10.0.1.100:56894 (Subnet)] GET /:/websockets/notifications?filters=log (11 live) TLS GZIP Signed-in Token (cogthecat)
Feb 04, 2021 23:25:24.044 [0x7f7fc901a0] DEBUG - WebSocket: Performing handshake from origin file://
Feb 04, 2021 23:25:24.044 [0x7f7fc901a0] DEBUG - Beginning read from WebSocket
Feb 04, 2021 23:25:24.094 [0x7f846031a0] DEBUG - Auth: authenticated user 1 as cogthecat
Feb 04, 2021 23:25:24.094 [0x7f7c99f1a0] DEBUG - Request: [10.0.1.100:56892 (Subnet)] GET /activities (11 live) TLS GZIP Signed-in Token (cogthecat)
Feb 04, 2021 23:25:24.094 [0x7f846031a0] DEBUG - Completed: [10.0.1.100:56892] 200 GET /activities (11 live) TLS GZIP 0ms 350 bytes (pipelined: 2)
Feb 04, 2021 23:25:26.063 [0x7f7fc901a0] DEBUG - Request: [127.0.0.1:39040 (Loopback)] GET /library/sections (12 live) GZIP Signed-in Token (cogthecat)
Feb 04, 2021 23:25:26.835 [0x7f843151a0] DEBUG - Completed: [127.0.0.1:39040] 200 GET /library/sections (12 live) GZIP 772ms 962 bytes
Feb 04, 2021 23:25:26.960 [0x7f5fa231a0] DEBUG - Request: [127.0.0.1:39044 (Loopback)] GET /system/agents (12 live) GZIP Signed-in Token (cogthecat)
Feb 04, 2021 23:25:26.960 [0x7f5fa231a0] DEBUG - [com.plexapp.system] Sending command over HTTP (GET): /system/agents
Feb 04, 2021 23:25:26.961 [0x7f5fa231a0] DEBUG - HTTP requesting GET http://127.0.0.1:35147/system/agents
Feb 04, 2021 23:25:27.189 [0x7f5fa231a0] DEBUG - HTTP 200 response from GET http://127.0.0.1:35147/system/agents
Feb 04, 2021 23:25:27.189 [0x7f5fa231a0] DEBUG - [com.plexapp.system] HTTP reply status 200, with 11383 bytes of content.
Feb 04, 2021 23:25:28.066 [0x7f843151a0] DEBUG - Completed: [127.0.0.1:39044] 200 GET /system/agents (12 live) GZIP 1106ms 2127 bytes
Feb 04, 2021 23:25:28.109 [0x7f7f0d81a0] DEBUG - Request: [127.0.0.1:39050 (Loopback)] GET /system/agents/com.plexapp.agents.none/config/1 (12 live) GZIP Signed-in Token (cogthecat)
Feb 04, 2021 23:25:28.109 [0x7f7f0d81a0] DEBUG - [com.plexapp.system] Sending command over HTTP (GET): /system/agents/com.plexapp.agents.none/config/1
Feb 04, 2021 23:25:28.110 [0x7f7f0d81a0] DEBUG - HTTP requesting GET http://127.0.0.1:35147/system/agents/com.plexapp.agents.none/config/1
Feb 04, 2021 23:25:28.695 [0x7f7f0d81a0] DEBUG - HTTP 200 response from GET http://127.0.0.1:35147/system/agents/com.plexapp.agents.none/config/1
Feb 04, 2021 23:25:28.696 [0x7f7f0d81a0] DEBUG - [com.plexapp.system] HTTP reply status 200, with 982 bytes of content.
Feb 04, 2021 23:25:28.697 [0x7f843151a0] DEBUG - Completed: [127.0.0.1:39050] 200 GET /system/agents/com.plexapp.agents.none/config/1 (12 live) GZIP 587ms 734 bytes
Feb 04, 2021 23:25:28.775 [0x7f7c3c31a0] DEBUG - File "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Code" changed: 2021-02-04 21:39:12 (1612499952) => 2021-02-04 23:25:05 (1612506305).
Feb 04, 2021 23:25:28.775 [0x7f7c3c31a0] DEBUG - File "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Info.plist" changed: 2021-02-04 21:39:12 (1612499952) => 2021-02-04 23:25:05 (1612506305).
Feb 04, 2021 23:25:28.775 [0x7f7c3c31a0] DEBUG - File "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Code/logger.py" changed: 2021-02-04 21:39:12 (1612499952) => 2021-02-04 23:25:05 (1612506305).
Feb 04, 2021 23:25:28.775 [0x7f7c3c31a0] DEBUG - File "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Code/__init__.py" changed: 2021-02-04 21:39:12 (1612499952) => 2021-02-04 23:25:05 (1612506305).
Feb 04, 2021 23:25:28.775 [0x7f7c3c31a0] DEBUG - Changed: "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Code"
Feb 04, 2021 23:25:28.864 [0x7f5fa231a0] DEBUG - Request: [127.0.0.1:39056 (Loopback)] GET /system/agents/com.plexapp.agents.none/config/2 (12 live) GZIP Signed-in Token (cogthecat)
Feb 04, 2021 23:25:28.864 [0x7f5fa231a0] DEBUG - [com.plexapp.system] Sending command over HTTP (GET): /system/agents/com.plexapp.agents.none/config/2
Feb 04, 2021 23:25:28.864 [0x7f5fa231a0] DEBUG - HTTP requesting GET http://127.0.0.1:35147/system/agents/com.plexapp.agents.none/config/2
Feb 04, 2021 23:25:28.933 [0x7f7c3c31a0] DEBUG - Changed: "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Info.plist"
Feb 04, 2021 23:25:28.933 [0x7f7c3c31a0] DEBUG - Changed: "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Code/logger.py"
Feb 04, 2021 23:25:28.933 [0x7f7c3c31a0] DEBUG - Changed: "/volume1/Plex/Library/Application Support/Plex Media Server/Plug-ins/Sub-Zero.bundle/Contents/Code/__init__.py"
Feb 04, 2021 23:25:28.950 [0x7f5fa231a0] DEBUG - HTTP 200 response from GET http://127.0.0.1:35147/system/agents/com.plexapp.agents.none/config/2
Feb 04, 2021 23:25:28.950 [0x7f5fa231a0] DEBUG - [com.plexapp.system] HTTP reply status 200, with 990 bytes of content.
Feb 04, 2021 23:25:28.951 [0x7f846031a0] DEBUG - Completed: [127.0.0.1:39056] 200 GET /system/agents/com.plexapp.agents.none/config/2 (12 live) GZIP 86ms 757 bytes
Feb 04, 2021 23:25:28.967 [0x7f7c99f1a0] DEBUG - Request: [127.0.0.1:39062 (Loopback)] GET /system/agents/com.plexapp.agents.imdb/config/1 (12 live) GZIP Signed-in Token (cogthecat)
Feb 04, 2021 23:25:28.968 [0x7f7c99f1a0] DEBUG - [com.plexapp.system] Sending command over HTTP (GET): /system/agents/com.plexapp.agents.imdb/config/1
Feb 04, 2021 23:25:28.968 [0x7f7c99f1a0] DEBUG - HTTP requesting GET http://127.0.0.1:35147/system/agents/com.plexapp.agents.imdb/config/1
Feb 04, 2021 23:25:29.194 [0x7f7c99f1a0] DEBUG - HTTP 200 response from GET http://127.0.0.1:35147/system/agents/com.plexapp.agents.imdb/config/1
Feb 04, 2021 23:25:29.194 [0x7f7c99f1a0] DEBUG - [com.plexapp.system] HTTP reply status 200, with 1030 bytes of content.
Feb 04, 2021 23:25:29.196 [0x7f843151a0] DEBUG - Completed: [127.0.0.1:39062] 200 GET /system/agents/com.plexapp.agents.imdb/config/1 (12 live) GZIP 228ms 737
5

Plex is on a shared volume containing all of its media. The only things that interact with that volume automatically are Plex itself, Sonarr, and Radarr (neither of which as far as I know mess with permissions in any way). Obviously I’ve been poking around via DSM and Windows, but I’ve only changed what we’ve talked about in this thread.

For those changes in particular I’m not 100% sure I didn’t do that, since my initial attempts at troubleshooting were admittedly pretty clumsy since I had a poor understanding of the issue at the time and those timestamps are well after I started.

7

Allow Failback to Insecure Connections was set for LAN only, but I’ve swapped it to Never. The others are already configured that way, and my computer has compatible hardware. Same issue so far.

9

Updating the client now, mostly as a best-practice, but I can’t imagine how that or my Windows version could be related to the permissions of the Plex service on my DS218play, given that the issue has been verified across multiple platforms. I should have mentioned in my initial post that I’ve also verified this on a Windows 7 machine (browser only), two phones (one Android, one iOS), one other PC whose OS I’m not certain of (browser only), and a Roku. Most of those tests happened before I was aware of what the issue was and didn’t reflect any of my troubleshooting, but I’ve just tested it again on the Roku device with the same problem.

To be clear, are we currently checking the issue of why it’s choosing to transcode when there seems not to be a need for it, or are we checking the permissions problem? They seem unrelated except that both behaviors are triggered by the same action. I think the transcoding thing is pretty low-priority since the NAS should be able to perform the transcode no problem even if it isn’t necessary, but solving that might let me limp along for the affected media files until the bigger permissions issue can be solved.

10

I’ve just been poking around to look for examples and counterexamples and I’ve discovered something interesting. Two media files from the same show share the same filetypes and encodings with the only differences according to the Media Info modal being filesize (3.35 GB vs. 2.54 GB), duration (51:48 vs. 39:32), bitrate (9257 vs. 9210), and the Indexes field for the first being blank and the second showing “sd”. The first fails, the second works, the episode after (which has very similar parameters) fails. Presumably this is because for some reason the working one isn’t calling the transcoder, but I don’t understand why that would be the case for this media file in particular but not the other ones around it in (seemingly) identical formats and comparable sizes.

Also updating the desktop app did nothing, unfortunately, and testing it on other platforms again also failed.

11

And another new development: the transcoder actually works! But only for some media. Someone just accessed a file other than the ones we’ve been working on and while the poor underspecced CPU on the DS218play is really getting thrashed by it, it is still transcoding successfully in the same folder it’s been griping about this whole time.

So that leaves the most likely culprit being the specific files. I don’t understand why or how that could happen, but it’s the only thing left that I can imagine might cause this.

12

Update: The issue appears to be data corruption on the individual video files. I have absolutely no idea how this happened (my NAS’s logs show no noteworthy events on the day in question) or what that has to do with the transcoder thinking it doesn’t have the right permissions, but I narrowed it down to all-so-far of the files modified in a specific 24-hour period a few weeks ago. Every file I’ve tested in that span and no files outside it have this issue.

I’m going to call this matter settled for the time being, but I’ve kept the affected files if it would be helpful for your analysis to hopefully make it so no one else has to deal with this headache.

14

As I said I didn’t have any unusual events on that day according to the logs. I’ve had power outages before and I don’t have a UPS (obviously that’s the likeliest cause of the corruption in the first place), but every time an event like that occurs it’s properly logged. The logs show nothing of the sort.

15

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