1501196 - Intermittent services/sync/tests/unit/test_service_wipeServer.js | xpcshell return code: 1

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=207204982&repo=autoland

https://queue.taskcluster.net/v1/task/MyLDjY1kS-C256dOzRw1cw/runs/0/artifacts/public/logs/live_backing.log

7:46:24     INFO -  TEST-START | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging.js
07:46:26     INFO -  TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging.js | took 1752ms
07:46:26     INFO -  TEST-START | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js
07:46:30     INFO -  TEST-PASS | toolkit/components/extensions/test/xpcshell/test_ext_native_messaging_perf.js | took 3886ms
07:46:30     INFO -  TEST-START | services/sync/tests/unit/test_service_wipeServer.js
07:47:33  WARNING -  TEST-UNEXPECTED-FAIL | services/sync/tests/unit/test_service_wipeServer.js | xpcshell return code: 1
07:47:33     INFO -  TEST-INFO took 62987ms
07:47:33     INFO -  >>>>>>>
07:47:33     INFO -  PID 11112 | JavaScript strict warning: Z:/task_1540279370/build/tests/xpcshell/tests/services/sync/tests/unit/head_helpers.js -> resource://testing-common/sinon-2.3.2.js, line 8941: ReferenceError: reference to undefined property "iso-8859-8-i"
07:47:33     INFO -  PID 11112 | JavaScript strict warning: resource://services-sync/policies.js, line 120: ReferenceError: reference to undefined property "_globalScore"
...
7:47:33     INFO -  PID 11112 | 1540280793117	Toolkit.ProfileAge	DEBUG	Using date: c:\\users\\task_1540279370\\appdata\\local\\temp\\xpc-profile-wr25m0\\startupCache = Tue Oct 23 2018 07:46:30 GMT+0000 (Greenwich Mean Time)
07:47:33     INFO -  PID 11112 | 1540280793119	Toolkit.ProfileAge	DEBUG	Using date: c:\\users\\task_1540279370\\appdata\\local\\temp\\xpc-profile-wr25m0\\times.json = Tue Oct 23 2018 07:46:32 GMT+0000 (Greenwich Mean Time)
07:47:33     INFO -  <<<<<<<
07:47:33     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/eFdJZz4_SMyGKHUXkSnt0w/artifacts/public/build/target.crashreporter-symbols.zip
07:47:36     INFO -  mozcrash Copy/paste: Z:\task_1540279370\build\win32-minidump_stackwalk.exe c:\users\task_1540279370\appdata\local\temp\xpc-other-mrixuw\0d606433-0d0e-4cbb-b09e-bb0b4d9cb261.dmp c:\users\task_1540279370\appdata\local\temp\tmpbileqr
07:47:37     INFO -  mozcrash Saved minidump as Z:\task_1540279370\build\blobber_upload_dir\0d606433-0d0e-4cbb-b09e-bb0b4d9cb261.dmp
07:47:37     INFO -  mozcrash Saved app info as Z:\task_1540279370\build\blobber_upload_dir\0d606433-0d0e-4cbb-b09e-bb0b4d9cb261.extra
07:47:37  WARNING -  PROCESS-CRASH | services/sync/tests/unit/test_service_wipeServer.js | application crashed [@ xul.dll + 0x34c7f4d]
07:47:37     INFO -  Crash dump filename: c:\users\task_1540279370\appdata\local\temp\xpc-other-mrixuw\0d606433-0d0e-4cbb-b09e-bb0b4d9cb261.dmp
07:47:37     INFO -  Operating system: Windows NT
07:47:37     INFO -                    10.0.15063
07:47:37     INFO -  CPU: amd64
07:47:37     INFO -       family 6 model 63 stepping 2
07:47:37     INFO -       8 CPUs
07:47:37     INFO -  GPU: UNKNOWN
07:47:37     INFO -  Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
07:47:37     INFO -  Crash address: 0x0
07:47:37     INFO -  Process uptime: 63 seconds
07:47:37     INFO -  Thread 0 (crashed)
07:47:37     INFO -   0  xul.dll + 0x34c7f4d
07:47:37     INFO -      rax = 0x0000000000000001   rdx = 0x0000000000000000
07:47:37     INFO -      rcx = 0x0000000000000000   rbx = 0x000001e75d207708
07:47:37     INFO -      rsi = 0x000001e75d207700   rdi = 0x000001e76787d0a8
07:47:37     INFO -      rbp = 0x0000000000000000   rsp = 0x00000070c31feac0
07:47:37     INFO -       r8 = 0x000001e768a010a0    r9 = 0x000001e769101449
07:47:37     INFO -      r10 = 0x0000000000000000   r11 = 0x000001e75d100100
07:47:37     INFO -      r12 = 0x00007ffd38fd6387   r13 = 0x00000000ffffffff
07:47:37     INFO -      r14 = 0x000001e75d234310   r15 = 0x0000000000000001
07:47:37     INFO -      rip = 0x00007ffd376a7f4d
07:47:37     INFO -      Found by: given as instruction pointer in context
07:47:37     INFO -  Thread 1
07:47:37     INFO -   0  ntdll.dll!NtRemoveIoCompletion + 0x14
07:47:37     INFO -      rax = 0xfffffffffffffffe   rdx = 0x000001e75d203100
07:47:37     INFO -      rcx = 0xfffffffffffffffe   rbx = 0x00000070c39ffdb0
07:47:37     INFO -      rsi = 0x000001e75d238100   rdi = 0x00000070c39ffdc4
07:47:37     INFO -      rbp = 0x00000070c39ffdc4   rsp = 0x00000070c39ffcf8
07:47:37     INFO -       r8 = 0x0000000000000074    r9 = 0x000000000000000f
07:47:37     INFO -      r10 = 0x00000070c39ffd18   r11 = 0x000001e75d203100
07:47:37     INFO -      r12 = 0x00000000000000c4   r13 = 0x0000000000000000
07:47:37     INFO -      r14 = 0x00007ffd66445530   r15 = 0x000001e75d238120
07:47:37     INFO -      rip = 0x00007ffd676654d4
07:47:37     INFO -      Found by: given as instruction pointer in context
07:47:37     INFO -   1  KERNELBASE.dll!LdrResGetRCConfig + 0x3ff
07:47:37     INFO -      rbx = 0x00000070c39ffdb0   rbp = 0x00000070c39ffdc4
07:47:37     INFO -      rsp = 0x00000070c39ffd00   r12 = 0x00000000000000c4
07:47:37     INFO -      r13 = 0x0000000000000000   r14 = 0x00007ffd66445530
07:47:37     INFO -      r15 = 0x000001e75d238120   rip = 0x00007ffd63e89aff

