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

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

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

Pushed patch to turn on logging to fx-team https://hg.mozilla.org/integration/fx-team/rev/78fb1730c9d3

Staging sometimes takes longer than the test timeout so let's give the tests some extra time to finish.

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.

Pushed to fx-team https://hg.mozilla.org/integration/fx-team/rev/00e7fde96977

Missed a couple of tests that should have the timeout increased.

Comment on attachment 812918 [details] [diff] [review] followup patch Review of attachment 812918 [details] [diff] [review]: ----------------------------------------------------------------- oops, I should have searched for that.

Followup patch pushed to fx-team https://hg.mozilla.org/integration/fx-team/rev/80b700d82742

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.

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?

(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.

Pushed to fx-team https://hg.mozilla.org/integration/fx-team/rev/4336b6ec32a8

That's fine and you can r=me

Thanks and pushed to fx-team https://hg.mozilla.org/integration/fx-team/rev/ef5c1b2b2d42

https://hg.mozilla.org/mozilla-central/rev/4336b6ec32a8 https://hg.mozilla.org/mozilla-central/rev/ef5c1b2b2d42