<div dir="ltr">Hi Stephen, Peter,<div><br></div><div>I created the ticket here:</div><div><a href="https://code.mythtv.org/trac/ticket/13181">https://code.mythtv.org/trac/ticket/13181</a><br></div><div><br></div><div>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.</div><div><br></div><div>Marc</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Nov 23, 2017 at 11:45 PM, Marc Rawji <span dir="ltr"><<a href="mailto:mrawji@gmail.com" target="_blank">mrawji@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div class="gmail_extra"><br><div class="gmail_quote"><div><div class="h5">On Thu, Nov 23, 2017 at 7:22 PM, Stephen Worthington <span dir="ltr"><<a href="mailto:stephen_agent@jsw.gen.nz" target="_blank">stephen_agent@jsw.gen.nz</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="m_8911448493572783279HOEnZb"><div class="m_8911448493572783279h5">On Thu, 23 Nov 2017 15:59:07 -0800, you wrote:<br>
<br>
>On Thu, Nov 23, 2017 at 7:40 AM, Peter Bennett <<a href="mailto:pb.mythtv@gmail.com" target="_blank">pb.mythtv@gmail.com</a>> wrote:<br>
><br>
>><br>
>><br>
>> On 11/23/2017 12:50 AM, Marc Rawji wrote:<br>
>><br>
>> On Wed, Nov 22, 2017 at 4:41 PM, Stephen Worthington <<br>
>> <a href="mailto:stephen_agent@jsw.gen.nz" target="_blank">stephen_agent@jsw.gen.nz</a>> wrote:<br>
>><br>
>>> On Wed, 22 Nov 2017 10:28:39 -0800, you wrote:<br>
>>><br>
>>> >On Tue, Nov 21, 2017 at 11:11 PM, Stephen Worthington <<br>
>>> ><a href="mailto:stephen_agent@jsw.gen.nz" target="_blank">stephen_agent@jsw.gen.nz</a>> wrote:<br>
>>> ><br>
>>> >> On Wed, 22 Nov 2017 06:03:31 +0000, you wrote:<br>
>>> >><br>
>>> >> >Hi Everyone,<br>
>>> >> ><br>
>>> >> >I've been working on an external recorder for a while. It works most<br>
>>> of<br>
>>> >> the<br>
>>> >> >time, but recently i've been getting new errors.<br>
>>> >> ><br>
>>> >> <snip><br>
>>> >> >My problem below is that I am getting a "Resource temporarily<br>
>>> unavailable<br>
>>> >> >(11)" when mythtv is trying to read from the stdin (the stdout of my<br>
>>> >> >program with the video stream)<br>
>>> >> ><br>
>>> >> >This seems to happen from this call:<br>
>>> >> ><a href="https://github.com/MythTV/mythtv/blob/master/mythtv/" rel="noreferrer" target="_blank">https://github.com/MythTV/myt<wbr>htv/blob/master/mythtv/</a><br>
>>> >> libs/libmythtv/recorders/Exter<wbr>nalStreamHandler.cpp#L125<br>
>>> >> ><br>
>>> >> >The STDIN stream is configured to be non blocking, so the errno 11<br>
>>> isn't<br>
>>> >> >unexpected:<br>
>>> >> ><a href="https://github.com/MythTV/mythtv/blob/master/mythtv/" rel="noreferrer" target="_blank">https://github.com/MythTV/myt<wbr>htv/blob/master/mythtv/</a><br>
>>> >> libs/libmythtv/recorders/Exter<wbr>nalStreamHandler.cpp#L343<br>
>>> >> ><br>
>>> >> >I am not sure what to change to keep this from happening.... it fails<br>
>>> >> about<br>
>>> >> >50% of the time, which is annoying.<br>
>>> >> ><br>
>>> >> >I am looking for advice on a fix, or how to troubleshoot. I am running<br>
>>> >> 0.29<br>
>>> >> >on Ubuntu 16.04.<br>
>>> >> ><br>
>>> >> >Thanks!<br>
>>> >> >Marc<br>
>>> >> ><br>
>>> >> <snip><br>
>>> >><br>
>>> >> If I am reading the ExternalStreamHandler.cpp.Exte<wbr>rnIO::Read function<br>
>>> >> correctly, then the only way that can happen is if your stdout stream<br>
>>> >> indicates that it has data buffered and available to be read (the<br>
>>> >> poll() call from the Ready() call says there is data there), but then<br>
>>> >> your stdout fails to provide that data when it is called from read().<br>
>>> >> The most obvious reason I can think of for that would be if your code<br>
>>> >> was slow in responding to the read(), due to some unforeseen<br>
>>> >> circumstance such as garbage collection or being swapped out at the<br>
>>> >> time. But I would have thought that your stdout buffer would have<br>
>>> >> been there waiting to be read, rather than any higher code needing to<br>
>>> >> be run to provide the data. Are you using buffered I/O on your<br>
>>> >> stdout?<br>
>>> >><br>
>>> >><br>
>>> >Thanks for the quick reply Stephen. I am going to very quickly expose my<br>
>>> >ignorance on how these FDs work. (just setting expectations)<br>
>>> ><br>
>>> >Yes, I am using buffered output, specifically a BufferedWriter in Python<br>
>>> (<br>
>>> ><a href="https://docs.python.org/2/library/io.html#io.BufferedWriter" rel="noreferrer" target="_blank">https://docs.python.org/2/lib<wbr>rary/io.html#io.BufferedWriter</a><wbr>). I added<br>
>>> >explicit "flush" commands after the 'write' command, but it didn't help.<br>
>>> ><br>
>>> >I'll try dropping the buffered output tonight and see what happens. I<br>
>>> >didn't think that using a buffered writer would affect how data is<br>
>>> present<br>
>>> >in the stream.<br>
>>> ><br>
>>> >Thanks,<br>
>>> >Marc<br>
>>><br>
>>> I would have hoped that using a BufferedWriter would have provided<br>
>>> more buffering rather than less, but it would be useful to try a<br>
>>> normal file instead, using the normal buffering, to see if it makes a<br>
>>> difference. The problem with this situation is that the<br>
>>> ExternalStreamHandler.cpp code needs to be able to read the data from<br>
>>> the pipe buffer instantly, as it has been told that there is data<br>
>>> waiting. So if the buffer the data is coming from is not locked in<br>
>>> RAM, it may not be instantly available. The normal file I/O buffers<br>
>>> in Python are handled in the underlying C library and should work the<br>
>>> way ExternalStreamHandler.cpp expects them to, but it is vaguely<br>
>>> possible that BufferedWriter changes that and accessing its buffers<br>
>>> requires running the Python interpreter, which could cause this<br>
>>> problem. The documentation of BufferedWriter is not specific enough<br>
>>> about how it works to know exactly how its low level buffering works,<br>
>>> but it is suggestive that the data may be lying in a higher level<br>
>>> buffer.<br>
>>><br>
>>><br>
>> Just gave it a go and no joy, same behavior as before...<br>
>><br>
>> In my Python code, the salient part is:<br>
>> data = fd.read(256)<br>
>> if data:<br>
>> if (self.last_write_time is None):<br>
>> self.logger.debug("First bytes written to stdout")<br>
>> self.__bin_stdout.write(data)<br>
>> self.__bin_stdout.flush()<br>
>> self.last_write_time = time.time()<br>
>> self.writer_control.wait(0.5)<br>
>><br>
>> and self.__bin_stdout is equal to sys.stdout.<br>
>><br>
>> Would it have to do with:<br>
>> <a href="http://pubs.opengroup.org/onlinepubs/9699919799/functions/poll.html" rel="noreferrer" target="_blank">http://pubs.opengroup.org/onli<wbr>nepubs/9699919799/functions/<wbr>poll.html</a><br>
>><br>
>> It indicates that for streams, the POLLIN is set even if the message is of<br>
>> zero length.<br>
>><br>
>> Thanks,<br>
>> Marc<br>
>><br>
>><br>
>><br>
>> I suggest creating a ticket for this.<br>
>><br>
>> You may want to look at the import recorder. I recently committed a fix<br>
>> that allows it to be used for recordings. See the fix at<br>
>> <a href="https://code.mythtv.org/trac/ticket/13114" rel="noreferrer" target="_blank">https://code.mythtv.org/trac/t<wbr>icket/13114</a> and documentation at<br>
>> <a href="https://www.mythtv.org/wiki/Import_recorder" rel="noreferrer" target="_blank">https://www.mythtv.org/wiki/Im<wbr>port_recorder</a> . Currently the fix is only<br>
>> available in master, scheduled for v30.<br>
>><br>
>> Peter<br>
>><br>
><br>
><br>
>Thanks for the suggestion, Peter. I'll look at possibly using the import<br>
>recorder...<br>
><br>
>Stephen, I grabbed the latest V30 (master) and hacked<br>
>up ExternalStreamHandler.cpp with extra log messages. I replaced the Ready<br>
>function to use select instead of poll and still had the same behavior. I<br>
>then commented out this line:<br>
>- m_error = "Failed to read from External Recorder: " + ENO;<br>
>+ //m_error = "MR: Failed to read from External Recorder: " + ENO;<br>
>preventing the hard failure, and got a functioning video stream.<br>
><br>
>In the snippet below, FD 62 is the "stdout" with the transport stream.<br>
>The "Checking for data" line comes from the Ready function: 1 indicates<br>
>there's data to read.<br>
>The empty line in the log is the from the commented out m_error... It's<br>
>when we get the unexpected "erno 11".<br>
><br>
>We can see there's data before and after the error... I am not sure it's a<br>
>problem with the Ready function, but with the 'read'<br>
><br>
>2017-11-23 15:07:35.517510 I ExternalRec(/home/mrawji/recor<wbr>der/record.sh):<br>
>ProcessCommand('StopStreaming<wbr>') = 'OK:Stopped'<br>
>2017-11-23 15:07:35.517516 E ExternIO::Read '256' bytes, buffer size 312<br>
>2017-11-23 15:07:35.517690 E MR: Checking for data, return value was:<br>
>'1', for FD '62'<br>
>2017-11-23 15:07:35.517693 E MR: Checking for data, return value was:<br>
>'1', for FD '62'<br>
>2017-11-23 15:07:35.517700 E<br>
>2017-11-23 15:07:35.517709 E ExternIO::Read '256' bytes, buffer size 380<br>
>2017-11-23 15:07:35.517822 E MR: Checking for data, return value was:<br>
>'1', for FD '62'<br>
>2017-11-23 15:07:35.517842 E ExternIO::Read '256' bytes, buffer size 260<br>
>2017-11-23 15:07:35.517879 E MR: Checking for data, return value was:<br>
>'1', for FD '62'<br>
>2017-11-23 15:07:35.517901 E ExternIO::Read '256' bytes, buffer size 328<br>
><br>
>I am thinking that I could possibly add a counter on the failed reads and<br>
>if we hit 2 (or n) in row, then fail... It also looks like it'll read "0<br>
>bytes" a few times despite the Ready function returning True. In the trace<br>
>above, I see 2 0 byte reads, followed by the "erno 11". Then, everything<br>
>keeps working again (9 microseconds after the error).<br>
><br>
>I am writing 256 bytes at a time from my python app... not sure if that<br>
>means anything.<br>
><br>
>Thanks<br>
>Marc<br>
<br>
</div></div>That certainly seems like a valid workaround, but it would be nice to<br>
be able to explain why it is happening when it should not be.<br>
<br>
I have seen what look like a couple of bugs in the<br>
ExternalStreamHandler.cpp code while I have been reading it. The<br>
first is in Ready, where I believe the line:<br>
<br>
if (m_poll[0].revents & POLLIN)<br>
<br>
should instead be:<br>
<br>
if (m_poll[0].revents & (POLLIN|POLLPRI))<br>
<br>
The second is in Fork where there is this code:<br>
<br>
bool error = false;<br>
error = (fcntl(m_appin, F_SETFL, O_NONBLOCK) == -1);<br>
error = (fcntl(m_appout, F_SETFL, O_NONBLOCK) == -1);<br>
error = (fcntl(m_apperr, F_SETFL, O_NONBLOCK) == -1);<br>
<br>
That overwrites the error flag, when they should be ORed together. So<br>
I think this should work:<br>
<br>
bool error =<br>
(fcntl(m_appin, F_SETFL, O_NONBLOCK) == -1) ||<br>
(fcntl(m_appout, F_SETFL, O_NONBLOCK) == -1) ||<br>
(fcntl(m_apperr, F_SETFL, O_NONBLOCK) == -1);<br>
<br>
or maybe<br>
<br>
bool error = false;<br>
error = error || (fcntl(m_appin, F_SETFL, O_NONBLOCK) == -1);<br>
error = error || (fcntl(m_appout, F_SETFL, O_NONBLOCK) == -1);<br>
error = error || (fcntl(m_apperr, F_SETFL, O_NONBLOCK) == -1);<br>
<br>
if it is required that all the fcntl calls always be performed.<br>
<br>
I can not see why either of those problems would be causing what you<br>
are seeing, but it might be worthwhile trying the fixes just in case.</blockquote><div><br></div></div></div><div>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.</div><div><br></div><div>I'll see if I can come up with any other bright ideas.</div><div><br></div><div>Thanks,</div><div>Marc </div></div></div></div>
</blockquote></div><br></div>