I can see a timeout for livetv tuning channel 044 at 12:23. We timed it out after 25 seconds. So it does look like the others. I am going to add to the set I referred to development to look into the suspected probesize mentioned by @workit247 - it was recently increased from 10 Mb to 20Mb
May 17, 2019 12:23:11.882 [0x7f917b9d4700] DEBUG - Request: [::ffff:10.0.10.95:59808 (Allowed Network (Subnet))] POST /livetv/dvrs/2/channels/044/tune (4 live) TLS GZIP Signed-in Token (suzandbob)
May 17, 2019 12:23:15.108 [0x7f91322b3700] DEBUG - DVR:Segmenter: Creating a new recorder for http://10.0.10.60:5004/auto/v657.
May 17, 2019 12:23:15.410 [0x7f91322b3700] DEBUG - Job running:
EAE_ROOT='/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/tmp/pms-23b59aa4-3e5a-43f1-907c-a8a61ed47439/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/Plex\ Media\ Server/Codecs/392df4f-2233-linux-x86_64/' XDG_CACHE_HOME='/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Library/Plex Media Server/Cache' XDG_DATA_HOME='/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/share/CACHEDEV1_DATA/.qpkg/PlexMediaServer/Plex Transcoder' '-noaccurate_seek' '-ignore_unknown' '-scan_all_pmts' '-1' '-rw_timeout' '30000000' '-reconnect' '1' '-reconnect_streamed' '1' '-reconnect_delay_max' '30' '-fflags' '+discardcorruptts+fillwallclockdts' '-probesize' '20000000' '-i' 'http://10.0.10.60:5004/auto/v657' '-map' '0:V?' '-codec:V' 'copy' '-map' '0:a?' '-codec:a' 'copy' '-map' '0:s?' '-codec:s' 'copy' '-break_non_keyframes' '1' '-segment_format' 'mpegts' '-f' 'ssegment' '-individual_header_trailer' '0' '-segment_time' '1' '-segment_start_number' '0' '-segment_time_delta' '0.25' '-segment_list' 'http://127.0.0.1:32400/video/:/transcode/session/5fba20c0-d604-4a59-8757-2a8de51b5605/b9605052-26ff-43ac-b9bf-73795d6e232f/seglist' '-segment_list_type' 'csv' '-segment_list_size' '2147483647' '-segment_list_separate_stream_times' '1' '-max_delay' '5000000' '-map_metadata' '-1' '-map_chapters' '-1' 'media-%05d.ts' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-xioerror' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/5fba20c0-d604-4a59-8757-2a8de51b5605/b9605052-26ff-43ac-b9bf-73795d6e232f/progress'
May 17, 2019 12:23:15.411 [0x7f91322b3700] DEBUG - Jobs: Starting child process with pid 377
May 17, 2019 12:23:40.411 [0x7f91322b3700] DEBUG - TranscodeSession: timed out waiting to find duration for live session
Win 10 x64
Updated to Version 1.15.4.994
Restarted after updating and Enabling Logging
Time at 11:20pm CST when I attempted to tune in channel 005 NBC, timed out, failed.
Then I tuned 007 ABC just fine.
Then I tried again on 005 NBC at 11:21pm again and failed, timed out.
Iām able to run HDHomeRun Win10 app and tune to 005 just fine.
Thanks
Edit: Looks like the same thatās been reportedā¦
May 17, 2019 23:20:25.774 [9704] DEBUG - Activity: updated activity 83302578-29f5-43ac-a8a2-c3492114736a - completed 8% - Recording
May 17, 2019 23:20:27.279 [7336] DEBUG - TranscodeSession: timed out waiting to find duration for live session
May 17, 2019 23:20:27.279 [7336] ERROR - Failed to start session.
May 17, 2019 23:20:27.279 [7336] DEBUG - Streaming Resource: Terminated session 0x829ee10:2dab017c-8598-41ed-af30-9f3b1b1bebd1 with reason Recording failed. Please check your tuner or antenna.
May 17, 2019 23:20:27.279 [7336] ERROR - DVR:Recorder: Unable to create transcode session or session failed to start.
May 17, 2019 23:20:27.279 [8024] DEBUG - Killing job.
May 17, 2019 23:20:27.285 [8024] DEBUG - Job was already killed, not killing again.
May 17, 2019 23:20:27.285 [6236] DEBUG - Jobs: āC:\Program Files (x86)\Plex\Plex Media Server\Plex Transcoder.exeā exit code for process 1996 is -1059143458 (intentional termination)
I appreciate that the problem is a complicated one. However, from the many logs that have been produced, along with my own, it seems to me that the common theme being presented is that of the transcoder timing out. Would it not be possible to focus on this? Surely the timeout limit can be extended or, perhaps more obvious, can a setting not be exposed to the UI that would allow users to specify the timeout themselves?
@sa2000 has responded to numerous posts asking for logs, and has received a great deal, but to my relatively untrained eye the problem is clear; transcoder timeout.
Not obvious perhaps, but worth pursuing? @sa2000 this has been going on for a very long time. Surely weāre at the stage where all options should be considered? Thereās threads going back a couple of years with this exact issue.
I am sending you a private message with download for 1.15.1.791 which was before the probesize change to establish if it is the issue - also some info on how to get channel capture using curl for channel 005
Some additional info. Not sure if this is a red herring or not, but for the last two weeks, I havenāt had the problem. Whats different? Iām now running two plex servers, with both connected to the HDHomerun Prime. I make sure that Iām not trying to use more than 3 streams.
To me, it didnāt seem to be a transcoding issue. Was able to connect to HDHomerun via non plex software, and to connect to the channel via Tivo (different cable card). Itās like the plex server wasnāt able to establish a socket to stream the requested channel. Restarting plex didnāt help, nor did rebooting server or the hdhomerun. At some stage it corrected itself.
Again, sorry if this is a red herring!
@elan and @sa2000 I enabled some advanced logging on the shim so that it displays the plex version number, the arguments being modified/replaced, and a dump of all arguments just before they are passed to āplex_transcoderā (the renamed Plex Transcoder for use with the shim).
Tested 1.15.1.791 and 1.15.6.1079 with and without shimming arguments. It looks like the only argument thatās modified on phase 1 (probe/discovery) is probesize. On phase 2 (streaming) it uses all of the argument modifications and removals to work consistently. I understand you guys definitely donāt want to remove/modify any arguments that might not need to be removed/modified so Iāll see if I can modify them to work instead of removing them and report to this thread.
ffmpeg.log is the log from the shim itself.
Edit: I guess Iāll reset my plex token now
Youāll see in ffmpeg.log that in 1.15.1.791 itās only reducing the probesize on stage 1 from 10MB to 9MB to make it get to stage 2. Without shimming, probesize set at 10MB it fails.
On phase 2 (streaming) it uses all of the argument modifications and removals to work consistently.
Correction: 1.15.6.1079 no longer needs removal of -x264opts:0 -preset:0 -crf:0 arguments to work. The only modification needed is the reduction of probesize to 9MB.
Thank you very much and thanks for the separate fffmpeg logging.
I am measuring the time from the transcoder invocation until the receipt of the transcoder progress update of progress?status=opened
So from your tests for channel 30
At 12:37:07 1.15.1.791-8bec0f76c with probesize 10,000,000 status=opened reached 25 seconds after invocation and timeout did apply (evidence from other users who tried 1.15.1.791 was that the status=opened was reached within 1 second of invocation)
At 12:38:04 1.15.1.791-8bec0f76c with your change of probesize 9,000,000 status=opened reached 21 seconds after invocation
(so successful but still too close to our 25 second timeout)
At 12:41:53 1.15.6.1079-78232c603 with probesize 20,000,000 status=opened not reached within the 25 second timeout
At 12:43:30 1.15.6.1079-78232c603 with your change to reduce probesize to 9,000,000 status=opened was reached at 12:43:53, 23 seconds after invocation of transcoder job
(so successful but still too close to our 25 second timeout)
Ah yes those, itās because Iām clearing all of the logs with an āecho >ā in a bash script before every test, so that my log dumps are minimal and so that they only contain the juicy bits. I figured live nulling would be easier for PMS to handle than deleting the files and possibly needing a restart every time.
