Live TV fails with "Error — Unable to find title for item of type 5"

General Discussions Plex Features
1

I’m seeing increased live TV failures lately, using an HDHomeRun Prime on Comcast (h.264). The channels are available; I can open the HDHomeRun app and immediately play the channel before/during/after the Plex failure. This happens everywhere I try: PlexWeb, Roku, Fire TV.

When a channel fails, I always see this error in the log. That error doesn’t seem to happen when a channel is tuned successfully.

"Error — Unable to find title for item of type 5".

It then keeps trying, and reaches a small transcode percentage in the log (no percentage is shown on the TV).

Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 8% - Recording

Then it eventually gives up and fails out.

Debug — TranscodeSession: timed out waiting to find duration for live session
Error — Failed to start session.
Debug — Streaming Resource: Terminated session 0x100e9668:269d88e8-682e-43ae-a298-84d76814e582 with reason Recording failed. Please check your tuner or antenna.
Error — DVR:Recorder: Unable to create transcode session or session failed to start.

Fuller logs are pasted below. I can provide more if needed, though preferably over PM.

Is there a known cause of this issue?

Apr 01, 2019 17:15:28.769 [7284] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:28.769 [3216] Debug — Request: [192.168.0.3:52659 (Subnet)] GET /tv.plex.providers.epg.onconnect:5/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F191276/grandchildren (13 live) TLS Page 0--1 GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:28.784 [3216] Debug — Setting container serialization range to [0, -1] (total=-1)
Apr 01, 2019 17:15:28.815 [3216] Debug — Setting container serialization range to [0, -1] (total=30)
Apr 01, 2019 17:15:28.815 [7284] Debug — Completed: [192.168.0.3:52659] 200 GET /tv.plex.providers.epg.onconnect:5/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F191276/grandchildren (13 live) TLS GZIP Page 0--1 48ms 624 bytes (pipelined: 1)
Apr 01, 2019 17:15:28.878 [7284] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:28.878 [4452] Debug — Request: [192.168.0.3:52659 (Subnet)] GET /tv.plex.providers.epg.onconnect:5/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F191276/grandchildren (13 live) TLS Page 0-29 GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:28.878 [4452] Debug — Setting container serialization range to [0, 29] (total=-1)
Apr 01, 2019 17:15:28.909 [4452] Debug — Setting container serialization range to [0, 29] (total=30)
Apr 01, 2019 17:15:28.925 [10164] Debug — Completed: [192.168.0.3:52659] 200 GET /tv.plex.providers.epg.onconnect:5/metadata/com%2Egracenote%2Eonconnect%3A%2F%2Fshow%2F191276/grandchildren (13 live) TLS GZIP Page 0-29 51ms 4032 bytes (pipelined: 2)
Apr 01, 2019 17:15:29.425 [10164] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:29.440 [3216] Debug — Request: [192.168.0.3:52659 (Subnet)] GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554163200&beginsAt%3C=1554170400&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (13 live) TLS GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:29.456 [7284] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:29.456 [4452] Debug — Request: [192.168.0.3:52660 (Subnet)] POST /livetv/dvrs/5/channels/1250/tune (14 live) TLS GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:29.456 [4452] Debug — DVR:Subscription: Starting a new rolling subscription for session 228e985eaac38c833480b041bc984d11 channel 1250.
Apr 01, 2019 17:15:29.628 [7284] Debug — Completed: [192.168.0.3:52659] 200 GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554163200&beginsAt%3C=1554170400&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (14 live) TLS GZIP 196ms 95558 bytes (pipelined: 3)
Apr 01, 2019 17:15:29.768 [7284] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:29.768 [8036] Debug — Request: [192.168.0.3:52659 (Subnet)] GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554170400&beginsAt%3C=1554175800&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (14 live) TLS GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:29.862 [4452] Debug — Activity: registered new activity 21ac9fd2-dab1-4654-a458-4512191c4e51 - Processing subscriptions
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:Subscription: Scheduling subscriptions.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:Subscription: Initialized 1 schedulers.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:Subscription: Starting with 0 grabs, scheduled 0 active ones preemptively.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:NewSchedule: Partitioning, step one, let's compute an absolute ordering.
Apr 01, 2019 17:15:29.862 [4452] Debug —  DVR:NewSchedule: Between 2019-04-01 17:15:29 and 2019-04-01 17:20:29 on channel 1250: 'Live TV - Session'
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:NewSchedule: Initial partitioning completed with 1 partitions.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:NewSchedule: Partitioning completed with 1 partitions.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:NewSchedule: PARTITION of size 1.
Apr 01, 2019 17:15:29.862 [4452] Debug —  DVR:NewSchedule:    Between 2019-04-01 17:15:29 and 2019-04-01 17:20:29 on channel 1250: 'Live TV - Session'
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:NewSchedule: After processing the partition, we have 3 alternate realities.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:NewSchedule: We computed 3 alternative realities in 0 ms.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:NewSchedule: The winning schedule had score: 10 and 0 conflicts.
Apr 01, 2019 17:15:29.862 [4452] Debug —  DVR:NewSchedule: device 0 tuner 1 airing 0 between 2019-04-01 17:15:29 and 2019-04-01 17:20:29 on channel 1250: 'Live TV - Session'
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:Grabber: Starting grab immediately for 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250 and we're 0 seconds in already.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:Subscription: Scheduled all subscriptions in 2 ms.
Apr 01, 2019 17:15:29.862 [4452] Debug — Activity: Ended activity 21ac9fd2-dab1-4654-a458-4512191c4e51.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:Subscription: There are 1 active grabs at the end.
Apr 01, 2019 17:15:29.862 [4452] Debug — DVR:Subscription: Waiting for media grab to start.
Apr 01, 2019 17:15:29.862 [5892] Debug — DVR:Grabber: Starting operation for 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250.
Apr 01, 2019 17:15:29.862 [5892] Debug — Activity: registered new activity b26126fb-80e4-4788-be91-b61b7cba6330 - Recording
Apr 01, 2019 17:15:29.862 [5892] Debug — DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/13117B45 (Silicondust HDHomeRun PRIME, supported) tuner 1.
Apr 01, 2019 17:15:29.862 [5892] Debug — DVR:Grabber: Creating custom segmented recorder for grab for channel 1250
Apr 01, 2019 17:15:29.862 [1308] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:29.862 [5892] Debug — HTTP requesting GET http://192.168.0.2:80/lineup.json
Apr 01, 2019 17:15:29.862 [1308] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:29.862 [1308] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:29.878 [1308] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:29.878 [7284] Debug — Completed: [192.168.0.3:52659] 200 GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554170400&beginsAt%3C=1554175800&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (14 live) TLS GZIP 106ms 77215 bytes (pipelined: 4)
Apr 01, 2019 17:15:29.925 [5892] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup.json
Apr 01, 2019 17:15:29.925 [5892] Debug — DVR:Segmenter: Creating a new recorder for http://192.168.0.2:5004/auto/v1250.
Apr 01, 2019 17:15:29.925 [5892] Debug — DVR:Grabber: Setting timer to stop grab of 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250 in 300 seconds.
Apr 01, 2019 17:15:29.925 [11372] Debug — Transcoder: Cleaning old transcode directories.
Apr 01, 2019 17:15:29.925 [5892] Debug — DVR:Grabber: Waiting for a tuner on device://tv.plex.grabbers.hdhomerun/13117B45 (3 available) for at most 300 seconds.
Apr 01, 2019 17:15:29.925 [5892] Debug — DVR:Grabber: Allocated a tuner on device://tv.plex.grabbers.hdhomerun/13117B45 (2 left)
Apr 01, 2019 17:15:29.925 [5892] Debug — We're going to try to auto-select an audio stream for account 1.
Apr 01, 2019 17:15:29.925 [5892] Debug — Selecting best audio stream for part ID -1 (autoselect: 1 language: en)
Apr 01, 2019 17:15:29.925 [5892] Debug — We're going to try to auto-select a subtitle.
Apr 01, 2019 17:15:29.925 [5892] Debug — Audio Stream: -1, Subtitle Stream: -1
Apr 01, 2019 17:15:29.925 [11372] Debug — Transcoder: Cleaning old transcode directory: "C:\Users\plex\AppData\Local\Plex Media Server\Cache\Transcode\Sessions\plex-transcode-269d88e8-682e-43ae-a298-84d76814e582"
Apr 01, 2019 17:15:29.925 [11372] Debug — Whacked session a0c0a470-4358-48ca-9f49-64a60aa3cc63, 0 remaining.
Apr 01, 2019 17:15:29.925 [11372] Debug — Streaming Resource: Removing session 0x100e9048:a0c0a470-4358-48ca-9f49-64a60aa3cc63
Apr 01, 2019 17:15:29.925 [11372] Debug — DVR:Subscription: Destroying rolling subscription session 228e985eaac38c833480b041bc984d11 for channel 1250.
Apr 01, 2019 17:15:29.940 [5892] Debug — MDE: Selected protocol hls; container: mpegts
Apr 01, 2019 17:15:29.940 [5892] Error — Unable to find title for item of type 5
Apr 01, 2019 17:15:29.940 [5892] Debug — MDE: analyzing media item -1
Apr 01, 2019 17:15:29.940 [5892] Debug — MDE: : no direct play video profile exists for http/mpegts/
Apr 01, 2019 17:15:29.940 [5892] Debug — MDE: : no direct play video profile exists for http/mpegts//
Apr 01, 2019 17:15:29.940 [5892] Debug — MDE: : codec is unavailable for analysis
Apr 01, 2019 17:15:29.940 [5892] Debug — MDE: : codec is unavailable for analysis
Apr 01, 2019 17:15:29.940 [5892] Error — Unable to find title for item of type 5
Apr 01, 2019 17:15:29.940 [5892] Debug — MDE: : selected media 0 / -1
Apr 01, 2019 17:15:29.940 [5892] Debug — Cleaning directory for session 269d88e8-682e-43ae-a298-84d76814e582 ()
Apr 01, 2019 17:15:29.940 [5892] Debug — Starting a transcode session 269d88e8-682e-43ae-a298-84d76814e582 at offset -1.0 (state=3)
Apr 01, 2019 17:15:29.940 [5892] Debug — Streaming Resource: Added session 0x100e9668:269d88e8-682e-43ae-a298-84d76814e582
Apr 01, 2019 17:15:29.940 [5892] Debug — TPU: hardware transcoding: enabled, but no hardware decode accelerator found
Apr 01, 2019 17:15:29.940 [5892] Debug — TPU: hardware transcoding: final decoder: , final encoder: 
Apr 01, 2019 17:15:29.940 [5892] Debug — Job running: EAE_ROOT='\\?\C:\Users\plex\AppData\Local\Plex Media Server\Cache\Transcode\Sessions\EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='C\:\\Users\\plex\\AppData\\Local\\Plex\ Media\ Server\\Codecs\\a22632d-2131-windows-x86\\' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' C:\Program Files (x86)\Plex\Plex Media Server\Plex Transcoder.exe -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://192.168.0.2:5004/auto/v1250 -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/269d88e8-682e-43ae-a298-84d76814e582/2ee868d6-23c7-4fc3-84da-aeb1117ce86a/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/269d88e8-682e-43ae-a298-84d76814e582/2ee868d6-23c7-4fc3-84da-aeb1117ce86a/progress 
Apr 01, 2019 17:15:29.956 [5892] Debug — Jobs: Starting child process with pid 13124
Apr 01, 2019 17:15:30.081 [3216] Debug — Request: [127.0.0.1:59701 (Loopback)] PUT /video/:/transcode/session/269d88e8-682e-43ae-a298-84d76814e582/2ee868d6-23c7-4fc3-84da-aeb1117ce86a/progress?status=startup (15 live) Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:30.081 [10164] Debug — Completed: [127.0.0.1:59701] 204 PUT /video/:/transcode/session/269d88e8-682e-43ae-a298-84d76814e582/2ee868d6-23c7-4fc3-84da-aeb1117ce86a/progress?status=startup (15 live) 0ms 203 bytes (pipelined: 1) (range: bytes=0-) 
Apr 01, 2019 17:15:30.081 [8036] Debug — Request: [127.0.0.1:59701 (Loopback)] PUT /video/:/transcode/session/269d88e8-682e-43ae-a298-84d76814e582/2ee868d6-23c7-4fc3-84da-aeb1117ce86a/progress?status=opening (15 live) Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:30.081 [7284] Debug — Completed: [127.0.0.1:59701] 204 PUT /video/:/transcode/session/269d88e8-682e-43ae-a298-84d76814e582/2ee868d6-23c7-4fc3-84da-aeb1117ce86a/progress?status=opening (15 live) 0ms 203 bytes (pipelined: 2) (range: bytes=0-) 
Apr 01, 2019 17:15:30.237 [7284] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:30.237 [3216] Debug — Request: [192.168.0.3:52659 (Subnet)] GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554175800&beginsAt%3C=1554183000&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (15 live) TLS GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:30.378 [10164] Debug — Completed: [192.168.0.3:52659] 200 GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554175800&beginsAt%3C=1554183000&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (15 live) TLS GZIP 143ms 84361 bytes (pipelined: 5)
Apr 01, 2019 17:15:30.487 [10164] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:30.487 [8036] Debug — Request: [192.168.0.3:52659 (Subnet)] GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554183000&beginsAt%3C=1554188400&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (15 live) TLS GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:30.628 [10164] Debug — Completed: [192.168.0.3:52659] 200 GET /tv.plex.providers.epg.onconnect:5/grid?type=1%2C4&sort=beginsAt&endsAt%3E=1554183000&beginsAt%3C=1554188400&excludeElements=Actor,Collection,Country,Director,Genre,Label,Mood,Part,Producer,Role,Similar,Writer,Photo&excludeFields=file,tagline (15 live) TLS GZIP 134ms 77658 bytes (pipelined: 6)
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:Subscription: Moving end of rolling sub for 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250 to 2019-04-01 17:20:30.
Apr 01, 2019 17:15:30.956 [9620] Debug — Activity: registered new activity 56bf957e-bfbd-479d-8d37-c29d7b2e25d0 - Processing subscriptions
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:Subscription: Scheduling subscriptions.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:Subscription: Initialized 1 schedulers.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:NewSchedule: Scheduled an operation 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250 on tuner 1 between 2019-04-01 17:15:29 and 2019-04-01 17:20:30
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:Grabber: Setting timer to stop grab of 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250 in 300 seconds.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:Subscription: Starting with 1 grabs, scheduled 1 active ones preemptively.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:NewSchedule: Partitioning, step one, let's compute an absolute ordering.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:NewSchedule: Initial partitioning completed with 0 partitions.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:NewSchedule: Partitioning completed with 0 partitions.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:NewSchedule: We computed 1 alternative realities in 0 ms.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:NewSchedule: The winning schedule had score: 0 and 0 conflicts.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:Subscription: Scheduled all subscriptions in 9 ms.
Apr 01, 2019 17:15:30.956 [9620] Debug — Activity: Ended activity 56bf957e-bfbd-479d-8d37-c29d7b2e25d0.
Apr 01, 2019 17:15:30.956 [9620] Debug — DVR:Subscription: There are 1 active grabs at the end.
Apr 01, 2019 17:15:32.909 [2740] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:32.909 [2740] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:32.909 [2740] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:32.909 [2740] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:32.940 [2740] Debug — DVR:Grabber: Signal information for tune on channel 1250: strength: 98, quality: 100
Apr 01, 2019 17:15:35.956 [5624] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:35.956 [5624] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:35.956 [5624] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:35.956 [5624] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:35.987 [5624] Debug — DVR:Grabber: Signal information for tune on channel 1250: strength: 99, quality: 100
Apr 01, 2019 17:15:35.987 [5624] Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 1% - Recording
Apr 01, 2019 17:15:39.002 [7104] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:39.002 [7104] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:39.002 [7104] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:39.002 [7104] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:39.033 [7104] Debug — DVR:Grabber: Signal information for tune on channel 1250: strength: 99, quality: 100
Apr 01, 2019 17:15:39.033 [7104] Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 3% - Recording
Apr 01, 2019 17:15:42.049 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:42.049 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:42.049 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:42.064 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:42.080 [10512] Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 4% - Recording
Apr 01, 2019 17:15:42.439 [10164] Debug — Completed: [192.168.0.4:54573] -2 GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (15 live) TLS GZIP 20014ms 5 bytes (pipelined: 19)
Apr 01, 2019 17:15:42.439 [10164] Debug — Auth: authenticated user 1 as Cafe Diem
Apr 01, 2019 17:15:42.439 [3216] Debug — Request: [192.168.0.4:54573 (Subnet)] GET /player/proxy/poll?deviceClass=pc&protocolVersion=3&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (15 live) TLS GZIP Signed-in Token (Cafe Diem)
Apr 01, 2019 17:15:45.095 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:45.095 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:45.095 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:45.095 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:45.127 [10512] Debug — DVR:Grabber: Signal information for tune on channel 1250: strength: 99, quality: 100
Apr 01, 2019 17:15:45.127 [10512] Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 5% - Recording
Apr 01, 2019 17:15:48.142 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:48.142 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:48.142 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:48.158 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:48.173 [10512] Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 6% - Recording
Apr 01, 2019 17:15:51.189 [9620] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:51.189 [9620] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:51.189 [9620] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:51.189 [9620] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:51.220 [9620] Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 7% - Recording
Apr 01, 2019 17:15:54.235 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:54.235 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/discover.json
Apr 01, 2019 17:15:54.235 [10512] Debug — HTTP requesting GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:54.235 [10512] Debug — HTTP 200 response from GET http://192.168.0.2:80/lineup_status.json
Apr 01, 2019 17:15:54.267 [10512] Debug — Activity: updated activity b26126fb-80e4-4788-be91-b61b7cba6330 - completed 8% - Recording
Apr 01, 2019 17:15:55.564 [5892] Debug — TranscodeSession: timed out waiting to find duration for live session
Apr 01, 2019 17:15:55.564 [5892] Error — Failed to start session.
Apr 01, 2019 17:15:55.564 [5892] Debug — Streaming Resource: Terminated session 0x100e9668:269d88e8-682e-43ae-a298-84d76814e582 with reason Recording failed. Please check your tuner or antenna.
Apr 01, 2019 17:15:55.564 [9620] Debug — Killing job.
Apr 01, 2019 17:15:55.564 [5892] Error — DVR:Recorder: Unable to create transcode session or session failed to start.
Apr 01, 2019 17:15:55.595 [9620] Debug — Job was already killed, not killing again.
Apr 01, 2019 17:15:55.595 [2700] Debug — Jobs: 'C:\Program Files (x86)\Plex\Plex Media Server\Plex Transcoder.exe' exit code for process 13124 is -1059143458 (intentional termination)
Apr 01, 2019 17:15:55.595 [9620] Debug — Stopping transcode session 269d88e8-682e-43ae-a298-84d76814e582
Apr 01, 2019 17:15:55.595 [5892] Debug — Job was already killed, not killing again.
Apr 01, 2019 17:15:55.595 [5892] Error — DVR:Recorder: Error 16 (Recording failed. Please check your tuner or antenna.) starting the record, shutting things down.
Apr 01, 2019 17:15:55.595 [1308] Debug — Cleaning directory for session 269d88e8-682e-43ae-a298-84d76814e582 (C:\Users\plex\AppData\Local\Plex Media Server\Cache\Transcode\Sessions\plex-transcode-269d88e8-682e-43ae-a298-84d76814e582)
Apr 01, 2019 17:15:55.595 [5892] Debug — DVR:Grabber: Cleaning up rolling grab for channel 1250.
Apr 01, 2019 17:15:55.595 [5892] Debug — DVR:Recorder: No more consumers, stopping.
Apr 01, 2019 17:15:55.595 [5892] Debug — DVR:Recorder: Asked to stop recording 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250.
Apr 01, 2019 17:15:55.595 [5892] Debug — DVR:Grabber: Freed a tuner on device://tv.plex.grabbers.hdhomerun/13117B45 (now 3 available)
Apr 01, 2019 17:15:55.595 [5892] Debug — DVR:Grabber: Operation for 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250 completed with status error (Recording failed. Please check your tuner or antenna.)
Apr 01, 2019 17:15:55.595 [5892] Debug — Activity: Ended activity b26126fb-80e4-4788-be91-b61b7cba6330.
Apr 01, 2019 17:15:55.595 [5892] Debug — DVR:Grabber: Cleaning up rolling grab for channel 1250.
Apr 01, 2019 17:15:55.595 [5892] Debug — DVR:Recorder: No more consumers, stopping.
Apr 01, 2019 17:15:55.595 [5892] Error — DVR:Grabber: Starting media grab failed.
Apr 01, 2019 17:15:55.595 [5892] Error — Unknown metadata type: 
Apr 01, 2019 17:15:55.595 [5892] Debug — Asked for unknown type: -1
Apr 01, 2019 17:15:55.595 [4452] Error — DVR:Subscription: Rolling media grab failed to start.
Apr 01, 2019 17:15:55.595 [4452] Debug — DVR:Subscription: Cancelling grab for subscription 538: 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250
Apr 01, 2019 17:15:55.595 [4452] Debug — DVR:Grabber: Cancelling operation for 'Live TV - Session 228e985eaac38c833480b041bc984d11' on channel 1250 with status cancelled.
Apr 01, 2019 17:15:55.595 [4452] Debug — DVR:Grabber: Operation was active, stopping recorder.
Apr 01, 2019 17:15:55.595 [4452] Debug — DVR:Grabber: We've cancelled the grab with 275 seconds remaining.```
2

