After 1.7.6 Post Processing Not moving remuxed/transcoded file

Originally when TS was used, I had no problems. I would convert the file from .ts to .mkv, delete the .ts version and when my postprocessing script was complete, Plex would move the output to the appropriate location.

When they changed to .mkv, I modified my script to rename the plex created .mkv file, transcode it as I wished to the plex created .mkv file, delete the source file, and when processing was complete plex would move the output to the appropriate location.

Now with the 1.7.6 - the filetype is .ts
I modified the script to transcode the .ts to .mkv and when finished delete the .ts fille.

It isn’t working at all. I’ve traced the script, it is working fine when used outside of postprocessing. It seems with the latest change that postprocessing no longer call the script. It is being skipped.

I’m seeing the same , everything just st hangs after recording and never gets passed off to post processing

One step forward, two steps back.

FWIW, I use the script found here reddit.com/r/PleX/comments/52v7vd/guide_commercialfree_experience_with_plex_dvr/ as my post-processing script to have MCEBuddy/comskip strip commercials. It continues to work just fine after upgrading to 1.7.6 yesterday (it doesn’t care about the extension; it just uses the filename passed into it by Plex). I’d recommend checking your logs to see if there is mention of Plex attempting to call your post-processing script, and any results of that attempt.

Here is a bit more information that was requested:

@sa2000 said:
» show previous quotes

Please could you provide logs and information about the setup of the post processing scripts so it can be referred to the
development team. If you could ensure debug logging is enabled on the server, restart the server and then get the logs for a >> recording and after it finishes and info on the post processing. If you have already raised it as an issue, please let me have >> the link to the topic / post
I presume you have already edited the post processing script to now look for .ts file instead of .mkv ?

Yes, I have debugging on and have also turned it on for the bash script. Nothing is showing up in the logs. It’s as if I haven’t specified a post-processing script. As I mentioned above, I’ve used this script (with modifications of course) when .ts was previously used and when the format was switched to .mkv - no issues.

Yes, I have modified the script to process .ts to .mkv. In addition, if I run the script myself, it works fine.

Here is the script:

#! /usr/bin/env bash

file=$1

lang_list="eng, spa, fre, por, und"
handbrake="HandBrakeCLI"

