908459 - Robocop test pass count is wrong sometimes

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Geoff Brown [:gbrown]]

Consider:

https://tbpl.mozilla.org/php/getParsedLog.php?id=26865351&tree=Mozilla-Central&full=1

which reports

04:38:40     INFO -  222 INFO TEST-START | Shutdown
04:38:40     INFO -  223 INFO Passed: 92
04:38:40     INFO -  224 INFO Failed: 0
04:38:40     INFO -  225 INFO Todo: 0
04:38:40     INFO -  226 INFO SimpleTest FINISHED

but by my count it should be 

Passed: 162
Failed: 0

Comment 1

[Geoff Brown [:gbrown]]

When I said it "should be" 162, I got that by adding the per-test Passed counts.

TEST-INFO lines seem to be causing the discrepancy. Consider:

04:38:22     INFO -  1 INFO TEST-START | testPasswordProvider
04:38:22     INFO -  EventExpecter: no longer listening for Gecko:Ready
04:38:22     INFO -  2 INFO TEST-PASS | testPasswordProvider | Insert returned correct uri - content://org.mozilla.fennec.db.passwords/passwords/1?profilePath=%2Fmnt%2Fsdcard%2Ftests%2Fprofile should equal content://org.mozilla.fennec.db.passwords/passwords/1?profilePath=%2Fmnt%2Fsdcard%2Ftests%2Fprofile
04:38:22     INFO -  3 INFO TEST-PASS | testPasswordProvider | List is correct length - 1 should equal 1
04:38:22     INFO -  4 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: hostname
04:38:22     INFO -  5 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: httpRealm
04:38:22     INFO -  6 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: formSubmitURL
04:38:22     INFO -  7 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: usernameField
04:38:22     INFO -  8 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: passwordField
04:38:22     INFO -  9 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: encryptedUsername
04:38:22     INFO -  10 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: encryptedPassword
04:38:22     INFO -  11 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: encType
04:38:22     INFO -  12 INFO TEST-PASS | testPasswordProvider | Password was found - true should equal true
04:38:22     INFO -  13 INFO TEST-PASS | testPasswordProvider | Correct number updated - 1 should equal 1
04:38:22     INFO -  14 INFO TEST-PASS | testPasswordProvider | List is correct length - 1 should equal 1
04:38:22     INFO -  15 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: hostname
04:38:22     INFO -  16 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: httpRealm
04:38:22     INFO -  17 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: formSubmitURL
04:38:22     INFO -  18 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: usernameField
04:38:22     INFO -  19 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: passwordField
04:38:22     INFO -  20 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: encryptedUsername
04:38:22     INFO -  21 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: encryptedPassword
04:38:22     INFO -  22 INFO TEST-INFO | testPasswordProvider | Comparing - Column values for: encType
04:38:22     INFO -  23 INFO TEST-PASS | testPasswordProvider | Password was found - true should equal true
04:38:22     INFO -  24 INFO TEST-PASS | testPasswordProvider | Correct number deleted - 1 should equal 1
04:38:22     INFO -  25 INFO TEST-PASS | testPasswordProvider | List is correct length - 0 should equal 0
04:38:22     INFO -  tearDown deleted /mnt/sdcard/tests/profile/signons.sqlite
04:38:22     INFO -  26 INFO TEST-END | testPasswordProvider | finished in 5029ms
04:38:22     INFO -  27 INFO TEST-START | Shutdown
04:38:22     INFO -  28 INFO Passed: 24
04:38:22     INFO -  29 INFO Failed: 0
04:38:22     INFO -  30 INFO Todo: 0

The per-test Passed count reflects the number of TEST-PASS or TEST-INFO lines. I think the test-chunk Passed count reflects only the number of TEST-PASS lines.

Comment 2

[Geoff Brown [:gbrown]]

Attachment: do not include TEST-INFO in per-test Passed count

FennecMochitestAsserter.info() messages (TEST-INFO) were being counted as Passes in robocop, but not by the mochitest harness for the final tally. Traditionally, info() has not been called much, but now all the JavascriptTests use info:

2 INFO TEST-INFO | testJNI | (xpcshell/head.js) - test 1 pending
3 INFO TEST-INFO | testJNI | (xpcshell/head.js) - test 2 pending
4 INFO TEST-INFO | testJNI | testJNI.js - Starting test_JNI

It seems to me that these messages should be ignored for Passed/Failed counts.

Try run at https://tbpl.mozilla.org/?tree=Try&rev=55a8d52d1f48. Using Android 4.0 rc1 as an example, now the Passed counts add up: 3+1+1+14+36+7+6+8+16 = 92

Comment 3

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

Comment on attachment 794636 [details] [diff] [review]
do not include TEST-INFO in per-test Passed count

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

much better!

Comment 4

[Geoff Brown [:gbrown]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1c49896db372

Comment 5

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/1c49896db372