931740 - [B2G][FOTA]The handset has no response if sdcard is full before applied the update

Status: RESOLVED FIXED

(Firefox OS Graveyard :: General, defect)

Description

[Kai-Zhen Li [:seinlin][:kli]]

【Repro Steps*】：
    1、Make sure the sdcard(/mnt/sdcard/) volume has enough space the do update(has space more than twice update file size).
    2、Enter into the settings, click 'check now' to get update info.
    3、Download the update file.
    4、When it start to download the update file, suspend the download. 
    5、Push some file into the /mnt/sdcard/  volume, let the remain space less than twice the update file size but more than the update file size(use adb push command)
    6、Push some file into the /data/local/  volume, let the remain space less the update file size(use adb push command)
    7、Resume the download.
    8、When the download execute to the case there is no space(has begin to uncompress), the handset has no response.  You can not boot the handset in any way. It will get a freeze device at booting logo. 

【Expect Result*】：
    The handset has response and notice that there is no space.
	
【Real Result*】：
    The handset has no response.  You can not boot the handset in any way.  It will get a freeze device at booting logo.

Comment 1

[Kai-Zhen Li [:seinlin][:kli]]

This bug is created to track the issue #2 of Bug 927291, which is caused by a different issue and needs a totally different fix.

Comment 2

[Kai-Zhen Li [:seinlin][:kli]]

Attachment: fota_applied_failed.txt

In normal case, after update.mar is downloaded, it will be applied as update.zip.

In attached file, after update.mar is downloaded and the space is not enough before it is applied. I think the update process should stop here.

Don't know why updater will continue apply the update in a different way, remount /system and apply update.zip to /system/b2g. This will cause the device can't boot anymore until ./flash gecko to it.

Comment 3

[Dave Hylands [:dhylands]]

Based on looking at the fota_applied_failed.txt, this was not a fota update.

I created a FOTA update for my unagi. If I then run:

  mar -t update.mar

it shows:

SIZE	MODE	NAME
67	0664	update.manifest
78	0664	updatev2.manifest
14	0644	precomplete
107722903	0644	update.zip

Because there are only 4 files, the progress output should only have 5 lines, and will typically look something like:

Progress [ =====                                              ]
Progress [ ==========                                         ]
Progress [ ============================                       ]
Progress [ ===============================================    ]
Progress [ ================================================   ]
Progress [ ================================================== ]

The progress indicator in the attachment looks like an update.mar for a regular OTA.

Comment 4

[Wayne Chang [:wchang]]

