[mythtv-users] ExternalRecorder - Errno 11
Marc Rawji
mrawji at gmail.com
Sat Nov 25 17:52:52 UTC 2017
Hi Stephen, Peter,
I created the ticket here:
https://code.mythtv.org/trac/ticket/13181
I've coded up the workaround (against fixes/29) and i'll test today on my
"prod" system. If everything checks out, i'll create the pull request in
github.
Marc
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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20171125/61f53a64/attachment.html>
More information about the mythtv-users
mailing list