845921 - Add-on manager runs background update check while Firefox is shutting down

Status: RESOLVED WONTFIX

(Toolkit :: Add-ons Manager, defect)

Description

[:Irving Reid (No longer working on Firefox)]

In the course of investigating bug 845842 I captured the following (snipped from https://bugzilla.mozilla.org/attachment.cgi?id=719088)


*** LOG addons.xpi: Calling bootstrap method shutdown on jid0-47DeivVljf2PE6XDCjdxijnA30o@jetpack version 0.1.2
*** LOG addons.xpi: Calling bootstrap method shutdown on jid1-F9UJ2thwoAm5gQ@jetpack version 0.25
*** LOG addons.xpi: Calling bootstrap method shutdown on jid0-edalmuivkozlouyij0lpdx548bc@jetpack version 1.11.11
*** LOG addons.xpi: Calling bootstrap method shutdown on {d10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d} version 2.2.3
...
1361985815259	Services.HealthReport.HealthReporter	INFO	Request to shut down.
1361985815260	Services.HealthReport.HealthReporter	WARN	Collector is in progress of initializing. Waiting to finish.
...
2043955552[10046a660]: nsIdleServiceDaily: Observe 'profile-change-teardown' (0)
2043955552[10046a660]: idleService: Remove observer fb1ac60 (900 seconds), 0 remain idle
*** LOG addons.updates: Requesting https://versioncheck-bg.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id=[e-mail]&version=&maxAppVersion=%ITEM_MAXAPPVERSION%&status=userEnabled,incompatible&appID={ec8030f7-c20a-464f-9b0e-13a3a9e97384}&appVersion=22.0a1&appOS=Darwin&appABI=x86_64-gcc3&locale=en-US&currentAppVersion=22.0a1&updateType=%UPDATE_TYPE%&compatMode=%COMPATIBILITY_MODE%
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** LOG addons.repository: Requesting https://services.addons.mozilla.org/en-US/firefox/api/1.5/search/guid:jid0-47DeivVljf2PE6XDCjdxijnA30o%40jetpack,jid1-F9UJ2thwoAm5gQ%40jetpack,SQLiteManager%40mrinalkant.blogspot.com,jid0-edalmuivkozlouyij0lpdx548bc%40jetpack,https-everywhere%40eff.org,%7B972ce4c6-7e08-4474-a285-3208198ce6fd%7D,%7Bd10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d%7D?src=firefox&appOS=Darwin&appVersion=22.0a1&tMain=108&tFirstPaint=26511&tSessionRestored=27103
*** WARN addons.repository: Search failed when repopulating cache
*** LOG addons.updates: Requesting https://versioncheck-bg.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id=jid0-47DeivVljf2PE6XDCjdxijnA30o@jetpack&version=0.1.2&maxAppVersion=17.*&status=userEnabled&appID={ec8030f7-c20a-464f-9b0e-13a3a9e97384}&appVersion=22.0a1&appOS=Darwin&appABI=x86_64-gcc3&locale=en-US&currentAppVersion=22.0a1&updateType=112&compatMode=normal
*** LOG addons.updates: Requesting https://versioncheck-bg.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id=jid1-F9UJ2thwoAm5gQ@jetpack&version=0.25&maxAppVersion=19.*&status=userEnabled&appID={ec8030f7-c20a-464f-9b0e-13a3a9e97384}&appVersion=22.0a1&appOS=Darwin&appABI=x86_64-gcc3&locale=en-US&currentAppVersion=22.0a1&updateType=112&compatMode=normal
*** LOG addons.updates: Requesting https://versioncheck-bg.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id=[e-mail]&version=0.7.7&maxAppVersion=16.*&status=userEnabled&appID={ec8030f7-c20a-464f-9b0e-13a3a9e97384}&appVersion=22.0a1&appOS=Darwin&appABI=x86_64-gcc3&locale=en-US&currentAppVersion=22.0a1&updateType=112&compatMode=normal
*** LOG addons.updates: Requesting https://versioncheck-bg.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id=jid0-edalmuivkozlouyij0lpdx548bc@jetpack&version=1.11.11&maxAppVersion=19.*&status=userEnabled&appID={ec8030f7-c20a-464f-9b0e-13a3a9e97384}&appVersion=22.0a1&appOS=Darwin&appABI=x86_64-gcc3&locale=en-US&currentAppVersion=22.0a1&updateType=112&compatMode=normal
*** LOG addons.updates: Requesting https://www.eff.org/files/https-everywhere-devel-update-2048.rdf
*** LOG addons.updates: Requesting https://versioncheck-bg.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id={972ce4c6-7e08-4474-a285-3208198ce6fd}&version=22.0a1&maxAppVersion=22.0a1&status=userEnabled&appID={ec8030f7-c20a-464f-9b0e-13a3a9e97384}&appVersion=22.0a1&appOS=Darwin&appABI=x86_64-gcc3&locale=en-US&currentAppVersion=22.0a1&updateType=112&compatMode=normal
*** LOG addons.updates: Requesting https://versioncheck-bg.addons.mozilla.org/update/VersionCheck.php?reqVersion=2&id={d10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d}&version=2.2.3&maxAppVersion=22.0&status=userEnabled&appID={ec8030f7-c20a-464f-9b0e-13a3a9e97384}&appVersion=22.0a1&appOS=Darwin&appABI=x86_64-gcc3&locale=en-US&currentAppVersion=22.0a1&updateType=112&compatMode=normal
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** WARN addons.updates: HTTP Request failed for an unknown reason
*** Blocklist::notify: Requesting https://addons.mozilla.org/blocklist/3/%7Bec8030f7-c20a-464f-9b0e-13a3a9e97384%7D/22.0a1/Firefox/20130227115236/Darwin_x86_64-gcc3/en-US/default/Darwin%2011.4.2/default/default/4/36/1/
*** Blocklist:onError: There was an error loading the blocklist file
nsIXMLHttpRequest channel unavailable

Comment 1

[:Irving Reid (No longer working on Firefox)]

WONTFIX based on the following IRC conversation.

16:08 (irving) it appears we can get notifications from the update-timer service late (up until xpcom-shutdown, if I read http://mxr.mozilla.org/comm-central/source/mozilla/toolkit/mozapps/update/nsUpdateTimerManager.js#106 correctly)
16:08 (Mossop) Sounds likely
16:09 (irving) should addon manager protect itself, or should we turn off the update-timer service earlier?
16:10 (Mossop) irving: So this only happens if the app happens to be shut down at just the right time, just when an update check is getting fired, correct?
16:11 (irving) Mossop: As far as I can tell, yes. I got "lucky" and caught it in a debug trace while I was looking for something else
16:11 (Mossop) And what issues does it actually cause?
16:12 (irving) might just be noise in the logs, I haven't reviewed the code closely to see if anything gets into an inconsistent state
16:13 (Mossop) The log shows all the http requests fail (as I'd expect), and in that case nothing should happen really. I don't think this is a probably we need to worry about much
16:15 (irving) So you suggest WONTFIX, or should I leave it open?
16:16 (rstrong) Mossop irving: do you think it would be worthwhile to change nsUpdateTimerManager to use xpcom-will-shutdown?
16:17 (Mossop) rstrong: It might help, but it'd still be possible to get the update notification immediately before that and hit shutdown while still doing the http requests
16:17 (Mossop) I'd just wontfix
16:17 (irving) Most update things need the profile, don't they? so it doesn't make much sense to fire after the profile is gone
16:19 (rstrong) irving: true though the case Mossop mentioned wouldn't be fixed by shutting down nsUpdateTimerManager before the profile is gone
16:19 (philor) I think there's at least one leak that thinks it's from that happening
16:20 (Mossop) We're meant to have update checks disabled for test runs
16:23 (irving) I see what you mean about having the async HTTP running across shutdown. Would take a bunch more code to cancel those properly...
16:23 (philor) I might have been thinking about the way safebrowsing leaks by hitting its local URL at the wrong time
16:26 (irving) do all open XHR requests get their error callback called when we shut down HTTP?
16:30 (bsmedberg) irving: do they still *exist* when we shut down HTTP? I believe that all content windows should be torn down before we get there
16:31 (irving) this is async HTTP from chrome, so maybe XHR was the wrong term to use
16:32 (irving) s/chrome/JS-implemented services/
16:35 (Mossop) The log in that bug suggests that they do
16:45 (irving) OK, I'm persuaded enough to WONTFIX unless someone else wants to keep it open
16:47 (bsmedberg) irving: I believe that all channels get closed when we shut down HTTP. I'm not sure what precise codes that would give you though