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

RESOLVED WORKSFORME

Status

()

Toolkit
Application Update
P5
normal
RESOLVED WORKSFORME
a year ago
4 months ago

People

(Reporter: Treeherder Bug Filer, Assigned: rstrong)

Tracking

({intermittent-failure})

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments, 2 obsolete attachments)

Created attachment 8883820 [details]
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.
Created attachment 8884110 [details] [diff] [review]
add more logging

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+
Created attachment 8884125 [details] [diff] [review]
patch for checkin

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
Keywords: leave-open

Comment 12

a year ago
Pushed by rstrong@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/7cf1dabb8f3d
add more app update test logging. r=mhowell
Created attachment 8884128 [details] [diff] [review]
patch as landed
Attachment #8884125 - Attachment is obsolete: true
Attachment #8884128 - Flags: review+
1 failures in 656 pushes (0.002 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows8-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1378641&startday=2017-07-03&endday=2017-07-09&tree=all
Status: ASSIGNED → RESOLVED
Last Resolved: 9 months 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.