(In reply to Kai-Zhen Li from comment #0)
>     5、Push some file into the /mnt/sdcard/  volume, let the remain space
> less than twice the update file size but more than the update file size(use
> adb push command)
>     6、Push some file into the /data/local/  volume, let the remain space
> less the update file size(use adb push command)
>     7、Resume the download.
>     8、When the download execute to the case there is no space(has begin to
> uncompress), the handset has no response.  You can not boot the handset in
> any way. It will get a freeze device at booting logo. 

Device freezes at boot logo likely due to system unable to write to /data partition, not directly related to the FOTA file. Maybe what we should consider is to have some sort of protection mechanism that ensures /data is never completely filled.

Comment 5

[Kai-Zhen Li [:seinlin][:kli]]

Attachment: fota_applied_success.txt

Dave, you are right, normal fota will get a different behavior. 

fota_applied_success.txt and fota_applied_failed.txt are testing log with the same update.mar file.

The different is, I try to make the space of sdcard is not enough to apply the update by pushing some file to it before the downloading is completed.

Suppose, when DirectoryProvider return null to indicate that the required space is not available, b2g should stop apply the update.

But the actual behavior I found it, b2g will continue to apply the update after modified the osUpdate=ture --> osUpdate=false for an unknown reason.

So I still looking for where and why osUpdate is modified from 'true' to 'false' and cause the update failed and the device will be brick.

Comment 6

[Kai-Zhen Li [:seinlin][:kli]]

Attachment: DirectoryProvider.diff

Hi, Dave, Do you think if it is reasonable to calculate the required space for each step? Because it is not required 2xsize before applying update.mar to update.zip.

Comment 7

[Kai-Zhen Li [:seinlin][:kli]]

I also found a strange case here, when the required space is not enough, ds->Get will return NS_ERROR_FAILURE, the process isn't assert failed and cause a "Segmentation fault".

http://dxr.mozilla.org/mozilla-central/source/toolkit/xre/nsUpdateDriver.cpp#611
--
  DebugOnly<nsresult> rv = ds->Get(XRE_OS_UPDATE_APPLY_TO_DIR, NS_GET_IID(nsIFile),
                                   getter_AddRefs(osApplyToDir));
  NS_ASSERTION(NS_SUCCEEDED(rv), "Can't get the OS applyTo dir");
--


After I replace "NS_ASSERTION(NS_SUCCEEDED(rv), "Can't get the OS applyTo dir");" with the following check, update will fail and prevent the device crash as in comment 2.
--
  if (NS_FAILED(rv)) {
    return rv;
  }
--

Also need to replace here http://dxr.mozilla.org/mozilla-central/source/toolkit/xre/nsUpdateDriver.cpp#1143

Comment 8

[Dave Hylands [:dhylands]]

(In reply to Kai-Zhen Li from comment #6)
> Created attachment 8336716 [details] [diff] [review]
> DirectoryProvider.diff
> 
> Hi, Dave, Do you think if it is reasonable to calculate the required space
> for each step? Because it is not required 2xsize before applying update.mar
> to update.zip.

Before starting the download, we need approx 2 x size of the update.mar file.

1 x is to store the update.mar
1 x is to store the update.zip (since update.zip is already compressed, it doesn't get much further compression and most of the size of the update.mar is the update.zip file.

Obviously, once the update.mar file has been downloaded, we no longer need 2x the size of the update.mar, we ony need 1x (or perhaps less if the update.zip has been partially or completely extracted)

Is this what you're asking about?

Comment 9

[Kai-Zhen Li [:seinlin][:kli]]

(In reply to Dave Hylands [:dhylands] from comment #8)
> (In reply to Kai-Zhen Li from comment #6)
> 
> Before starting the download, we need approx 2 x size of the update.mar file.
> 
> 1 x is to store the update.mar
> 1 x is to store the update.zip (since update.zip is already compressed, it
> doesn't get much further compression and most of the size of the update.mar
> is the update.zip file.
> 
> Obviously, once the update.mar file has been downloaded, we no longer need
> 2x the size of the update.mar, we ony need 1x (or perhaps less if the
> update.zip has been partially or completely extracted)
> 
> Is this what you're asking about?

Yes, now we check 2x for two times, before download and before extract update.mar. So the available size must be 3x to get the update success. 
And I found that update.zip is a little larger than update.mar, that why I think we should use 2.1x OR a little more than 2x to ensure the space is enough.

Comment 10

[Dave Hylands [:dhylands]]

Comment on attachment 8336716 [details] [diff] [review]
DirectoryProvider.diff

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

This feels backwards to me.

The process for OTA:

- download update.mar (so we need 1x the space in /data or /sdcard - where ever we're downloading to)
- unpack update.mar (so we need 1x the space in /system)

The process for FOTA:

- download update.mar (so we need 1x the space in /data or /sdcard - where ever we're downloading to)
- unpack the update.mar to create update.zip - we need an additional 1x space

So I think that for OTA we should be checking for 1.1x space in the download location and the uncompressed size in /system (I don't think that we're doing this test now - I'd be good with filing a followup bug)

And for FOTA we should be checking for 2.1x the space (since we need to store both the update.mar and update.zip)

Comment 11

[Kai-Zhen Li [:seinlin][:kli]]

This issue happens on FOTA update. 

It is very easy to duplicate this issue, the current behaviour is as below:
case 1: available space > 3X, update successfully
case 2: available space < 2X, update will not start
case 3: 3X > available space > 2X, update will start but device has no response after update and apply.

There are two reasons why case 3 fail
1. we should check the 2X available space after the update.mar is downloaded.
2. in case of available space is enough in second time check, the update should stop; now the update will continue as in comment 7. I notice that when available space check failed the service didn't stop and cause segment fault. A new thread is started to continue the update and result a strange behaviour.

Now, update service will check 2X available space TWO TIMES. That's why I think we should check the available space depends on requirement of each step as in  attachment 8336716 [details] [diff] [review].

Comment 12

[Dave Hylands [:dhylands]]

(In reply to Kai-Zhen Li from comment #11)
> This issue happens on FOTA update. 
> 
> It is very easy to duplicate this issue, the current behaviour is as below:
> case 1: available space > 3X, update successfully
> case 2: available space < 2X, update will not start
> case 3: 3X > available space > 2X, update will start but device has no
> response after update and apply.
> 
> There are two reasons why case 3 fail
> 1. we should check the 2X available space after the update.mar is downloaded.

So I guess the question is why do we need 2x the available space AFTER the update.mar is downloaded?

I could conceive that perhaps the recovery ROM is expanding the .zip file in the volume where the update.zip is located. If that's the case then we need the uncompressed size of the update.mar + the uncompressed size of the update.zip.

It could be really good to know exactly what the extra space is needed for so that we can size it properly.

Can you supply a log from the recover ROM when we hit case 3? (i.e. /cache/recovery/last_log)

> 2. in case of available space is enough in second time check, the update
> should stop; now the update will continue as in comment 7. I notice that
> when available space check failed the service didn't stop and cause segment
> fault. A new thread is started to continue the update and result a strange
> behaviour.

This is probably worth a bug of its own.

> Now, update service will check 2X available space TWO TIMES. That's why I
> think we should check the available space depends on requirement of each
> step as in  attachment 8336716 [details] [diff] [review].

I agree that the amount of each space changes depending on when you check, and it makes sense to pass in some state which allows the code to check for the correct amount of space.

Comment 13

[Kai-Zhen Li [:seinlin][:kli]]

(In reply to Dave Hylands [:dhylands] from comment #12)
> 
> So I guess the question is why do we need 2x the available space AFTER the
> update.mar is downloaded?

Sorry, what I'd like to say is we should not to check 2X after update.mar is download. 
Actually a little bit more than 1X is enough.

> I could conceive that perhaps the recovery ROM is expanding the .zip file in
> the volume where the update.zip is located. If that's the case then we need
> the uncompressed size of the update.mar + the uncompressed size of the
> update.zip.
> 
> It could be really good to know exactly what the extra space is needed for
> so that we can size it properly.
> 
> Can you supply a log from the recover ROM when we hit case 3? (i.e.
> /cache/recovery/last_log)
>

When the error happen, the device is not reboot into recovery ROM, and the device can't be boot up at all until flash gecko. 
I'd checked /system/b2g, I can see "update.zip" will be there and some files are missing. The missing files could be different in each time of test. I try many times, the symptoms are the same.


> > 2. in case of available space is enough in second time check, the update
> > should stop; now the update will continue as in comment 7. I notice that
> > when available space check failed the service didn't stop and cause segment
> > fault. A new thread is started to continue the update and result a strange
> > behaviour.
> 
> This is probably worth a bug of its own.
> 

OK, I will file a new bug for these error.

Comment 14

[Kai-Zhen Li [:seinlin][:kli]]

Hi Dave, I verified attachment 8336716 [details] [diff] [review] together with patch from bug 947585. 
Both OTA and FOTA can work properly. I'd like to submit a patch for attachment 8336716 [details] [diff] [review]. 
Do you have other suggestion? 
Thanks!

Comment 15

[Dave Hylands [:dhylands]]

So I played around with this a bit and ran into the following situation:

My update.mar was 96 Mb. There was about 120 Mb free on /sdcard. I modified DirectoryProvider.js to not even look in /data (so I didn't have to keep filling it up).

The first time I tried to apply the update, it failed with a file too big error.

18:02:44.487 512/512                     Gecko  I   *** AUS:SVC Creating Downloader
18:02:44.487 512/512              GeckoConsole  E   AUS:SVC Creating Downloader
18:02:44.487 512/512                     Gecko  I   *** AUS:SVC UpdateService:_downloadUpdate
18:02:44.487 512/512              GeckoConsole  E   AUS:SVC UpdateService:_downloadUpdate
18:02:44.497 512/512                     Gecko  I   *** AUS:SVC readStringFromFile - file doesn't exist: /data/local/updates/0/update.status
18:02:44.497 512/512              GeckoConsole  E   AUS:SVC readStringFromFile - file doesn't exist: /data/local/updates/0/update.status
18:02:44.497 512/512                     Gecko  I   *** AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:02:44.497 512/512              GeckoConsole  E   AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:02:44.507 512/512                     Gecko  I   *** AUS:SVC UpdateManager:_loadXMLFileIntoArray: XML file does not exist
18:02:44.507 512/512              GeckoConsole  E   AUS:SVC UpdateManager:_loadXMLFileIntoArray: XML file does not exist
18:02:44.507 512/512                     Gecko  I   *** AUS:SVC UpdateManager:_loadXMLFileIntoArray: XML file does not exist
18:02:44.507 512/512              GeckoConsole  E   AUS:SVC UpdateManager:_loadXMLFileIntoArray: XML file does not exist
18:02:44.597 512/512                     Gecko  I   *** AUS:SVC readStringFromFile - file doesn't exist: /data/local/updates/0/update.status
18:02:44.597 512/512              GeckoConsole  E   AUS:SVC readStringFromFile - file doesn't exist: /data/local/updates/0/update.status
18:02:44.597 512/512                     Gecko  I   *** AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:02:44.597 512/512              GeckoConsole  E   AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:02:44.597 512/512                     Gecko  I   getUpdateDir: xsize = 2.1
18:02:44.607 512/512                     Gecko  I   getUpdateDir: requiredSpace = 202018786.20000002
18:02:44.607 512/512                     Gecko  I   DirectoryProvider: Error: No volume found with 202018786.20000002 bytes for downloading update Firefox 99.0
18:02:44.607 512/512                     Gecko  I   getUpdateDir: Returning NS_ERROR_FILE_TOO_BIG
18:02:44.617 512/512                     Gecko  I   UpdatePrompt: Error downloading update Firefox 99.0: -2142109681
18:02:44.617 512/512                     Gecko  I   UpdatePrompt: Update error, state: null, errorCode: -2142109681
18:02:44.687 512/512                     Gecko  I   UpdatePrompt: Setting gecko.updateStatus: file-too-big
18:02:44.707 512/512                 GeckoDump  I   XXX FIXME : Got a mozContentEvent: update-available-result

However, I didn't see any indication of the error on the U. It just went back to looking like there was a download available.

I then went to the sdcard and freed up some space, so that there was now 222Mb free, and tried to redownload.

The second time, I also got a file-too-big error, but it didn't actually check for free space. It seems to just be reporting the file-too-big error from the first download attempt.

18:04:44.234 512/512                     Gecko  I   *** AUS:SVC Creating Downloader
18:04:44.234 512/512              GeckoConsole  E   AUS:SVC Creating Downloader
18:04:44.234 512/512                     Gecko  I   *** AUS:SVC UpdateService:_downloadUpdate
18:04:44.234 512/512              GeckoConsole  E   AUS:SVC UpdateService:_downloadUpdate
18:04:44.244 512/512                     Gecko  I   *** AUS:SVC readStringFromFile - file doesn't exist: /data/local/updates/0/update.status
18:04:44.244 512/512              GeckoConsole  E   AUS:SVC readStringFromFile - file doesn't exist: /data/local/updates/0/update.status
18:04:44.244 512/512                     Gecko  I   *** AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:04:44.244 512/512              GeckoConsole  E   AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:04:44.244 512/512                     Gecko  I   *** AUS:SVC Downloader:_selectPatch - found existing patch with state: null
18:04:44.244 512/512              GeckoConsole  E   AUS:SVC Downloader:_selectPatch - found existing patch with state: null
18:04:44.244 512/512                     Gecko  I   *** AUS:SVC Downloader:_selectPatch - failed to apply complete patch!
18:04:44.244 512/512              GeckoConsole  E   AUS:SVC Downloader:_selectPatch - failed to apply complete patch!
18:04:44.334 512/512                     Gecko  I   *** AUS:SVC Downloader:downloadUpdate - no patch to download
18:04:44.334 512/512              GeckoConsole  E   AUS:SVC Downloader:downloadUpdate - no patch to download
18:04:44.344 512/512                     Gecko  I   *** AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:04:44.354 512/512              GeckoConsole  E   AUS:SVC readStatusFile - status: null, path: /data/local/updates/0/update.status
18:04:44.354 512/512                     Gecko  I   UpdatePrompt: Error downloading update Firefox 99.0: -2142109681
18:04:44.354 512/512                     Gecko  I   UpdatePrompt: Update error, state: null, errorCode: -2142109681
18:04:44.494 512/512                     Gecko  I   UpdatePrompt: Setting gecko.updateStatus: file-too-big
18:04:44.524 512/512                 GeckoDump  I   XXX FIXME : Got a mozContentEvent: update-available-result

I can tell because the prints I added into getUpdateDir and the DirectoryProvider error didn't show up.

So I think something wasn't left in an appropriate state after the first download attempt.

Comment 16

[Kai-Zhen Li [:seinlin][:kli]]

Hi Dave, The error in second time is a different issue. I filed a bug and you can see bug 950534 for detail.

Comment 17

[Dave Hylands [:dhylands]]

Hi Kai-Zhen,

Yes - I was thinking about it some more after I made that comment. Let me do a couple more tests, and if they're good, I'll change my review to r+

Comment 18

[Kai-Zhen Li [:seinlin][:kli]]

Attachment: bug-931740-fix.patch

Comment 19

[Dave Hylands [:dhylands]]

Comment on attachment 8348534 [details] [diff] [review]
bug-931740-fix.patch

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

OK - finished all of my testing. Looks good.

Comment 20

[Jason Smith [:jsmith]]

blocking because updates need to be solid

Comment 21

[Kai-Zhen Li [:seinlin][:kli]]

Try result: 
https://tbpl.mozilla.org/?tree=Try&rev=7c5e96d506a6
https://tbpl.mozilla.org/?tree=Try&rev=e69724f87b1b

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/4546a3b6c2b0

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/4546a3b6c2b0

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/8911ddbd3ab7