Closed Bug 1378641 Opened 7 years ago Closed 7 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/update/tests/unit_service_updater/invalidArgInstallDirPathTooLongFailureSvc.js | Test timed out

Categories

(Toolkit :: Application Update, defect, P5)

defect

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Assigned: robert.strong.bugs)

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 2 obsolete files)

Attached file relevant log
Very strange... there are a whole bunch of the following in the log for this test but for no other tests. I don't recall seeing that in any update test previously.
WARNING: No active window: file c:/builds/moz2_slave/autoland-w64-d-000000000000000/build/src/js/xpconnect/src/XPCJSContext.cpp, line 538

I suspect this timeout was an anomaly outside of app update because of the above.
Priority: -- → P5
Bill, any idea how this xpcshell test would have repeatedly hit the following?
http://searchfox.org/mozilla-central/source/js/xpconnect/src/XPCJSContext.cpp#538
Flags: needinfo?(wmccloskey)
I think the warning is just a side effect of the test taking a long time. The code that's running is for the slow script dialog. A script that's not associated with a DOM window is taking a long time.
Flags: needinfo?(wmccloskey)
Is there a way to disable it or to extend the time in the test so it won't be triggered?
Flags: needinfo?(wmccloskey)
I think that might be hard since, if I remember correctly, prefs_general.js is not used by xpcshell tests. We could modify xpcshell itself I guess.

In any case, I don't think the warning is a problem. The real issue is that the test is taking a long time.
Flags: needinfo?(wmccloskey)
Checking on the test itself the following are the times for the test setup
18:38:07:894 start - general test setup
18:38:10:623 finish - general test setup
18:40:25:776 start - copying or creating symlinks to application files for the test

https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/tests/unit_service_updater/invalidArgInstallDirPathTooLongFailureSvc.js#12

function run_test() {
This call prints to the log "start - general test setup"
Time 18:38:07:894
  if (!setupTestCommon()) {
    return;
  }
After setupTestCommon finishes it prints to the log "finish - general test setup"
Time 18:38:10:623

Simple assignment
  gTestFiles = gTestFilesCompleteSuccess;

Simple assignment
  gTestDirs = gTestDirsCompleteSuccess;

Enumerates two arrays of objects and changes existing values
Enumeration
https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js#1022
Objects
https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js#420
https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js#734
  setTestFilesAndDirsForFailure();

This call prints to the log "start - copying or creating symlinks to application files for the test" immediately
Time 18:40:25:776
  setupUpdaterTest(FILE_COMPLETE_MAR, false);
}

So, the two assignments and the setting the values of the two arrays containing objects took over 2 minutes and 15 seconds. I really don't think those operations could account for that much time.
It looks like setupUpdaterTest does a lot of stuff before it prints anything.
Thanks and I missed that... looks like it might have taken longer than normal to create files and directories on that system.
Attached patch add more logging (obsolete) — Splinter Review
Matt, this just adds logging to setupUpdaterTest in case this happens again.
Assignee: nobody → robert.strong.bugs
Status: NEW → ASSIGNED
Attachment #8884110 - Flags: review?(mhowell)
A passing test run on Windows 8 x64 debug (takes less than 4 seconds)
16:15:18     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_service_updater/invalidArgInstallDirPathTooLongFailureSvc.js | took 3786ms
16:15:18     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_service_updater/invalidArgInstallDirPathTraversalFailureSvc.js

This test runs sync since it is a service test so other tests shouldn't affect it.

For whatever reason this failing run took over 2 minutes to create directories / files and copying several files used by the test and a passing run takes under 4 seconds to perform the entire test which includes creating those same directories / files and copying several files.
Attachment #8884110 - Flags: review?(mhowell) → review+
Attached patch patch for checkin (obsolete) — Splinter Review
I changed the log location of the "finish - updater test setup" since setupAppFilesAsync can be async and it makes it clearer in the logging what is going on.
debugDump("finish - updater test setup");
setupAppFilesAsync();
Attachment #8884125 - Flags: review+
Attachment #8884110 - Attachment is obsolete: true
Pushed by rstrong@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/7cf1dabb8f3d
add more app update test logging. r=mhowell
Attached patch patch as landedSplinter Review
Attachment #8884125 - Attachment is obsolete: true
Attachment #8884128 - Flags: review+
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → WORKSFORME
Removing leave-open keyword from resolved bugs, per :sylvestre.
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: