1505772 - Intermittent - services/sync/tests/unit/test_service_wipeServer.js | Test timed out when Gecko 65 merges to Beta on 2018-12-03

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect, P1)

Description

[Stefan Hindli [:stefan_hindli]]

[Tracking Requested - why for this release]:

This occurs only on late beta: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&tochange=e002ac26fe2fa2e4e079dba4ff71cde2e35d0636&fromchange=667ddffc382ff2864cd02d4bd4d2f25c4e74dd85&selectedJob=210565392

https://treeherder.mozilla.org/logviewer.html#?job_id=210565392&repo=try&lineNumber=11345

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Two previous occurrences, also for beta simulations:

Oct 23rd 2018
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e89a18702b2ac45df87c768dd48b2b1857b9307a&selectedJob=207268997

Oxt 26th 2018
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8d8f3bcc6f80cb19ce0f6c00f6846405a6fd836c&selectedJob=208017104

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://treeherder.mozilla.org/logviewer.html#?job_id=207268997&repo=try&lineNumber=10620

14:36:37     INFO -  TEST-START | services/sync/tests/unit/test_load_modules.js
14:41:37  WARNING -  TEST-UNEXPECTED-TIMEOUT | services/sync/tests/unit/test_load_modules.js | Test timed out
14:41:37     INFO -  TEST-INFO took 300000ms
14:41:37     INFO -  >>>>>>>
14:41:37     INFO -  PID 10328 | JavaScript strict warning: Z:/task_1540303685/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"
14:41:37     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/addonutils.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/addonsreconciler.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/browserid_identity.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/constants.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/addons.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/bookmarks.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/clients.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/extension-storage.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/forms.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/history.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/passwords.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/prefs.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines/tabs.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/engines.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/keys.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/main.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/policies.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/record.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/resource.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/service.js
14:41:37     INFO -  PID 10328 | JavaScript strict warning: resource://services-sync/policies.js, line 120: ReferenceError: reference to undefined property "_globalScore"
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/stages/declined.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/stages/enginesync.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/status.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://services-sync/util.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://testing-common/services/sync/fakeservices.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://testing-common/services/sync/rotaryengine.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://testing-common/services/sync/utils.js
14:41:37     INFO -  PID 10328 | Attempting to load resource://testing-common/services/sync/fxa_utils.js
14:41:37     INFO -  (xpcshell/head.js) | test MAIN run_test finished (1)
14:41:37     INFO -  exiting test
14:41:37     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "iso-8859-8-i"" {file: "Z:/task_1540303685/build/tests/xpcshell/tests/services/sync/tests/unit/head_helpers.js -> resource://testing-common/sinon-2.3.2.js" line: 8941}]"
14:41:37     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "_globalScore"" {file: "resource://services-sync/policies.js" line: 120}]"
14:41:37     INFO -  PID 10328 | [GPU 11664, Chrome_ChildThread] WARNING: pipe error: 232: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 513
14:41:37     INFO -  PID 10328 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 683: Error: Phase "xpcom-will-shutdown" is finished, it is too late to register completion condition "ClientManagerService: start destroying IPC actors early"
14:41:37     INFO -  PID 10328 | ###!!! [Parent][DispatchAsyncMessage] Error: PClientSource::Msg_ExecutionReady Route error: message sent to unknown actor ID
14:41:37     INFO -  PID 10328 | 1540305397618	Sync.EngineManager	ERROR	Could not initialize engine : Error: Phase "profile-before-change" is finished, it is too late to register completion condition "JSON store: writing data"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
14:41:37     INFO -  PID 10328 | [e-mail]:494:5
14:41:37     INFO -  PID 10328 | [e-mail]:436:7
14:41:37     INFO -  PID 10328 | [e-mail]:117:3
14:41:37     INFO -  PID 10328 | [e-mail]:59:19
14:41:37     INFO -  PID 10328 | [e-mail]:211:3
14:41:37     INFO -  PID 10328 | get [e-mail]:856:19
14:41:37     INFO -  PID 10328 | [e-mail]:702:3
14:41:37     INFO -  PID 10328 | [e-mail]:100:3
14:41:37     INFO -  PID 10328 | [e-mail]:639:20
14:41:37     INFO -  PID 10328 | [e-mail]:401:17
14:41:37     INFO -  PID 10328 | 1540305397621	Sync.EngineManager	ERROR	Could not initialize engine : Error: Phase "profile-before-change" is finished, it is too late to register completion condition "JSON store: writing data"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
14:41:37     INFO -  PID 10328 | [e-mail]:494:5
14:41:37     INFO -  PID 10328 | [e-mail]:436:7
14:41:37     INFO -  PID 10328 | [e-mail]:117:3
14:41:37     INFO -  PID 10328 | [e-mail]:59:19
14:41:37     INFO -  PID 10328 | [e-mail]:489:3
14:41:37     INFO -  PID 10328 | get [e-mail]:856:19
14:41:37     INFO -  PID 10328 | [e-mail]:702:3
14:41:37     INFO -  PID 10328 | [e-mail]:37:3
14:41:37     INFO -  PID 10328 | [e-mail]:639:20
14:41:37     INFO -  PID 10328 | [e-mail]:401:17
14:41:37     INFO -  PID 10328 | 1540305397622	Sync.EngineManager	ERROR	Could not initialize engine : Error: Phase "profile-before-change" is finished, it is too late to register completion condition "JSON store: writing data"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
14:41:37     INFO -  PID 10328 | [e-mail]:494:5
14:41:37     INFO -  PID 10328 | [e-mail]:436:7
14:41:37     INFO -  PID 10328 | [e-mail]:117:3
14:41:37     INFO -  PID 10328 | [e-mail]:59:19
14:41:37     INFO -  PID 10328 | [e-mail]:325:3
14:41:37     INFO -  PID 10328 | get [e-mail]:856:19
14:41:37     INFO -  PID 10328 | [e-mail]:702:3
14:41:37     INFO -  PID 10328 | [e-mail]:70:3
14:41:37     INFO -  PID 10328 | [e-mail]:639:20
14:41:37     INFO -  PID 10328 | [e-mail]:401:17
14:41:37     INFO -  PID 10328 | 1540305397623	Sync.EngineManager	ERROR	Could not initialize engine : Error: Phase "profile-before-change" is finished, it is too late to register completion condition "JSON store: writing data"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
14:41:37     INFO -  PID 10328 | [e-mail]:494:5
14:41:37     INFO -  PID 10328 | [e-mail]:436:7
14:41:37     INFO -  PID 10328 | [e-mail]:117:3
14:41:37     INFO -  PID 10328 | [e-mail]:59:19
14:41:37     INFO -  PID 10328 | [e-mail]:235:3
14:41:37     INFO -  PID 10328 | get [e-mail]:856:19
14:41:37     INFO -  PID 10328 | [e-mail]:702:3
14:41:37     INFO -  PID 10328 | [e-mail]:36:3
14:41:37     INFO -  PID 10328 | [e-mail]:639:20
14:41:37     INFO -  PID 10328 | [e-mail]:401:17
14:41:37     INFO -  PID 10328 | 1540305397623	Sync.EngineManager	ERROR	Could not initialize engine : Error: Phase "profile-before-change" is finished, it is too late to register completion condition "JSON store: writing data"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
14:41:37     INFO -  PID 10328 | [e-mail]:494:5
14:41:37     INFO -  PID 10328 | [e-mail]:436:7
14:41:37     INFO -  PID 10328 | [e-mail]:117:3
14:41:37     INFO -  PID 10328 | [e-mail]:59:19
14:41:37     INFO -  PID 10328 | [e-mail]:274:3
14:41:37     INFO -  PID 10328 | get [e-mail]:856:19
14:41:37     INFO -  PID 10328 | [e-mail]:702:3
14:41:37     INFO -  PID 10328 | [e-mail]:40:3
14:41:37     INFO -  PID 10328 | [e-mail]:639:20
14:41:37     INFO -  PID 10328 | [e-mail]:401:17
14:41:37     INFO -  PID 10328 | 1540305397624	Sync.EngineManager	ERROR	Could not initialize engine : Error: Phase "profile-before-change" is finished, it is too late to register completion condition "JSON store: writing data"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
14:41:37     INFO -  PID 10328 | [e-mail]:494:5
14:41:37     INFO -  PID 10328 | [e-mail]:436:7
14:41:37     INFO -  PID 10328 | [e-mail]:117:3
14:41:37     INFO -  PID 10328 | [e-mail]:59:19
14:41:37     INFO -  PID 10328 | [e-mail]:62:3
14:41:37     INFO -  PID 10328 | get [e-mail]:856:19
14:41:37     INFO -  PID 10328 | [e-mail]:702:3
14:41:37     INFO -  PID 10328 | [e-mail]:25:3
14:41:37     INFO -  PID 10328 | [e-mail]:639:20
14:41:37     INFO -  PID 10328 | [e-mail]:401:17
14:41:37     INFO -  PID 10328 | 1540305397625	Sync.EngineManager	ERROR	Could not initialize engine : Error: Phase "profile-before-change" is finished, it is too late to register completion condition "JSON store: writing data"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
14:41:37     INFO -  PID 10328 | [e-mail]:494:5
14:41:37     INFO -  PID 10328 | [e-mail]:436:7
14:41:37     INFO -  PID 10328 | [e-mail]:117:3
14:41:37     INFO -  PID 10328 | [e-mail]:59:19
14:41:37     INFO -  PID 10328 | [e-mail]:1282:3
14:41:37     INFO -  PID 10328 | get [e-mail]:856:19
14:41:37     INFO -  PID 10328 | [e-mail]:702:3
14:41:37     INFO -  PID 10328 | [e-mail]:313:3
14:41:37     INFO -  PID 10328 | [e-mail]:493:3
14:41:37     INFO -  PID 10328 | [e-mail]:639:20
14:41:37     INFO -  PID 10328 | [e-mail]:554:11
14:41:37     INFO -  PID 10328 | [e-mail]:409:17
14:41:37     INFO -  PID 10328 | JavaScript strict warning: resource://services-sync/engines.js, line 571: ReferenceError: reference to undefined property "Prefs"
14:41:37     INFO -  PID 10328 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 683: Error: Phase "profile-change-teardown" is finished, it is too late to register completion condition "Places Clients shutdown"
14:41:37     INFO -  PID 10328 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 683: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "Places Connection shutdown"
14:41:37     INFO -  PID 10328 | JavaScript strict warning: resource://gre/modules/PlacesDBUtils.jsm, line 117: ReferenceError: reference to undefined property "status"
14:41:37     INFO -  <<<<<<<
14:41:37     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 10328: error 5
14:41:37     INFO -  xpcshell return code: None
14:41:37     INFO -  services/sync/tests/unit/test_load_modules.js | Process still running after test!
14:41:37     INFO -  rmtree() failed for "('c:\\users\\task_1540303685\\appdata\\local\\temp\\xpc-other-yhguet',)". Reason: The directory is not empty (41). Retrying...
14:41:37     INFO -  TEST-START | services/sync/tests/unit/test_service_wipeClient.js
14:41:37     INFO -  TEST-PASS | services/sync/tests/unit/test_service_wipeClient.js | took 678ms
14:41:38     INFO -  TEST-START | services/sync/tests/unit/test_service_wipeServer.js
14:46:38  WARNING -  TEST-UNEXPECTED-TIMEOUT | services/sync/tests/unit/test_service_wipeServer.js | Test timed out

Comment 3

[Intermittent Failures Robot]

6 failures in 3007 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* try: 6

Platform breakdown:
* windows10-64-nightly: 1
* windows10-64-devedition: 5

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

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 4

Platform breakdown:
* windows10-64-nightly: 3
* windows10-64-devedition: 1

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1

Platform breakdown:
* windows10-64-nightly: 1

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

Comment 6

[Lina Butler (ex-Mozilla)]

Looking at a recent log...the entire test appears to take less than 3 seconds. `test_wipeServer_all_connectionRefused` finishes, and presumably we start shutting down. Then we see this:

> 14:09:33     INFO -  PID 2072 | 1542636276667	Toolkit.ProfileAge	DEBUG	Using date: c:\\users\\task_1542634379\\appdata\\local\\temp\\xpc-profile-is0d87\\times.json = Mon Nov 19 2018 14:04:36 GMT+0000 (Greenwich Mean Time)
> 14:09:33     INFO -  PID 2072 | 1542636456552	Sqlite.ConnectionOpener	INFO	Opening database: c:\\users\\task_1542634379\\appdata\\local\\temp\\xpc-profile-is0d87\\formhistory.sqlite (formhistory.sqlite#0)

There's a 3 minute (!) gap between those entries. That's followed by several "too late to register completion condition" errors, because we're in shutdown.

> 14:09:33     INFO -  PID 2072 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 683: Error: Phase "profile-change-teardown" is finished, it is too late to register completion condition "Places Clients shutdown"
> 14:09:33     INFO -  PID 2072 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 683: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "Places Connection shutdown"
> 14:09:33     INFO -  PID 2072 | 1542636456623	Sqlite.ConnectionOpener	INFO	Opening database: c:\\users\\task_1542634379\\appdata\\local\\temp\\xpc-profile-is0d87\\places.sqlite (places.sqlite#0)
> 14:09:33     INFO -  PID 2072 | 1542636456624	Sqlite.ConnectionOpener	INFO	Connection opened
> 14:09:33     INFO -  PID 2072 | 1542636456624	Sqlite.Connection	INFO	formhistory.sqlite#0: Opened
> 14:09:33     INFO -  PID 2072 | 1542636456625	Sqlite.ConnectionOpener	WARN	Could not open database: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "Sqlite.jsm shutdown blocker"(resource://gre/modules/AsyncShutdown.jsm:683:15) JS Stack trace: [e-mail]:683:15
> 14:09:33     INFO -  PID 2072 | [e-mail]:494:5
> 14:09:33     INFO -  PID 2072 | [e-mail]:436:7
> 14:09:33     INFO -  PID 2072 | @Sqlite.jsm:150:3
> 14:09:33     INFO -  PID 2072 | [e-mail]:129:43
> 14:09:33     INFO -  PID 2072 | [e-mail]:258:3
> 14:09:33     INFO -  PID 2072 | [e-mail]:1190:26
> 14:09:33     INFO -  PID 2072 | openConnection/</<@Sqlite.jsm:1000:11

How and why are we trying to open a database here? Are we trying to sync on shutdown, or is someone else trying to initialize form history?

Comment 7

[Lina Butler (ex-Mozilla)]

(In reply to Lina Cambridge (she/her) [:lina] from comment #6)
> How and why are we trying to open a database here? Are we trying to sync on
> shutdown, or is someone else trying to initialize form history?

(And Places).

Comment 8

[Lina Butler (ex-Mozilla)]

On a related note, I'm wondering why opening `formhistory.sqlite` and `places.sqlite` succeeds at all here. Reading through https://wiki.mozilla.org/XPCOM_Shutdown, it looks like the last phase we can access the profile directory is `profile-before-change`.

Should we have mozStorage fail calls to `Open{Async, Unshared}Database` after that, since that connection is unlikely to be usable, anyway? I see we clean up on `xpcom-shutdown-threads` (https://searchfox.org/mozilla-central/rev/d35199ef15ffa57d190886e20d5df6471faf0870/storage/mozStorageService.cpp#766), but, AFAICT, nothing prevents us from trying to open connections? Or is it the caller's responsibility to check for shutdown?

I think we should still fix syncing (or whatever's trying to initialize form history and Places) on shutdown; this is just musing. Asuth, do you have any thoughts on this? :-)

Comment 9

[Andrew Sutherland [:asuth] (he/him)]

So, it looks like Sqlite.jsm explicitly creates a "profile-before-change" blocker at https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/toolkit/modules/Sqlite.jsm#150 and that sets `isClosed` that should fail any new opens via Sqlite.jsm (which is what FormHistory.jsm uses) and clones (which is what PlacesUtils.jsm uses).  So it seems like the code in question should already have shutdown protection in place?


I think that somewhat moots your mozStorage question, but just in case... mozStorage needs to be able to continue to operate through at least the end of "profile-before-change-qm" which comes after "profile-before-change" and is just before "profile-before-change-telemetry".  I think this means the first possible safe point to universally trigger explosions is "xpcom-will-shutdown" (or something that fires immediately after "profile-before-change-telemetry").

For Sqlite.jsm, if tighter-enforcement were desired... In some C++ APIs we have a convention of passing a `const MutexAutoLock& aProofOfLock` argument that helps make explicit the requirement to be holding a lock when making a call.  Perhaps AsyncShutdown.jsm and SQLite.jsm could be augmented so that openConnection()/cloneStorageConnection() would *require* that the return value of `addBlocker` be provided.  If the blocker has completed, the API would throw hard.

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-beta: 2

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

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

Comment 12

[Intermittent Failures Robot]

8 failures in 2648 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 6
* try: 2

Platform breakdown:
* windows10-64-nightly: 1
* windows7-32: 6
* windows10-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1505772&startday=2018-12-17&endday=2018-12-23&tree=all

Comment 13

[Ryan VanderMeulen [:RyanVM]]

It's not clear to me who owns the next step here? This is still hitting pretty frequently on Beta at the moment, so any progress would be appreciated :)

Comment 14

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 2

Platform breakdown:
* windows7-32: 1
* windows10-64-devedition: 1

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

Comment 15

[Andrew Sutherland [:asuth] (he/him)]

As far as this bug is concerned, things need to be addressed at the places/formhistory/whatever level.  Any changes to mozStorage would just be to add _more_ fatal assertions and therefore test failures.

Design rationale-wise: If you're trying to open a database, you either a) really want to persist some date, in which case it's very concerning that we're doing things too late and so a fatal assertion is in order or b) you don't actually want to be opening the database, and that decision should have been made at a much higher level and so a fatal assertion is still in order to call attention to the problem.  That said, there are places where it makes sense to have a boundary that just returns non-fatal-assertion errors that will cascade up through layers, but that layer should be above mozStorage and ideally continually moved upward.

Comment 16

[Ryan VanderMeulen [:RyanVM]]

Mike, AFAICT you're the last person to spend any time working on FormHistory. Any chance you could take a look at this issue? It's pretty frequent on Beta :\

Comment 17

[Intermittent Failures Robot]

10 failures in 1668 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* try: 4
* mozilla-beta: 6

Platform breakdown:
* windows10-64-devedition: 5
* windows7-32: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1505772&startday=2018-12-31&endday=2019-01-06&tree=all

Comment 18

[Mike Conley (:mconley) (:⚙️)]

Did some digging into this today.

It looks like both FormHistory and Places are attempting to do some kind of maintainance keyed off of idle-daily, and for some reason, we're hitting idle-daily when we're supposed to be shutting down.

Stay tuned.

Comment 19

[Intermittent Failures Robot]

4 failures in 2627 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• mozilla-beta: 3

Platform breakdown:

• windows7-32: 2
• windows10-64-nightly: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1505772&startday=2019-01-07&endday=2019-01-13&tree=all

Comment 20

[Mike Conley (:mconley) (:⚙️)]

Okay, I think I've figured out what's going on here.

When running xpcshell tests, we notify about profile shutdown stuff here:

https://searchfox.org/mozilla-central/rev/b29663c6c9c61b0bf29e8add490cbd6bad293a67/testing/xpcshell/head.js#608-613

nsIdleServiceDaily is set up to ignore idle events after profile-after-change and xpcom-shutdown is observed:

https://searchfox.org/mozilla-central/rev/b29663c6c9c61b0bf29e8add490cbd6bad293a67/widget/nsIdleService.cpp#214-218
and
https://searchfox.org/mozilla-central/rev/b29663c6c9c61b0bf29e8add490cbd6bad293a67/widget/nsIdleService.cpp#79-86

From what I can tell via logging, it looks like it's possible to instantiate an nsIdleServiceDaily after profile-after-change has been fired. Presumably, perhaps while spinning the event loop inside AsyncShutdown.jsm, something is creating an nsIdleService (which creates and inits an nsIdleServiceDaily), which never unregisters itself because it's past the point where it normally does that (the point where profile-after-change fires).

The idle-daily fires not long after the service inits, and that causes things like the FormHistory expiries and Places maintenance stuff to kick off, which opens up the databases. And at that point, the AsyncShutdown.jsm stuff has gone past the profile-before-change notification where Sqlite.jsm normally closes those database handles.

This is all a bit hand-wavey because I can only reproduce this on try, and I'm doing analysis with logging. And even then, the error case is hit irregularly.

So it's a bit of a cluster. I think what we probably want to do here is prevent the nsIdleService and nsIdleServiceDaily from running any observers if we're in the midst of shutting down.

I'll try to post a patch that does that.

Comment 21

[Lina Butler (ex-Mozilla)]

Holy moly. 😲 Thanks for the sleuthing, mconley!

Comment 22

[Mike Conley (:mconley) (:⚙️)]

Just so more notes here:

I actually think the idle service stuff is a symptom of a larger problem. Even if I disable the idle service, the test will still fail periodically because some sync stuff fires up and fails when registering AsyncShutdown stuff.

As far as I can tell, this is happening because:

1. Sync's service.js runs this.Service.onStartup() anytime it's imported, including in xpcshell tests like test_load_modules.js
2. test_load_modules.js runs synchronously, and doesn't wait for this.Service.onStartup() to finish its work before exiting. So the xpcshell framework goes, "oh, I guess this test is done now", and starts to tear down the fake profile. This causes the profile-before-change, profile-foo-teardown, xpcom-shutdown observer notifications to fire
3. Then, sometimes, onStartup reaches the point in engine registration where it attempts to do stuff with AsyncShutdown.jsm - but by that point, it's too late because the observer notifications it cares about have already fired, so AsyncShutdown throws exceptions

And I think that causes everything to just kinda wait for a bit. Eventually the idle service kicks off, and that adds even more console spew because we're right at the edge of shutting down, and the idle-daily stuff also tries to access db things

So this is a classic race - the race between xpcshell shutting itself down, and sync starting itself up. Often times, it seems Sync gets itself started up first, and that's when we're all green. It's when Sync loses that race where things go sideways.

Lina, am I okay to hand this over to you now?

Comment 23

[Mark Hammond [:markh] [:mhammond]]

(In reply to Mike Conley (:mconley) (:⚙️) from comment #22)

2. test_load_modules.js runs synchronously, and doesn't wait for this.Service.onStartup() to finish its work before exiting. So the xpcshell framework goes, "oh, I guess this test is done now", and starts to tear down the fake profile. This causes the profile-before-change, profile-foo-teardown, xpcom-shutdown observer notifications to fire

Ouch - nice sleuthing Mike! I guess in theory this isn't limited to test_load_modules, but if that's the actual problem we should either just kill this test entirely (I don't think it adds much value TBH - if this test fails but another test doesn't we've got a big gap in our test coverage), or remove service.js from the list of modules it imports (as a failure to import that will definitely cause the vast majority of our tests to fail)

Comment 24

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 3

Platform breakdown:

• windows10-64-nightly: 2
• windows10-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1505772&startday=2019-01-14&endday=2019-01-20&tree=all

Comment 25

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1505772&startday=2019-01-21&endday=2019-01-27&tree=all

Comment 26

[Ryan VanderMeulen [:RyanVM]]

Not sure what happened here, but it's too late to do anything for 65 at this point :(

Comment 27

[Intermittent Failures Robot]

6 failures in 2832 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• mozilla-beta: 3
• mozilla-release: 2

Platform breakdown:

• windows10-64: 5
• windows10-64-nightly: 1

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

Comment 28

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 5
• mozilla-beta: 3

Platform breakdown:

• windows10-64: 6
• windows10-64-devedition: 1
• windows10-64-nightly: 1

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

Comment 29

[Intermittent Failures Robot]

6 failures in 2981 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 2
• try: 3
• mozilla-release: 1

Platform breakdown:

• windows10-64: 6

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

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 3

Platform breakdown:

• windows10-64: 3

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

Comment 32

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Not seen for 2 months.

Comment 33

[BugBot [:suhaib / :marco/ :calixte]]

Bugbug thinks this bug is a regression, but please revert this change in case of error.