[mythtv-users] recording from external recording sending XOFF and never sending XON
Brian J. Murrell
brian at interlinx.bc.ca
Wed Nov 14 12:24:51 UTC 2018
I'm trying to record from an external recorder on v29.1-11-gbd764db and
the BE is starting the external recorder, then pausing it and never
resuming it. Here's a log from MythBE's perspective:
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler tv_rec.cpp:319 (RecordPending) TVRec[6]: RecordPending on inputid 6
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler cardutil.cpp:1448 (GetConflictingInputs) CardUtil: GetConflictingInputs() input 6
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler tv_rec.cpp:433 (StartRecording) TVRec[6]: StartRecording("Ollie! The Boy Who Became What He Ate":"Sweet Potato Spy")
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler tv_rec.cpp:730 (SetRecordingStatus) TVRec[6]: SetRecordingStatus(Unknown->Aborted) on line 439
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler tv_rec.cpp:829 (StartedRecording) TVRec[6]: StartedRecording(4006_2018-11-14T12:08:00Z) fn(/var/lib/mythtv/recordings/4006_20181114120800.ts)
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: E Scheduler tv_rec.cpp:4141 (LoadProfile) TVRec[6]: Profile 'Default' not found, and unable to load fallback profile 'Default'. Results may be unpredicable
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(CancelNextRecording,) -> RunMainLoop, @ tv_rec.cpp:629
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler tv_rec.cpp:730 (SetRecordingStatus) TVRec[6]: SetRecordingStatus(Aborted->Tuning) on line 632
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:1088 (HandleStateChange) TVRec[6]: Changing from None to RecordingOnly
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop, @ tv_rec.cpp:1316
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3492 (HandleTuning) TVRec[6]: HandleTuning Request: Program(ProgramInfo(4006_20181114120800.ts): channame(CBLT) startts(Wed Nov 14 12:00:00 2018 GMT) endts(Wed Nov 14 12:15:00 2018 GMT)#012 recstartts(Wed Nov 14 12:08:00 2018 GMT) recendts(Wed Nov 14 12:15:00 2018 GMT)#012 title(Ollie! The Boy Who Became What He Ate)) channel() input() flags(Recording,)
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3561 (TuningShutdowns) TVRec[6]: TuningShutdowns(Program(ProgramInfo(4006_20181114120800.ts): channame(CBLT) startts(Wed Nov 14 12:00:00 2018 GMT) endts(Wed Nov 14 12:15:00 2018 GMT)#012 recstartts(Wed Nov 14 12:08:00 2018 GMT) recendts(Wed Nov 14 12:15:00 2018 GMT)#012 title(Ollie! The Boy Who Became What He Ate)) channel(6) input(MPEG2TS) flags(Recording,))
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop, @ tv_rec.cpp:3627
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3514 (HandleTuning) TVRec[6]: No recorder yet, calling TuningFrequency
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3649 (TuningFrequency) TVRec[6]: TuningFrequency
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:548 (ExternalStreamHandler) ExternalRec(/home/mythtv/bin/m3u_recorder): args "--verbose general,record --loglevel info --quiet --syslog local7"
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:767 (OpenApp) ExternalRec(/home/mythtv/bin/m3u_recorder): Spawn '/home/mythtv/bin/m3u_recorder'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:233 (Run) ExternIO::Run()
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:320 (Fork) ExternIO::Fork 'm3u_recorder --verbose general,record --loglevel info --quiet --syslog local7 -q'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:378 (Fork) Spawned
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('Version?') = 'OK:1.0.0'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('HasTuner?') = 'OK:Yes'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('HasPictureAttributes?') = 'OK:No'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('FlowControl?') = 'OK:XON/XOFF'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:813 (OpenApp) ExternalRec(/home/mythtv/bin/m3u_recorder): App opened successfully
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:821 (OpenApp) ExternalRec(/home/mythtv/bin/m3u_recorder): Capabilities: tuner(yes) Picture attributes(no) Flow control(XON/XOFF)
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('BlockSize:6160384') = 'OK'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:474 (Get) ExternSH: Creating new stream handler /home/mythtv/bin/m3u_recorder for /home/mythtv/bin/m3u_recorder
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalChannel.cpp:55 (Open) ExternChan[6](/home/mythtv/bin/m3u_recorder): Opened
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent cardutil.cpp:1448 (GetConflictingInputs) CardUtil: GetConflictingInputs() input 6
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('TuneChannel:6') = 'OK'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3776 (TuningFrequency) TVRec[6]: Starting Signal Monitor
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:2037 (SetupSignalMonitor) TVRec[6]: SetupSignalMonitor(1, 0)
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('Version?') = 'OK:1.0.0'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:482 (Get) ExternSH: Using existing stream handler for /home/mythtv/bin/m3u_recorder (2 in use)
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('LockTimeout?') = 'OK:5000'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:2060 (SetupSignalMonitor) TVRec[6]: Signal monitor successfully created
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:1857 (SetupDTVSignalMonitor) TVRec[6]: Setting up table monitoring.
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: E TVRecEvent tv_rec.cpp:4141 (LoadProfile) TVRec[6]: Profile 'Live TV' not found, and unable to load fallback profile 'Default'. Results may be unpredicable
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:1971 (SetupDTVSignalMonitor) TVRec[6]: MPEG program number: 0
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent mpeg/mpegstreamdata.cpp:90 (SetDesiredProgram) MPEGStream[6](0x9f5e4c8): SetDesiredProgram(0)
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:1992 (SetupDTVSignalMonitor) TVRec[6]: Successfully set up MPEG table monitoring.
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4398 (SetFlags) TVRec[6]: SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning, @ tv_rec.cpp:3803
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning, @ tv_rec.cpp:3804
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4398 (SetFlags) TVRec[6]: SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning, @ tv_rec.cpp:3809
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning, @ tv_rec.cpp:3870
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4398 (SetFlags) TVRec[6]: SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning, @ tv_rec.cpp:3872
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3994 (TuningSignalCheck) TVRec[6]: TuningSignalCheck: Still waiting. Will timeout @ 07:15:00.000
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('SignalStrengthPercent?') = 'OK:100'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('HasLock?') = 'OK:Yes'
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/streamhandler.cpp:81 (AddListener) SH(/home/mythtv/bin/m3u_recorder): AddListener(0x9f5e4c8) -- begin
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/streamhandler.cpp:93 (AddListener) SH(/home/mythtv/bin/m3u_recorder): AddListener(0x9f5e4c8) -- locked
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I Scheduler scheduler.cpp:2923 (HandleRecordingStatusChange) Tuning recording: "Ollie! The Boy Who Became What He Ate":"Sweet Potato Spy": channel 4006 on cardid [6], sourceid 4
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:581 (run) ExternalRec(/home/mythtv/bin/m3u_recorder): run(): begin
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/streamhandler.cpp:115 (AddListener) SH(/home/mythtv/bin/m3u_recorder): AddListener(0x9f5e4c8) -- end
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/ExternalStreamHandler.cpp:960 (StartStreaming) ExternalRec(/home/mythtv/bin/m3u_recorder): StartStreaming with 0 current listeners
Nov 14 07:07:56 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('Version?') = 'OK:1.0.0'
Nov 14 07:07:57 mythbe mythbackend: mythbackend[8167]: C CoreContext programinfo.cpp:340 (ProgramInfo) ProgramInfo(): Failed to find recorded entry for 0.
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('StartStreaming') = 'OK:Started'
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/ExternalStreamHandler.cpp:990 (StartStreaming) ExternalRec(/home/mythtv/bin/m3u_recorder): Streaming started
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I SignalMonitor recorders/ExternalStreamHandler.cpp:999 (StartStreaming) ExternalRec(/home/mythtv/bin/m3u_recorder): StartStreaming 1 listeners
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('IsOpen?') = 'OK:Open'
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: E ExternSH recorders/dtvsignalmonitor.cpp:323 (HandlePAT) DTVSigMon[6](/home/mythtv/bin/m3u_recorder): Program #0 not found in PAT!#012Program Association Section#012 PSIP tableID(0x0) length(13) extension(0x1)#012 version(0) current(1) section(0) last_section(0)#012 tsid(1) programCount(1)#012 program number 1 has PID 0x1000
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: E ExternSH recorders/dtvsignalmonitor.cpp:329 (HandlePAT) DTVSigMon[6](/home/mythtv/bin/m3u_recorder): But there is only one program in the PAT, so we'll just use it
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I ExternSH mpeg/mpegstreamdata.cpp:90 (SetDesiredProgram) MPEGStream[6](0x9f5e4c8): SetDesiredProgram(1)
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: W ExternSH mpeg/mpegstreamdata.cpp:775 (ProcessPAT) MPEGStream[6](0x9f5e4c8): ProcessPAT: PAT is missing program, setting timeout
Nov 14 07:07:58 mythbe mythbackend: mythbackend[8167]: I ExternSH mpeg/mpegstreamdata.cpp:791 (ProcessPAT) MPEGStream[6](0x9f5e4c8): ProcessPAT: Good PAT seen after a bad PAT
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3898 (TuningSignalCheck) TVRec[6]: TuningSignalCheck: Good signal
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:730 (SetRecordingStatus) TVRec[6]: SetRecordingStatus(Tuning->Recording) on line 4000
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:2093 (TeardownSignalMonitor) TVRec[6]: TeardownSignalMonitor() -- begin
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I CoreContext scheduler.cpp:734 (UpdateRecStatus) Updating status for "Ollie! The Boy Who Became What He Ate":"Sweet Potato Spy" on cardid [6] (Tuning => Recording)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/ExternalStreamHandler.cpp:506 (Return) ExternSH: Return '/home/mythtv/bin/m3u_recorder' in use 2
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:2112 (TeardownSignalMonitor) TVRec[6]: TeardownSignalMonitor() -- end
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder, @ tv_rec.cpp:4026
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder, @ tv_rec.cpp:4028
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4153 (TuningNewRecorder) TVRec[6]: Starting Recorder
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: E TVRecEvent tv_rec.cpp:4141 (LoadProfile) TVRec[6]: Profile 'Default' not found, and unable to load fallback profile 'Default'. Results may be unpredicable
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4192 (TuningNewRecorder) TVRec[6]: rec->GetPathname(): '/var/lib/mythtv/recordings/4006_20181114120800.ts'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4224 (TuningNewRecorder) TVRec[6]: TuningNewRecorder - CreateRecorder()
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/dtvrecorder.cpp:182 (ResetForNewFile) DTVRec[6]: ResetForNewFile(void)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: E TVRecEvent recorders/recorderbase.cpp:232 (SetStrOption) RecBase[6](/home/mythtv/bin/m3u_recorder): SetStrOption(...recordingtype): Option not in profile.
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: E TVRecEvent recorders/recorderbase.cpp:222 (SetIntOption) RecBase[6](/home/mythtv/bin/m3u_recorder): SetIntOption(...recordmpts): Option not in profile.
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/recorderbase.cpp:101 (SetRingBuffer) RecBase[6](/home/mythtv/bin/m3u_recorder): SetRingBuffer(0x9f4bf18) '/var/lib/mythtv/recordings/4006_20181114120800.ts'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/recorderbase.cpp:111 (SetRecording) RecBase[6](/home/mythtv/bin/m3u_recorder): SetRecording(0xffffffffab0b0e00) title(Ollie! The Boy Who Became What He Ate)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent mpeg/mpegstreamdata.cpp:90 (SetDesiredProgram) MPEGStream[6](0x9f5e4c8): SetDesiredProgram(1)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/dtvrecorder.cpp:1289 (HandlePAT) DTVRec[6]: SetPAT(1 on 0x1000)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec(/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/dtvrecorder.cpp:1309 (HandlePMT) DTVRec[6]: SetPMT(1, valid)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent recorders/dtvrecorder.cpp:1314 (HandlePMT) DTVRec[6]: SetPMT(1)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/dtvrecorder.cpp:182 (ResetForNewFile) DTVRec[6]: ResetForNewFile(void)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/ExternalStreamHandler.cpp:482 (Get) ExternSH: Using existing stream handler for /home/mythtv/bin/m3u_recorder (2 in use)
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('Version?') = 'OK:1.0.0'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/ExternalRecorder.cpp:151 (Open) ExternalRec[6](/home/mythtv/bin/m3u_recorder): Opened successfully
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4398 (SetFlags) TVRec[6]: SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady, @ tv_rec.cpp:4296
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:4298
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/streamhandler.cpp:81 (AddListener) SH[6](/home/mythtv/bin/m3u_recorder): AddListener(0x9f5e4c8) -- begin
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/streamhandler.cpp:93 (AddListener) SH[6](/home/mythtv/bin/m3u_recorder): AddListener(0x9f5e4c8) -- locked
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/streamhandler.cpp:115 (AddListener) SH[6](/home/mythtv/bin/m3u_recorder): AddListener(0x9f5e4c8) -- end
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I CoreContext mythsystemevent.cpp:308 (customEvent) MythSystemEventHandler: Starting thread for command '/home/mythtv/bin/rec_started_writing "Ollie! The Boy Who Became What He Ate" "Sweet Potato Spy" "mythbe" "mythbe" "6" "2018-11-14T12:08:00Z" "2018-11-14T12:15:00Z" "-2" "%REACTIVATE%" "/var/lib/mythtv/recordings" "4006_20181114120800.ts" "4006" "Default" "0" "0" "2018-11-14T07:08:00" "2018-11-14T07:15:00"'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/dtvrecorder.cpp:1038 (FindH264Keyframes) DTVRec[6]: FindH264Keyframes: timescale: 60, tick: 1, framerate: 30000
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/dtvrecorder.cpp:1599 (ProcessAVTSPacket) DTVRec[6]: PID 0x100 Found Payload Start
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/dtvrecorder.cpp:1599 (ProcessAVTSPacket) DTVRec[6]: PID 0x101 Found Payload Start
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/ExternalStreamHandler.cpp:942 (ReplayStream) ExternalRec[6](/home/mythtv/bin/m3u_recorder): Replayed 1572736 bytes
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I RecThread recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I SystemEvent mythsystemevent.cpp:55 (run) MythSystemEventHandler: Finished '/home/mythtv/bin/rec_started_writing "Ollie! The Boy Who Became What He Ate" "Sweet Potato Spy" "mythbe" "mythbe" "6" "2018-11-14T12:08:00Z" "2018-11-14T12:15:00Z" "-2" "%REACTIVATE%" "/var/lib/mythtv/recordings" "4006_20181114120800.ts" "4006" "Default" "0" "0" "2018-11-14T07:08:00" "2018-11-14T07:15:00"' result 0
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:07:59 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:00 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XON') = 'OK'
Nov 14 07:08:01 mythbe mythbackend: mythbackend[8167]: I ExternSH recorders/ExternalStreamHandler.cpp:1131 (ProcessCommand) ExternalRec[6](/home/mythtv/bin/m3u_recorder): ProcessCommand('XOFF') = 'OK'
Nov 14 07:08:06 mythbe mythbackend: mythbackend[8167]: N Expire autoexpire.cpp:251 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
Nov 14 07:08:56 mythbe mythbackend: mythbackend[8167]: I Metadata_18078 jobqueue.cpp:2157 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for "Ollie! The Boy Who Became What He Ate":"Sweet Potato Spy" recorded from channel 4006 at 2018-11-14T12:08:00Z
Nov 14 07:08:58 mythbe mythbackend: mythbackend[8167]: E Metadata_18078 jobqueue.cpp:2221 (DoMetadataLookupThread) JobQueue: Metadata Lookup Errored: "Ollie! The Boy Who Became What He Ate":"Sweet Potato Spy" recorded from channel 4006 at 2018-11-14T12:08:00Z (Failed with exit status 128)
Nov 14 07:09:00 mythbe mythbackend: mythbackend[8167]: W TVRecEvent recorders/recorderbase.cpp:651 (SavePositionMap) RecBase[6](/home/mythtv/bin/m3u_recorder): It has been over 60 seconds since we've checked for a ringbuffer switch.
Nov 14 07:09:01 mythbe mythbackend: mythbackend[8167]: I Commflag_18079 jobqueue.cpp:2282 (DoFlagCommercialsThread) JobQueue: Commercial Detection Starting for "Ollie! The Boy Who Became What He Ate":"Sweet Potato Spy" recorded from channel 4006 at 2018-11-14T12:08:00Z
Nov 14 07:09:02 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Playback
Nov 14 07:09:02 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: mythbe(9f37390) as a client (events: 0)
Nov 14 07:09:02 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Nov 14 07:09:02 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: mythbe(9f57fb0) as a client (events: 1)
Nov 14 07:09:02 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Playback
Nov 14 07:09:02 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: mythbe(9f4c218) as a client (events: 0)
Nov 14 07:10:00 mythbe mythbackend: mythbackend[8167]: W TVRecEvent recorders/recorderbase.cpp:651 (SavePositionMap) RecBase[6](/home/mythtv/bin/m3u_recorder): It has been over 60 seconds since we've checked for a ringbuffer switch.
Nov 14 07:11:00 mythbe mythbackend: mythbackend[8167]: W TVRecEvent recorders/recorderbase.cpp:651 (SavePositionMap) RecBase[6](/home/mythtv/bin/m3u_recorder): It has been over 60 seconds since we've checked for a ringbuffer switch.
Nov 14 07:12:00 mythbe mythbackend: mythbackend[8167]: W TVRecEvent recorders/recorderbase.cpp:651 (SavePositionMap) RecBase[6](/home/mythtv/bin/m3u_recorder): It has been over 60 seconds since we've checked for a ringbuffer switch.
Nov 14 07:13:00 mythbe mythbackend: mythbackend[8167]: W TVRecEvent recorders/recorderbase.cpp:651 (SavePositionMap) RecBase[6](/home/mythtv/bin/m3u_recorder): It has been over 60 seconds since we've checked for a ringbuffer switch.
Nov 14 07:14:00 mythbe mythbackend: mythbackend[8167]: W TVRecEvent recorders/recorderbase.cpp:651 (SavePositionMap) RecBase[6](/home/mythtv/bin/m3u_recorder): It has been over 60 seconds since we've checked for a ringbuffer switch.
Nov 14 07:15:00 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(FinishRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:1346
Nov 14 07:15:00 mythbe mythbackend: mythbackend[8167]: W TVRecEvent recorders/recorderbase.cpp:651 (SavePositionMap) RecBase[6](/home/mythtv/bin/m3u_recorder): It has been over 60 seconds since we've checked for a ringbuffer switch.
Nov 14 07:15:00 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:1088 (HandleStateChange) TVRec[6]: Changing from RecordingOnly to None
Nov 14 07:15:00 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:4407 (ClearFlags) TVRec[6]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:1316
Nov 14 07:15:00 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3492 (HandleTuning) TVRec[6]: HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
Nov 14 07:15:00 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:3561 (TuningShutdowns) TVRec[6]: TuningShutdowns(Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,))
Nov 14 07:15:00 mythbe mythbackend: mythbackend[8167]: I TVRecEvent tv_rec.cpp:1135 (TeardownRecorder) TVRec[6]: TeardownRecorder()
Nov 14 07:19:05 mythbe mythbackend: mythbackend[8167]: I MythSocketThread(83) mainserver.cpp:7643 (connectionClosed) Playback sock(9f4c218) 'mythbe' disconnected
Nov 14 07:19:06 mythbe mythbackend: mythbackend[8167]: I MythSocketThread(53) mainserver.cpp:7643 (connectionClosed) Playback sock(9f37390) 'mythbe' disconnected
Nov 14 07:19:06 mythbe mythbackend: mythbackend[8167]: I MythSocketThread(80) mainserver.cpp:7643 (connectionClosed) Monitor sock(9f57fb0) 'mythbe' disconnected
Nov 14 07:19:07 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Nov 14 07:19:07 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: mythbe(9f2b400) as a client (events: 0)
Nov 14 07:19:07 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Nov 14 07:19:07 mythbe mythbackend: mythbackend[8167]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: mythbe(9ed0d58) as a client (events: 1)
Nov 14 07:19:09 mythbe mythbackend: mythbackend[8167]: I MythSocketThread(53) mainserver.cpp:7643 (connectionClosed) Monitor sock(9f2b400) 'mythbe' disconnected
Nov 14 07:19:09 mythbe mythbackend: mythbackend[8167]: I MythSocketThread(65) mainserver.cpp:7643 (connectionClosed) Monitor sock(9ed0d58) 'mythbe' disconnected
Of note of course is that the last flow-control operation is an XOFF,
pausing the recorder at 07:08:56 with no subsequent XON resuming it.
So why would the backend pause the recorder without ever resuming it?
Cheers,
b.
More information about the mythtv-users
mailing list