Closed Bug 877984 Opened 7 years ago Closed 7 years ago

[Buri] Trying to update a hosted app preloading appcache that was preinstalled will fail to update

Categories

(Core Graveyard :: DOM: Apps, defect, P2)

ARM
Gonk (Firefox OS)
defect

Tracking

(blocking-b2g:tef+, firefox22 wontfix, firefox23 wontfix, firefox24 fixed, b2g18 fixed, b2g18-v1.0.0 wontfix, b2g18-v1.0.1 verified, b2g-v1.1hd fixed)

RESOLVED FIXED
1.0.1 IOT3 (3jun)
blocking-b2g tef+
Tracking Status
firefox22 --- wontfix
firefox23 --- wontfix
firefox24 --- fixed
b2g18 --- fixed
b2g18-v1.0.0 --- wontfix
b2g18-v1.0.1 --- verified
b2g-v1.1hd --- fixed

People

(Reporter: sync-1, Assigned: fabrice)

References

Details

(Whiteboard: [apps watch list][fixed-in-birch])

Attachments

(6 files, 2 obsolete files)

AU_LINUX_GECKO_ICS_STRAWBERRY_V1.01.00.01.019.121
 Firefox os  v1.0.1
 Mozilla build ID:20130527070203
 
 DEFECT DESCRIPTION:
 
 STR:
 1. pre-install some 3rd party apps.
 2. flash code to device.
 3. connect to network with wifi.
 4. there will popup apps update available notification.
 5. click Download to update the apps, but the download failed.
 
 Note: Currently "AccuWeather" and "Wikipedia" are failed to update.
 
 
  REPRODUCING PROCEDURES:
 
  EXPECTED BEHAVIOUR:
 
 the apps can be updated.
 
  ASSOCIATE SPECIFICATION:
 
  TEST PLAN REFERENCE:
 
  TOOLS AND PLATFORMS USED:
 
  USER IMPACT:
 
  REPRODUCING RATE:
 
  For FT PR, Please list reference mobile's behavior:
