search

tellytv / telly

An IPTV proxy
MIT License
769 stars 107 forks source link

"Unable to tune channel" on Plex #154

Closed julien-blanchon closed 6 years ago

julien-blanchon commented 6 years ago

Hi,

I'm running the latest Plex version (+ Plex pass) on a Quickbox.io core (Dedicated server, Ubuntu 16.04.5 amd64). I set up Telly 1.1.0.1 (beta 2) properly (telly with chmod a+x in /bin/), and start it (telly --iptv.playlist=/home/exy/tv.m3u). Than, he start:

Flag --iptv.playlist has been deprecated, use the configuration file instead.
Flag --filter.regex has been deprecated, use the configuration file instead.
INFO[2018-08-21T18:03:23+02:00] telly is preparing to go live (version=1.1.0.1, branch=dev, revision=309792d7b5976a9689d2386c43961ead77cc11ec)
WARN[2018-08-21T18:03:23+02:00] Legacy --iptv.playlist argument or environment variable provided, using Custom provider with default configuration, this may fail! If so, you should use a configuration file for full flexibility.
INFO[2018-08-21T18:03:23+02:00] Loading M3U from /home/exy/tv.m3u
INFO[2018-08-21T18:03:23+02:00] Loaded 262 channels into the lineup from Legacy provider created using arguments/environment variables
INFO[2018-08-21T18:03:23+02:00] telly is live and on the air!
INFO[2018-08-21T18:03:23+02:00] Broadcasting from http://localhost:6077/
INFO[2018-08-21T18:03:23+02:00] EPG URL: http://localhost:6077/epg.xml
INFO[2018-08-21T18:03:35+02:00] Serving channel number 10000

Plex reaches it, I do all the setup and finally, when starting a stream I got "Unable to tune channel".

Here an extract of my Plex logs:

