Closed Bug 825722 Opened 12 years ago Closed 12 years ago

Intermittent end-of-year timebomb and intermittent failure that piled on in test_incoming.js: TEST-UNEXPECTED-FAIL | false was false, expected true | got false, expected true

Categories

(Core :: DOM: Device Interfaces, defect)

Product:
Core
Component:
DOM: Device Interfaces
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla22

People

(Reporter: philor, Assigned: rwood)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Updated incoming SMS test
2.16 KB, patch
jgriffin
: review+
Details | Diff | Splinter Review
+++ This bug was initially created as a clone of Bug #760199 +++ Not immediately obvious (to someone who is terrible at time and timezone math) why, but test_incoming.js seems to have an end-of-year (or a 2013) timebomb bug - every run since it became January 1 in GMT (including runs on pushes which previously passed) has failed like https://tbpl.mozilla.org/php/getParsedLog.php?id=18381079&tree=Mozilla-Inbound b2g_ics_armv7a_gecko_emulator mozilla-inbound opt test marionette-webapi on 2012-12-31 19:30:00 PST for push b3993179ea52 slave: talos-r3-fed-043 19:36:50 INFO - TEST-START test_incoming.js 19:36:51 INFO - /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/sms/tests/marionette/test_incoming.js, runTest (marionette_test.MarionetteJSTestCase) ... FAIL 19:36:51 INFO - ====================================================================== 19:36:51 INFO - FAIL: /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/sms/tests/marionette/test_incoming.js, runTest (marionette_test.MarionetteJSTestCase) 19:36:51 INFO - ---------------------------------------------------------------------- 19:36:51 ERROR - Traceback (most recent call last): 19:36:51 INFO - File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette_test.py", line 229, in runTest 19:36:51 INFO - '%d tests failed:\n%s' % (results['failed'], '\n'.join(fails))) 19:36:51 INFO - AssertionError: 1 tests failed: 19:36:51 INFO - TEST-UNEXPECTED-FAIL | test_incoming.js | false was false, expected true | got false, expected true 19:36:51 INFO - START LOG: 19:36:51 INFO - INFO TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/sms/tests/marionette/test_incoming.js Tue Jan 01 2013 03:36:39 GMT+0000 (GMT) 19:36:51 INFO - INFO Sent fake SMS: OK Tue Jan 01 2013 03:36:40 GMT+0000 (GMT) 19:36:51 INFO - INFO Received an SMS! Tue Jan 01 2013 03:36:40 GMT+0000 (GMT) 19:36:51 INFO - END LOG: ... 19:41:02 INFO - I/Gecko ( 299): 1357011400016 Marionette INFO sendToClient: {"emulator_cmd":"sms send 5555552368 Hello SMS world!","id":163}, undefined, {b7b62902-3f92-4f79-b4d9-f59ee10373a5} 19:41:02 INFO - I/Gecko ( 299): 1357011400025 Marionette WARN got a response with no command_id 19:41:02 INFO - I/Gecko ( 299): MARIONETTE LOG: INFO: Sent fake SMS: OK 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - OK should equal OK 19:41:02 INFO - I/Gecko ( 299): MARIONETTE LOG: INFO: Received an SMS! 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - true was false, expected true 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - received should equal received 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - success should equal success 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - 5555552368 should equal 5555552368 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - null should equal null 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - Hello SMS world! should equal Hello SMS world! 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - normal should equal normal 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-PASS | test_incoming.js | undefined - true was false, expected true 19:41:02 INFO - I/Gecko ( 299): MARIONETTE TEST RESULT:TEST-UNEXPECTED-FAIL | test_incoming.js | undefined - false was false, expected true https://tbpl.mozilla.org/php/getParsedLog.php?id=18381288&tree=Mozilla-Inbound https://tbpl.mozilla.org/php/getParsedLog.php?id=18379758&tree=Mozilla-Aurora https://tbpl.mozilla.org/php/getParsedLog.php?id=18380846&tree=Mozilla-Aurora https://tbpl.mozilla.org/php/getParsedLog.php?id=18381223&tree=Mozilla-Aurora https://tbpl.mozilla.org/php/getParsedLog.php?id=18379235&tree=Firefox https://tbpl.mozilla.org/php/getParsedLog.php?id=18381200&tree=Firefox https://tbpl.mozilla.org/php/getParsedLog.php?id=18381272&tree=Firefox
And since it started passing again once it became 2013 in Mountain View Time, apparently it is just an end-of-year timebomb.
Summary: Permaorange test_incoming.js: TEST-UNEXPECTED-FAIL | false was false, expected true | got false, expected true → Intermittent end-of-year timebomb in test_incoming.js: TEST-UNEXPECTED-FAIL | false was false, expected true | got false, expected true
Incoming SMS timestamps are determined by the SMSC, not the device/emulator timestamp. Perhaps there was an issue with the SMSC at the new year switch-over. The actual timestamps compared by the test unfortunately are not printed in the logs so I can't confirm that the SMSC did or did not provide a valid timestamp while this test was failing. I will update the test to log the actual timestamps so if a similar issue happens again we can see the SMSC value.
It seems the end of the year is coming in March :|
As you can see, I like a little more verbosity with my logging, but there you go - off by 1.
Summary: Intermittent end-of-year timebomb in test_incoming.js: TEST-UNEXPECTED-FAIL | false was false, expected true | got false, expected true → Intermittent end-of-year timebomb and intermittent failure that piled on in test_incoming.js: TEST-UNEXPECTED-FAIL | false was false, expected true | got false, expected true
If we can't reliably compare the SMS timestamps, should we just drop this comparison?
Flags: needinfo?(rwood)
Yes I agree, since it looks like it is quite unreliable. I will make a patch.
Flags: needinfo?(rwood)
Removed timestamp comparison, improved logging.
Assignee: nobody → rwood
Status: NEW → ASSIGNED
Attachment #729164 - Flags: review?(jgriffin)
Comment on attachment 729164 [details] [diff] [review] Updated incoming SMS test Review of attachment 729164 [details] [diff] [review]: ----------------------------------------------------------------- Cool, thanks. Intermittent oranges -1!
Attachment #729164 - Flags: review?(jgriffin) → review+
:) thanks Jonathan Pushed to try: https://tbpl.mozilla.org/?tree=Try&rev=0e5c28bfcd53
https://hg.mozilla.org/mozilla-central/rev/fabc285294b5
Status: ASSIGNED → RESOLVED
Closed: 12 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla22
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: