Closed Bug 918029 Opened 7 years ago Closed 7 years ago

Intermittent test_0017_check_staging_basic.xul | Test timed out. Maximum time allowed is 180 seconds (and several more)

Categories

(Toolkit :: Application Update, defect)

Product:
Toolkit
Component:
Application Update
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla27
Tracking Flags:
Tracking Status
firefox25 --- unaffected
firefox26 --- unaffected
firefox27 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: KWierso, Assigned: robert.strong.bugs)

Details

(Keywords: crash, intermittent-failure)

Crash Data

Attachments

(6 files, 1 obsolete file)

screenshot.png
647.08 KB, image/png
Details
enable debug logging
790 bytes, patch
robert.strong.bugs
: review+
robert.strong.bugs
: checkin+
Details | Diff | Splinter Review
Increase the timeout for these tests
1.53 KB, patch
bbondy
: review+
Details | Diff | Splinter Review
followup patch
3.31 KB, patch
bbondy
: review+
Details | Diff | Splinter Review
patch - disable tests on linux due to the timeout caused by copying too many files
2.26 KB, patch
bbondy
: review+
Details | Diff | Splinter Review
Remove unneeded slow tests
7.63 KB, patch
robert.strong.bugs
: review+
Details | Diff | Splinter Review
Attached image screenshot.png — 
https://tbpl.mozilla.org/php/getParsedLog.php?id=28039610&tree=Mozilla-Inbound
slave: tst-linux64-ec2-367

08:11:04     INFO -  34980 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0017_check_staging_basic.xul | Test timed out. Maximum time allowed is 90 seconds
08:11:04     INFO -  INFO | automation.py | Launching: /builds/slave/test/build/tests/bin/screentopng
08:11:05     INFO -  Xlib:  extension "RANDR" missing on display ":0".
08:11:10     INFO -  SCREENSHOT: [SEE ATTACHMENT]
08:11:10     INFO -  34981 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0017_check_staging_basic.xul | Checking if TESTS[0] test was performed... callback function name = defaultCallback, pageid = checking
08:11:10     INFO -  34982 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0017_check_staging_basic.xul | Checking if TESTS[1] test was performed... callback function name = defaultCallback, pageid = updatesfoundbasic
08:11:10     INFO -  34983 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0017_check_staging_basic.xul | Checking if TESTS[2] test was performed... callback function name = defaultCallback, pageid = downloading
08:11:10     INFO -  34984 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0017_check_staging_basic.xul | Checking if TESTS[3] test was performed... callback function name = defaultCallback, pageid = finished
08:11:10     INFO -  34985 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0017_check_staging_basic.xul | Found an existing Update Window from the current or a previous test... attempting to close it.
08:11:10     INFO -  --DOCSHELL 0x941c4d0 == 41 [id = 847]
08:11:10     INFO -  34986 INFO TEST-END | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0017_check_staging_basic.xul | finished in 91364ms

08:11:44     INFO -  36835 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking cancel button disabled attribute value equals true
08:11:44     INFO -  Xlib:  extension "RANDR" missing on display ":0".
08:11:44     INFO -  36836 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking currentPage.pageid equals finished in pageshow - got errors, expected finished
08:11:44     INFO -  36837 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking currentPage.pageid equals finished after executeSoon - got errors, expected finished
08:11:44     INFO -  36838 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking extra1 button hidden attribute value equals false - got true, expected false
08:11:44     INFO -  36839 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking extra1 button disabled attribute value equals false - got true, expected false
08:11:44     INFO -  36840 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking extra2 button hidden attribute value equals true
08:11:44     INFO -  36841 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking extra2 button disabled attribute value equals true
08:11:44     INFO -  36842 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking back button hidden attribute value equals true
08:11:44     INFO -  36843 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking back button disabled attribute value equals true
08:11:44     INFO -  36844 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking next button hidden attribute value equals true
08:11:44     INFO -  36845 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking next button disabled attribute value equals true
08:11:44     INFO -  36846 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking finish button hidden attribute value equals false
08:11:44     INFO -  36847 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking finish button disabled attribute value equals false
08:11:44     INFO -  36848 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking cancel button hidden attribute value equals true
08:11:44     INFO -  36849 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking cancel button disabled attribute value equals true
08:11:44     INFO -  [Parent 2370] WARNING: waitpid failed pid:2713 errno:10: file ../../../ipc/chromium/src/base/process_util_posix.cc, line 251