Aug 21, 2018 18:03:35.277 [0x7ff739ffd700] DEBUG - DVR:Subscription: Starting a new rolling subscription for session aihi5wwmpowxfr979fsq2nfq channel 1.
Aug 21, 2018 18:03:35.303 [0x7ff739ffd700] DEBUG - Activity: registered new activity 6cf0cc67-2b01-4172-b628-be0063a545c2 - Processing subscriptions
Aug 21, 2018 18:03:35.303 [0x7ff739ffd700] DEBUG - DVR:Subscription: Scheduling subscriptions.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Subscription: Initialized 1 schedulers.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Subscription: Starting with 0 grabs, scheduled 0 active ones preemptively.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Schedule: Attempting to schedule the item 'Live TV - Session'.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Schedule: Trying airing at 2018-08-21 18:03:35 on channel 1.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Schedule: Device 0 tuner 0 scheduled recording between 2018-08-21 18:03:35 and 2018-08-21 18:08:35 on channel 1.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Grabber: Starting grab immediately for 'Live TV - Session' and we're 0 seconds in already.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Subscription: Scheduled all subscriptions in 0 ms.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - Activity: Ended activity 6cf0cc67-2b01-4172-b628-be0063a545c2.
Aug 21, 2018 18:03:35.304 [0x7ff739ffd700] DEBUG - DVR:Subscription: There are 1 grabs at the end.
Aug 21, 2018 18:03:35.305 [0x7ff739ffd700] DEBUG - DVR:Subscription: Waiting for media grab to start.
Aug 21, 2018 18:03:35.305 [0x7ff73afff700] DEBUG - DVR:Grabber: Starting operation for 'Live TV - Session'.
Aug 21, 2018 18:03:35.306 [0x7ff73afff700] DEBUG - Activity: registered new activity 372530df-a504-4454-b3b8-669eeea24af4 - Recording
Aug 21, 2018 18:03:35.306 [0x7ff73afff700] DEBUG - DVR:Grabber: HDHomerun starting a media grab on device device://tv.plex.grabbers.hdhomerun/12345678 (Silicondust HDHomerun (telly), supported) tuner 0.
Aug 21, 2018 18:03:35.306 [0x7ff73afff700] DEBUG - DVR:Grabber: Creating custom segmented recorder for grab for channel 1
Aug 21, 2018 18:03:35.307 [0x7ff73afff700] DEBUG - HTTP requesting GET http://localhost:6077/lineup.json
Aug 21, 2018 18:03:35.311 [0x7ff73afff700] DEBUG - HTTP 200 response from GET http://localhost:6077/lineup.json
Aug 21, 2018 18:03:35.313 [0x7ff73afff700] DEBUG - DVR:Segmenter: Creating a new recorder for http://localhost:6077/auto/v10000?transcode=none.
Aug 21, 2018 18:03:35.314 [0x7ff73afff700] DEBUG - DVR:Grabber: Setting timer to stop grab of 'Live TV - Session' in 300 seconds.
Aug 21, 2018 18:03:35.314 [0x7ff73afff700] DEBUG - DVR:Grabber: Waiting for a tuner (1 available).
Aug 21, 2018 18:03:35.314 [0x7ff73afff700] DEBUG - DVR:Grabber: Allocated a tuner (0 left)
Aug 21, 2018 18:03:35.315 [0x7ff73afff700] DEBUG - We're going to try to auto-select an audio stream for account 1.
Aug 21, 2018 18:03:35.315 [0x7ff73afff700] DEBUG - Selecting best audio stream for part ID -1 (autoselect: 1 language: fr)
Aug 21, 2018 18:03:35.315 [0x7ff73afff700] DEBUG - Audio Stream: -1, Subtitle Stream: -1
Aug 21, 2018 18:03:35.315 [0x7ff73afff700] DEBUG - MDE: Selected protocol hls; container: mpegts
Aug 21, 2018 18:03:35.315 [0x7ff73afff700] ERROR - Unable to find title for item of type 5
Aug 21, 2018 18:03:35.315 [0x7ff73afff700] DEBUG - MDE: analyzing media item -1
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - MDE: : no direct play video profile exists for http/mpegts/
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - MDE: : no direct play video profile exists for http/mpegts//
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - MDE: : codec is unavailable for analysis
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - MDE: : codec is unavailable for analysis
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] ERROR - Unable to find title for item of type 5
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - MDE: : selected media 0 / -1
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - Cleaning directory for session 81d8745c-2e10-4c5a-b97d-63ff86be1f66 ()
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - Starting a transcode session 81d8745c-2e10-4c5a-b97d-63ff86be1f66 at offset -1.0 (state=3)
Aug 21, 2018 18:03:35.316 [0x7ff73afff700] DEBUG - Streaming Resource: Added session 0x7ff740650720:81d8745c-2e10-4c5a-b97d-63ff86be1f66
Aug 21, 2018 18:03:35.318 [0x7ff73afff700] DEBUG - Job running: EAE_ROOT='/tmp/pms-6c236ac4-e876-4b2e-b845-704b33a2b4fd/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/var/lib/plexmediaserver/Library/Application\ Support/Plex\ Media\ Server/Codecs/e944d3a-1309-linux-ubuntu-x86_64/' XDG_CACHE_HOME='/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache' XDG_DATA_HOME='/usr/lib/plexmediaserver/Resources' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/lib/plexmediaserver/Plex Transcoder' '-noaccurate_seek' '-ignore_unknown' '-scan_all_pmts' '-1' '-rw_timeout' '30000000' '-fflags' '+discardcorruptts+fillwallclockdts' '-i' 'http://localhost:6077/auto/v10000?transcode=none' '-map' '0:V?' '-codec:V' 'copy' '-map' '0:a?' '-codec:a' 'copy' '-copypriorss:a' '0' '-map' '0:s?' '-codec:s' 'copy' '-segment_format' 'mpegts' '-f' 'ssegment' '-individual_header_trailer' '0' '-segment_time' '1' '-segment_start_number' '0' '-segment_time_delta' '0.0625' '-segment_list' 'http://127.0.0.1:32400/video/:/transcode/session/81d8745c-2e10-4c5a-b97d-63ff86be1f66/0942c910-29c6-4a7f-bde9-026389299839/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' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/81d8745c-2e10-4c5a-b97d-63ff86be1f66/0942c910-29c6-4a7f-bde9-026389299839/progress'
Aug 21, 2018 18:03:35.321 [0x7ff73afff700] DEBUG - Jobs: Starting child process with pid 5613
Aug 21, 2018 18:03:35.431 [0x7ff736ffd700] ERROR - [Transcoder] http://localhost:6077/auto/v10000?transcode=none: Server returned 401 Unauthorized (authorization failed)
Aug 21, 2018 18:03:35.432 [0x7ff753bff700] DEBUG - Jobs: '/usr/lib/plexmediaserver/Plex Transcoder' exit code for process 5613 is 1 (failure)
Aug 21, 2018 18:03:38.306 [0x7ff7397fc700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 1% - Recording
Aug 21, 2018 18:03:41.307 [0x7ff7497ff700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 2% - Recording
Aug 21, 2018 18:03:43.592 [0x7ff7397fc700] DEBUG - DVR:Subscription: Moving end of rolling sub for 'Live TV - Session' to 2018-08-21 18:08:43.
Aug 21, 2018 18:03:43.593 [0x7ff7397fc700] DEBUG - Activity: registered new activity b2997dae-fdf8-44fe-9fab-57ec626f7a16 - Processing subscriptions
Aug 21, 2018 18:03:43.593 [0x7ff7397fc700] DEBUG - DVR:Subscription: Scheduling subscriptions.
Aug 21, 2018 18:03:43.595 [0x7ff7397fc700] DEBUG - DVR:Subscription: Initialized 1 schedulers.
Aug 21, 2018 18:03:43.595 [0x7ff7397fc700] DEBUG - DVR:Schedule: Scheduled an active operation 'Live TV - Session' on tuner 0 between 2018-08-21 18:03:35 and 2018-08-21 18:08:43 on channel 1
Aug 21, 2018 18:03:43.596 [0x7ff7397fc700] DEBUG - DVR:Grabber: Setting timer to stop grab of 'Live TV - Session' in 300 seconds.
Aug 21, 2018 18:03:43.596 [0x7ff7397fc700] DEBUG - DVR:Subscription: Starting with 1 grabs, scheduled 1 active ones preemptively.
Aug 21, 2018 18:03:43.596 [0x7ff7397fc700] DEBUG - DVR:Subscription: Scheduled all subscriptions in 2 ms.
Aug 21, 2018 18:03:43.596 [0x7ff7397fc700] DEBUG - Activity: Ended activity b2997dae-fdf8-44fe-9fab-57ec626f7a16.
Aug 21, 2018 18:03:43.596 [0x7ff7397fc700] DEBUG - DVR:Subscription: There are 1 grabs at the end.
Aug 21, 2018 18:03:47.307 [0x7ff7497ff700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 3% - Recording
Aug 21, 2018 18:03:50.307 [0x7ff7497ff700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 4% - Recording
Aug 21, 2018 18:03:53.308 [0x7ff7397fc700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 5% - Recording
Aug 21, 2018 18:03:56.308 [0x7ff7497ff700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 6% - Recording
Aug 21, 2018 18:03:59.308 [0x7ff7497ff700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 7% - Recording
Aug 21, 2018 18:04:02.309 [0x7ff7497ff700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 8% - Recording
Aug 21, 2018 18:04:05.309 [0x7ff7397fc700] DEBUG - Activity: updated activity 372530df-a504-4454-b3b8-669eeea24af4 - completed 9% - Recording
Aug 21, 2018 18:04:05.321 [0x7ff73afff700] DEBUG - Using default transcode duration of 120 minutes
Aug 21, 2018 18:04:05.321 [0x7ff73afff700] DEBUG - Started session successfully: 81d8745c-2e10-4c5a-b97d-63ff86be1f66
Aug 21, 2018 18:04:05.322 [0x7ff73afff700] DEBUG - DVR:Recorder: It took 30.0 sec to start the session for http://localhost:6077/auto/v10000?transcode=none
Aug 21, 2018 18:04:05.322 [0x7ff73afff700] DEBUG - DVR:Grabber: Merging EPG item with live item.
Aug 21, 2018 18:04:05.322 [0x7ff73afff700] ERROR - DVR:Recorder: No part because session isn't reporting one.
Aug 21, 2018 18:04:05.322 [0x7ff73afff700] DEBUG - DVR:Grabber: Operation for Live TV - Session completed with status error (Could not start recording)
Aug 21, 2018 18:04:05.322 [0x7ff73afff700] DEBUG - Activity: Ended activity 372530df-a504-4454-b3b8-669eeea24af4.
Aug 21, 2018 18:04:05.323 [0x7ff73afff700] DEBUG - DVR:Grabber: Cleaning up rolling grab for channel 1.
Aug 21, 2018 18:04:05.323 [0x7ff73afff700] DEBUG - DVR:Recorder: Asked to stop recording 'Live TV - Session'.
Aug 21, 2018 18:04:05.323 [0x7ff73afff700] DEBUG - DVR:Recorder: Stopping transcode session.
Aug 21, 2018 18:04:05.323 [0x7ff73afff700] DEBUG - Killing job.
Aug 21, 2018 18:04:05.323 [0x7ff73afff700] DEBUG - Signalling job ID 5613 with 9
Aug 21, 2018 18:04:05.323 [0x7ff73afff700] DEBUG - Job was already killed, not killing again.
Aug 21, 2018 18:04:05.323 [0x7ff73afff700] DEBUG - Stopping transcode session 81d8745c-2e10-4c5a-b97d-63ff86be1f66
Aug 21, 2018 18:04:05.323 [0x7ff7397fc700] DEBUG - Cleaning directory for session 81d8745c-2e10-4c5a-b97d-63ff86be1f66 (/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-81d8745c-2e10-4c5a-b97d-63ff86be1f66)
Aug 21, 2018 18:04:05.324 [0x7ff73afff700] DEBUG - DVR:Grabber: Freed a tuner (now 1 available)
Aug 21, 2018 18:04:05.324 [0x7ff739ffd700] ERROR - DVR:Subscription: Rolling media grab failed to start.
Aug 21, 2018 18:04:05.324 [0x7ff739ffd700] DEBUG - DVR:Grabber: Cancelling operation for 'Live TV - Session' with status cancelled.
Aug 21, 2018 18:04:05.324 [0x7ff739ffd700] DEBUG - DVR:Grabber: Operation was active, stopping recorder.
Aug 21, 2018 18:04:05.324 [0x7ff739ffd700] DEBUG - DVR:Grabber: We've cancelled the grab with 278 seconds remaining.
Aug 21, 2018 18:04:05.324 [0x7ff739ffd700] DEBUG - DVR:Grabber: Cleaning up rolling grab for channel 1.
Aug 21, 2018 18:04:05.324 [0x7ff739ffd700] DEBUG - DVR:Recorder: Asked to stop recording 'Live TV - Session'.
Aug 21, 2018 18:04:05.324 [0x7ff736ffd700] DEBUG - DVR:Grabber: Recording for 'Live TV - Session' stopped with status complete.
Aug 21, 2018 18:04:05.325 [0x7ff736ffd700] DEBUG - DVR:Grabber: This was a rolling sub, not assimilating.
Aug 21, 2018 18:04:05.351 [0x7ff739ffd700] DEBUG - Activity: registered new activity 60de25bc-f861-4f57-9b6f-6d6a9c8d054b - Processing subscriptions
Aug 21, 2018 18:04:05.351 [0x7ff739ffd700] DEBUG - DVR:Subscription: Scheduling subscriptions.
Aug 21, 2018 18:04:05.353 [0x7ff739ffd700] DEBUG - DVR:Subscription: Initialized 1 schedulers.
Aug 21, 2018 18:04:05.353 [0x7ff739ffd700] DEBUG - DVR:Subscription: Starting with 1 grabs, scheduled 0 active ones preemptively.
Aug 21, 2018 18:04:05.353 [0x7ff739ffd700] DEBUG - DVR:Subscription: Scheduled all subscriptions in 1 ms.
Aug 21, 2018 18:04:05.353 [0x7ff739ffd700] DEBUG - Activity: Ended activity 60de25bc-f861-4f57-9b6f-6d6a9c8d054b.
Aug 21, 2018 18:04:05.354 [0x7ff739ffd700] DEBUG - DVR:Subscription: There are 0 grabs at the end.
Aug 21, 2018 18:04:05.355 [0x7ff758fff700] DEBUG - Completed: [::1:58802] 200 POST /livetv/dvrs/6/channels/1/tune (7 live) TLS GZIP 30078ms 536 bytes (pipelined: 5)
Aug 21, 2018 18:04:05.356 [0x7ff736ffd700] DEBUG - Activity: registered new activity b82564c1-bd32-47cc-b071-3df9ca2f5989 - Processing subscriptions
Aug 21, 2018 18:04:05.356 [0x7ff736ffd700] DEBUG - DVR:Subscription: Scheduling subscriptions.
Aug 21, 2018 18:04:05.358 [0x7ff736ffd700] DEBUG - DVR:Subscription: Initialized 1 schedulers.
Aug 21, 2018 18:04:05.358 [0x7ff736ffd700] DEBUG - DVR:Subscription: Starting with 0 grabs, scheduled 0 active ones preemptively.
Aug 21, 2018 18:04:05.358 [0x7ff736ffd700] DEBUG - DVR:Subscription: Scheduled all subscriptions in 1 ms.
Aug 21, 2018 18:04:05.358 [0x7ff736ffd700] DEBUG - Activity: Ended activity b82564c1-bd32-47cc-b071-3df9ca2f5989.
Aug 21, 2018 18:04:05.358 [0x7ff736ffd700] DEBUG - DVR:Subscription: There are 0 grabs at the end.
Aug 21, 2018 18:04:05.492 [0x7ff758fff700] DEBUG - Auth: authenticated user 1 as BlanchonJ
Aug 21, 2018 18:04:05.492 [0x7ff7307fb700] DEBUG - Request: [::1:58834 (WAN)] GET /status/sessions/background (7 live) TLS GZIP Signed-in Token (BlanchonJ)
Aug 21, 2018 18:04:05.494 [0x7ff758fff700] DEBUG - Completed: [::1:58834] 200 GET /status/sessions/background (7 live) TLS GZIP 1ms 470 bytes (pipelined: 1)
Aug 21, 2018 18:04:06.314 [0x7ff737fff700] DEBUG - DVR:Recorder: Asked to stop recording 'Live TV - Session'.
Aug 21, 2018 18:04:08.309 [0x7ff73afff700] DEBUG - Transcoder: Cleaning old transcode directories.
Aug 21, 2018 18:04:08.310 [0x7ff73afff700] DEBUG - Whacked session 81d8745c-2e10-4c5a-b97d-63ff86be1f66, 0 remaining.
Aug 21, 2018 18:04:08.310 [0x7ff73afff700] DEBUG - Streaming Resource: Terminated session 0x7ff740650720:81d8745c-2e10-4c5a-b97d-63ff86be1f66 with reason Client stopped playback.
Foebik commented 6 years ago

I get the same issue, sometimes restarting Plex a bunch of times will get it to work.

chazlarson commented 6 years ago

This is probably the source of the failure:

Aug 21, 2018 18:03:35.431 [0x7ff736ffd700] ERROR - [Transcoder] http://localhost:6077/auto/v10000?transcode=none: Server returned 401 Unauthorized (authorization failed)

That request to telly would have resulted in a redirect to the provider stream, which apparently failed with a 401.

robbiet480 commented 6 years ago

Hopefully will be fixed via https://github.com/tellytv/telly/commit/2130ad62bf17f6279a2201a7badaeecd60070fe9

julien-blanchon commented 6 years ago

Yes, It's because my IP is blocked by the provider. Solved

Nottt commented 5 years ago

I'm having the same issue :/

julien-blanchon commented 5 years ago

Check if you're ip is banned by the provider. Try to ping the the server

chazlarson commented 5 years ago

See the wiki articles regarding connection issues.