Bump for the morning crowd. I can confirm I’m also seeing this happen on Linux PMS with similar errors so I’ve added it to the tags at the top.

1 Like
3

Same here. One specific channel can’t tune or record and shows this specific error message, but is viewable via direct link on HDHR, through HDHR app and others.

1 Like
4

Same problem again tonight.

The HDHomeRun confirms the attempt to tune the channel, and says it’s successfully subscribed. After 25 seconds it errors out with this:

Tuner: tuner0 http stream ended (remote closed)

Any Live TV devs out there reading these?

5

I’m seeing this exact same problem with one channel (possibly more, but I haven’t done extensive testing).

This channel fails for me in both the Roku and the Plex Web Client. The same errors show up in the log as reference in the thread.

The channel plays flawlessly in the HDHomeRun app.

6

Windows x86 fix here. Step by step instructions to generate your own Windows x86 fix here.

“TranscodeSession: timed out waiting to find duration for live session”

It looked like the -probesize in the call to ‘Plex Transcoder’ was being sent as 4x the default of ffmpeg. Probesize pre-loads the stream/file a certain amount to get information about the stream, size, codec, tracks, etc before processing it. I created a python shim to bump that value down to keep PMS from timing out. Strangely, there were other arguments being passed that ‘Plex Transcoder’ didn’t like, so I removed those too. YMMV

