[mythtv-commits] Ticket #13181: ExternalRecorder fails with "resource temporarily unavailable"

[MythTV]

#13181: ExternalRecorder fails with "resource temporarily unavailable"
--------------------------------------+--------------------------
     Reporter:  mrawji@…              |      Owner:
         Type:  Bug Report - General  |     Status:  new
     Priority:  minor                 |  Milestone:  needs_triage
    Component:  MythTV - General      |    Version:  Unspecified
     Severity:  medium                |   Keywords:
Ticket locked:  0                     |
--------------------------------------+--------------------------
 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.

--
Ticket URL: <https://code.mythtv.org/trac/ticket/13181>
MythTV <http://www.mythtv.org>
MythTV Media Center