full_filename=${file##*/}
full_directory=${file%/*}
filename=${full_filename%.*}
filetype=${full_filename#*.}

source "/vault/plex_utils/src_tp_ck_codec"
source "/vault/plex_utils/src_static_plex_table"

filemkv=$full_directory"/"$filename".mkv"

handbrake_options="-e ${output_codec[$index]} -q ${output_quality[$index]} -r 30 --pfr -B 192 --subtitle-lang-list $lang_list"

"$handbrake" -i "$file" -o "$filemkv" $handbrake_options < /dev/null

if [ $? = 0 ]; then
        rm "$file"
fi

exit

@rwhapham said:
FWIW, I use the script found here reddit.com/r/PleX/comments/52v7vd/guide_commercialfree_experience_with_plex_dvr/ as my post-processing script to have MCEBuddy/comskip strip commercials. It continues to work just fine after upgrading to 1.7.6 yesterday (it doesn’t care about the extension; it just uses the filename passed into it by Plex). I’d recommend checking your logs to see if there is mention of Plex attempting to call your post-processing script, and any results of that attempt.

Thanks for the reply, yes I checked the logs, nothing - as I mentioned it as if the script isn’t being called. Isn’t mcebuddy for windows… if so, that might be why it is still working for you. I’m running on Fedora Linux.

Here is the output of in the log of a program I recorded starting at 09:20. As you can see, it says absolutely nothing about the post-processing script. The show ended at 09:30 which is when the post processing script should have run. It apparently did not:
Jul 13, 2017 09:20:39.763 [0x7f4f7d3fa700] ERROR - Unable to find title for item of type 5 Jul 13, 2017 09:20:39.763 [0x7f4f7d3fa700] ERROR - Unable to find title for item of type 5 Jul 13, 2017 09:20:40.142 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.161 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.171 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.180 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.200 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.209 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.218 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.247 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.249 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.257 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.286 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.295 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.305 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.324 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.334 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.335 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.363 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.372 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.373 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.392 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.401 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.402 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.429 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.439 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.440 [0x7f4f7cbf9700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.545 [0x7f4f7dbfb700] ERROR - [Transcoder] [mpeg2video @ 0x1c232a0] Invalid frame dimensions 0x0. Jul 13, 2017 09:20:40.617 [0x7f4f7d3fa700] ERROR - Unable to find title for item of type 5 Jul 13, 2017 09:20:40.617 [0x7f4f7d3fa700] ERROR - get - invalid frameRate value: 59.940 Jul 13, 2017 09:20:40.617 [0x7f4f7d3fa700] ERROR - Unable to find title for item of type 5 Jul 13, 2017 09:21:36.927 [0x7f4f7d3fa700] ERROR - Error issuing curl_easy_perform(handle): 28 Jul 13, 2017 09:30:04.407 [0x7f4f9b7ff700] WARN - No matches for search. Jul 13, 2017 09:30:04.635 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:04.635 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F9257455 Jul 13, 2017 09:30:04.792 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:04.792 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F10551643 Jul 13, 2017 09:30:04.794 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:04.794 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F11770893 Jul 13, 2017 09:30:04.899 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:04.899 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F185113 Jul 13, 2017 09:30:04.903 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:04.903 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F3563021 Jul 13, 2017 09:30:05.299 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.299 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F11775284 Jul 13, 2017 09:30:05.470 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.470 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F13139727 Jul 13, 2017 09:30:05.474 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.474 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F12993857 Jul 13, 2017 09:30:05.493 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.493 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F13043704 Jul 13, 2017 09:30:05.496 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.496 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F13043704 Jul 13, 2017 09:30:05.500 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.500 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F12730145 Jul 13, 2017 09:30:05.503 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.503 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fepisode%2F7848813%2F2017-05-28 Jul 13, 2017 09:30:05.506 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.506 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fepisode%2F3554620%2F2017-05-28 Jul 13, 2017 09:30:05.533 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.533 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fepisode%2FEP000000351365 Jul 13, 2017 09:30:05.536 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.536 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fepisode%2F676925%2F2017-07-09 Jul 13, 2017 09:30:05.539 [0x7f4f7d3fa700] ERROR - downloadContainer: expected MediaContainer element, found html Jul 13, 2017 09:30:05.539 [0x7f4f7d3fa700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fepisode%2FEP011761321049

@gbcox said:
Thanks for the reply, yes I checked the logs, nothing - as I mentioned it as if the script isn’t being called. Isn’t mcebuddy for windows… if so, that might be why it is still working for you. I’m running on Fedora Linux.

Yes, I’m running on Windows. So, you’re right, that might be the difference.

Duh… I didn’t have debugging on. Here is the log so it’s finding the script after all… but my “set -x” output isn’t showing in the log - so I don’t see the issue. Does anyone know how to get bash script trace output to show up in the log? Here is the snippet:

Jul 13, 2017 16:00:01.267 [0x7fc0af7ff700] DEBUG - DVR:Grabber: Freed a tuner (now 2 available)
Jul 13, 2017 16:00:01.267 [0x7fc0af7ff700] DEBUG - DVR:Grabber: Recording for 'KTLA 5 News at 3 - Episode 07-13' stopped with status cancelled.
Jul 13, 2017 16:00:01.267 [0x7fc0c9bff700] DEBUG - DVR:Recorder: Asked to stop recording 'KTLA 5 News at 3 - Episode 07-13'.
Jul 13, 2017 16:00:01.267 [0x7fc0af7ff700] DEBUG - Activity: updated activity 84ba6cc8-3b53-4fb9-99b9-361b7bfc1452 - completed 100% - Recording
Jul 13, 2017 16:00:01.268 [0x7fc0af7ff700] DEBUG - Job running: '/vault/plex_utils/plex_post' '/bzb/bzb3/vault/gcstar/films_pictures/hd_dvr/Shows/.grab/6a43aeb00fba49a2a6f0a1fbab6026a632e44680/KTLA 5 News at 3 (2015) - 2017-07-13 00 00 00 - Episode 07-13.ts'
Jul 13, 2017 16:00:01.271 [0x7fc0af7ff700] VERBOSE - Jobs: Starting child process with pid 6962
Jul 13, 2017 16:00:01.289 [0x7fc0bc7ff700] DEBUG - EPG[onconnect]: Next thing to start/end is at 2017-07-13 23:05:00 (in 300 seconds)
Jul 13, 2017 16:00:01.300 [0x7fc0c8bff700] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication.
Jul 13, 2017 16:00:01.300 [0x7fc0c8bff700] DEBUG - Auth: authenticated user 1 as gbcox
Jul 13, 2017 16:00:01.300 [0x7fc0c8bff700] DEBUG - Auth: Came in with a super-token, authorization succeeded.
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] DEBUG - Request: [192.168.1.10:59516 (Subnet)] GET /status/sessions/background (13 live) TLS GZIP Signed-in Token (gbcox)
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * Host => 192-168-1-10.fe6cd840f03845cbbf5d0857823db8ad.plex.direct:32400
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * User-Agent => Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:54.0) Gecko/20100101 Firefox/54.0
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * Accept => text/plain, */*; q=0.01
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * Accept-Language => en
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * Accept-Encoding => gzip, deflate, br
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * Referer => https://app.plex.tv/web/app
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * Origin => https://app.plex.tv
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * Connection => keep-alive
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Client-Identifier => a62f9260-b5e0-4c0e-b3a0-a98164325581
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Device => Linux
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Device-Name => Plex Web (Firefox)
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Device-Screen-Resolution => 1672x816,1920x1080
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Platform => Firefox
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Platform-Version => 54.0
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Product => Plex Web
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx
Jul 13, 2017 16:00:01.301 [0x7fc0ba3ff700] VERBOSE -  * X-Plex-Version => 3.11.0
Jul 13, 2017 16:00:01.302 [0x7fc0ba3ff700] VERBOSE - It took 0.0 sec to serialize a list with 0 elements.
Jul 13, 2017 16:00:01.303 [0x7fc0c83fe700] DEBUG - Completed: [192.168.1.10:59516] 200 GET /status/sessions/background (13 live) TLS GZIP 2ms 470 bytes (pipelined: 4)
Jul 13, 2017 16:00:01.311 [0x7fc0c4ffe700] VERBOSE - JobManager: child process with PID 6962 exited
Jul 13, 2017 16:00:01.311 [0x7fc0af7ff700] DEBUG - Jobs: '/vault/plex_utils/plex_post' exit code for process 6962 is 0
Jul 13, 2017 16:00:01.311 [0x7fc0af7ff700] DEBUG - DVR:Recorder: Postprocessing script '/vault/plex_utils/plex_post' was successful in 0.0 seconds. Nicely done.
Jul 13, 2017 16:00:01.311 [0x7fc0af7ff700] DEBUG - DVR:Grabber: Scheduling 'KTLA 5 News at 3 - Episode 07-13' for assimilation.
Jul 13, 2017 16:00:01.315 [0x7fc0c67d2700] DEBUG - DVR:Subscription: Failed to resolve subscription for 'grandparentGuid: com.gracenote.onconnect://show/11371685 grandparentThumb: http://tmsimg.plex.tv/assets/p11371685_b_v8_aa.jpg grandparentTitle: KTLA 5 News at 3 grandparentYear: 2015 guid: com.gracenote.onconnect://episode/11371685/2017-07-13 originallyAvailableAt: 2017-07-13 parentIndex: 2017 title:  type: 4 year: 2017' to library item
Jul 13, 2017 16:00:01.315 [0x7fc0c67d2700] DEBUG - DVR:Grabber: Postprocessing, we're going to put `KTLA 5 News at 3 - Episode 07-13` in `/bzb/bzb3/vault/gcstar/films_pictures/hd_dvr/Shows/KTLA 5 News at 3 (2015)/Season 2017/KTLA 5 News at 3 (2015) - 2017-07-13 00 00 00 - Episode 07-13.ts`
Jul 13, 2017 16:00:01.315 [0x7fc0c67d2700] DEBUG - DVR:Grabber: Moving /bzb/bzb3/vault/gcstar/films_pictures/hd_dvr/Shows/.grab/6a43aeb00fba49a2a6f0a1fbab6026a632e44680/KTLA 5 News at 3 (2015) - 2017-07-13 00 00 00 - Episode 07-13.ts to /bzb/bzb3/vault/gcstar/films_pictures/hd_dvr/Shows/KTLA 5 News at 3 (2015)/Season 2017/KTLA 5 News at 3 (2015) - 2017-07-13 00 00 00 - Episode 07-13.ts

may be what you need is to have your own log file you write to from within your script - so that you can see what your script is doing at every stage

The Plex Media Server log shows it starting at 16:00:01.268 and completing at 16:00:01.311

Thanks, didn’t think of that… here is the problem:

  • filemkv=’/bzb/bzb3/vault/gcstar/films_pictures/hd_dvr/Shows/.grab/4760d9f19612bb12518ab5963cbc4db0c6ae6297/Justice for All With Judge Cristina Perez (2012) - 2016-11-23 00 00 00 - Treehouse Misadventures & Pay for What.mkv’
  • handbrake_options=’-e X265 -q 20 -r 30 --pfr -B 192 --subtitle-lang-list eng, spa, fre, por, und’
  • HandBrakeCLI -i ‘/bzb/bzb3/vault/gcstar/films_pictures/hd_dvr/Shows/.grab/4760d9f19612bb12518ab5963cbc4db0c6ae6297/Justice for All With Judge Cristina Perez (2012) - 2016-11-23 00 00 00 - Treehouse Misadventures & Pay for What.ts’ -o ‘/bzb/bzb3/vault/gcstar/films_pictures/hd_dvr/Shows/.grab/4760d9f19612bb12518ab5963cbc4db0c6ae6297/Justice for All With Judge Cristina Perez (2012) - 2016-11-23 00 00 00 - Treehouse Misadventures & Pay for What.mkv’ -e X265 -q 20 -r 30 --pfr -B 192 --subtitle-lang-list eng, spa, fre, por, und
    HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by HandBrakeCLI)
    HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
    HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
    HandBrakeCLI: /usr/lib/plexmediaserver/libz.so.1: version `ZLIB_1.2.9’ not found (required by /lib64/libpng16.so.16)
  • ‘[’ 1 = 0 ‘]’
  • exit
    This just started happening with 1.7.6 - prior releases didn’t have this issue… Please advise.

full PMS log please so I can establish the exact build and platform - or just get me the first 4 lines of the Plex Media Server.log

And which version worked ok?

Thanks for the quick response:
Here are the first lines of the log:
Jul 13, 2017 16:41:58.455 [0x7f9def059700] INFO - Plex Media Server v1.7.6.4058-8fa494d15 - ubuntu PC x86_64 - build: linux-ubuntu-x86_64 redhat - GMT -07:00
Jul 13, 2017 16:41:58.455 [0x7f9def059700] INFO - Linux version: 4.11.9-300.fc26.x86_64 (#1 SMP Wed Jul 5 16:21:56 UTC 2017), language: en-US
Jul 13, 2017 16:41:58.455 [0x7f9def059700] INFO - Processor AMD FX™-8350 Eight-Core Processor
Jul 13, 2017 16:41:58.455 [0x7f9def059700] INFO - /usr/lib/plexmediaserver/Plex Media Server
Jul 13, 2017 16:41:58.578 [0x7f9debbfd700] INFO - Successfully retrieved OCSP response
Jul 13, 2017 16:42:02.132 [0x7f9de07ff700] INFO - SQLITE3:0x10, 283, recovered 910 frames from WAL file /var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Plug-in Support/Databases/tv.plex.providers.epg.onconnect-5c0f4935-d102-428a-af84-f1d40bdc21c5.db-wal
Jul 13, 2017 16:42:02.207 [0x7f9dd9bff700] ERROR - downloadContainer: expected MediaContainer element, found html
Jul 13, 2017 16:42:02.208 [0x7f9dd9bff700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F9257455
Jul 13, 2017 16:42:02.384 [0x7f9dd9bff700] ERROR - downloadContainer: expected MediaContainer element, found html
Jul 13, 2017 16:42:02.384 [0x7f9dd9bff700] WARN - DVR:Subscription: No container available for /tv.plex.providers.epg.onconnect:6/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F10551643

As an aside - what is with the MediaContainer and DVR:Subscription errors. They are filling up my log.

I noticed that plex includes it’s own version of libxml2.so.2 and libz.so.1 - so I believe what is happening is that when I run the post processing script in the plex environment, HandBrakeCLI picks up the plex versions and complains.

When I run from my own environment using sudo plex handbrakecli, everything works fine because it is picking up the Fedora version.

As I mentioned, I haven’t encountered this issue before prior to the 1.7.6 release. Versions 1.7.5 and prior worked fine with handbrake.

Just to help other people who may encounter this issue before it is fixed:

To trace your bash script, insert:
set -x
after the #! line in your script

If you want to direct log output to a file for debugging purposes, insert:
logfile="path_to_logfile_that_you_want_to_create"
then insert:
exec > $logfile 2>&1

Lastly, to temporarily circumvent this issue, within your bash script export the path that you want to take preference. This
will effectively bypass the PLEX provided libraries and allow your script to run correctly. In the example below, the path provided is for Fedora 26. Your distribution may be different.

export LD_LIBRARY_PATH="/usr/lib64"

@gbcox said:
I noticed that plex includes it’s own version of libxml2.so.2 and libz.so.1 - so I believe what is happening is that when I run the post processing script in the plex environment, HandBrakeCLI picks up the plex versions and complains.

When I run from my own environment using sudo plex handbrakecli, everything works fine because it is picking up the Fedora version.

As I mentioned, I haven’t encountered this issue before prior to the 1.7.6 release. Versions 1.7.5 and prior worked fine with handbrake.

Thanks for all the information

I am sorry to be persistent on this but i need to establish if there has been a regression

When you ran on 1.7.5 before - was it in the plex environment ?
and if it was, it can only be one two things
Either these files had version information available in 1.7.5 but not in 1.7.6
or
the script in 1.7.5 plex environment did not pick the plex libraries because of some difference in environment variables etc

HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by HandBrakeCLI)
HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
HandBrakeCLI: /usr/lib/plexmediaserver/libz.so.1: version `ZLIB_1.2.9' not found (required by /lib64/libpng16.so.16)

@sa2000 said:
Thanks for all the information

I am sorry to be persistent on this but i need to establish if there has been a regression

When you ran on 1.7.5 before - was it in the plex environment ?
and if it was, it can only be one two things
Either these files had version information available in 1.7.5 but not in 1.7.6
or
the script in 1.7.5 plex environment did not pick the plex libraries because of some difference in environment variables etc

HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by HandBrakeCLI)
HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
HandBrakeCLI: /usr/lib/plexmediaserver/libz.so.1: version `ZLIB_1.2.9' not found (required by /lib64/libpng16.so.16)

Thanks again for the quick response.

Yes, it was in the plex environment. To execute, I’ve always just specified the script as a postprocessing script within PLEX. Prior to 1.7.6 it always worked, no issues. Now with 1.7.6 I get the above errors.

If I export LD_LIBRARY_PATH within the script to override the PLEX defaults (which then allows HandBrakeCLI to use the Fedora provided libraries) it works.

@gbcox said:

@sa2000 said:
Thanks for all the information

I am sorry to be persistent on this but i need to establish if there has been a regression

When you ran on 1.7.5 before - was it in the plex environment ?
and if it was, it can only be one two things
Either these files had version information available in 1.7.5 but not in 1.7.6
or
the script in 1.7.5 plex environment did not pick the plex libraries because of some difference in environment variables etc

HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by HandBrakeCLI)
HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
HandBrakeCLI: /usr/lib/plexmediaserver/libxml2.so.2: no version information available (required by /lib64/libbluray.so.2)
HandBrakeCLI: /usr/lib/plexmediaserver/libz.so.1: version `ZLIB_1.2.9' not found (required by /lib64/libpng16.so.16)

