[mythtv-users] XOFF not followed by an XON for the ExternalRecorder

Marc Rawji mrawji at gmail.com
Sun Dec 2 06:54:00 UTC 2018


Hello Everyone,

I've had a working ExternalRecorder for a while. I recently upgraded to the
latest fixes/29. I am getting an XOFF, but not followed by an XON. I don't
see any timeouts or "out-of-sync" messages between mythtv and my recorder.

I can't see anything different between a successful recording and one where
I never get an XON message after the XOFF. When I've experience this, it's
at the beginning of the recording (within a  few MBs / seconds).

Does anyone know what's going on, or how to troubleshoot?

Logs are below.
Marc

My recorder sees:
2018-12-01 19:00:14,438 root        : debug received StartStreaming
2018-12-01 19:00:14,439 StreamRecorder: info last_write_time is None for: 1
2018-12-01 19:00:15,440 StreamRecorder: info last_write_time is None for: 2
2018-12-01 19:00:16,438 StreamRecorder: warning Player still hasn't
started... returning success, but risky
2018-12-01 19:00:16,439 root        : debug returning OK:Started
2018-12-01 19:00:16,439 root        : debug Done processing command
2018-12-01 19:00:16,440 root        : debug received XON
2018-12-01 19:00:16,440 root        : debug returning OK
2018-12-01 19:00:16,440 root        : debug Done processing command
2018-12-01 19:00:16,441 StreamRecorder: info last_write_time is None for: 3
2018-12-01 19:00:17,442 StreamRecorder: info last_write_time is None for: 4
2018-12-01 19:00:18,212 StreamRecorder: debug __playing is True
2018-12-01 19:00:18,214 StreamRecorder: debug writer_control is True
2018-12-01 19:00:18,443 StreamRecorder: info last_write_time is None for: 5
2018-12-01 19:00:19,445 StreamRecorder: info last_write_time is None for: 6
2018-12-01 19:00:20,446 StreamRecorder: info last_write_time is None for: 7
2018-12-01 19:00:21,447 StreamRecorder: info last_write_time is None for: 8
2018-12-01 19:00:22,449 StreamRecorder: info last_write_time is None for: 9
2018-12-01 19:00:23,450 StreamRecorder: info last_write_time is None for: 10
2018-12-01 19:00:24,369 StreamRecorder: debug First bytes written to stdout
2018-12-01 19:00:24,480 root        : debug received Version?
2018-12-01 19:00:24,480 root        : debug returning OK:1.0
2018-12-01 19:00:24,481 root        : debug Done processing command
2018-12-01 19:00:24,481 root        : debug received XOFF
2018-12-01 19:00:24,484 root        : debug returning OK
2018-12-01 19:00:24,484 root        : debug Done processing command
2018-12-01 19:00:24,511 root        : debug received XON
2018-12-01 19:00:24,511 root        : debug returning OK
2018-12-01 19:00:24,512 StreamRecorder: debug writer_control is True
2018-12-01 19:00:24,512 root        : debug Done processing command
2018-12-01 19:00:28,284 root        : debug received XOFF
2018-12-01 19:00:28,284 root        : debug returning OK

After the XOFF at (19:00:28,284), there are no more commands sent to my
recorder.