You’ll have to rename ‘Plex Transcoder’ to ‘plex_transcoder’ and create ‘Plex Transcoder’ with this python code, executable.

#!/usr/bin/python
import sys
from sys import argv
import subprocess

# Tell this shim where the 'real' Plex Transcoder is
#cmd = '/Applications/Plex Media Server.app/Contents/MacOS/plex_transcoder' # for mac
cmd = '/usr/lib/plexmediaserver/plex_transcoder' # for linux/ubuntu

# Get all arguments passed to what it thinks is the original 'Plex Transcoder'

cmdargs = sys.argv

# Remove the first argument (the script/program name itself)

cmdargs.pop(0)

# Initialize the argument counter

cmdindex=0

# Loop through all arguments and modify them as needed
# - remove arguments that when passed to the original 'Plex Transcoder' error it out.

for cmdarg in cmdargs:
  
  # lower the '-probesize' so that it keeps us under the timeout limit of PMS
  if cmdarg == "-probesize":
    cmdargs[cmdindex+1]="9000000" # was 20000000

  # remove offending arguments
  if cmdarg == "-x264opts:0" or cmdarg == "-crf:0" or cmdarg == "-preset:0":
    cmdargs[cmdindex]=""

  # escape single quotes in arguments
  cmdargs[cmdindex]=str(cmdarg).replace("'", "\\'")
  
  # bump up the counter for the next loop
  cmdindex += 1

