904839 - B2G emulator tests still timing out after 1200s, even with the mozprocess-timeout code

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Jonathan Griffin (:jgriffin)]

B2G emulator unittests are still being killed by buildbot after 1200s with no output, despite the fact that we are running them with mozprocess and an output_timeout of 1000, which should cause them to be killed by mozharness instead, and thus allow a dump of the logcat to occur.

sample log:  https://tbpl.mozilla.org/php/getParsedLog.php?id=26160870&full=1&branch=mozilla-central

Comment 1

[Jonathan Griffin (:jgriffin)]

Attachment: Add some mozprocess logging,

This adds some logging to the mozprocess section of run_command; hopefully this will help us figure out why the problem described in this bug's summary is occurring.

Comment 2

[Andrew Halberstadt [:ahal]]

Comment on attachment 793563 [details] [diff] [review]
Add some mozprocess logging,

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

A print statement in the on_timeout method might also be helpful.

Comment 3

[Jonathan Griffin (:jgriffin)]

I added your suggestion and landed:  https://hg.mozilla.org/build/mozharness/rev/a4e6f54010d3

I'll trigger a run on cedar to make sure nothing bad happens, then push to production.

Comment 4

[Armen [:armenzg]]

Merged to production branch of mozharness.
Live as of now.

Comment 5

[Jonathan Griffin (:jgriffin)]

In all cases this logging shows that we are using mozprocess to run the command, but in some cases we're not catching the timeout.  I can't tell why.

Comment 6

[Andrew Halberstadt [:ahal]]

In bug 917252 I noticed that the messages in the on_timeout handler can get interleaved with the process output somehow. Did you ctrl-f for "mozprocess timed out"? Because it could just be hidden among some random line of output above.

Comment 7

[Jonathan Griffin (:jgriffin)]

That doesn't appear to be the case here; see a recent log:  https://tbpl.mozilla.org/php/getParsedLog.php?id=28100440&full=1&branch=mozilla-inbound

Comment 9

[Jonathan Griffin (:jgriffin)]

Attachment: Use os.read instead of readline in readWithTimeout,

WIP.  This seems to resolve this issue on try, but I need to do a full try run to make sure it doesn't break anything else.

Without this patch: https://tbpl.mozilla.org/?tree=Try&rev=2471fcda8961
With this patch: https://tbpl.mozilla.org/?tree=Try&rev=fc8f06309cfa

Comment 10

[Jonathan Griffin (:jgriffin)]

full try run:  https://tbpl.mozilla.org/?tree=Try&rev=6dcdc9b326cb

Comment 11

[Jonathan Griffin (:jgriffin)]