Mythbackend logs show:
Dec  1 19:00:16 everest mythbackend: mythbackend[1536]: I SignalMonitor
recorders/ExternalStreamHandler.cpp:1217 (ProcessVer1)
ExternalRec(/home/xbmc/recorders/recorder1/record.sh):
ProcessCommand('StartStreaming') = 'OK:Started' took 2001ms
Dec  1 19:00:16 everest mythbackend: mythbackend[1536]: I SignalMonitor
recorders/ExternalStreamHandler.cpp:1056 (StartStreaming)
ExternalRec(/home/xbmc/recorders/recorder1/record.sh): Streaming started
Dec  1 19:00:16 everest mythbackend: mythbackend[1536]: I SignalMonitor
recorders/ExternalStreamHandler.cpp:1065 (StartStreaming)
ExternalRec(/home/xbmc/recorders/recorder1/record.sh): StartStreaming 1
listeners
Dec  1 19:00:16 everest mythbackend: mythbackend[1536]: I ExternSH
recorders/ExternalStreamHandler.cpp:1217 (ProcessVer1)
ExternalRec(/home/xbmc/recorders/recorder1/record.sh):
ProcessCommand('XON') = 'OK' took 0ms
Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest
mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest
mainserver.cpp:1743 (HandleAnnounce) MainServer: adding:
everest(555dd353b350) as a client (events: 0)
Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest
mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest
mainserver.cpp:1743 (HandleAnnounce) MainServer: adding:
everest(555dd351ec10) as a client (events: 1)
Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4006 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: Still
waiting.  Will timeout @ 22:30:00.000
Dec  1 19:00:20 everest mythbackend: mythbackend[1536]: I
MythSocketThread(42) mainserver.cpp:7674 (connectionClosed) Monitor
sock(555dd353a2d0) 'everest' disconnected
Dec  1 19:00:20 everest mythbackend: mythbackend[1536]: I
MythSocketThread(70) mainserver.cpp:7674 (connectionClosed) Monitor
sock(555dd3768eb0) 'everest' disconnected
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I
MythSocketThread(84) mainserver.cpp:7674 (connectionClosed) Monitor
sock(555dd353b350) 'everest' disconnected
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I
MythSocketThread(86) mainserver.cpp:7674 (connectionClosed) Monitor
sock(555dd351ec10) 'everest' disconnected
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:3914 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: Good signal
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:730 (SetRecordingStatus) TVRec[1]:
SetRecordingStatus(Tuning->Recording) on line 4012
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:2107 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor()
-- begin
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/ExternalSignalMonitor.cpp:61 (~ExternalSignalMonitor)
ExternSigMon(/home/xbmc/recorders/recorder1/record.sh): dtor
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/ExternalSignalMonitor.cpp:73 (Stop)
ExternSigMon(/home/xbmc/recorders/recorder1/record.sh): Stop() -- begin
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I CoreContext
scheduler.cpp:734 (UpdateRecStatus) Updating status for "Test
Recording":"2018-12-01 19:00:00" on cardid [1] (Tuning => Recording)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/ExternalSignalMonitor.cpp:83 (Stop)
ExternSigMon(/home/xbmc/recorders/recorder1/record.sh): Stop() -- end
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/ExternalStreamHandler.cpp:510 (Return) ExternSH: Return
'/home/xbmc/recorders/recorder1/record.sh' in use 2
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:2126 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor()
-- end
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4419 (ClearFlags) TVRec[1]: ClearFlags(SignalMonitorRunning,) ->
RunMainLoop,WaitingForSignal,NeedToStartRecorder,RingBufferReady, @
tv_rec.cpp:4038
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4419 (ClearFlags) TVRec[1]: ClearFlags(WaitingForSignal,) ->
RunMainLoop,NeedToStartRecorder,RingBufferReady, @ tv_rec.cpp:4040
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4165 (TuningNewRecorder) TVRec[1]: Starting Recorder
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: E TVRecEvent
tv_rec.cpp:4153 (LoadProfile) TVRec[1]: Profile 'Default' not found, and
unable to load fallback profile 'Default'.  Results may be unpredicable
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4204 (TuningNewRecorder) TVRec[1]: rec->GetPathname():
'/home/xbmc/media/Recordings/1005_20181202030000.ts'
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4236 (TuningNewRecorder) TVRec[1]: TuningNewRecorder -
CreateRecorder()
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/dtvrecorder.cpp:182 (ResetForNewFile) DTVRec[1]:
ResetForNewFile(void)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: E TVRecEvent
recorders/recorderbase.cpp:232 (SetStrOption)
RecBase[1](/home/xbmc/recorders/recorder1/record.sh):
SetStrOption(...recordingtype): Option not in profile.
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: E TVRecEvent
recorders/recorderbase.cpp:222 (SetIntOption)
RecBase[1](/home/xbmc/recorders/recorder1/record.sh):
SetIntOption(...recordmpts): Option not in profile.
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/recorderbase.cpp:101 (SetRingBuffer)
RecBase[1](/home/xbmc/recorders/recorder1/record.sh):
SetRingBuffer(0x7f8d1401d320)
'/home/xbmc/media/Recordings/1005_20181202030000.ts'
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/recorderbase.cpp:111 (SetRecording)
RecBase[1](/home/xbmc/recorders/recorder1/record.sh):
SetRecording(0x7f8cfc022380) title(Test Recording)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
mpeg/mpegstreamdata.cpp:90 (SetDesiredProgram)
MPEGStream[1](0x7f8d140558b0): SetDesiredProgram(1)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/dtvrecorder.cpp:1289 (HandlePAT) DTVRec[1]: SetPAT(1 on 0xfff)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/dtvrecorder.cpp:1309 (HandlePMT) DTVRec[1]: SetPMT(1, valid)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
recorders/dtvrecorder.cpp:1314 (HandlePMT) DTVRec[1]: SetPMT(1)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/dtvrecorder.cpp:182 (ResetForNewFile) DTVRec[1]:
ResetForNewFile(void)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/ExternalStreamHandler.cpp:486 (Get) ExternSH: Using existing
stream handler for /home/xbmc/recorders/recorder1/record.sh (2 in use)
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/ExternalStreamHandler.cpp:1217 (ProcessVer1)
ExternalRec[1](/home/xbmc/recorders/recorder1/record.sh):
ProcessCommand('Version?') = 'OK:1.0' took 0ms
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/ExternalRecorder.cpp:151 (Open)
ExternalRec[1](/home/xbmc/recorders/recorder1/record.sh): Opened
successfully
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/streamhandler.cpp:81 (AddListener)
SH[1](/home/xbmc/recorders/recorder1/record.sh):
AddListener(0x7f8d140558b0) -- begin
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/streamhandler.cpp:93 (AddListener)
SH[1](/home/xbmc/recorders/recorder1/record.sh):
AddListener(0x7f8d140558b0) -- locked
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/streamhandler.cpp:115 (AddListener)
SH[1](/home/xbmc/recorders/recorder1/record.sh):
AddListener(0x7f8d140558b0) -- end
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/ExternalStreamHandler.cpp:1217 (ProcessVer1)
ExternalRec[1](/home/xbmc/recorders/recorder1/record.sh):
ProcessCommand('XOFF') = 'OK' took 2ms
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/dtvrecorder.cpp:1599 (ProcessAVTSPacket) DTVRec[1]: PID 0x100
Found Payload Start
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/dtvrecorder.cpp:1599 (ProcessAVTSPacket) DTVRec[1]: PID 0x101
Found Payload Start
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4410 (SetFlags) TVRec[1]:
SetFlags(RecorderRunning,RingBufferReady,) ->
RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady, @
tv_rec.cpp:4308
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent
tv_rec.cpp:4419 (ClearFlags) TVRec[1]: ClearFlags(NeedToStartRecorder,) ->
RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:4310
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/ExternalStreamHandler.cpp:1014 (ReplayStream)
ExternalRec[1](/home/xbmc/recorders/recorder1/record.sh): Replayed 2891628
bytes
Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread
recorders/ExternalStreamHandler.cpp:1217 (ProcessVer1)
ExternalRec[1](/home/xbmc/recorders/recorder1/record.sh):
ProcessCommand('XON') = 'OK' took 0ms
Dec  1 19:00:28 everest mythbackend: mythbackend[1536]: I ExternSH
recorders/ExternalStreamHandler.cpp:1217 (ProcessVer1)
ExternalRec[1](/home/xbmc/recorders/recorder1/record.sh):
ProcessCommand('XOFF') = 'OK' took 0ms
Dec  1 19:01:10 everest mythbackend: mythbackend[1536]: I Commflag_995
jobqueue.cpp:2282 (DoFlagCommercialsThread) JobQueue: Commercial Detection
Starting for "Test Recording":"2018-12-01 19:00:00" recorded from channel
1005 at 2018-12-02T03:00:00Z


Version details:
MythTV Version : v29.1
MythTV Branch :
Network Protocol : 91
Library API : 29.20180316-1
QT Version : 5.9.5
Options compiled in:
 linux profile use_hidesyms using_alsa using_oss using_pulse
using_pulseoutput using_backend using_bindings_perl using_bindings_python
using_bindings_php using_crystalhd using_dvb using_firewire using_frontend
using_hdhomerun using_vbox using_ceton using_hdpvr using_ivtv
using_joystick_menu using_libcec using_libcrypto using_libdns_sd
using_libfftw3 using_libxml2 using_lirc using_mheg using_opengl
using_opengl_video using_opengl_themepainter using_qtwebkit using_qtscript
using_qtdbus using_taglib using_v4l2 using_x11 using_xrandr using_xv
using_profiletype using_systemd_notify using_systemd_journal
using_bindings_perl using_bindings_python using_bindings_php
using_freetype2 using_mythtranscode using_opengl using_vaapi using_vdpau
using_ffmpeg_threads using_mheg using_libass using_libxml2 using_libmp3lame
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20181201/e2028468/attachment-0001.html>


More information about the mythtv-users mailing list