829763 - App infrastructure stalls when checking for an update for a hosted app

Status: RESOLVED FIXED

(Core Graveyard :: DOM: Apps, defect)

Description

[Bobby Holley (:bholley)]

This appears to happen even with the patch in bug 824697. It's totally possibly I'm just doing something wrong though.

In writing my tests for bug 826058, I'm generating the appcache manifest dynamically via an sjs file. I was in the process of writing the ETag infrastructure so that the sjs would correctly return 304 when the app had not been update. Before that though, I decided to see what happens when the appcache file is always served, effectively meaning that there always appears to be updates available.

Unfortunately, checkForUpdates appears to hang, with no response ever delivered to the DOMRequest. I added some basic logging to see what's happening, and it appears that updateObserver is never being called:

http://mxr.mozilla.org/mozilla-central/source/dom/apps/src/Webapps.jsm#1228

I've attached my logging patch, which gives the following output:

3 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | setVersion OK
4 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Checking uninstalled app
5 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Message from app: OK: Launched app
6 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | App is not installed
7 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Version should be correct
8 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Messaging from app complete
9 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | setVersion OK
10 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | setVersion OK
11 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Installing cached app
-*-*- Webapps.jsm : Creating AppcacheObserver for http://example.org - pending
12 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | App is non-null
13 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | App is pending. Waiting for progress
-*-*- Webapps.jsm : Offline cache state change for http://example.org : 5
-*-*- Webapps.jsm : Offlinecache setStatus to pending for http://example.org
-*-*- Webapps.jsm : Offline cache state change for http://example.org : 6
-*-*- Webapps.jsm : Offlinecache setStatus to pending for http://example.org
14 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Got download progress
15 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Got download progress
-*-*- Webapps.jsm : Offline cache state change for http://example.org : 8
-*-*- Webapps.jsm : Offlinecache setStatus to pending for http://example.org
16 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Got download progress
-*-*- Webapps.jsm : Offline cache state change for http://example.org : 7
-*-*- Webapps.jsm : Offline cache state change for http://example.org : 10
-*-*- Webapps.jsm : Offlinecache setStatus to installed for http://example.org
17 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | App is installed
18 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Checking installed app
19 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Message from app: OK: Launched app
20 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | App is installed
21 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Message from app: OK: Really Rapid Release (cached) == Really Rapid Release (cached) - Manifest name should be correct
22 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Message from app: OK: http://example.org == http://example.org - App origin should be correct
23 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Message from app: OK: http://mochi.test:8888 == http://mochi.test:8888 - Install origin should be correct
24 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Version should be correct
25 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Messaging from app complete
26 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Setting callbacks
27 INFO TEST-PASS | /tests/dom/apps/tests/test_app_update.html | Checking for updates
-*-*- Webapps.jsm : checkForUpdate for http://example.org/tests/dom/apps/tests/file_cached_app.webapp
-*-*- Webapps.jsm : Checking manifest at http://example.org/tests/dom/apps/tests/file_cached_app.webapp
-*-*- Webapps.jsm : Got http status=200 for http://example.org/tests/dom/apps/tests/file_cached_app.webapp
-*-*- Webapps.jsm : updateHostedApp http://example.org/tests/dom/apps/tests/file_cached_app.webapp
-*-*- Webapps.jsm : Calling this._saveApps
-*-*- Webapps.jsm : Updating permissions
-*-*- Webapps.jsm : _saveApps callback invoked
-*-*- Webapps.jsm : Firing off the update observer


Again, I may well be doing something wrong here. But in general, I don't think it should be possible to stall things such that neither onerror of onsuccess of the associated DOMRequest are called.

Comment 1

[Bobby Holley (:bholley)]

Attachment: mochitest testcase

Comment 2

[Bobby Holley (:bholley)]

Attachment: logging patch

Comment 3

[Honza Bambas (:mayhemer)]

I'll apply the patches locally to Fx desktop build and check what happens.

Comment 4

[Bobby Holley (:bholley)]

