[mythtv-users] ExternalRecorder - Errno 11

Marc Rawji mrawji at gmail.com
Sun Nov 26 05:10:21 UTC 2017


>
> On Thu, Nov 23, 2017 at 11:45 PM, Marc Rawji <mrawji at gmail.com> wrote:
>
>>
>> On Thu, Nov 23, 2017 at 7:22 PM, Stephen Worthington <
>> stephen_agent at jsw.gen.nz> wrote:
>>
>>> On Thu, 23 Nov 2017 15:59:07 -0800, you wrote:
>>>
>>> >On Thu, Nov 23, 2017 at 7:40 AM, Peter Bennett <pb.mythtv at gmail.com>
>>> wrote:
>>> >
>>> >>
>>> >>
>>> >> On 11/23/2017 12:50 AM, Marc Rawji wrote:
>>> >>
>>> >> On Wed, Nov 22, 2017 at 4:41 PM, Stephen Worthington <
>>> >> stephen_agent at jsw.gen.nz> wrote:
>>> >>
>>> >>> On Wed, 22 Nov 2017 10:28:39 -0800, you wrote:
>>> >>>
>>> >>> >On Tue, Nov 21, 2017 at 11:11 PM, Stephen Worthington <
>>> >>> >stephen_agent at jsw.gen.nz> wrote:
>>> >>> >
>>> >>> >> On Wed, 22 Nov 2017 06:03:31 +0000, you wrote:
>>> >>> >>
>>> >>> >> >Hi Everyone,
>>> >>> >> >
>>> >>> >> >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.
>>> >>> >> >
>>> >>> >> <snip>
>>> >>> >> >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
>>> >>> >> >
>>> >>> >> <snip>
>>> >>> >>
>>> >>> >> If I am reading the ExternalStreamHandler.cpp.ExternIO::Read
>>> function
>>> >>> >> correctly, then the only way that can happen is if your stdout
>>> stream
>>> >>> >> indicates that it has data buffered and available to be read (the
>>> >>> >> poll() call from the Ready() call says there is data there), but
>>> then
>>> >>> >> your stdout fails to provide that data when it is called from
>>> read().
>>> >>> >> The most obvious reason I can think of for that would be if your
>>> code
>>> >>> >> was slow in responding to the read(), due to some unforeseen
>>> >>> >> circumstance such as garbage collection or being swapped out at
>>> the
>>> >>> >> time.  But I would have thought that your stdout buffer would have
>>> >>> >> been there waiting to be read, rather than any higher code
>>> needing to
>>> >>> >> be run to provide the data.  Are you using buffered I/O on your
>>> >>> >> stdout?
>>> >>> >>
>>> >>> >>
>>> >>> >Thanks for the quick reply Stephen. I am going to very quickly
>>> expose my
>>> >>> >ignorance on how these FDs work. (just setting expectations)
>>> >>> >
>>> >>> >Yes, I am using buffered output, specifically a BufferedWriter in
>>> Python
>>> >>> (
>>> >>> >https://docs.python.org/2/library/io.html#io.BufferedWriter). I
>>> added
>>> >>> >explicit "flush" commands after the 'write' command, but it didn't
>>> help.
>>> >>> >
>>> >>> >I'll try dropping the buffered output tonight and see what happens.
>>> I
>>> >>> >didn't think that using a buffered writer would affect how data is
>>> >>> present
>>> >>> >in the stream.
>>> >>> >
>>> >>> >Thanks,
>>> >>> >Marc
>>> >>>
>>> >>> I would have hoped that using a BufferedWriter would have provided
>>> >>> more buffering rather than less, but it would be useful to try a
>>> >>> normal file instead, using the normal buffering, to see if it makes a
>>> >>> difference.  The problem with this situation is that the
>>> >>> ExternalStreamHandler.cpp code needs to be able to read the data from
>>> >>> the pipe buffer instantly, as it has been told that there is data
>>> >>> waiting.  So if the buffer the data is coming from is not locked in
>>> >>> RAM, it may not be instantly available.  The normal file I/O buffers
>>> >>> in Python are handled in the underlying C library and should work the
>>> >>> way ExternalStreamHandler.cpp expects them to, but it is vaguely
>>> >>> possible that BufferedWriter changes that and accessing its buffers
>>> >>> requires running the Python interpreter, which could cause this
>>> >>> problem.  The documentation of BufferedWriter is not specific enough
>>> >>> about how it works to know exactly how its low level buffering works,
>>> >>> but it is suggestive that the data may be lying in a higher level
>>> >>> buffer.
>>> >>>
>>> >>>
>>> >> Just gave it a go and no joy, same behavior as before...
>>> >>
>>> >> In my Python code, the salient part is:
>>> >> data = fd.read(256)
>>> >> if data:
>>> >>     if (self.last_write_time is None):
>>> >>         self.logger.debug("First bytes written to stdout")
>>> >>     self.__bin_stdout.write(data)
>>> >>     self.__bin_stdout.flush()
>>> >>     self.last_write_time = time.time()
>>> >> self.writer_control.wait(0.5)
>>> >>
>>> >> and self.__bin_stdout is equal to sys.stdout.
>>> >>
>>> >> Would it have to do with:
>>> >> http://pubs.opengroup.org/onlinepubs/9699919799/functions/poll.html
>>> >>
>>> >> It indicates that for streams, the POLLIN is set even if the message
>>> is of
>>> >> zero length.
>>> >>
>>> >> Thanks,
>>> >> Marc
>>> >>
>>> >>
>>> >>
>>> >> I suggest creating a ticket for this.
>>> >>
>>> >> You may want to look at the import recorder. I recently committed a
>>> fix
>>> >> that allows it to be used for recordings. See the fix at
>>> >> https://code.mythtv.org/trac/ticket/13114 and documentation at
>>> >> https://www.mythtv.org/wiki/Import_recorder . Currently the fix is
>>> only
>>> >> available in master, scheduled for v30.
>>> >>
>>> >> Peter
>>> >>
>>> >
>>> >
>>> >Thanks for the suggestion, Peter. I'll look at possibly using the import
>>> >recorder...
>>> >
>>> >Stephen, 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/recor
>>> der/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 2 0 byte reads, 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.
>>> >
>>> >Thanks
>>> >Marc
>>>
>>> That certainly seems like a valid workaround, but it would be nice to
>>> be able to explain why it is happening when it should not be.
>>>
>>> I have seen what look like a couple of bugs in the
>>> ExternalStreamHandler.cpp code while I have been reading it.  The
>>> first is in Ready, where I believe the line:
>>>
>>> if (m_poll[0].revents & POLLIN)
>>>
>>> should instead be:
>>>
>>> if (m_poll[0].revents & (POLLIN|POLLPRI))
>>>
>>> The second is in Fork where there is this code:
>>>
>>>         bool error = false;
>>>         error = (fcntl(m_appin,  F_SETFL, O_NONBLOCK) == -1);
>>>         error = (fcntl(m_appout, F_SETFL, O_NONBLOCK) == -1);
>>>         error = (fcntl(m_apperr, F_SETFL, O_NONBLOCK) == -1);
>>>
>>> That overwrites the error flag, when they should be ORed together.  So
>>> I think this should work:
>>>
>>>         bool error =
>>>           (fcntl(m_appin,  F_SETFL, O_NONBLOCK) == -1) ||
>>>           (fcntl(m_appout, F_SETFL, O_NONBLOCK) == -1) ||
>>>           (fcntl(m_apperr, F_SETFL, O_NONBLOCK) == -1);
>>>
>>> or maybe
>>>
>>>         bool error = false;
>>>         error = error || (fcntl(m_appin,  F_SETFL, O_NONBLOCK) == -1);
>>>         error = error || (fcntl(m_appout, F_SETFL, O_NONBLOCK) == -1);
>>>         error = error || (fcntl(m_apperr, F_SETFL, O_NONBLOCK) == -1);
>>>
>>> if it is required that all the fcntl calls always be performed.
>>>
>>> I can not see why either of those problems would be causing what you
>>> are seeing, but it might be worthwhile trying the fixes just in case.
>>
>>
>> I made the changes and still the same behavior (somewhat expected). On a
>> hunch, i tried increasing the size of my 'writes' to 1k instead of 256
>> bytes, but no luck there either.
>>
>> I'll see if I can come up with any other bright ideas.
>>
>> Thanks,
>> Marc
>>
>
> Ok, just wanted to close off the conversation here, in case anyone finds
this via Google. I've tested the workaround coded here and it seems to be
working.
https://github.com/MythTV/mythtv/pull/161

Currently tracking via this ticket:
https://code.mythtv.org/trac/ticket/13181

Thanks for everyone's help!
Marc
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20171125/9378d447/attachment-0001.html>


More information about the mythtv-users mailing list