913975 - [mozprocess] _processOutput should call self.processOutputLine one more time on timeout (I think)

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Jeff Hammel]

automation.py.in logs a line, potentially, on timeout:

http://mxr.mozilla.org/mozilla-central/source/build/automation.py.in#760

759       if didTimeout:
760         if line:
761           self.log.info(line.rstrip().decode("UTF-8", "ignore"))
762         self.log.info("TEST-UNEXPECTED-FAIL | %s | application
timed out after %d seconds with no output", self.lastTestSeen,
int(timeout))
763         if browserProcessId == -1:
764           browserProcessId = proc.pid
765         self.killAndGetStack(browserProcessId, utilityPath,
debuggerInfo)

mozprocess, on the other hand, does not:

https://github.com/mozilla/mozbase/blob/master/mozprocess/mozprocess/processhandler.py#L699

            (line, self.didTimeout) = self.readWithTimeout(logsource,
            lineReadTimeout)
            while line != "" and not self.didTimeout:
                self.processOutputLine(line.rstrip())
                if timeout:
                    lineReadTimeout = timeout - (datetime.now() -
            self.startTime).seconds
                (line, self.didTimeout) =
            self.readWithTimeout(logsource, lineReadTimeout)

I'm not sure what, if any, the circumstances are where there will be
a final unlogged line here, but if there is such a line...mozprocess
should be calling processOutputLine on it.

Comment 1

[Jeff Hammel]

potentially related? https://bugzilla.mozilla.org/show_bug.cgi?id=932382

Comment 2

[Andrew Halberstadt [:ahal]]

Attachment: 0001-Bug-913975-processOutputLine-should-be-called-with-l.patch

I see what you mean. I think this patch will do what we want, though I haven't tested on try yet.

I don't remember how you feel about while/else clauses, so if you want me to make it more readable, I can.

Comment 3

[Andrew Halberstadt [:ahal]]

Comment on attachment 824215 [details] [diff] [review]
0001-Bug-913975-processOutputLine-should-be-called-with-l.patch

Oops, this is wrong anyway. Here onTimeout only gets called if there *is* still output. New patch coming shortly.

Comment 4

[Jeff Hammel]

Comment on attachment 824215 [details] [diff] [review]
0001-Bug-913975-processOutputLine-should-be-called-with-l.patch

Review of attachment 824215 [details] [diff] [review]:
-----------------------------------------------------------------

I quite like while: else: and think this is an elegant solution :) r+

That said, whether what is in mozprocess currently or what i noted from automation.py is "correct" (and why) is a bit hard to ascertain.  Still, I'd rather land this as A. it *could* help; and B. there are a number of bugs that point to problems with output that are more concrete in manifestation if more abstract to diagnose and fix.

Comment 5

[Jeff Hammel]

Comment on attachment 824215 [details] [diff] [review]
0001-Bug-913975-processOutputLine-should-be-called-with-l.patch

Review of attachment 824215 [details] [diff] [review]:
-----------------------------------------------------------------

Somehow the r+ got swallowed

Comment 6

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.0 - make sure processOutputLine called with last line of output

Comment 7

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.0 - make sure processOutputLine called with last line of output

Gah, that was the same patch, cwd fail. Sorry for the bugspam.

Comment 8

[Andrew Halberstadt [:ahal]]

Comment on attachment 824240 [details] [diff] [review]
Patch 1.0 - make sure processOutputLine called with last line of output

Review of attachment 824240 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry jhammel, I didn't notice you were being quick on your reviews when I was uploading my patches. The first patch failed one of the mozprocess tests (hooray for unittests!) because it doesn't execute the onTimeout callback if line=="" and didTimeout == True. This patch seems to pass without problems.

Comment 9

[Jeff Hammel]

Coolz;  shall we check in?

Comment 10

[Andrew Halberstadt [:ahal]]

Actually I'm not sure this is going to do anything. If you look at the _readWithTimeout function, anywhere we return "True" for timeout, we also explicitly return an empty string: https://github.com/mozilla/mozbase/blob/master/mozprocess/mozprocess/processhandler.py#L787

So this patch might future proof a bit in case that changes, but I don't think it will fix any problems. Up to you if you want to take it anyway?

Comment 11

[Jeff Hammel]

In reply to Andrew Halberstadt [:ahal] from comment #10)
> Actually I'm not sure this is going to do anything. If you look at the
> _readWithTimeout function, anywhere we return "True" for timeout, we also
> explicitly return an empty string:
> https://github.com/mozilla/mozbase/blob/master/mozprocess/mozprocess/
> processhandler.py#L787
> 
> So this patch might future proof a bit in case that changes, but I don't
> think it will fix any problems. Up to you if you want to take it anyway?

I'm not entirely convinced it will do anything either.  The real goal, which is beyond the title/scope of the bug, is to ensure that the buffer is completely eaten on timeout.  I don't necessarily think this will do that, but A. it doesn't hurt; and B. it gives parity to ancient undocumented automation.py code.

Comment 12

[Jeff Hammel]

pushed: https://github.com/mozilla/mozbase/commit/36c8a63f04d1098d76d1ccbec8440c6ebe3164af