Looking at the code more, it appears that we use the webapp manifest, rather than the appcache manifest, to determine whether there's an update. So whether or not an update is available as far as this test is concerned depends on how httpd.js does cache management.

Either way though, presumably we should get a callback one way or another from the DOMRequest.

Comment 5

[Bobby Holley (:bholley)]

(In reply to Honza Bambas (:mayhemer) from comment #3)
> I'll apply the patches locally to Fx desktop build and check what happens.

Note that the mochitests aren't going to work on a desktop build, because the BrowserElementPromptService is busted there. If you have some other way of simulating the situation though then that's fine.

Comment 6

[Honza Bambas (:mayhemer)]

(In reply to Bobby Holley (:bholley) from comment #5)
> (In reply to Honza Bambas (:mayhemer) from comment #3)
> > I'll apply the patches locally to Fx desktop build and check what happens.
> 
> Note that the mochitests aren't going to work on a desktop build, because
> the BrowserElementPromptService is busted there. If you have some other way
> of simulating the situation though then that's fine.

On desktop build of Firefox or Boot2Gecko with GAIA?  (I so far didn't get b2g build on win these days, but it used to work).

Comment 7

[Bobby Holley (:bholley)]

(In reply to Honza Bambas (:mayhemer) from comment #6)
> (In reply to Bobby Holley (:bholley) from comment #5)
> > (In reply to Honza Bambas (:mayhemer) from comment #3)
> > > I'll apply the patches locally to Fx desktop build and check what happens.
> > 
> > Note that the mochitests aren't going to work on a desktop build, because
> > the BrowserElementPromptService is busted there. If you have some other way
> > of simulating the situation though then that's fine.
> 
> On desktop build of Firefox or Boot2Gecko with GAIA?  (I so far didn't get
> b2g build on win these days, but it used to work).

The latter. I've been pushing to get mochitests running on b2g (in bug 826111). But with those patches applied, these tests fail early on due to some weirdness in the Prompt Service. :-(

Comment 8

[Bobby Holley (:bholley)]

Attachment: updated mochitest testcase

I've updated the testcase to add Etag support and serve the manifests via SJS. This still exhibits the issue for me, and is a lot easier to instrument given the sjs.

Comment 9

[Honza Bambas (:mayhemer)]

I run the test on Fx desktop.  I'm getting following messages (alerts()): "OK: Launched app", "NOT_INSTALLED", "VERSION: MyWebApp v1", "DONE".  checkForUpdate API is not called at all.

Comment 10

[Honza Bambas (:mayhemer)]

Is the Webapps.jsm code called on the child process?  If so, then it cannot work because of e10s.  There is no support for updateCheck when called from child since I was told there is no need to.  You may check for a throw from updateSvc.checkForUpdate.

Comment 11

[Bobby Holley (:bholley)]

(In reply to Honza Bambas (:mayhemer) from comment #9)
> I run the test on Fx desktop.  I'm getting following messages (alerts()):
> "OK: Launched app", "NOT_INSTALLED", "VERSION: MyWebApp v1", "DONE". 
> checkForUpdate API is not called at all.

Yes, because as noted, the test doesn't work on desktop b2g. See comment 7.

(In reply to Honza Bambas (:mayhemer) from comment #10)
> Is the Webapps.jsm code called on the child process?  If so, then it cannot
> work because of e10s.  There is no support for updateCheck when called from
> child since I was told there is no need to.  You may check for a throw from
> updateSvc.checkForUpdate.

That would be strange. How would the test be doing that?

Comment 12

[Johnny Stenback (:jst)]

Blocking, we need updates to be solid.

Comment 13

[Honza Bambas (:mayhemer)]

(In reply to Bobby Holley (:bholley) from comment #11)
> (In reply to Honza Bambas (:mayhemer) from comment #9)
> > I run the test on Fx desktop.  I'm getting following messages (alerts()):
> > "OK: Launched app", "NOT_INSTALLED", "VERSION: MyWebApp v1", "DONE". 
> > checkForUpdate API is not called at all.
> 
> Yes, because as noted, the test doesn't work on desktop b2g. See comment 7.

I was running it on Firefox desktop.

> 
> (In reply to Honza Bambas (:mayhemer) from comment #10)
> > Is the Webapps.jsm code called on the child process?  If so, then it cannot
> > work because of e10s.  There is no support for updateCheck when called from
> > child since I was told there is no need to.  You may check for a throw from
> > updateSvc.checkForUpdate.
> 
> That would be strange. How would the test be doing that?

Test?  I'm not talking about the test.  I'm talking about a chrome code in Webapps.jsm.

Comment 14

[[:fabrice] Fabrice Desré]

Webapps.jsm only runs in the parent process.

Comment 15

[Honza Bambas (:mayhemer)]

(In reply to Fabrice Desré [:fabrice] from comment #14)
> Webapps.jsm only runs in the parent process.

Thanks.  That is what I expect and correct then.

Comment 16

[Bobby Holley (:bholley)]

(In reply to Honza Bambas (:mayhemer) from comment #13)
> > Yes, because as noted, the test doesn't work on desktop b2g. See comment 7.
> 
> I was running it on Firefox desktop.

In which case it won't work at all. mozbrowsers aren't available in Firefox per spec, I think.

Comment 17

[Josh Matthews [:jdm]]

Well, there's http://mxr.mozilla.org/mozilla-central/find?text=&string=browser-element%2Fmochitest.

Comment 18

[Bobby Holley (:bholley)]

(In reply to Josh Matthews [:jdm] from comment #17)
> Well, there's
> http://mxr.mozilla.org/mozilla-central/find?text=&string=browser-
> element%2Fmochitest.

Maybe it was that you can't load a mozapp in a mozbrowser? I can't quite remember, but sicking once described the numerous reasons that these tests wouldn't work on desktop. Ask him if you're curious.

Comment 19

[Jason Smith [:jsmith]]

Moving to tef? as we don't know if this blocks or not without having someone dig into this.

ferjm - Can you find out why these tests are failing? Is it a bug in the tests or an actual bug? If it's an actual bug, how severe is it?

Comment 20

[Fernando Jiménez Moreno [:ferjm]]

(In reply to Jason Smith [:jsmith] from comment #19)
> Moving to tef? as we don't know if this blocks or not without having someone
> dig into this.
> 
> ferjm - Can you find out why these tests are failing? Is it a bug in the
> tests or an actual bug? If it's an actual bug, how severe is it?

Sorry, I couldn't run the tests yet.
The emulator is not working for me in OSX and Linux 64bits (currently building in a VM with 32bits) and I couldn't make them work in b2g-desktop yet :\. I will try on the device and let you know what I find out asap.

Comment 21

[Bobby Holley (:bholley)]

FWIW the emulator worked for me on osx64.

You're using arm, right?

Comment 22

[Fernando Jiménez Moreno [:ferjm]]

Yes, I am using arm.

Testing again with a real scenario, the behaviour is the following:

Modifying the app manifest in the server so we get a 200 response I am getting the following output (I'm showing only the interesting part):

I/Gecko   (  109): -*-*- Webapps.jsm : checkForUpdate for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : adding manifest etag:2f8241624ee25077d2c7ccabfedea4a3
I/Gecko   (  109): -*-*- Webapps.jsm : Checking manifest at http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : Got http status=200 for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : at update got app etag=dfaa68e0f5609a200e20aac5f1b06cc6
I/Gecko   (  109): -*-*- Webapps.jsm : updateHostedApp http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.appcache
E/GeckoConsole(  109): Offline cache manifest magic incorect, URL=http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.appcache
==== Note this message [1]=========
I/Gecko   (  109): -*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate return for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp - event is offline-cache-update-unavailable
===================================
I/Gecko   (  109): UpdatePrompt: appsUpdated: 0 apps to update

Message [1] comes from https://mxr.mozilla.org/mozilla-central/source/dom/apps/src/Webapps.jsm#1238 , which means that updateObserver is being called.


*However*, this is still not working as expected :(. Modifying also the offline cache manifest in the server (changing a comment and adding a new entry with its corresponding file) shows the following output:

I/Gecko   (  109): -*-*- Webapps.jsm : checkForUpdate for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : adding manifest etag:456b1e1632b8174a4873b8256246aa1d
I/Gecko   (  109): -*-*- Webapps.jsm : Checking manifest at http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : Got http status=304 for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : updateHostedApp http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  109): -*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.appcache
E/GeckoConsole(  109): Offline cache manifest magic incorect, URL=http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.appcache
I/Gecko   (  109): -*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate return for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp - event is offline-cache-update-unavailable
I/Gecko   (  109): UpdatePrompt: appsUpdated: 0 apps to update

As you can see, we are getting an expected 304 for the application manifest, so, after Bug 824697, we also check for the offline cache changes which is giving us a 'offline-cache-update-unavailable' even with an offline cache manifest modified in the server. 

Note the "Offline cache manifest magic incorect". Honza, as you know, I've seen that before for the marketplace-dev offline cache. I might be doing something wrong in the server side, but would you mind taking a look at this, please? The offline cache manifest is located at http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.appcache and I've checked that this error message is thrown when the first line of the manifest is not exactly 'CACHE MANIFEST', am I right? In this case, the manifest contains that exact line, so I don't know where the error is.

Comment 23

[Jason Smith [:jsmith]]

Based on what I'm hearing from the above comment, sounds like this is actually a bug, not a bug in the test.

Also sounds like a blocker if I'm reading this right.

Is my understanding correct?

Comment 24

[[:fabrice] Fabrice Desré]

(In reply to Fernando Jiménez Moreno [:ferjm] from comment #22)

> Note the "Offline cache manifest magic incorect". Honza, as you know, I've
> seen that before for the marketplace-dev offline cache. I might be doing
> something wrong in the server side, but would you mind taking a look at
> this, please? The offline cache manifest is located at
> http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.appcache and I've
> checked that this error message is thrown when the first line of the
> manifest is not exactly 'CACHE MANIFEST', am I right? In this case, the
> manifest contains that exact line, so I don't know where the error is.

I also see the "Offline cache manifest magic incorect" when checking for updates the Slithering appcache from Bug 829853. I added some debug output at https://mxr.mozilla.org/mozilla-central/source/uriloader/prefetch/nsOfflineCacheUpdate.cpp#876 to print the value of "magic" and this is an empty string. No idea why, since the manifest's resources were downloaded when installing. The appcache manifest is at http://snake-app.github.com/snake.appcache and looks totally correct to me.

Comment 25

[Honza Bambas (:mayhemer)]

What is the way you reproduce?  How to install that app in desktop Firefox?  I don't have any b2g desktop builds right now.

Comment 26

[Honza Bambas (:mayhemer)]

BTW, I believe the empty magic is caused by processing 'null' data that we 'load' when the resource is loaded from cache - LOAD_ONLY_IF_MODIFIED flag causes this.  

I think it is a bug at nsOfflineManifestItem::OnStopRequest.  If you move lines from [1] to [2] to the else branch of the mBytesRead == 0 condition, does it fix the problem?

[1] http://hg.mozilla.org/mozilla-central/annotate/d29ffd335728/uriloader/prefetch/nsOfflineCacheUpdate.cpp#l1174
[2] http://hg.mozilla.org/mozilla-central/annotate/d29ffd335728/uriloader/prefetch/nsOfflineCacheUpdate.cpp#l1179

Comment 27

[[:fabrice] Fabrice Desré]

I'm not sure if that fixes the issue, since it's intermittent, but I didn't see it again with this change.

Comment 28

[Fernando Jiménez Moreno [:ferjm]]

Attachment: Fix

I also can confirm that with the attached fix suggested by Honza in comment 26 the update works as expected:

I/Gecko   (  701): -*-*- Webapps.jsm : Got http status=304 for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  701): -*-*- Webapps.jsm : updateHostedApp http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp
I/Gecko   (  701): -*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.appcache
I/Gecko   (  701): -*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate return for http://apptester.eu01.aws.af.cm/apps/bigHostedApp/manifest.webapp - event is offline-cache-update-available
I/Gecko   (  701): UpdatePrompt: appsUpdated: 1 apps to update

Comment 29

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

Fernando: There's not enough information here to make a blocking decision.

Can you describe *when* this happens (as much as we understand of that at least), I.e. does this happen for all hosted apps that use appcache, or only if the server serves some specific headers or such? And *what* happens when this bug is triggered, i.e. do we just not update until the phone is restarted? Or do we never update?

Comment 30

[Honza Bambas (:mayhemer)]

Does the " updated mochitest testcase " reproduce this bug?

If so, we can have a production quality patch to review/land as I understand.  Anybody to produce it?  I can do the review.

Comment 31

[Bobby Holley (:bholley)]

(In reply to Honza Bambas (:mayhemer) from comment #30)
> Does the " updated mochitest testcase " reproduce this bug?

Yes, though it shouldn't be checked in, because it's just a partial implementation of the tests in bug 826058.

Comment 32

[Jason Duell]

Comment on attachment 703846 [details] [diff] [review]
Fix

Review of attachment 703846 [details] [diff] [review]:
-----------------------------------------------------------------

So is this patch ready for review?  Looks like a simple fix, but honza knows code better than me.

Comment 33

[Fernando Jiménez Moreno [:ferjm]]

(In reply to Jonas Sicking (:sicking) from comment #29)
> Fernando: There's not enough information here to make a blocking decision.
> 
> Can you describe *when* this happens (as much as we understand of that at
> least), I.e. does this happen for all hosted apps that use appcache, or only
> if the server serves some specific headers or such? And *what* happens when
> this bug is triggered, i.e. do we just not update until the phone is
> restarted? Or do we never update?

I've done further testing in the device with a few apps hosted in two different servers and it is happening randomly for me. I can't find a clear STR :|.

In any case, when the issue appears, what happens is that the update notification is never triggered, even after rebooting the device, and the app is only updated when it is manually opened, as any other normal web content.

Applying the attached patch seems to fix the issue as I can't reproduce it anymore.

However, note that this issue is probably not related with the tests failure described in the bug description (updateObserver is never being called). As I explained in comment 22, in the device updateObserver is always called even without the patch to fix the "Offline cache manifest magic incorect" issue. So there might be another issue in the apps implementation or an issue with the tests itself. Dale is working on them in Bug 826058.

Comment 34

[Honza Bambas (:mayhemer)]

Comment on attachment 703846 [details] [diff] [review]
Fix

Review of attachment 703846 [details] [diff] [review]:
-----------------------------------------------------------------

r=honzab

::: uriloader/prefetch/nsOfflineCacheUpdate.cpp
@@ +1172,5 @@
> +        nsCString::const_iterator begin, end;
> +        mReadBuf.BeginReading(begin);
> +        mReadBuf.EndReading(end);
> +        nsresult rv = HandleManifestLine(begin, end);
> +        NS_ENSURE_SUCCESS(rv, rv);

New line under this line please.

Comment 36

[Fernando Jiménez Moreno [:ferjm]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/93ca53db2831

Comment 37

[(no longer active)]

https://hg.mozilla.org/mozilla-central/rev/93ca53db2831

Comment 38

[Jason Smith [:jsmith]]

Can someone land this on b2g18 as well?

Comment 39

[[:fabrice] Fabrice Desré]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/f76f36a5f385

Comment 40

[Lukas Blakk [:lsblakk] use ?needinfo]

Landed on mozilla-b2g18/gaia master prior to the 1/25 branching to mozilla-b2g18_v1_0_0/v1.0.0, updating status-b2g-v1.0.0 to fixed.