This patch seems to work well for B2G mochitests/reftests, but fails for linux tests and for B2G marionette. :(

Comment 12

[Jonathan Griffin (:jgriffin)]

Attachment: Use os.read instead of readline in readWithTimeout,

v2..handle the case where os.read returns only one or more newlines.  try: https://tbpl.mozilla.org/?tree=Try&rev=6f94f56145c8

Comment 13

[Jonathan Griffin (:jgriffin)]

(In reply to Jonathan Griffin (:jgriffin) from comment #12)
> Created attachment 816074 [details] [diff] [review]
> Use os.read instead of readline in readWithTimeout,
> 
> v2..handle the case where os.read returns only one or more newlines.  try:
> https://tbpl.mozilla.org/?tree=Try&rev=6f94f56145c8

This is much better; the only problem left is that we're somehow messing up Windows builds.  Will investigate a little more.

Comment 14

[Jonathan Griffin (:jgriffin)]

Attachment: mozprocess.diff

v3: locally fixes the Windows build problems

Comment 15

[Jonathan Griffin (:jgriffin)]

pushed to try: https://tbpl.mozilla.org/?tree=Try&rev=247cd269d6fe

Comment 16

[Jonathan Griffin (:jgriffin)]

Comment on attachment 816650 [details] [diff] [review]
mozprocess.diff

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

This is looking good on try, so I'm putting up for review.

Comment 17

[Jeff Hammel]

Comment on attachment 816650 [details] [diff] [review]
mozprocess.diff

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

Nice.  Looks good.

::: testing/mozbase/mozprocess/mozprocess/processhandler.py
@@ +695,5 @@
>                  lineReadTimeout = outputTimeout
>  
> +            (lines, self.didTimeout) = self.readWithTimeout(logsource, lineReadTimeout)
> +            while lines != "" and not self.didTimeout:
> +                for line in lines.split('\n'):

why not splitlines? Is this from universal newlines? (do we enforce that?)

@@ +793,5 @@
> +                self.read_buffer += output
> +                if '\n' not in self.read_buffer:
> +                    time.sleep(0.01)
> +                    continue
> +                tmp = self.read_buffer.split('\n')

again, '\n' v splitlines

Comment 18

[Jonathan Griffin (:jgriffin)]

split('\n') seemed more precise.  Here's a try run using splitlines() instead:

https://tbpl.mozilla.org/?tree=Try&rev=8b2d8b3c7af7

Comment 19

[Jonathan Griffin (:jgriffin)]

(In reply to Jonathan Griffin (:jgriffin) from comment #18)
> split('\n') seemed more precise.  Here's a try run using splitlines()
> instead:
> 
> https://tbpl.mozilla.org/?tree=Try&rev=8b2d8b3c7af7

It turns out this doesn't quite work, at least for the second case.  In that case, we want to differentiate between 'test\nfoo\n' and 'test\nfoo', which is a little clumsier with splitlines().  So, I'll keep split('\n') in that case.

Comment 20

[Jonathan Griffin (:jgriffin)]

(In reply to Jonathan Griffin (:jgriffin) from comment #19)
> (In reply to Jonathan Griffin (:jgriffin) from comment #18)
> > split('\n') seemed more precise.  Here's a try run using splitlines()
> > instead:
> > 
> > https://tbpl.mozilla.org/?tree=Try&rev=8b2d8b3c7af7
> 
> It turns out this doesn't quite work, at least for the second case.  In that
> case, we want to differentiate between 'test\nfoo\n' and 'test\nfoo', which
> is a little clumsier with splitlines().  So, I'll keep split('\n') in that
> case.

And here's a green try run which shows this works ok:  https://hg.mozilla.org/try/rev/1c31fd8992c5

Comment 21

[Jonathan Griffin (:jgriffin)]

https://github.com/mozilla/mozbase/commit/576b5285c981b6ba938cb1f8716aa96cd7e3b046

We'll have to mirror to m-c before we can tell if this fixes this problem, so I'll leave this bug open until then.

Comment 22

[Jonathan Griffin (:jgriffin)]

(In reply to Jonathan Griffin (:jgriffin) from comment #21)
> https://github.com/mozilla/mozbase/commit/
> 576b5285c981b6ba938cb1f8716aa96cd7e3b046
> 
> We'll have to mirror to m-c before we can tell if this fixes this problem,
> so I'll leave this bug open until then.

Totally green!  After the versionbump patch is r+'d, I'll land that in github and do another try run with the result, since it will include a few more packages than the above.

Comment 23

[Jonathan Griffin (:jgriffin)]

(In reply to Jonathan Griffin (:jgriffin) from comment #22)
> (In reply to Jonathan Griffin (:jgriffin) from comment #21)
> > https://github.com/mozilla/mozbase/commit/
> > 576b5285c981b6ba938cb1f8716aa96cd7e3b046
> > 
> > We'll have to mirror to m-c before we can tell if this fixes this problem,
> > so I'll leave this bug open until then.
> 
> Totally green!  After the versionbump patch is r+'d, I'll land that in
> github and do another try run with the result, since it will include a few
> more packages than the above.

wrong bug, sorry !

Comment 24

[Jonathan Griffin (:jgriffin)]

This appears to be fixed by some recent changes to mozrunner and/or mozprocess.  I'll re-open if I see this again.

Getting stack traces appropriately is being handled under separate bugs, like bug 919353.

Comment 25

[Joel Maher ( :jmaher ) (UTC -8)]

this is causing talos to fail if I run with mozprocess 0.13.  I get a never ending stream of __metrics (a line printed at the end of the logfile for the warmup run).  I really need another fix that is in 0.13 and not in 0.11.

Comment 26

[Joel Maher ( :jmaher ) (UTC -8)]

I added a \n to the last __metrics line printed out here: http://hg.mozilla.org/build/talos/file/tip/talos/getInfo.html#l66, and the problem is solved.  We really need to fix this in the mozprocess code as this is not handling generic process output.

Comment 27

[Jonathan Griffin (:jgriffin)]

(In reply to Joel Maher (:jmaher) from comment #26)
> I added a \n to the last __metrics line printed out here:
> http://hg.mozilla.org/build/talos/file/tip/talos/getInfo.html#l66, and the
> problem is solved.  We really need to fix this in the mozprocess code as
> this is not handling generic process output.

Agreed.  Is this problem you're seeing on Windows, or everywhere?

Comment 28

[Joel Maher ( :jmaher ) (UTC -8)]

oh, bad bug reporting.  this was seen on all linux and osx platforms, which was easily seen here:
https://github.com/mozilla/mozbase/blob/master/mozprocess/mozprocess/processhandler.py#L779

windows worked great.

Comment 29

[Jonathan Griffin (:jgriffin)]

Thanks, I'll try to write a test to reproduce this.