Comment 1

[Raul Gurzau (:RaulG)]

Performed some r/b here: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=windows%2C10%2Cx64%2Cpgo%2Cxpcshell%2Ctests%2Ctest-windows10-64-pgo%2Fopt-xpcshell%2Cx%28x%29&tochange=b7b09fca2cc5c9b06ecf3a4fb4494b9a867d4541&fromchange=7884434cdddeaa4c763168db3524cd785486b10d&selectedJob=207414626

And this failure seems to have started with Bug 1499554

Comment 2

[Intermittent Failures Robot]

15 failures in 496 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:
* autoland: 10
* mozilla-central: 2
* mozilla-inbound: 3

Platform breakdown:
* windows10-64: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1501196&startday=2018-10-24&endday=2018-10-24&tree=all

Comment 3

[Eliza Balazs [:ebalazs_]]

rhunt: Hi, This frequent failing test seems to be related to Bug 1499554. Please see Comment 1.

Comment 4

[Intermittent Failures Robot]

17 failures in 448 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 3
* autoland: 12
* mozilla-central: 1
* try: 1

Platform breakdown:
* windows10-64: 17

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1501196&startday=2018-10-25&endday=2018-10-25&tree=all

Comment 5

[Intermittent Failures Robot]

61 failures in 2584 pushes (0.024 failures/push) were associated with this bug in the last 7 days.

This is the #31 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 41
* try: 2
* mozilla-inbound: 12
* mozilla-central: 6

Platform breakdown:
* windows10-64: 61

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1501196&startday=2018-10-22&endday=2018-10-28&tree=all

Comment 6