Thanks again for the quick response.

Yes, it was in the plex environment. To execute, I’ve always just specified the script as a postprocessing script within PLEX. Prior to 1.7.6 it always worked, no issues. Now with 1.7.6 I get the above errors.

If I export LD_LIBRARY_PATH within the script to override the PLEX defaults (which then allows HandBrakeCLI to use the Fedora provided libraries) it works.

Thank you. I will discuss with the development team

@gbcox said:

Thanks again for the quick response.

Yes, it was in the plex environment. To execute, I’ve always just specified the script as a postprocessing script within PLEX. Prior to 1.7.6 it always worked, no issues. Now with 1.7.6 I get the above errors.

If I export LD_LIBRARY_PATH within the script to override the PLEX defaults (which then allows HandBrakeCLI to use the Fedora provided libraries) it works.

Redefining LD_LIBRARY_PATH to remove PMS’s libraries from the list (which is the environment PMS created for post processing) is best for you. You’re correct… Override it / clear it out.

Many of us invoke mkvtoolnix or ffmpeg .

HandBrake doesn’t like what it sees with the PMS libraries also being available to it because they don’t contain the version information and failing for that reason apparently (fussy).

I also have Fedora 24 and will see if I come up with a way to have both environments but truly is no need to keep /usr/lib/plexmediaserver in LD_LIBRARY_PATH in your post processing script.

Summary: I’ll work with @sa2000 on this and with the rest of engineering. Feel free to stomp the variable.

Thanks for the clarification. After doing a bit of research it appears that the error message is a bit misleading. What it means in this instance is that the version of libxml used to build handbrake was newer than the library version. So that explains why it probably worked ok in the past. With F26 libxml is newer than what is being provided by Plex… hence the error.

I’ve not yet put FC26 to any strenuous testing myself yet. It’s still ‘wet behind the ear’ and will be receiving a lot of updates over the next two weeks which is typical. As always, Fedora is bleeding edge.

Since you tracked it down to specifically libxml, then definitely stomp LD_LIBRARY_PATH