1304681 - robocop has blank test property

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Testing, defect, P1)

Description

[Kyle Lahnakoski [:ekyle]]

The structured log for robocop has a blank `test` property.  You can find them with a search for

> "test": ""

... in ...

https://public-artifacts.taskcluster.net/GrYFE7LzQbyjachPpPcR6Q/0/public/test_info//robocop_raw.log

... and seeing the lines above.

ActiveData complains about these lines because it is assuming all lines belong to tests.  If this is not the case, please tell me how I should deal with them.  I have no issue with the structured log containing inter-test log lines, but I would like to be certain about when they do occur.

Thank you!!

Comment 1

[Geoff Brown [:gbrown]]

To make sure we are seeing the same thing, can you confirm: many items in that robocop structured log have a non-blank 'test' property, such as:

{"thread": "None", "pid": null, "source": "robocop", "test": "testFilePicker", ...

only one item in the log you cited has a blank 'test':

{"status": "PASS", "thread": "None", "subtest": "Given message occurred for registered event: {\"message\":\"\\nTEST-PASS | testEventDispatcher.js | [send_message_for_response\\/< : 39] error == error\\n\",\"innerType\":\"progress\",\"type\":\"Robocop:JS\"}", "pid": null, "source": "robocop", "test": "", "time": 1474486881367, "action": "test_status", "message": "Robocop:JS should equal Robocop:JS"}

Comment 2

[Geoff Brown [:gbrown]]

There are also lots of items that do not include a 'test' attribute:

{"source": "mochitest", "thread": "MainThread", "time": 1474485610710, "action": "log", "message": "Checking for orphan ssltunnel processes...", "level": "INFO", "pid": 1079}

Are those OK?

Comment 3

[Kyle Lahnakoski [:ekyle]]

I reviewed my code [1] to see specifically what I am assuming:  All {"action": "test_status"} lines should contain a valid "test" property.  In that light, I was wrong to mention "lines" plural; it is only that one line.

[1] https://github.com/klahnakoski/ActiveData-ETL/blob/bcb7c7a81dcf047bc255aa9f58f4cdf4d612e8f9/activedata_etl/transforms/unittest_logs_to_sink.py#L203

Comment 4

[Geoff Brown [:gbrown]]

That one line happens at the end of the log. It looks like testEventDispatcher ends, the harness reports the summary of the test run, and then another status line is logged that likely originated in testEventDispatcher:

{"status": "OK", "thread": "None", "pid": null, "source": "robocop", "test": "testEventDispatcher", "time": 1474486881341, "action": "test_end", "message": "finished in 58587ms"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474486881344, "action": "log", "exc_info": false, "message": "TEST-START | Shutdown"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474486881349, "action": "log", "exc_info": false, "message": "Passed: 383"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474486881352, "action": "log", "exc_info": false, "message": "Failed: 0"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474486881357, "action": "log", "exc_info": false, "message": "Todo: 0"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474486881360, "action": "log", "exc_info": false, "message": "SimpleTest FINISHED"}
{"status": "PASS", "thread": "None", "subtest": "Given message occurred for registered event: {\"message\":\"\\nTEST-PASS | testEventDispatcher.js | [send_message_for_response\\/< : 39] error == error\\n\",\"innerType\":\"progress\",\"type\":\"Robocop:JS\"}", "pid": null, "source": "robocop", "test": "", "time": 1474486881367, "action": "test_status", "message": "Robocop:JS should equal Robocop:JS"}
{"source": "mochitest", "thread": "MainThread", "time": 1474486904142, "action": "log", "message": "runApp completes with status 0", "level": "DEBUG", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474486904663, "action": "log", "message": "Remote log /storage/sdcard/tests/logs/mochitest.log retrieved to robocop.log", "level": "DEBUG", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474486904671, "action": "log", "message": "Test src/org/mozilla/gecko/tests/testEventDispatcher.java completes with status 0 (log status 0)", "level": "DEBUG", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474486904671, "action": "log", "message": "Cleaning up...", "level": "DEBUG", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474486904671, "action": "log", "message": "Stopping web server", "level": "INFO", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474487031936, "action": "log", "message": "Stopping web socket server", "level": "INFO", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474487031957, "action": "log", "message": "Stopping ssltunnel", "level": "INFO", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474487032144, "action": "log", "message": "Pulling any remote moz logs and screenshots to /home/worker/workspace/build/blobber_upload_dir.", "level": "DEBUG", "pid": 1079}
{"source": "mochitest", "thread": "MainThread", "time": 1474487033743, "action": "log", "message": "Cleanup complete.", "level": "DEBUG", "pid": 1079}
{"action": "suite_end", "source": "mochitest", "pid": 1079, "thread": "MainThread", "time": 1474487033743}


In contrast, it looks like most such logs end like:

https://public-artifacts.taskcluster.net/YsUGwwH-TO2WUKcIHGsemg/0/public/test_info//robocop_raw.log


{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474556225415, "action": "log", "exc_info": false, "message": "testEventDispatcher.js | executing cleanup function."}
{"status": "PASS", "thread": "None", "subtest": "Given message occurred for registered event: {\"message\":\"\\nTEST-INFO | (xpcshell\\/head.js) | exiting test\\n\",\"innerType\":\"progress\",\"type\":\"Robocop:JS\"}", "pid": null, "source": "robocop", "test": "testEventDispatcher", "time": 1474556225447, "action": "test_status", "message": "Robocop:JS should equal Robocop:JS"}
{"status": "PASS", "thread": "None", "subtest": "Given message occurred for registered event: {\"innerType\":\"sync-reply\",\"type\":\"Robocop:JS\",\"args\":[],\"method\":\"finish_test\"}", "pid": null, "source": "robocop", "test": "testEventDispatcher", "time": 1474556225457, "action": "test_status", "message": "Robocop:JS should equal Robocop:JS"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474556225465, "action": "log", "exc_info": false, "message": "(xpcshell/head.js) | exiting test"}
{"thread": "MainThread", "level": "info", "pid": 1082, "source": "mochitest", "time": 1474556234419, "action": "log", "exc_info": false, "message": "EventExpecter: no longer listening for Robocop:JS"}
{"status": "OK", "thread": "None", "pid": null, "source": "robocop", "test": "testEventDispatcher", "time": 1474556225491, "action": "test_end", "message": "finished in 55034ms"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474556225495, "action": "log", "exc_info": false, "message": "TEST-START | Shutdown"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474556225498, "action": "log", "exc_info": false, "message": "Passed: 385"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474556225527, "action": "log", "exc_info": false, "message": "Failed: 0"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474556225531, "action": "log", "exc_info": false, "message": "Todo: 0"}
{"thread": "None", "level": "info", "pid": null, "source": "robocop", "time": 1474556225534, "action": "log", "exc_info": false, "message": "SimpleTest FINISHED"}
{"source": "mochitest", "thread": "MainThread", "time": 1474556246343, "action": "log", "message": "runApp completes with status 0", "level": "DEBUG", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556246864, "action": "log", "message": "Remote log /storage/sdcard/tests/logs/mochitest.log retrieved to robocop.log", "level": "DEBUG", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556246871, "action": "log", "message": "Test src/org/mozilla/gecko/tests/testEventDispatcher.java completes with status 0 (log status 0)", "level": "DEBUG", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556246872, "action": "log", "message": "Cleaning up...", "level": "DEBUG", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556246872, "action": "log", "message": "Stopping web server", "level": "INFO", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556374105, "action": "log", "message": "Stopping web socket server", "level": "INFO", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556374125, "action": "log", "message": "Stopping ssltunnel", "level": "INFO", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556374312, "action": "log", "message": "Pulling any remote moz logs and screenshots to /home/worker/workspace/build/blobber_upload_dir.", "level": "DEBUG", "pid": 1082}
{"source": "mochitest", "thread": "MainThread", "time": 1474556376012, "action": "log", "message": "Cleanup complete.", "level": "DEBUG", "pid": 1082}
{"action": "suite_end", "source": "mochitest", "pid": 1082, "thread": "MainThread", "time": 1474556376012}

Comment 5

[Geoff Brown [:gbrown]]

The problematic record:

{"status": "PASS", "thread": "None", "subtest": "Given message occurred for registered event: {\"message\":\"\\nTEST-PASS | testEventDispatcher.js | [send_message_for_response\\/< : 39] error == error\\n\",\"innerType\":\"progress\",\"type\":\"Robocop:JS\"}", "pid": null, "source": "robocop", "test": "", "time": 1474486881367, "action": "test_status", "message": "Robocop:JS should equal Robocop:JS"}

is logged by a robocop GeckoEventExpecter -- https://hg.mozilla.org/mozilla-central/annotate/560b2c805bf7bebeb3ceebc495a81b2aa4c0c755/mobile/android/tests/browser/robocop/src/org/mozilla/gecko/FennecNativeActions.java#l70. The way to prevent a GeckoEventExpecter from handling messages, and logging them, is to unregister it: We should unregister the GeckoEventExpecter before ending the test.

testEventDispatcher is a JavascriptBridgeTest, which uses a JavascriptBridge, which uses a GeckoEventExpecter. JavascriptBridge unregisters the GeckoEventExpecter in JavascriptBridge.disconnect(), which is called from JavascriptBridge.tearDown() -- https://hg.mozilla.org/mozilla-central/annotate/560b2c805bf7bebeb3ceebc495a81b2aa4c0c755/mobile/android/tests/browser/robocop/src/org/mozilla/gecko/tests/JavascriptBridgeTest.java#l43. That all seems correct: It should ensure that no more messages are logged after the test ends.

Comment 6

[Geoff Brown [:gbrown]]

I have not been able to reproduce this, and another example or two might help me understand what is happening.

:ekyle -- Do you have any other examples?

Comment 7

[Kyle Lahnakoski [:ekyle]]

http://queue.taskcluster.net/v1/task/SR6N9BKxRB6UFmuL2td-fQ/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/Yd19oR0ARfGVbXUh1Y73fw/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/MmyyGhDFTR2fS7d4SyhenA/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/C99O-KpsSJ6MoORLhe3S_Q/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/LOLlQ4TLT6miv7V1ANF4DQ/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/SR6N9BKxRB6UFmuL2td-fQ/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/GrYFE7LzQbyjachPpPcR6Q/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/WKnFgj-MQeitp01x5qiiQw/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/eZBmRFlmQTyZbM50u4HyaQ/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/ZIfrrvcNQt-klptglRPatw/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/NB-3qnvTQtuc_b33JEVE6A/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/cTM0OC_5RNuBarWBbbyBsA/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/FoSOu2cPTTCBXZ_qYc9BgA/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/cLF1CajaTPiNsLUGkTkLHQ/artifacts/public/test_info//robocop_raw.log
http://queue.taskcluster.net/v1/task/O7JzCrVATrCdrzXdofz2pQ/artifacts/public/test_info//robocop_raw.log

Comment 8

[Geoff Brown [:gbrown]]

Thanks Kyle - that's great.

It looks like all the bad records are at the end of testEventDispatcher. Each record occurs later in the log than the EventExpecter unregister record, but the timestamps are in the correct order: Robocop:JS record (earlier), unregister record (later). The bad record consistently appears after the test summary start (sometimes during the summary, sometimes after). 

I find it surprising that the test ends before the Robocop:JS (error == error) message is received (well, logged?) -- shouldn't the test wait for that before completing? The test does waitForAsyncEvent() but that doesn't seem to verify any specific message...perhaps the message responses are not the ones the test appears to be waiting for?

Comment 9

[Geoff Brown [:gbrown]]

I see now that waitForAsyncEvent() is unrelated to Robocop:JS progress messages. Also, JavascriptBridge.syncCall waits for sync-reply, but has no expectations about Robocop:JS progress messages. The JavascriptMessageParser examines the progress messages and translates them into assertions (which may generate StructuredLogger.testStatus() calls, which is where we run into trouble) but has no expectations about when or how many such messages to expect. If a progress message is still in-flight when all test expectations have been met, I expect the test ends, the EventExpecter is unregistered, and the in-flight progress messages will be silently discarded. But I think it may also be possible for such messages to be processed after EventExpecter.unregister() has been called -- that's the only way I can account for the problems found by :ekyle.

Comment 10

[Geoff Brown [:gbrown]]

To summarize, I believe that -- sometimes, infrequently -- testEventDispatcher completes, having received all expected sync-reply messages, including the one for the "finish_test" at:

https://dxr.mozilla.org/mozilla-central/rev/c55bcb7c777ea09431b4d16903ed079ae5632648/mobile/android/tests/browser/robocop/src/org/mozilla/gecko/tests/testEventDispatcher.java#135

and then subsequently receives a Robocop:JS progress message (spawned by the earlier "error" BACKGROUND_RESPONSE_EVENT) during test tearDown().

Comment 11

[Geoff Brown [:gbrown]]

Attachment: do not clear test name between robocop tests

The test is working as intended. I would like to discard the troublesome log message if it is generated after the test ends, but I see no reliable-and-easy way of doing so. Instead, if we do not clear the test name between tests, messages should continue to be logged with the old test name until the new test starts. I think that's not bad and it should ensure that we create a valid structured log.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3d5372c5a1b6bb49d1f43dede5c2f6ff13c48766

Comment 12

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

Comment on attachment 8795302 [details] [diff] [review]
do not clear test name between robocop tests

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

is there a need to clear the test name at a different point, or is it done somewhere else?

Comment 13

[Geoff Brown [:gbrown]]

It is never cleared, but I think that is okay: The test name will be updated at the start of the next test, and, except for odd edge cases such as those highlighted by this bug, it won't be used between tests.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/281b6ca012d1
Do not clear robocop test name between tests; r=jmaher

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/281b6ca012d1