[Ryan Hunt [:rhunt] (on leave until early May)]

I've been investigating this, but don't have any answers yet. It's definitely related to bug 1501197.

The crash is happening in shutdown, and seems to be happening in RuntimeService::NoteIdleThread [1]. I have no idea how enabling the GPU process in some xpcshell tests could have caused this. Maybe some timings have changed.

I've ran through the shutdown code and the stack traces I could find for this crash, and nothing really makes sense.

I've been working on a couple of try runs to get more information. One with a speculative fix that didn't work [2]. Another trying to reproduce with force enabling the GPU process on linux so we could use RR [3]. And now one adding a bunch of logging to find what order of events are happening [4].

I'm leaving the ni? as I'm still working on this.

[1] https://searchfox.org/mozilla-central/rev/8848b9741fc4ee4e9bc3ae83ea0fc048da39979f/dom/workers/RuntimeService.cpp#2475
[2] https://treeherder.mozilla.org/#/jobs?repo=try&revision=9518c9f3a5988d12925a1a3c49b9122b730847fb
[3] https://treeherder.mozilla.org/#/jobs?repo=try&revision=af02fa27e32900dff7c04e154690f752649a7040
[4] https://treeherder.mozilla.org/#/jobs?repo=try&revision=e8a64ce42d363ce18a7d5eef2bb1d92d4db7fa4f

Comment 7

[Ryan Hunt [:rhunt] (on leave until early May)]

I've got a patch that fixes this. [1]

[1] https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=208695616&revision=0ca7e9fd3744f75ec84dffe30f5e17d45e4841b9

Comment 8

[Ryan Hunt [:rhunt] (on leave until early May)]

Attachment: Bug 1501196 - Ensure RuntimeService::Shutdown() is always called. r?baku

It's possible for RuntimeService to be created after 'xpcom-shutdown' has fired. In this case, it
will receive 'xpcom-shutdown-threads' and perform Cleanup() but not Shutdown(). This means that
mShuttingDown will not be set to 'true', but mIdleThreadTimer will be destroyed. This can cause
crashes if a NoteIdleThread callback runs after Cleanup(). This has been observed to happen in
xpcshell tests.

I think the easiest way to handle this is to manually call Shutdown() in Cleanup() when we
see that mShuttingDown == false. This means that Shutdown() might be called in GetOrCreateService()
if we fail to create the service, but it looks like the code can handle this.

Comment 9

[Ryan Hunt [:rhunt] (on leave until early May)]

For reference, here's a try run with logging for the sequence of events that lead to this crash. [1]

[1] https://treeherder.mozilla.org/logviewer.html#?job_id=208661122&repo=try&lineNumber=10434

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e28fa79bc2f9
Ensure RuntimeService::Shutdown() is always called. r=baku

Comment 11

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/e28fa79bc2f9

Comment 12

[Eliza Balazs [:ebalazs_]]

Backed out changeset e28fa79bc2f9 (Bug 1501196) for suspicion of causing Bug 1503757. a=backout

Backout push: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&resultStatus=testfailed%2Cbusted%2Cexception%2Cusercancel%2Crunnable&revision=3cff4bff1c9d8e65e73a966fe09c4e5aa1ed734a

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/mozilla-central/rev/182a1b088330
Ensure RuntimeService::Shutdown() is always called. r=baku a=reland

Comment 14

[Eliza Balazs [:ebalazs_]]

This was relanded, see Comment 13.

Comment 15

[Intermittent Failures Robot]

38 failures in 2978 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* mozilla-central: 4
* autoland: 19
* oak: 1
* mozilla-inbound: 13
* try: 1

Platform breakdown:
* windows10-64: 37
* windows10-64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1501196&startday=2018-10-29&endday=2018-11-04&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 2602 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1501196&startday=2019-02-18&endday=2019-02-24&tree=all

Comment 17

[Intermittent Failures Robot]

2 failures in 2771 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 2

Platform breakdown:

• windows10-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1501196&startday=2019-03-11&endday=2019-03-17&tree=all

Comment 18

[Intermittent Failures Robot]

3 failures in 3910 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 3

Platform breakdown:

• windows10-64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1501196&startday=2019-03-25&endday=2019-03-31&tree=all