target = [cmd] + cmdargs
subprocess.call(target)
2 Likes
7

@Plex it would be great to have some of these arguments that are used for Plex Transcoder to be read from a config file (namely -probesize), clobbering the defaults if present. Alternatively, if you had a setting under ‘Transcoder’ where a user could change the PMS timeout when it expects to get a response from the probe, that would ease a lot of headaches. I expect HDHR and other tuners, especially those over WIFI or VPN may have inherent delays or lower throughput from the tuner, resulting in timeouts. In my case, it was one single channel that was the issue. I’d bet the native stream for that specific channel is just a slightly higher bitrate or ‘size’ than others, causing the -probesize of 20MB to time out before PMS was expecting to hear back.

8

This is great information! I don’t feel comfortable implementing this myself, but hopefully this will lead the dev team to a quick patch for this issue.

Thanks for the effort!

1 Like
9

I also don’t have the time right now to add this into my Plex install (and I’m guessing it would be replaced with every update). I should probably make sure some of the Plex folks know about that troubleshooting and possible solution, but I’m really not sure who takes care of Live TV. Going to toss out @sa2000 @Achilles @ChuckPa in case one of them is around, and can perhaps give us direction for who should be aware of this.

10

Engineering is aware of it.

As for bypassing the Plex transcoder invocation command line, upcoming changes may not work correctly with this in place. Please take this into consideration before using.

