[mythtv-users] Problems with ExternalRecorder and streamlink

Peter Carlsson maillist.peter at home.se
Wed Feb 10 21:27:33 UTC 2021


On Tue, Feb 02, 2021 at 01:13:23PM -0700, John P Poet wrote:
> On Sun, Jan 31, 2021 at 3:10 PM Peter Carlsson <maillist.peter at home.se>
> wrote:
> 
> > On Sat, Jan 30, 2021 at 03:01:02PM -0700, John P Poet wrote:
> > > On Tue, Jan 26, 2021 at 3:11 PM Peter Carlsson <maillist.peter at home.se>
> > > wrote:
> > >
> > > > Hello!
> > > >
> > > > I had MythTV setup using the ExternalRecorder together with streamlink.
> > > >
> > > > Last summer the svtplay plugin for streamlink stopped working and I
> > > > temporarily stopped using it by changing the recording priority to use
> > > > another recorder.
> > > >
> > > > In streamlink version 1.6.0 (2020-09-22) it was fixed (by Ian Cameron)
> > > > and I verified in streamlink that it worked but I never took the time
> > to
> > > > change back the recording priority until recently.
> > > >
> > > > But I can not get it to work again. I don't remember to have done
> > > > anything else specific to the original problem but much has changed
> > > > since then.
> > > >
> > > > MythTV has been upgraded to version 31 and streamlink to version 2.0.0
> > > > where streamlink has dropped support for Python 2 and Python 3.5 and
> > > > MythTV added support for Python 3.
> > > >
> > > > I use Debian Buster and have both Python 2.7 and 3.7 installed.
> > > >
> > > > I tried he following but it just stops at the last line below.
> > > >
> > > > mythexternrecorder --conf
> > > > /home/peter/delat/script/mythtv-svtplay-external-recorder.conf
> > --loglevel
> > > > debug --verbose all
> > > > 2021-01-26 22:55:35.201299 C  mythexternrecorder version:  [v31.0]
> > > > www.mythtv.org
> > > > 2021-01-26 22:55:35.201337 C  Qt version: compile: 5.11.3, runtime:
> > 5.11.3
> > > > 2021-01-26 22:55:35.201391 I  Debian GNU/Linux 10 (buster) (i386)
> > > > 2021-01-26 22:55:35.201394 N  Enabled verbose msgs: all
> > > > 2021-01-26 22:55:35.201415 N  Setting Log Level to LOG_DEBUG
> > > > 2021-01-26 22:55:35.212913 I  : Buffer: Ready for data.
> > > > 2021-01-26 22:55:35.212956 I  Added logging to the console
> > > > 2021-01-26 22:55:35.212986 I  : Command parser ready.
> > > > 2021-01-26 22:55:35.213774 D  New Logging Client: ID:  (#1)
> > > > 2021-01-26 22:55:35.231943 I   Channels in
> > > >
> > '/home/peter/delat/script/mythtv-svtplay-external-recorder-channels.conf',
> > > > Tuner: '', Scanner: ''
> > > > ^C
> > > >
> > > > What can I do to debug this problem?
> > > >
> > > > Please let me know if I should provide additional information.
> > > >
> > > > cat /home/peter/delat/script/mythtv-svtplay-external-recorder.conf
> > > >
> > > > [RECORDER]
> > > > # The recorder command to execute.  %URL% is optional, and
> > > > # will be replaced with the channel's "URL" as defined in the
> > > > # [TUNER/channels] (channel conf) configuration file
> > > > #command="cvlc \"%URL%\" --sout \"#std{mux=ts,access=file,dst=-}\""
> > > > command="streamlink --player=vlc --stdout \"%URL%\" best"
> > > >
> > > > # Used in logging events, %ARG% are replaced from the channel info
> > > > desc=streamlink \"%URL%\" \"%CHANNUM%\" \"%CHANNAME%\" \"%CALLSIGN%\"
> > > >
> > > > [TUNER]
> > > > # An optional CONF file which provides channel details.  If it does not
> > > > # exist, then channel changes are not supported.
> > > > channels=mythtv-svtplay-external-recorder-channels.conf
> > > >
> > > > # If [TUNER/command] is provided, it will be executed to "tune" the
> > > > # channel. A %URL% parameter will be substituted with the "URL" as
> > > > # defined in the [TUNER/channels] configuration file
> > > > #command=
> > > >
> > > > # Timeout for changing channels in msecs
> > > > #timeout=
> > > >
> > > > [SCANNER]
> > > > # When MythTV scans for channels, The contents of the [TUNER/channels]
> > > > # config file are used to populate MythTV's channel information.
> > > > # If a command is provided here, it will be executed first, so it can
> > > > # populate the [TUNER/channels] config file
> > > > #command=/home/myth/bin/scan.sh "%CHANCONF%"
> > > >
> > > > # Timeout for scan command in msecs
> > > > #timeout=60000
> > > >
> > > >
> > > > cat
> > > > /home/peter/delat/script/mythtv-svtplay-external-recorder-channels.conf
> > > >
> > > > [1]
> > > > NAME=SVT1 HD
> > > > CALLSIGN=SVT1HD
> > > > XMLTVID=svt1.svt.se
> > > > URL="https://www.svtplay.se/kanaler/svt1?start=auto"
> > > > ICON=/home/mythtv/.mythtv/channels/svt1.svt.se.png
> > > >
> > > > [2]
> > > > NAME=SVT2 HD
> > > > CALLSIGN=SVT2HD
> > > > XMLTVID=svt2.svt.se
> > > > URL="https://www.svtplay.se/kanaler/svt2?start=auto"
> > > > ICON=/home/mythtv/.mythtv/channels/svt2.svt.se.png
> > > >
> > > > [3]
> > > > NAME=Kunskapskanalen
> > > > CALLSIGN=Kunskapskanalen
> > > > XMLTVID=kunskapskanalen.svt.se
> > > > URL="https://www.svtplay.se/kanaler/kunskapskanalen?start=auto"
> > > > ICON=/home/mythtv/.mythtv/channels/kunskapskanalen.svt.se.png
> > > >
> > > > [4]
> > > > NAME=Barnkanalen
> > > > CALLSIGN=Barnkanalen
> > > > XMLTVID=barnkanalen.svt.se
> > > > URL="https://www.svtplay.se/kanaler/svtbarn?start=auto"
> > > > ICON=/home/mythtv/.mythtv/channels/barnkanalen.svt.se.png
> > > >
> > > > [5]
> > > > NAME=SVT24
> > > > CALLSIGN=SVT24
> > > > XMLTVID=svt24.svt.se
> > > > URL="https://www.svtplay.se/kanaler/svt24?start=auto"
> > > > ICON=/home/mythtv/.mythtv/channels/svt24.svt.se.png
> > > >
> > > >
> > > Hi Peter,
> > >
> > > The behavior you describe is correct. At that point mythexternrecorder is
> > > expecting to be given commands from mythackend. For example, instead of
> > > hitting CTRL-C where you did, you could type:
> > > APIVersion?
> > > and it should spit out something like
> > > OK:2
> > >
> > > If you look at https://www.mythtv.org/wiki/ExternalRecorder you can see
> > the
> > > commands that are allowed. With APIVersion2, the serial number at the
> > > beginning of each command should be incremented.
> >
> > Hello John,
> >
> > Thanks for you answer. I tried to send some commands and they all seems
> > to work until I try to send TuneStatus? where I would have expected
> > '9:OK:Tuned to 1' or similar. Am I on the right track and is this
> > indicating that something is wrong?
> >
> > It seems that although I add arguments '--loglevel debug --verbose' I
> > don't get that much help of the output.
> >
> > I can call streamlink directly and get a stream that I can watch in VLC.
> >
> > mythexternrecorder --conf
> > /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel
> > debug --verbose
> > 2021-01-31 22:58:06.872700 C  mythexternrecorder version:  [v31.0]
> > www.mythtv.org
> > 2021-01-31 22:58:06.872720 C  Qt version: compile: 5.11.3, runtime: 5.11.3
> > 2021-01-31 22:58:06.872748 I  Debian GNU/Linux 10 (buster) (x86_64)
> > 2021-01-31 22:58:06.872750 N  Enabled verbose msgs:  general
> > 2021-01-31 22:58:06.872760 N  Setting Log Level to LOG_DEBUG
> > 2021-01-31 22:58:06.883132 I  Added logging to the console
> > 1::HasTuner?
> > 1:OK:Yes
> > 2::LoadChannels
> > 2:OK:5
> > 3::FirstChannel
> > 3:OK:1,SVT1 HD,SVT1HD,svt1.svt.se
> > ,/home/mythtv/.mythtv/channels/svt1.svt.se.png
> > 4:NextChannel
> > 4:OK:2,SVT2 HD,SVT2HD,svt2.svt.se
> > ,/home/mythtv/.mythtv/channels/svt2.svt.se.png
> > 5:NextChannel
> > 5:OK:3,Kunskapskanalen,Kunskapskanalen,kunskapskanalen.svt.se
> > ,/home/mythtv/.mythtv/channels/kunskapskanalen.svt.se.png
> > 6:NextChannel
> > 6:OK:4,Barnkanalen,Barnkanalen,barnkanalen.svt.se
> > ,/home/mythtv/.mythtv/channels/barnkanalen.svt.se.png
> > 7:NextChannel
> > 7:OK:5,SVT24,SVT24,svt24.svt.se
> > ,/home/mythtv/.mythtv/channels/svt24.svt.se.png
> > 8:TuneChannel:1
> > 8:OK:Tuned to 1
> > 9:TuneStatus?
> > 9:OK:Tuned to
> >
> > /Peter
> >
> 
> Hi Peter,
> 
> Sorry for the slow responses. I have some other things going on.
> 
> As far as the TuneStatus? response, that could be a minor bug. mythbackend
> will only issue that command if TuneChannel: returns "OK:InProgress". In
> your example it returned "OK:Tuned to 1" so mythbackend would never have
> issued "TuneStatus?", therefore I never noticed that the response was poor.
> I will take a look at that.
> 
> mythbackend will normally send the following commands after the channel is
> tuned:
> Description?
> SignalStrengthPercent?
> HasLock?
> IsOpen?
> Those are just to gather information. It will then do:
> StartStreaming
> XON
> Which tells mythexternrecorder to actually start processing data. The
> transport stream will be parsed so mythtv can verify that it is valid. Then
> the stream will be shut down:
> XOFF
> Version?
> StopStreaming
> ..
> Then mythbackend is finally ready to start recording, so it will start the
> stream back up:
> ..
> StartStreaming
> XON
> and mythexternrecorder will pass the transport stream to mythbackend for it
> to record.
> 
> When mythbackend invokes mythexternrecorder it passes arguments such as
> --logpath to it. Wherever the mythbackend logs are stored (e.g.
> /var/log/mythtv) you should also find mythexternrecorder log files. If
> mythbackend is started up with "--logpath /var/log/mythtv -v
> channel,record" then mythexternrecorder will as well. When debugging
> recording issues make sure you have told mythbackend to run with "-v
> channel,record".

Hello John,

I very much appreciate your help!

I added more logging as you suggested. Don't know why it is truncated in
the log messages.

Do you make anything out of the log messages?

What would be my next step?

Best regards,
Peter Carlsson

Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.285294 I  ExternChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): Open()
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.286900 I  ChannelBase[21]: Input #21: 'MPEG2TS' schan(1) sourceid(4)
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.287222 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): args "--conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha --verbose general,channel,record --logpath
 /var/log/mythtv --loglevel info --quiet --inputid 21"
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.287275 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): Spawn '/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha'
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.287281 I  ExternIO::Run()
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.308616 I  ExternIO::Fork 'mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha --verbose general,channel,record --logpath /var/log/mythtv --loglevel info --quiet --inputid 21'
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.314137 I  Spawned
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.567769 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessCommand('APIVersion?') = 'OK:2' took 243ms
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.567940 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessV2('1:APIVersion:2') = 'OK:2' took 0ms
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.568051 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessV2('2:Version?') = 'OK:0.6' took 0ms
Feb 10 22:09:06 htpc mythbackend[1097]: 2021-02-10 22:09:06.568173 W  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessV2('3:Description?') = 'WARN:Not set' took 0ms <-- NOTE
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.570731 E  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessVer2: Giving up waiting for response for command '4:HasTuner?'
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.577774 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessV2('5:HasTuner?') = 'OK:Yes' took 6ms
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.588000 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessV2('6:HasPictureAttributes?') = 'OK:No' took 10ms
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.588178 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessV2('7:FlowControl?') = 'OK:XON/XOFF' took 0ms
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.588194 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): App opened successfully
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.588224 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): Capabilities: tuner(yes) Picture attributes(no) Flow control(XON/XOFF)
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.598156 I  ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): ProcessV2('8:BlockSize:1540096') = 'OK' took 9ms
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.598179 I  ExternSH[21]: Creating new stream handler 21 for /usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.598193 I  ExternChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): Opened
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.598205 I  DTVChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): SetChannelByString(1):
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.598219 I  CardUtil[21]: GetConflictingInputs() input 21
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.599105 I  CardUtil[21]: GetConflictingInputs() got input 22
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.599147 I  CardUtil[21]: GetConflictingInputs() got input 23
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.599167 I  CardUtil[21]: GetConflictingInputs() got input 24
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.599233 I  ChannelBase[21]: Input is free on 0/0
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601241 E  DTVMux: ParseTuningParams -- Unknown tuner type = 0xffffffff80000000
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601295 E  DTVChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): SetChannelByString(1): Failed to initialize multiplex options
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601306 I  DTVChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --loglevel debug --verbose cha): SetChannelByString(1): failure
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601321 E  TVRec[21]: Failed to set channel to 1. Reverting to kState_None
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601355 I  TVRec[21]: Changing from WatchingLiveTV to None
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601392 I  TVRec[21]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop, @ tv_rec.cpp:1291
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601412 I  TVRec[21]: HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601439 I  TVRec[21]: TuningShutdowns(Program(NULL) channel() input() flags(KillRec,KillRingBuffer,))
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601473 I  TVRec[21]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop, @ tv_rec.cpp:3640
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.601582 I  TVRec[21]: SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording, @ tv_rec.cpp:2691
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.668791 I  MainServer: MainServer::ANN Playback
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.668815 I  MainServer: adding: server(168bfa0) as a client (events: 0)
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.686075 I  MainServer: adding: server(168a9b0) as a file transfer
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.696841 I  FileTransfer sock(1652c90) disconnected
Feb 10 22:09:10 htpc mythbackend[1097]: 2021-02-10 22:09:10.699146 I  Playback sock(a4e8a0e0) 'server' disconnected
Feb 10 22:09:50 htpc mythbackend[1097]: 2021-02-10 22:09:50.700293 I  Playback sock(90649d90) 'server' disconnected
Feb 10 22:09:50 htpc mythbackend[1097]: 2021-02-10 22:09:50.726349 I  FileTransfer sock(168a9b0) disconnected
Feb 10 22:09:50 htpc mythbackend[1097]: 2021-02-10 22:09:50.736473 I  Playback sock(168bfa0) 'server' disconnected
Feb 10 22:10:00 htpc mythbackend[1097]: 2021-02-10 22:10:00.772972 I  TVRec[1]: ClearFlags(FinishRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:1329
Feb 10 22:10:00 htpc mythbackend[1097]: 2021-02-10 22:10:00.773027 I  TVRec[1]: Changing from RecordingOnly to None
Feb 10 22:10:00 htpc mythbackend[1097]: 2021-02-10 22:10:00.773570 I  TVRec[1]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:1291
Feb 10 22:10:00 htpc mythbackend[1097]: 2021-02-10 22:10:00.773611 I  TVRec[1]: HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
Feb 10 22:10:00 htpc mythbackend[1097]: 2021-02-10 22:10:00.773648 I  TVRec[1]: TuningShutdowns(Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,))
Feb 10 22:10:00 htpc mythbackend[1097]: 2021-02-10 22:10:00.773667 I  TVRec[1]: TeardownRecorder()


More information about the mythtv-users mailing list