756704 - Robocop: missing / missed events can cause infinite hangs

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Geoff Brown [:gbrown]]

Several Robocop utilities wait indefinitely for events. If the event never comes, or a race condition causes the event to be missed, the test waits forever. In most cases, we can probably add a timeout, reducing test time.

Comment 1

[Geoff Brown [:gbrown]]

Attachment: wip patch

Comment 2

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

Comment on attachment 625330 [details] [diff] [review]
wip patch

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

I like this approach.  I think for the testcheck stuff we might need more time.  Also would we want some tests to self recheck?

Comment 3

[Geoff Brown [:gbrown]]

"Dependent" on bug 757475 in that this patch shows that testPermissions fails consistently; we should address that failure before checking-in this patch.

Comment 4

[Geoff Brown [:gbrown]]

(In reply to Joel Maher (:jmaher) from comment #2)
> I like this approach.  I think for the testcheck stuff we might need more
> time.  Also would we want some tests to self recheck?

I don't see much in testCheck/2/3 that uses blockForEvent, etc; those are long-running tests but I don't think there is a long wait for any event. I reviewed wait times for testCheck and testCheck2 and found a maximum wait of 15000 ms.

I also reviewed wait times across all mochitests and found most were under 4000 ms. However, the initial wait for "Gecko:Ready" can be 40000+ ms; in light of this, I will increase the max wait to 90000 ms.

Comment 5

[Geoff Brown [:gbrown]]

Attachment: wait in blockForEvent (and related) for a maximum of 90 seconds

The idea here is to avoid sitting in an infinite wait() call when an event is somehow missed. If this happens currently, the framework eventually kills the process, diagnostics are poor, and it is difficult to see where the test was hung. By changing to wait(max-wait), we can detect and explicitly report the timeout.

I opted to use one maximum wait time for all events, rather than requiring the caller to specify a wait time, for simplicity. 90 s seems to provide ample room for all of our current test scenarios and is still reasonable, for exceptional failures.

Comment 6

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 626469 [details] [diff] [review]
wait in blockForEvent (and related) for a maximum of 90 seconds

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

I think I would prefer just throwing an exception or calling the mAsserter.ok(false) from blockForEvent directly if it times out. Having to check the return value in each test seems unnecessarily cumbersome. We can add a second method blockForEvent(long timeout) to control the timeout if we ever have a test that needs more control over the behaviour.

Comment 7

[Geoff Brown [:gbrown]]

(In reply to Kartikaya Gupta (:kats) from comment #6)
> I think I would prefer just throwing an exception or calling the
> mAsserter.ok(false) from blockForEvent directly if it times out. Having to
> check the return value in each test seems unnecessarily cumbersome. 

blockForEvent is in FennecNativeActions, which doesn't have access to mAsserter; Actions can use something like FennecNativeDriver.log(), but that won't cause the test to fail and could go unnoticed.

I am trying to use return values rather than exceptions in core robocop code because of the experience and sentiments expressed in bug 725094.

Comment 8

[Kartikaya Gupta (email:[e-mail])]

(In reply to Geoff Brown [:gbrown] from comment #7)
> 
> blockForEvent is in FennecNativeActions, which doesn't have access to
> mAsserter; Actions can use something like FennecNativeDriver.log(), but that
> won't cause the test to fail and could go unnoticed.

Could you pass in the mAsserter to blockForEvent? Or maybe even do something mActions.setAsserter(mAsserter) in the BaseTest setup code. I just feel like the tests should have as little boilerplate as possible, because adding overhead to writing tests means fewer tests will get written and there's more room for error.

Comment 9

[Geoff Brown [:gbrown]]

Attachment: wait in blockForEvent (and related) for a maximum of 90 seconds

In this version, mAsserter is passed into FennecNativeActions so that tests don't need to check return codes and report errors. The patch for bug 758392 makes this change much easier.

Comment 10

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 627750 [details] [diff] [review]
wait in blockForEvent (and related) for a maximum of 90 seconds

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

Much better, thanks! Just a few nits below.

::: build/mobile/robocop/FennecNativeActions.java.in
@@ +136,5 @@
>                      FennecNativeDriver.log(LogLevel.ERROR, ie);
>                      break;
>                  }
> +                endTime = SystemClock.uptimeMillis();
> +                if (endTime - startTime >= MAX_WAIT_MS) {

Just to be extra safe, I would prefer if this condition (and the others) read like this:

if (!mEventReceived && (endTime - startTime >= MAX_WAIT_MS)) {

That will guard against a false-positive failure in the case where the event is received in time but the endTime assignment run until after the 90s deadline (which might happen if this thread is being starved for whatever reason).

@@ +137,5 @@
>                      break;
>                  }
> +                endTime = SystemClock.uptimeMillis();
> +                if (endTime - startTime >= MAX_WAIT_MS) {
> +                    mAsserter.ok(false, "GeckoEventExpecter", "blockForEvent timeout");

Add mGeckoEvent to the log message somewhere so that it'll be more obvious as to what is failing when we look at the log.

Comment 11

[Geoff Brown [:gbrown]]

Attachment: wait in blockForEvent (and related) for a maximum of 90 seconds

Both nits addressed. r=kats carried.

Comment 12

[Geoff Brown [:gbrown]]

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

Comment 13

[Geoff Brown [:gbrown]]

Attachment: wait in blockForEvent (and related) for a maximum of 90 seconds

updated for bitrot only. r=kats

Comment 14

[Geoff Brown [:gbrown]]

Inbound: https://hg.mozilla.org/integration/mozilla-inbound/rev/b4fdcc91afb9

Comment 15

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/b4fdcc91afb9