08:13:13     INFO -  36850 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Test timed out. Maximum time allowed is 90 seconds
08:13:13     INFO -  Not taking screenshot here: see the one that was previously logged
08:13:13     INFO -  36851 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking if TESTS[0] test was performed... callback function name = defaultCallback, pageid = updatesfoundbasic
08:13:13     INFO -  36852 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking if TESTS[1] test was performed... callback function name = defaultCallback, pageid = downloading
08:13:13     INFO -  36853 INFO TEST-PASS | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Checking if TESTS[2] test was performed... callback function name = defaultCallback, pageid = finished
08:13:13     INFO -  36854 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | Found an existing Update Window from the current or a previous test... attempting to close it.
08:13:13     INFO -  --DOCSHELL 0x7016260 == 41 [id = 889]
08:13:13     INFO -  36855 INFO TEST-END | chrome://mochitests/content/chrome/toolkit/mozapps/update/test/chrome/test_0037_available_staging_basic.xul | finished in 90371ms

08:16:07     INFO -  --DOMWINDOW == 99 (0x11a25598) [serial = 4895] [outer = (nil)] [url = chrome://mochitests/content/chrome/widget/tests/test_position_on_resize.xul]
08:16:07     INFO -  nsStringStats
08:16:07     INFO -   => mAllocCount:            235
08:16:07     INFO -   => mReallocCount:            1
08:16:07     INFO -   => mFreeCount:             235
08:16:07     INFO -   => mShareCount:            165
08:16:07     INFO -   => mAdoptCount:              0
08:16:07     INFO -   => mAdoptFreeCount:          0
08:16:07     INFO -  [Parent 2370] WARNING: NS_ENSURE_TRUE(mDB) failed: file ../../../netwerk/cache/nsDiskCacheDeviceSQL.cpp, line 1396
08:16:07     INFO -  [Parent 2370] WARNING: waitpid failed pid:2713 errno:10: file ../../../ipc/chromium/src/base/process_util_posix.cc, line 251
08:16:07     INFO -  [Parent 2370] WARNING: NS_ENSURE_TRUE(mThread != PR_GetCurrentThread()) failed: file ../../../xpcom/threads/nsThread.cpp, line 435
08:21:37  WARNING -  TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
08:21:37     INFO -  Not taking screenshot here: see the one that was previously logged
08:21:38     INFO -  INFO | automation.py | Application ran for: 0:32:29.104667
08:21:38     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpobTQfzpidlog
08:21:38     INFO -  ==> process 2370 launched child process 2417
08:21:38     INFO -  ==> process 2370 launched child process 2448
08:21:38     INFO -  ==> process 2370 launched child process 2457
08:21:38     INFO -  ==> process 2370 launched child process 2462
08:21:38     INFO -  ==> process 2370 launched child process 2466
08:21:38     INFO -  ==> process 2370 launched child process 2470
08:21:38     INFO -  ==> process 2370 launched child process 2475
08:21:38     INFO -  ==> process 2370 launched child process 2713
08:21:38     INFO -  ==> process 2370 launched child process 2717
08:21:38     INFO -  ==> process 2370 launched child process 2721
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2417
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2448
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2457
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2462
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2466
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2470
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2475
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2713
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2717
08:21:38     INFO -  INFO | zombiecheck | Checking for orphan process with PID: 2721
08:21:45  WARNING -  PROCESS-CRASH | Shutdown | application crashed [@ libpthread-2.15.so + 0xbd84]
08:21:45     INFO -  Crash dump filename: /tmp/tmp1_vJTV/minidumps/6dd51a04-f260-9863-4af194cc-1415465b.dmp
08:21:45     INFO -  Operating system: Linux
08:21:45     INFO -                    0.0.0 Linux 3.2.0-23-generic #36-Ubuntu SMP Tue Apr 10 20:39:51 UTC 2012 x86_64
08:21:45     INFO -  CPU: amd64
08:21:45     INFO -       family 6 model 45 stepping 7
08:21:45     INFO -       1 CPU
08:21:45     INFO -  Crash reason:  SIGABRT
08:21:45     INFO -  Crash address: 0x3e800000927
08:21:45     INFO -  Thread 0 (crashed)
08:21:45     INFO -   0  libpthread-2.15.so + 0xbd84
08:21:45     INFO -      rbx = 0x00000000015ea400   r12 = 0x00000000015303e0
08:21:45     INFO -      r13 = 0x00007f4d659bd740   r14 = 0x00000000ffffffff
08:21:45     INFO -      r15 = 0x00000000015eaba8   rip = 0x00007f4d655a8d84
08:21:45     INFO -      rsp = 0x00007fff484dcd00   rbp = 0x00007fff484dcd60
08:21:45     INFO -      Found by: given as instruction pointer in context
The crash is likely bug 763952 or one of the other libpthread-2.15.so crashes https://bugzilla.mozilla.org/buglist.cgi?quicksearch=libpthread-2.15.so

This test has been extremely stable and I suspect that whatever is causing the libpthread-2.15.so crash is also causing this test failure.
I got an r+ from bbondy over irc to turn on debug logging for these tests
Assignee: nobody → robert.bugzilla
Status: NEW → ASSIGNED
Attachment #811413 - Flags: review+
Pushed to fx-team
https://hg.mozilla.org/integration/fx-team/rev/d3c5c7c61894

This will hopefully help with figuring out what is going on... please leave open
Whiteboard: [leave open]
I backed out the changeset since it looks like it made this bug happen on OSX as well. Hopefully the OSX log will help figure this out.
bah... it was a different failure and I didn't need to back out
Attachment #812390 - Flags: review?(netzen)
Staging sometimes takes longer than the test timeout so let's give the tests some extra time to finish.
Attachment #812390 - Attachment is obsolete: true
Attachment #812390 - Flags: review?(netzen)
Attachment #812391 - Flags: review?(netzen)
BTW: I am very certain this is due to having to copy the bin dir when staging the update and that is why I initially set the timeout to 90 seconds.
Attachment #812391 - Flags: review?(netzen) → review+
Pushed to fx-team
https://hg.mozilla.org/integration/fx-team/rev/00e7fde96977
Flags: in-testsuite+
Whiteboard: [leave open]
Target Milestone: --- → mozilla27
https://hg.mozilla.org/mozilla-central/rev/00e7fde96977
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Attached patch followup patch — — Splinter Review 
Missed a couple of tests that should have the timeout increased.
Attachment #812918 - Flags: review?(netzen)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Comment on attachment 812918 [details] [diff] [review]
followup patch

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

oops, I should have searched for that.
Attachment #812918 - Flags: review?(netzen) → review+
https://hg.mozilla.org/mozilla-central/rev/80b700d82742
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
Still failing with 180 as the timeout. Since the maximum is 330 I will up the timeout to 320 and if that is not enough perhaps disable some of these on linux.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Summary: Intermittent TEST-UNEXPECTED-FAIL | test_0017_check_staging_basic.xul | Test timed out. Maximum time allowed is 90 seconds | Checking if TESTS[3] test was performed... callback function name = defaultCallback → Intermittent TEST-UNEXPECTED-FAIL | test_0017_check_staging_basic.xul | Test timed out. Maximum time allowed is 180 seconds | Checking if TESTS[3] test was performed... callback function name = defaultCallback
Summary: Intermittent TEST-UNEXPECTED-FAIL | test_0017_check_staging_basic.xul | Test timed out. Maximum time allowed is 180 seconds | Checking if TESTS[3] test was performed... callback function name = defaultCallback, pageid = finished |and more updater failures → Intermittent test_0017_check_staging_basic.xul | Test timed out. Maximum time allowed is 180 seconds (and several more)
Brian, since these tests take a long time to run due to the copying of dist/bin to the updated dir what do you think about removing all but one of them as well?
Attachment #817646 - Flags: review?(netzen)
Attachment #817646 - Flags: review?(netzen) → review+
(In reply to Robert Strong [:rstrong] (do not email) from comment #100)
> Created attachment 817646 [details] [diff] [review]
> patch - disable tests on linux due to the timeout caused by copying too many
> files
> 
> Brian, since these tests take a long time to run due to the copying of
> dist/bin to the updated dir what do you think about removing all but one of
> them as well?

Do you mean removing completely or just disabling? If disabling is it just temporary?
Would it be possible to somehow keep them enabled when running locally but not from talos machines?
Removing completely. I added this test for the staging phase UI and since the test takes quite a while to copy dist/bin along with the code being tested being the same for the other cases I don't think it would hurt.
That's fine and you can r=me
https://hg.mozilla.org/mozilla-central/rev/4336b6ec32a8
https://hg.mozilla.org/mozilla-central/rev/ef5c1b2b2d42
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.