id summary reporter owner description type status priority milestone component version severity resolution keywords cc mlocked 13181 "ExternalRecorder fails with ""resource temporarily unavailable""" Marc Rawji jpoet "I've been working on an external recorder for a while. It works most of the time, but recently i've been getting new errors. First, the sequence of calls for a successful play look like this: StartStreaming StopStreaming StartStreaming There's only a few milliseconds between the StopStreaming and the 2nd StartStreaming, so my code allows for it and that seems to work just fine... The StopStreaming in the logs below is probably a red herring. My problem below is that I am getting a ""Resource temporarily unavailable (11)"" when mythtv is trying to read from the stdin (the stdout of my program with the video stream) This seems to happen from this call: https://github.com/MythTV/mythtv/blob/master/mythtv/libs/libmythtv/recorders/ExternalStreamHandler.cpp#L125 The STDIN stream is configured to be non blocking, so the errno 11 isn't unexpected: https://github.com/MythTV/mythtv/blob/master/mythtv/libs/libmythtv/recorders/ExternalStreamHandler.cpp#L343 I am not sure what to change to keep this from happening.... it fails about 50% of the time, which is annoying. I am looking for advice on a fix, or how to troubleshoot. I am running 0.29 on Ubuntu 16.04. Thanks! Marc Trimmed logs from mythbackend: {{{ Nov 21 21:23:30 mythbackend: mythbackend[1286]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1077 (ProcessCommand) ExternalRec(/home/recorder1/record.sh): ProcessCommand('Version?') = 'OK:1.0' Nov 21 21:23:30 mythbackend: mythbackend[1286]: W TVRecEvent recorders/ExternalStreamHandler.cpp:1066 (ProcessCommand) ExternalRec(/home/recorder1/record.sh): External Recorder did not respond to 'StopStreaming' Nov 21 21:23:30 mythbackend: mythbackend[1286]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1077 (ProcessCommand) ExternalRec(/home/recorder1/record.sh): ProcessCommand('StopStreaming') = 'OK:Stopped' Nov 21 21:23:30 mythbackend: mythbackend[1286]: E TVRecEvent recorders/ExternalStreamHandler.cpp:130 (Read) Failed to read from External Recorder: #012#011#011#011eno: Resource temporarily unavailable (11) Nov 21 21:23:30 everest mythbackend: mythbackend[1286]: E TVRecEvent recorders/ExternalStreamHandler.cpp:151 (GetStatus) ExternIO::GetStatus: already in error state: 'Failed to read from External Recorder: #012#011#011#011eno: Resource temporarily unavailable (11)' Nov 21 21:23:30 mythbackend: mythbackend[1286]: I TVRecEvent recorders/ExternalStreamHandler.cpp:1014 (StopStreaming) ExternalRec(/home/recorder1/record.sh): Streaming stopped Nov 21 21:23:30 mythbackend: mythbackend[1286]: E ExternSH recorders/ExternalStreamHandler.cpp:625 (run) ExternalRec(/home/recorder1/record.sh): Failed to read from External Recorder: Failed to read from External Recorder: #012#011#011#011eno: Resource temporarily unavailable (11) }}} I grabbed the latest V30 (master) and hacked up ExternalStreamHandler.cpp with extra log messages. I replaced the Ready function to use select instead of poll and still had the same behavior. I then commented out this line: - m_error = ""Failed to read from External Recorder: "" + ENO; + //m_error = ""MR: Failed to read from External Recorder: "" + ENO; preventing the hard failure, and got a functioning video stream. In the snippet below, FD 62 is the ""stdout"" with the transport stream. The ""Checking for data"" line comes from the Ready function: 1 indicates there's data to read. The empty line in the log is the from the commented out m_error... It's when we get the unexpected ""erno 11"". We can see there's data before and after the error... I am not sure it's a problem with the Ready function, but with the 'read' {{{ 2017-11-23 15:07:35.517510 I ExternalRec(/home/mrawji/recorder/record.sh): ProcessCommand('StopStreaming') = 'OK:Stopped' 2017-11-23 15:07:35.517516 E ExternIO::Read '256' bytes, buffer size 312 2017-11-23 15:07:35.517690 E MR: Checking for data, return value was: '1', for FD '62' 2017-11-23 15:07:35.517693 E MR: Checking for data, return value was: '1', for FD '62' 2017-11-23 15:07:35.517700 E 2017-11-23 15:07:35.517709 E ExternIO::Read '256' bytes, buffer size 380 2017-11-23 15:07:35.517822 E MR: Checking for data, return value was: '1', for FD '62' 2017-11-23 15:07:35.517842 E ExternIO::Read '256' bytes, buffer size 260 2017-11-23 15:07:35.517879 E MR: Checking for data, return value was: '1', for FD '62' 2017-11-23 15:07:35.517901 E ExternIO::Read '256' bytes, buffer size 328 }}} I am thinking that I could possibly add a counter on the failed reads and if we hit 2 (or n) in row, then fail... It also looks like it'll read ""0 bytes"" a few times despite the Ready function returning True. In the trace above, I see one 0 byte read, followed by the ""erno 11"". Then, everything keeps working again (9 microseconds after the error). I am writing 256 bytes at a time from my python app... not sure if that means anything. " Bug Report - General closed minor 29.1 MythTV - General Master Head medium Fixed 0