Robocop test pass count is wrong sometimes

RESOLVED FIXED in mozilla26

Status

Testing
Mochitest
RESOLVED FIXED
4 years ago
4 years ago

People

(Reporter: gbrown, Assigned: gbrown)

Tracking

unspecified
mozilla26
x86
Android
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

(Assignee)

Description

4 years ago
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
(Assignee)

Comment 1

4 years ago
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.
(Assignee)

Comment 2

4 years ago
Created attachment 794636 [details] [diff] [review]
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
Attachment #794636 - Flags: review?(jmaher)
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!
Attachment #794636 - Flags: review?(jmaher) → review+
(Assignee)

Comment 4

4 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/1c49896db372
Assignee: nobody → gbrown
https://hg.mozilla.org/mozilla-central/rev/1c49896db372
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla26
You need to log in before you can comment on or make changes to this bug.