3 Likes
11

Good to know, hopefully I won’t have a need to use the shim in the upcoming changes. Thank you for the quick reply!

12

Thank you! Glad to know engineering is aware of it.

13

… upcoming changes may not work correctly with this in place

This shim still needed for 1.15.3.876 (tested on OSX and ubuntu).

I agree nobody should expect it to work in future versions, but @Cafe_Diem you’re right it’ll just be replaced with every update. No harm to have it while it works, then update and see if the problem is solved without it.

In 1.15.3.876 strangely I now have an issue tuning many channels that didn’t have an issue with, and the single problem channel (SD and HD) now doesn’t have an issue tuning (actually initially tunes 10 seconds faster than before, then hangs after a few seconds, pauses for 10 seconds, then plays). Re-installed shim, all channels tune.

@ChuckPa worth sending logs, or is it pretty straightforward?

14

No sense sending logs at this late stage.
Suggest waiting until we see the transcoder changes.
Can’t help with tuning as I no longer have the ability to test here.

15

@King_Family @Cafe_Diem what platform are you guys running? I might be able to put together a quick install script, or step by step.

16

I’m running on Windows. But with engineering aware, I’ll probably just wait for a patch.

17

same issue here. I was working with @sa2000 on the same symptoms and he told me that there are ‘NO’ on-going LiveTV issues (Unable to tune to channel (again, more research now) - #76 by sa2000).

My logs show the same:

38%20AM
38%20AM1026×334 164 KB

For me it affects CNN and ESPN (HDHR Prime, Comcast, Windows server)

We NEED a fix! :slight_smile:

18

Windows for me too (Windows 10 1803 right now). But I’m also willing to give a little time for engineering to work this out, now that I know they’re working on it. I can use the HDHR app on Fire TV for the moment.

But I can’t rule out that I’ll change my mind later. I really appreciate the offer.

19

I installed PMS on windows, modified the script to target the windows PMS folder “C:\Program Files (x86)\Plex\Plex Media Server” and ran it through py2exe so we don’t need an entire installation of python2.7 to run. Working on a step-by-step in case anybody wants to try it on Windows. It’ll basically be downloading a zip, extracting it, opening the PMS folder, right-click rename ‘Plex Transcoder’ to ‘plex_transcoder’ then dragging all files from the extracted zip into the PMS folder. Should be pretty straightforward.

20

@Cafe_Diem @tachtevrenidis @King_Family (Plex Media Server x86 only)

I found an easier way by packaging the windows x86-specific python script using ‘pyinstaller --onefile’ within Anaconda python development platform. If you want to use the python script instead, install Python 2.7 with ‘Add to Path’ option and use the script instead, as it will look for the default Python 2.7 installation folder and path.

To use the drop-in executable, installation is done by renaming ‘Plex Transcoder’ (in “C:\Program Files (x86)\Plex\Plex Media Server”) to ‘plex_transcoder’ and copying the included ‘Plex Transcoder’ in its place. README file and python source included with additional information. I’m hoping this isn’t against Plex Forum policy :kissing:

plex_transcoder_probesize_x86.zip (3.4 MB)

1 Like