<div dir="ltr"><div><div>Hello Everyone,</div><div><br></div><div>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.</div><div><br></div><div>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).</div><div><br></div><div>Does anyone know what's going on, or how to troubleshoot?</div><div><br></div><div>Logs are below.</div><div>Marc</div><div><br></div><div>My recorder sees:</div><div>2018-12-01 19:00:14,438 root        : debug received StartStreaming</div><div>2018-12-01 19:00:14,439 StreamRecorder: info last_write_time is None for: 1</div><div>2018-12-01 19:00:15,440 StreamRecorder: info last_write_time is None for: 2</div><div>2018-12-01 19:00:16,438 StreamRecorder: warning Player still hasn't started... returning success, but risky</div><div>2018-12-01 19:00:16,439 root        : debug returning OK:Started</div><div>2018-12-01 19:00:16,439 root        : debug Done processing command</div><div>2018-12-01 19:00:16,440 root        : debug received XON</div><div>2018-12-01 19:00:16,440 root        : debug returning OK</div><div>2018-12-01 19:00:16,440 root        : debug Done processing command</div><div>2018-12-01 19:00:16,441 StreamRecorder: info last_write_time is None for: 3</div><div>2018-12-01 19:00:17,442 StreamRecorder: info last_write_time is None for: 4</div><div>2018-12-01 19:00:18,212 StreamRecorder: debug __playing is True</div><div>2018-12-01 19:00:18,214 StreamRecorder: debug writer_control is True</div><div>2018-12-01 19:00:18,443 StreamRecorder: info last_write_time is None for: 5</div><div>2018-12-01 19:00:19,445 StreamRecorder: info last_write_time is None for: 6</div><div>2018-12-01 19:00:20,446 StreamRecorder: info last_write_time is None for: 7</div><div>2018-12-01 19:00:21,447 StreamRecorder: info last_write_time is None for: 8</div><div>2018-12-01 19:00:22,449 StreamRecorder: info last_write_time is None for: 9</div><div>2018-12-01 19:00:23,450 StreamRecorder: info last_write_time is None for: 10</div><div>2018-12-01 19:00:24,369 StreamRecorder: debug First bytes written to stdout</div><div>2018-12-01 19:00:24,480 root        : debug received Version?</div><div>2018-12-01 19:00:24,480 root        : debug returning OK:1.0</div><div>2018-12-01 19:00:24,481 root        : debug Done processing command</div><div>2018-12-01 19:00:24,481 root        : debug received XOFF</div><div>2018-12-01 19:00:24,484 root        : debug returning OK</div><div>2018-12-01 19:00:24,484 root        : debug Done processing command</div><div>2018-12-01 19:00:24,511 root        : debug received XON</div><div>2018-12-01 19:00:24,511 root        : debug returning OK</div><div>2018-12-01 19:00:24,512 StreamRecorder: debug writer_control is True</div><div>2018-12-01 19:00:24,512 root        : debug Done processing command</div><div>2018-12-01 19:00:28,284 root        : debug received XOFF</div><div>2018-12-01 19:00:28,284 root        : debug returning OK</div><div><br></div><div>After the XOFF at (19:00:28,284), there are no more commands sent to my recorder.</div><div><br></div><div>Mythbackend logs show:</div><div>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</div><div>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</div><div>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</div><div>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</div><div>Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Monitor</div><div>Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: everest(555dd353b350) as a client (events: 0)</div><div>Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Monitor</div><div>Dec  1 19:00:19 everest mythbackend: mythbackend[1536]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: everest(555dd351ec10) as a client (events: 1)</div><div>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</div><div>Dec  1 19:00:20 everest mythbackend: mythbackend[1536]: I MythSocketThread(42) mainserver.cpp:7674 (connectionClosed) Monitor sock(555dd353a2d0) 'everest' disconnected</div><div>Dec  1 19:00:20 everest mythbackend: mythbackend[1536]: I MythSocketThread(70) mainserver.cpp:7674 (connectionClosed) Monitor sock(555dd3768eb0) 'everest' disconnected</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I MythSocketThread(84) mainserver.cpp:7674 (connectionClosed) Monitor sock(555dd353b350) 'everest' disconnected</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I MythSocketThread(86) mainserver.cpp:7674 (connectionClosed) Monitor sock(555dd351ec10) 'everest' disconnected</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent tv_rec.cpp:3914 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: Good signal</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent tv_rec.cpp:730 (SetRecordingStatus) TVRec[1]: SetRecordingStatus(Tuning->Recording) on line 4012</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent tv_rec.cpp:2107 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor() -- begin</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent recorders/ExternalSignalMonitor.cpp:61 (~ExternalSignalMonitor) ExternSigMon(/home/xbmc/recorders/recorder1/record.sh): dtor</div><div>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</div><div>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)</div><div>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</div><div>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</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent tv_rec.cpp:2126 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor() -- end</div><div>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</div><div>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</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent tv_rec.cpp:4165 (TuningNewRecorder) TVRec[1]: Starting Recorder</div><div>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</div><div>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'</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent tv_rec.cpp:4236 (TuningNewRecorder) TVRec[1]: TuningNewRecorder - CreateRecorder()</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent recorders/dtvrecorder.cpp:182 (ResetForNewFile) DTVRec[1]: ResetForNewFile(void)</div><div>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.</div><div>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.</div><div>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'</div><div>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)</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent mpeg/mpegstreamdata.cpp:90 (SetDesiredProgram) MPEGStream[1](0x7f8d140558b0): SetDesiredProgram(1)</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent recorders/dtvrecorder.cpp:1289 (HandlePAT) DTVRec[1]: SetPAT(1 on 0xfff)</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent recorders/dtvrecorder.cpp:1309 (HandlePMT) DTVRec[1]: SetPMT(1, valid)</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I TVRecEvent recorders/dtvrecorder.cpp:1314 (HandlePMT) DTVRec[1]: SetPMT(1)</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread recorders/dtvrecorder.cpp:182 (ResetForNewFile) DTVRec[1]: ResetForNewFile(void)</div><div>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)</div><div>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</div><div>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</div><div>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</div><div>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</div><div>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</div><div>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</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread recorders/dtvrecorder.cpp:1599 (ProcessAVTSPacket) DTVRec[1]: PID 0x100 Found Payload Start</div><div>Dec  1 19:00:24 everest mythbackend: mythbackend[1536]: I RecThread recorders/dtvrecorder.cpp:1599 (ProcessAVTSPacket) DTVRec[1]: PID 0x101 Found Payload Start</div><div>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</div><div>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</div><div>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</div><div>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</div><div>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</div><div>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</div><div><br></div><div><br></div><div>Version details:</div><div>MythTV Version : v29.1</div><div>MythTV Branch : </div><div>Network Protocol : 91</div><div>Library API : 29.20180316-1</div><div>QT Version : 5.9.5</div><div>Options compiled in:</div><div> 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</div></div><div><br></div></div>