715309 - robocop needs to have a more uniform log format

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

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

Attachment: cleanup robocop logs and test running (1.0)

robocop has native logging, but it doesn't work very good when it comes to integration into mozilla-central.  

This patch:
* adds a summary and test-start/test-end.
* cleans up the remote runner
* adds tighter integration with existing devicemanager functions

Comment 1

[Geoff Brown [:gbrown]]

Comment on attachment 585863 [details] [diff] [review]
cleanup robocop logs and test running (1.0)

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

This is a big step in the right direction: I can see how useful this kind of logging will be.

I am seeing some problems. Most troubling: With this patch, only the first test runs for me, Fennec is killed, and then the script seems to hang. (I don't know why.)
I see output like this:
...
INFO | runtests.py | Running tests: start.


org.mozilla.fennec_mozdev.tests.testAwesomebar:.
Test results for InstrumentationTestRunner=.
Time: 29.274

OK (1 test)


INFO | automation.py | Application pid: 2764
0 INFO SimpleTest START
1 INFO TEST-START | Awesomebar URL Typed Properly
2 INFO TEST-PASS | ROBOCOP | Awesomebar URL Typed Properly - http://mochi.test:8888/tests/robocop/robocop_blank_01.html should equal http://mochi.test:8888/tests/robocop/robocop_blank_01.html
3 INFO TEST-PASS | ROBOCOP | Awesomebar URL stayed the same - http://mochi.test:8888/tests/robocop/robocop_blank_01.html should equal http://mochi.test:8888/tests/robocop/robocop_blank_01.html
4 INFO TEST-END | Awesomebar URL Typed Properly
5 INFO TEST-START | Shutdown
6 INFO Passed: 2
7 INFO Failed: 0
8 INFO Todo: 0
9 INFO SimpleTest FINISHED


Also, I notice there are logging functions in FennecNativeDriver still...can they be removed / consolidated?

::: build/mobile/robocop/FennecNativeAssert.java.in
@@ +124,5 @@
>      logFile = filename;
> +
> +    String message;
> +    if (!logStarted) {
> +      message = Integer.toString(lineNumber++) + " INFO SimpleTest START";

Why "SimpleTest"? Perhaps have the caller pass a test case name to setLogFile().

@@ +132,5 @@
> +
> +    if (logTestName != "") {
> +      message = Integer.toString(lineNumber++) + " INFO TEST-END | " + logTestName;
> +// TODO: add a timer in here when we do a TEST-START so we can report test times.
> +//      message += " | finished in 3567ms";

This is a great idea -- let's do it now!

@@ -133,0 +159,5 @@
> > +    String message;
> > +    if (logTestName == "") {
> > +      message = Integer.toString(lineNumber++) + " INFO TEST-START | " + test.name;
> > +      dumpLog(message);
> > +      logTestName = test.name;

This doesn't seem right to me. I think we want to see something like "INFO TEST-START testAwesomeBar", but test.name seems to be the text associated with an assertion -- something like "URL has been updated". _logResult (logging the result of a test assertion) is probably the wrong place to be trying to record the start of a test; consider having each test case setUp() call something like Assert.logTestStart(testName).

@@ -158,0 +191,24 @@
> > +
> > +    if (test.todo) {
> > +      todo++;
> > +    } else if (isError) {
NaN more ...

I find this message confusing -- why TEST-START when shutting down? Maybe remove this message entirely?

@@ -158,0 +191,32 @@
> > +
> > +    if (test.todo) {
> > +      todo++;
> > +    } else if (isError) {
NaN more ...

Another "SimpleTest" here.

Comment 2

[Geoff Brown [:gbrown]]

Grrr. Bugzilla got confused on those last 2 comments; both actually apply to FennecNativeAssert.finalize().

Comment 3

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

so a few pieces here are remnants of the original mochitest logging format.  The Simpletest and "START-TEST | Shutdown".  I don't want to rock the boat too much and this is the compatible way to go.

I can fix the test.name to be the class name, remove the duplicated code in fennecnativedriver.java.in, and get the tests to run to completion.  Also I can get the timing of the tests in the log file.  I will have a patch up (probably tomorrow) that addresses these issues.

Comment 4

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

Attachment: cleanup robocop logs and test running (2.0)

updated for bitrot and per comments above.

Comment 5

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

Attachment: cleanup robocop logs and test running (2.1)

fixed remote profile location to allow for looping of tests.

Comment 6

[Geoff Brown [:gbrown]]

This still hangs for me, waiting for the remote process to end -- bug 716077.

Comment 7

[Geoff Brown [:gbrown]]

With the pending fix for 716077, the tests run fine and the logging works as intended.

Comment 8

[Geoff Brown [:gbrown]]

Comment on attachment 586523 [details] [diff] [review]
cleanup robocop logs and test running (2.1)

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

Looks good!

Comment 9

[Ed Morley [:emorley]]

Landed (https://hg.mozilla.org/integration/mozilla-inbound/rev/32f8d3be2ad1) but that push was backed out again (https://hg.mozilla.org/integration/mozilla-inbound/rev/879883efec3c) for mochitest/reftest failures on Android & Windows:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=8ec01f6f316f

Comment 10

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

inbound:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8b1c24ce4537

Comment 11

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/8b1c24ce4537

Comment 12

[Brad Lassey [:blassey] (use needinfo?)]

Joel, please request aurora approval or market the whiteboard not-fennec-11