[mythtv-users] External recorder command flow

Thu Aug 4 03:52:31 UTC 2016

On Wed, Aug 3, 2016 at 7:19 PM, John P Poet <jppoet at gmail.com> wrote:

> On Tue, Aug 2, 2016 at 10:26 PM Marc Rawji <mrawji at gmail.com> wrote:
>
>> Hello (again),
>>
>> I am trying to write an external recorder. I don't quite understand the
>> message flow that I am seeing in my recorder. I am seeing a StartStreaming,
>> followed by a StropStreaming, then a StartStreaming, then it streams to the
>> frontend.
>>
>> See my annotated and trimmed logs (removed Calls with no impact on the
>> streaming, and the many many SendBytes):
>> 2016-08-01 22:13:01,922 root        : DEBUG received TuneChannel:2
>> 2016-08-01 22:13:01,975 root        : DEBUG received StartStreaming
>> 2016-08-01 22:13:04,788 root        : DEBUG returning OK:Started  //Took
>> approx 3 seconds to start getting data
>> 2016-08-01 22:13:04,790 root        : DEBUG received SendBytes
>> 2016-08-01 22:13:04,877 root        : DEBUG returning OK
>>  //Sending 1 SendBytes of data to STDOUT
>> 2016-08-01 22:13:04,895 root        : DEBUG received StopStreaming // as
>> soon as i start sending data, i get a StopStreaming
>> 2016-08-01 22:13:05,899 root        : DEBUG returning OK:Stopped
>> 2016-08-01 22:13:06,007 root        : DEBUG received StartStreaming // as
>> soon as it stops, then it asks me to start it again
>> 2016-08-01 22:13:08,423 root        : DEBUG returning OK:Started // takes
>> 2.5 seconds to start getting data
>> 2016-08-01 22:13:08,430 root        : DEBUG received SendBytes  // we now
>> send data
>> 2016-08-01 22:13:08,602 root        : DEBUG returning OK
>> <send bytes is repeated and I see data on frontend>
>>
>> On the backend, i only see this in the same time period:
>> 2016-08-01 22:13:01.933523 N  ApplyRecordRecGroupChange: LiveTV to LiveTV
>> (2)
>> 2016-08-01 22:13:05.955482 N  AutoExpire: CalcParams(): Max required Free
>> Space: 2.0 GB w/freq: 15 min
>> 2016-08-01 22:13:05.957646 W  LoadFromProgram(): SQL contains LIMIT
>> clause, caller should be updated to use limit parameter instead
>> 2016-08-01 22:13:05.969135 N  ApplyRecordRecGroupChange: LiveTV to LiveTV
>> (2)
>> 2016-08-01 22:13:05.969857 I  TVRec[1]: TuningNewRecorder -
>> CreateRecorder()
>> 2016-08-01 22:13:05.971848 E
>>  RecBase[1](/home/mrawji/recorder/record.sh):
>> SetStrOption(...recordingtype): Option not in profile.
>> 2016-08-01 22:13:05.971860 E
>>  RecBase[1](/home/mrawji/recorder/record.sh): SetIntOption(...recordmpts):
>> Option not in profile.
>>
>>
>>
>> Does anyone know why I get a Start, followed by a Stop, then another
>> Start?
>>
>> Thanks,
>> Marc
>> <https://forum.mythtv.org>
>>
>
> Mythbackend first checks to make sure the 'signal' is valid.  I have a
> dream of changing it to hand off the stream from the SignalMonitor to the
> Recorder, where it would not Start/Stop/Restart, but that is a major
> architecture change.
>
> When running mythbackend, I would recommend using `-v channel,record` to
> see more useful information.
>
> John
>
>
Thanks so much for the reply. With the more verbose logging, I don't see
anything worrisome between the Start and Stop:

2016-08-03 20:36:57.213675 I  ExternSH(/home/mrawji/recorder/record.sh):
ProcessCommand('StartStreaming') = 'OK:Started'
2016-08-03 20:36:57.213695 I  ExternSH(/home/mrawji/recorder/record.sh):
Streaming started
2016-08-03 20:36:57.213708 I  ExternSH(/home/mrawji/recorder/record.sh):
StartStreaming 1 listeners
2016-08-03 20:36:57.414768 I  TVRec[1]: TuningSignalCheck: Good signal
2016-08-03 20:36:57.414809 I  TVRec[1]:
SetRecordingStatus(Unknown->Recording) on line 4023
2016-08-03 20:36:57.414913 I  TVRec[1]: TeardownSignalMonitor() -- begin
2016-08-03 20:36:57.414934 I
 ExternSigMon(/home/mrawji/recorder/record.sh): dtor
2016-08-03 20:36:57.414947 I
 ExternSigMon(/home/mrawji/recorder/record.sh): Stop() -- begin
2016-08-03 20:36:57.414964 I  ExternSH(/home/mrawji/recorder/record.sh):
StopStreaming 1 listeners
2016-08-03 20:36:57.414976 I  ExternSH(/home/mrawji/recorder/record.sh):
StopStreaming
2016-08-03 20:36:57.424594 I  ExternSH(/home/mrawji/recorder/record.sh):
ProcessCommand('Version?') = 'OK:1.0'
2016-08-03 20:36:58.432030 I  ExternSH(/home/mrawji/recorder/record.sh):
ProcessCommand('StopStreaming') = 'OK:Stopped'
2016-08-03 20:36:58.434253 I  ExternSH(/home/mrawji/recorder/record.sh):
Streaming stopped
2016-08-03 20:36:58.474514 I  SH(/home/mrawji/recorder/record.sh):
RemoveListener(0x7f4574023420) -- begin
2016-08-03 20:36:58.474537 I  SH(/home/mrawji/recorder/record.sh):
RemoveListener(0x7f4574023420) -- locked
2016-08-03 20:36:58.475340 I  ExternSH(/home/mrawji/recorder/record.sh):
run(): shutdown
2016-08-03 20:36:58.475405 I  ExternSH(/home/mrawji/recorder/record.sh):
run(): end
2016-08-03 20:36:58.475540 I  SH(/home/mrawji/recorder/record.sh):
RemoveListener(0x7f4574023420) -- end
2016-08-03 20:36:58.475555 I
 ExternSigMon(/home/mrawji/recorder/record.sh): Stop() -- end

The only error I see before that is:
2016-08-03 20:36:54.493505 E  TVRec[1]: Profile 'Live TV' not found, and
unable to load fallback profile 'Default'.  Results may be unpredicable

But, i also see with the second "startStreaming" and then everything "just
works".

Thanks for your help!
Marc
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20160803/92806511/attachment.html>