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

Status: RESOLVED FIXED

(Thunderbird :: General, defect)

Description

[Jorg K (CEST = GMT+2)]

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

when run in Thunderbird on Windows only.

M-C last good: c9f6d6242851d25e230bc6a81fb45bfc8f
M-C first bad: d94d73fcec772472f47a3b29f5bf6addd4
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=c9f6d6242851d25e230bc6a81fb45bfc8f&tochange=d94d73fcec772472f47a3b29f5bf6addd4
long regression range due to missing builds caused by build bustages :-(

Could be
3d22697d9c23 Kirk Steuber - Bug 1458314 - Move the update directory to an installation specific location r=rstrong
and our not-yet-complete port in bug 1501792.

Comment 1

[Jorg K (CEST = GMT+2)]

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=f4f5f2f0e706f73bfa37abdbd5909cbd467698ee

Comment 2

[Jorg K (CEST = GMT+2)]

https://taskcluster-artifacts.net/XpITAE5CTPGYF-4hJmM8Rw/0/public/logs/live_backing.log

says:

19:07:22     INFO -  "19:02:23:807 | TEST-INFO | ../data/xpcshellUtilsAUS.js | [stageUpdate : 2191] finish - attempting to stage update"
19:07:22     INFO -  (xpcshell/head.js) | test setupUpdaterTestFinished finished (2)
19:07:22     INFO -  PID 9168 | *** AUS:SVC readStatusFile - status: applied, path: C:\\ProgramData\\Thunderbird\\updates\\marStageSuccessCompleteSvc\\updates\\0\\update.status
19:07:22     INFO -  PID 9168 | *** AUS:SVC isServiceInstalled - returning true
19:07:22     INFO -  PID 9168 | *** AUS:SVC shouldUseService - returning true
19:07:22     INFO -  PID 9168 | [9168, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520015: file z:/build/build/src/netwerk/base/nsFileStreams.cpp, line 263
19:07:22     INFO -  PID 9168 | [9168, Main Thread] WARNING: writing to output stream failed! data may be lost: file z:/build/build/src/netwerk/base/nsFileStreams.cpp, line 921
19:07:22     INFO -  PID 9168 | *** AUS:SVC Unable to write to critical update file: C:\\ProgramData\\Thunderbird\\updates\\marStageSuccessCompleteSvc\\updates\\0\\update.status
19:07:22     INFO -  PID 9168 | JavaScript error: jar:file:///Z:/task_1540493232/build/application/thunderbird/omni.ja!/components/nsUpdateService.js, line 1106: NS_ERROR_XPC_CANT_MODIFY_PROP_ON_WN: Cannot modify properties of a WrappedNative
19:07:22     INFO -  "CONSOLE_MESSAGE: (info) AUS:SVC readStatusFile - status: applied, path: C:\\ProgramData\\Thunderbird\\updates\\marStageSuccessCompleteSvc\\updates\\0\\update.status"
19:07:22     INFO -  "CONSOLE_MESSAGE: (info) AUS:SVC isServiceInstalled - returning true"
19:07:22     INFO -  "CONSOLE_MESSAGE: (info) AUS:SVC shouldUseService - returning true"
19:07:22     INFO -  "CONSOLE_MESSAGE: (info) AUS:SVC Unable to write to critical update file: C:\\ProgramData\\Thunderbird\\updates\\marStageSuccessCompleteSvc\\updates\\0\\update.status"
19:07:22     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_XPC_CANT_MODIFY_PROP_ON_WN: Cannot modify properties of a WrappedNative" {file: "jar:file:///Z:/task_1540493232/build/application/thunderbird/omni.ja!/components/nsUpdateService.js" line: 1106}]"
19:07:22     INFO -  <<<<<<<
19:07:23     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 9168: error 5
19:07:23     INFO -  xpcshell return code: None
19:07:23     INFO -  toolkit/mozapps/update/tests/unit_service_updater/marStageSuccessCompleteSvc.js | Process still running after test!
19:07:23  WARNING -  TEST-UNEXPECTED-FAIL | Received SIGINT (control-C), so stopped run. (Use --keep-going to keep running tests after killing one with SIGINT)

Hmm, so something in nsUpdateService.js fails and that was last changed in bug 1458314.

Kirk, how can I work out what's going on here?

Comment 3

[Robin Steuber (she/her) [:bytesized]]

Well, it looks to me like the error code that you are getting when attempting to write the file (0x80520015) is an access denied error [1].

This looks to me like the exact problem that we had where the update directory that we are switching to already exists in the test image with permissions that prevent us from writing to it or even adjusting the permissions. We ended up filing Bug 1494048 and ultimately had this resolved by adjusting the test image permissions to allow us to write to that directory.

Can you find out if the test image being used to run these tests has the same issue that ours had? I am guessing that that is the problem.

[1] https://searchfox.org/mozilla-central/source/__GENERATED__/xpcom/base/ErrorList.h#245

Comment 4

[Jorg K (CEST = GMT+2)]

Thanks Kirk, interesting reply :-)

(In reply to Kirk Steuber [:bytesized] from comment #3)
> Can you find out if the test image being used to run these tests has the
> same issue that ours had?
I wouldn't know how. Maybe if I understood the question. By "image" you mean the executable? Since TB is just a "recompilation" of FF, I assume that the executable will have the same permissions.

I can see the problem now.
https://github.com/mozilla-releng/OpenCloudConfig/commit/89327b90f836308baf2689de6bb670b99a2f6445
grants permissions to c:\\ProgramData\\Mozilla but our stuff accesses C:\\ProgramData\\Thunderbird as you can see in comment #2.

Rob, this is becoming a build/release/infra issue. Can you please take over here and get something similar to
https://github.com/mozilla-releng/OpenCloudConfig/commit/89327b90f836308baf2689de6bb670b99a2f6445
and of necessary
https://github.com/mozilla-releng/OpenCloudConfig/commit/e9cfd9fec435b32792ad4398243f70d04a0c38e0
going for Thunderbird.

Comment 5

[Rob Lemley [:rjl]]

I'll look into it and report back here as progress is made.

Comment 6

[Jorg K (CEST = GMT+2)]

Rob, please note bug 1501792 comment #11:
  I have a fix for the test failure and should have it fixed by no later than Monday.

I'm not sure what is meant by that, but let's wait until it becomes clearer.

Comment 7

[Jorg K (CEST = GMT+2)]

Rob, no further action required here, see 1501792 comment #13 and bug 1502681.

Comment 8

[Jorg K (CEST = GMT+2)]

Not seen after bug 1502681 landed.