blocking-b2g: --- → tef?
Clone from brother
Attached file log for update failed.
Clone from brother
karen/jason, what's your thoughts on this? thanks
Whiteboard: [apps watch list1]
Flags: needinfo?(jsmith)
Flags: needinfo?(jsmith)
Whiteboard: [apps watch list1] → [apps watch list]
(In reply to Joe Cheng [:jcheng] from comment #3)
> karen/jason, what's your thoughts on this? thanks

Uh oh. We recently modified how we preinstall appcache for hosted apps that preinstall appcache. Which Accuweather and Wikipedia happen to fall into that category. Let me see if I can reproduce.

Btw - the log doesn't tell me anything. needinfo on fabrice to see if he has any ideas as well.
Flags: needinfo?(fabrice)
I can reproduce on a Ikura 5/30 build. This is bad.
Trying to do a second update after the update failure causes the download to get stuck at 0.00 bytes. This sounds like a dom apps bug.
Uh oh. Saw this in the logs during the 0.00 bytes downloading:

05-31 09:44:49.899: E/GeckoConsole(113): Content JS INFO at app://system.gaiamobile.org/js/updatable.js:102 in anonymous: downloadError event, error code is NO_DOWNLOAD_AVAILABLE
Component: Gaia → DOM: Apps
Product: Boot2Gecko → Core
Version: unspecified → Trunk
Root cause bug here btw:

Trying to update a hosted app preloading appcache that was preinstalled will fail to update
Summary: [Buri]Some apps cannot be updated → [Buri] Trying to update a hosted app preloading appcache that was preinstalled will fail to update
I installed the spain customization and set debug on in webapps.jsm. When we check for updates I get: 

-*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate return for http://m.accuweather.com/mozilla.webapp - event is offline-cache-update-available

-*-*- Webapps.jsm : updateHostedApp: updateSvc.checkForUpdate return for https://bits.wikimedia.org/WikipediaMobileFirefoxOS/manifest.webapp - event is offline-cache-update-available

I then only selected accuweather to update:
I/Gecko   ( 1979): -*-*- Webapps.jsm : startDownload for http://m.accuweather.com/mozilla.webapp
I/Gecko   ( 1979): -*-*- Webapps.jsm : appcache found
I/Gecko   ( 1979): -*-*- Webapps.jsm : Saving /data/local/webapps/webapps.json
I/Gecko   ( 1979): -*-*- Webapps.jsm : Creating AppcacheObserver for http://m.accuweather.com - updating
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 5
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to updating with progress 0 for http://m.accuweather.com
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 6
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to updating with progress 0 for http://m.accuweather.com
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 6
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to updating with progress 0 for http://m.accuweather.com
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 6
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to updating with progress 0 for http://m.accuweather.com
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to updating with progress 512 for http://m.accuweather.com
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 7
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 7
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to updating with progress 21893 for http://m.accuweather.com
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to updating with progress 41193 for http://m.accuweather.com
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 8
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 7
E/GeckoConsole( 1979): Offline cache update done, URL=http://m.accuweather.com/awx.appcache
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offline cache state change for http://m.accuweather.com : 10
I/Gecko   ( 1979): -*-*- Webapps.jsm : Offlinecache setStatus to installed with progress 52690 for http://m.accuweather.com

So everything went fine here also, and I have one less app in the "to update" list. I then selected wikipedia to update, and that worked too.
Flags: needinfo?(fabrice)
Fabrice - What device did you test that on?

I reproduced this on Ikura, FWIW.
(In reply to Jason Smith [:jsmith] from comment #13)
> Fabrice - What device did you test that on?
> 
> I reproduced this on Ikura, FWIW.

Ikura partner build 5/30 to be specific.
I tested on v1-train with a leo device. I have no 1.01 build ready that I can tweak quickly
And now I'm not even getting updates for the wikipedia and accuweather apps after restarting the phone and checking for updates on the partner build. Let me flash a clean build and try testing this again.
Keywords: qawanted
QA Contact: jsmith
Still reproduces for me on a clean flashed 5/30 Ikura partner build.
Keywords: qawanted
Assignee: nobody → fabrice
Weird. So apparently this problem fixes itself on a restart after applying the update (or we stopped checking for updates entirely). We need to understand which one it is however:

1. Did we complete the update after a restart?
2. Did we give up permanently on trying to find an update after a restart?
I checked on a buri with a current 1.0.1 build (I had to rebuild gecko to add debug info) and this worked like expected. I'm confused.
I flashed a different customization this time (before was latam, this time I did spain) for Ikura. Still can reproduce this bug with Accuweather and Wikipedia.

This time I tested this with a spain customization on a 5/28 partner build.
Duplicate of this bug: 878451
i am seeing the same thing on Buri partner build just as reported and as Jason
It looks like a tef+ bug to me.
(In reply to Fabrice Desré [:fabrice] from comment #19)
> I checked on a buri with a current 1.0.1 build (I had to rebuild gecko to
> add debug info) and this worked like expected. I'm confused.

Fabrice, did you use partner customized build? Thanks.
I can reproduce this bug in both Buri and Ikura.
Moved to TEF+ based on discussion with Carrier (Shira - Stephan F)
blocking-b2g: tef? → tef+
Target Milestone: --- → 1.0.1 IOT3 (3jun)
(In reply to kward@mozilla.com from comment #26)
> Moved to TEF+ based on discussion with Carrier (Shira - Stephan F)

Agreed.

(In reply to khu from comment #24)
> (In reply to Fabrice Desré [:fabrice] from comment #19)
> > I checked on a buri with a current 1.0.1 build (I had to rebuild gecko to
> > add debug info) and this worked like expected. I'm confused.
> 
> Fabrice, did you use partner customized build? Thanks.

I'm think the testing Fabrice is doing here is with debug builds to see if he can reproduce generally on our own builds. Which it looks like we cannot reproduce it on own builds. But we can reproduce it on partner builds. This is definitely strange.

I'll debug with this with Fabrice today.
Some context from discussion with fabrice in IRC:

fabrice	jsmith: I reproed the update issue. Not sure yet if it's a gecko or gaia issue, but it seems gaia restarts updates for already updated apps and that fails
jsmith	fabrice: Hmm okay. Did you reproduce it on the partner build or your own build?
fabrice	jsmith: partner build, but what happens is : first update went fine, but then gaia still insists that we can update the app, and this fails
fabrice	something is definitely wrong somewhere
jsmith	fabrice: That's really strange. So that actually explains why then if I restart the phone, I never find that I have an update available.
fabrice	yes
I re-tested using a partner build (P752D04_TME_FOR_PARTENER_20130602), where the only change I made was enabling debug output in Webapps.jsm and adding some in Webapps.js

Here's what I saw:
1) At first check for updates, I'm offered 7 updates, including accuweather and wikipedia that use appcache.
2) I updated accuweather only, that went fine. 6 updates remaining.
3) I updated wikipedia only, that went fine, but I still have 6 updates remaining: accuweather is once again said to be updatable.
4) I tried to update accuweather again, and here I got the never ending throbber with a 0.00 download progress.

The logs for this last step shows this:
I/Gecko   ( 2273): -*-*- Webapps.jsm : startDownload for http://m.accuweather.com/mozilla.webapp
I/Gecko   ( 2273): -*-*- Webapps.jsm : No download available, bailing out with Webapps:PackageEvent canceled
I/Gecko   ( 2421): Webapps.js : canceled, donwloaderror = NO_DOWNLOAD_AVAILABLE
I/Gecko   ( 2273): Webapps.js : canceled, donwloaderror = NO_DOWNLOAD_AVAILABLE
I/Gecko   ( 2273): Webapps.js : canceled, donwloaderror = NO_DOWNLOAD_AVAILABLE
I/Gecko   ( 2273): Webapps.js : canceled, donwloaderror = NO_DOWNLOAD_AVAILABLE

So it looks everything is ok on the gecko side, and webapps.json is consistent with that observation. We need someone to debug the gaia side at this point.
Hmm...okay. Julien is on PTO.

Etienne - Can you help with debugging this on the Gaia side?
Flags: needinfo?(etienne)
cc'ing honza in case there's gecko bits involved here--but sounds like this is prob a gaia bug.
I am |console.log| through the updatable.js in Gaia ... so far I got errorCallback filed for Wikipedia update.
I tried to reproduce this on unagi without success; they both updated successfully on the second try.
(In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) from comment #33)
> I tried to reproduce this on unagi without success; they both updated
> successfully on the second try.

Testing we've done here so far has revealed that only reproduces on partner builds, not builds we make.
OK, here is the STR and the bug I saw, specifically on Gaia (and maybe Gecko on it's API design) is that

0. On a Unagi
1. Latest OTA Gecko, do |make reset-gaia| on Gaia v1.0.1 with Accuweather and Wikipedia copied to external-apps.
2. Wait for some time and the update dialog will pop-up, for update are offered (Here map, Marketplace, Accuweather and Wikipedia).
3. Press "update all"
4. Marketplace and Here map will fail with error code NO_DOWNLOAD_AVAILABLE, Wikipedia and Accuweather will be updated.

Expected

1. Two "update failed" banner will be shown. The update hint on the utility tray will stop offer Wikipedia and Accuweather, but give the user a change to re-try Here map and Marketplace.

Actual

1. The update hint on the utility tray stay the same, offers four app updates.
2. As soon as I press the the "update all" again, the same expected update error will shown for Marketplace and Here map
3. But for Wikipedia and Accuweather, no callback (error nor success) will ever fired by Gecko.
4. The UI will keep showing "downloading... 0.00 bytes downloaded." and never finish.
(In reply to Jason Smith [:jsmith] from comment #34)
> (In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) from comment #33)
> > I tried to reproduce this on unagi without success; they both updated
> > successfully on the second try.
> 
> Testing we've done here so far has revealed that only reproduces on partner
> builds, not builds we make.

OK, maybe the bug of previous comment is unrelated?

If this only happens on partner build, I will not be able to debug it because I cannot remount the system partition.
Did some initial investigation and was able to reproduce on partner build... I was not able to come up with a quick fix before my EOD- debug patch attached above maybe this will be somewhat helpful... If there is not a patch by the morning I will continue looking into it.
Assignee: fabrice → jcheng
Component: DOM: Apps → Gaia::System
Product: Core → Boot2Gecko
Version: Trunk → unspecified
Update: I think Etienne or anyone would be happy to deliver a fix if this bug explicitly is about what I mentioned on comment 35.

I don't want to push for a unrelated fix on the same place and not actually fix the bug.
Rudy and I is now working on reproduce the bug on pvt build.
Assignee: jcheng → timdream
(In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) from comment #40)
> Rudy and I is now working on reproduce the bug on pvt build.

I am currently having trouble reproducing this on pvt build because the phone does not offer me an update.
(In reply to Jason Smith [:jsmith] from comment #28)
> Some context from discussion with fabrice in IRC:
> 
> fabrice	jsmith: I reproed the update issue. Not sure yet if it's a gecko or
> gaia issue, but it seems gaia restarts updates for already updated apps and
> that fails
> jsmith	fabrice: Hmm okay. Did you reproduce it on the partner build or your
> own build?
> fabrice	jsmith: partner build, but what happens is : first update went fine,
> but then gaia still insists that we can update the app, and this fails
> fabrice	something is definitely wrong somewhere
> jsmith	fabrice: That's really strange. So that actually explains why then if
> I restart the phone, I never find that I have an update available.
> fabrice	yes

Base on this comment I would say we somehow manage to reproduce the same thing (comment 35) but with different steps. I am now trying to find a way to fix that issue, but the original author (Etienne) should work on this in if he is available.
I am now convinced that Gecko is at fault here.

UpdateManager kepts all the reference of available-for-update app in |UpdateManager.updatesQueue|, and the reference is supposed to be removed once there is no update available (i.e. update is applied).

If you update 2 apps at the same time, when the #1 app completes it's update, we do removed the apps in |removeFromUpdatesQueue()|; that part of the code didn't fail. However, The #1 app is being add back to the queue by |checkStatuses()| as soon as all #2 is downloaded and the queue is empty.

https://github.com/mozilla-b2g/gaia/blob/88277996/apps/system/js/update_manager.js#L461

|checkStatuses()| will look for |app.downloadAvailable| flag, and the flag is true for the updated app, so it's being add back to the queue.
Assignee: timdream → nobody
Component: Gaia::System → DOM: Apps
Product: Boot2Gecko → Core
(In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) from comment #43)
> |checkStatuses()| will look for |app.downloadAvailable| flag, and the flag
> is true for the updated app, so it's being add back to the queue.

Long story short: |app.downloadAvailable| flag did not flip to false after a successful app update.
Summing up the comments it looks like the fundamental issue is that we have an app in the |UpdateManager.updatesQueue| that shouldn't be here anymore.
If true rebooting the phone should fix the problem (since we don't persist the updates queue on the gaia side).

Looking at the gecko code it looks like the app object is always updated properly before the success/error callback is called. So not sure what's causing the updates queue to get out of sync.

That said, an easy and safe change would be to remove any app where |!app.downloadAvailable| from the updates queue in the |checkStatuses()| method.

I'll send a WIP asap but I'll need QA.
So, scratch Comment 45 :) (Thanks Tim!)

Looks like the gecko code updates the |app.downloadAvailable| properly for Webapps:PackageEvent messages but not for Webapps:OfflineCache messages [1].

So in gaia we see that, even if there was an error, |app.downloadAvailable| is still true so we keep the app in the updates queue [2].

[1] https://mxr.mozilla.org/mozilla-central/source/dom/apps/src/Webapps.js#567
[2] https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/updatable.js#L107
Flags: needinfo?(etienne)
Attached patch WIP (obsolete) — Splinter Review
Last time I tried to write a quick patch for Webapps.jsm it didn't end well :)

But I _think_ this could help.
Attachment #757904 - Flags: feedback?(fabrice)
(In reply to Etienne Segonzac (:etienne) from comment #47)
> Created attachment 757904 [details] [diff] [review]
> WIP
> 
> Last time I tried to write a quick patch for Webapps.jsm it didn't end well
> :)
> 
> But I _think_ this could help.

Wrong patch?
Attached patch WIP (obsolete) — Splinter Review
The good patch.
Attachment #757904 - Attachment is obsolete: true
Attachment #757904 - Flags: feedback?(fabrice)
Attachment #757914 - Flags: feedback?(fabrice)
Leaving breadcrumbs for Fabrice.

- I'm not able to reproduce the issue in tests :/
- looks like the downloadAvailable flag should already be correctly taken care of for AppCache apps [1].

[1] https://mxr.mozilla.org/mozilla-central/source/dom/apps/src/Webapps.jsm#1496
(In reply to Etienne Segonzac (:etienne) from comment #50)
> Leaving breadcrumbs for Fabrice.
> 
> - I'm not able to reproduce the issue in tests :/

But I'm not sure I understand the test.
The comments says we should always have a new update and then asserts that we never get a |ondownloadavailable| callback [1].


[1] https://mxr.mozilla.org/mozilla-central/source/dom/apps/tests/test_app_update.html?force=1#151
Attached patch patchSplinter Review
This is the simplest and safest patch to fix that. This ensure that https://mxr.mozilla.org/mozilla-central/source/dom/apps/src/Webapps.jsm#3204 and https://mxr.mozilla.org/mozilla-central/source/dom/apps/src/Webapps.js#567 are kept in sync.

We should also fix the bug in gaia where we don't honor the downloaderror after doing a startDownload() while downloadAvailable is false.
Assignee: nobody → fabrice
Attachment #757914 - Attachment is obsolete: true
Attachment #757914 - Flags: feedback?(fabrice)
Attachment #758062 - Flags: review?(ferjmoreno)
(In reply to Fabrice Desré [:fabrice] from comment #52)
> We should also fix the bug in gaia where we don't honor the downloaderror
> after doing a startDownload() while downloadAvailable is false.

errorCallback didn't fire in this case; Gecko should have fire the callback when |startDownload()| is call while downloadAvailable is false. Anyhow, let's fix the |downloadAvailable| first.
(In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) from comment #53)
> (In reply to Fabrice Desré [:fabrice] from comment #52)
> > We should also fix the bug in gaia where we don't honor the downloaderror
> > after doing a startDownload() while downloadAvailable is false.
> 
> errorCallback didn't fire in this case; Gecko should have fire the callback
> when |startDownload()| is call while downloadAvailable is false. Anyhow,
> let's fix the |downloadAvailable| first.

I'm sorry Tim but that's not true. I have debug traces showing gecko firing the event in this case (see comment 29,  but you did not try to repro these steps).
Comment on attachment 758062 [details] [diff] [review]
patch

I'm helping land this to all the needed branches.
Attachment #758062 - Flags: review?(ferjmoreno) → review+
Keywords: verifyme
(In reply to Fabrice Desré [:fabrice] from comment #54)
> I'm sorry Tim but that's not true. I have debug traces showing gecko firing
> the event in this case (see comment 29,  but you did not try to repro these
> steps).

Hum, I am seeing the entire opposite in Gaia :-/
https://hg.mozilla.org/mozilla-central/rev/c8e85b2b4cce
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
(In reply to Tim Guan-tin Chien [:timdream] (MoCo-TPE) from comment #58)
> (In reply to Fabrice Desré [:fabrice] from comment #54)
> > I'm sorry Tim but that's not true. I have debug traces showing gecko firing
> > the event in this case (see comment 29,  but you did not try to repro these
> > steps).
> 
> Hum, I am seeing the entire opposite in Gaia :-/

Can you please clearly state if there is anything wrong in Gecko?

If so, please open a new bug (CC me) and put reliable and as much as possible simple STR, thanks.
(In reply to Honza Bambas (:mayhemer) from comment #60)
> 
> Can you please clearly state if there is anything wrong in Gecko?
> 
> If so, please open a new bug (CC me) and put reliable and as much as
> possible simple STR, thanks.

Honza, there was no problem with the appcache implementation itself here.
(In reply to Fabrice Desré [:fabrice] from comment #61)
> Honza, there was no problem with the appcache implementation itself here.

Thanks.
(In reply to Fabrice Desré [:fabrice] from comment #52)
> We should also fix the bug in gaia where we don't honor the downloaderror
> after doing a startDownload() while downloadAvailable is false.

We do honor it, we always display the error banner and remove the app from the active downloads.

We just don't remove the app from the _available_ updates if the app still has downloadAvailable set to true.
On a 6/6 Buri 1.01 build, this patch doesn't work for me. I'm still failing to update Accuweather and Wikipedia.
Followup filed in bug 880826.
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.