876307 - [FOTA]system crash after the update package has been downloaded

Status: RESOLVED FIXED

(Firefox OS Graveyard :: General, defect)

Description

[songsy]

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.63 Safari/537.31

Steps to reproduce:

1) boot up the system 
2) Check system updates: Settings->device infomation->Check for updates
3) Download the system update package



Actual results:

system crash after the update package has been downloaded


Expected results:

After the update package has been downloaded, the system should verify the update package and then notify user to update

Comment 1

[Jason Smith [:jsmith]]

We need a crash stack here.

Can you get a crash report URL?

Comment 2

[songsy]

The crash is caused by fanotify_event_metadata.

Here is the output of logcat:
I/Adreno200-EGLSUB(  111): <GetImageAttributes:1200>: RGBA_8888
I/Gecko   (  111): *** AUS:SVC Downloader:onProgress - progress: 7048972/8478730
I/Adreno200-EGLSUB(  111): <CreateImage:991>: Android Image
I/Adreno200-EGLSUB(  111): <GetImageAttributes:1200>: RGBA_8888
I/Gecko   (  111): *** AUS:SVC Downloader:onProgress - progress: 7362244/8478730
I/Adreno200-EGLSUB(  111): <CreateImage:991>: Android Image
I/Adreno200-EGLSUB(  111): <GetImageAttributes:1200>: RGBA_8888
I/Gecko   (  111): *** AUS:SVC Downloader:onProgress - progress: 7716556/8478730
I/Adreno200-EGLSUB(  111): <CreateImage:991>: Android Image
I/Adreno200-EGLSUB(  111): <GetImageAttributes:1200>: RGBA_8888
I/Gecko   (  111): *** AUS:SVC Downloader:onProgress - progress: 8053084/8478730
I/Adreno200-EGLSUB(  111): <CreateImage:991>: Android Image
I/Adreno200-EGLSUB(  111): <GetImageAttributes:1200>: RGBA_8888
I/Gecko   (  111): *** AUS:SVC Downloader:onProgress - progress: 8356780/8478730
I/Adreno200-EGLSUB(  111): <CreateImage:991>: Android Image
I/Adreno200-EGLSUB(  111): <GetImageAttributes:1200>: RGBA_8888
I/Gecko   (  111): *** AUS:SVC Downloader:onProgress - progress: 8478730/8478730
I/Gecko   (  111): *** AUS:SVC Downloader:onStopRequest - original URI spec: http://firefox.ztems.com/prerelease/roamer2/\
18.0/20130527030711/update.mar, final URI spec: http://firefox.ztems.com/prerelease/roamer2/18.0/20130527030711/update.ma\
r, status: 0
I/Gecko   (  111): *** AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 20, retryTimeout: 30000
I/Gecko   (  111): *** AUS:SVC Downloader:_verifyDownload called
I/Gecko   (  111): *** AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
I/Gecko   (  111): *** AUS:SVC Downloader:_verifyDownload hashes match.
I/Gecko   (  111): *** AUS:SVC Downloader:onStopRequest - setting state to: pending
I/Gecko   (  111): *** AUS:SVC gCanStageUpdates - able to stage updates because we'll use the service
I/Gecko   (  111): *** AUS:SVC UpdateService:applyUpdateInBackground called with the following update: Firefox 18.0
I/Gecko   (  111): About to crash: fanotify_event_metadata read error.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
I/GonkAutoMounter( 1141): Mounted /system partition as read-write
I/GeckoUpdater( 1141): Progress [ =====                                              ]
I/GeckoUpdater( 1141): Progress [ ==========                                         ]
E/AudioHardwareMSM76XXA( 1144): failed to open AUTO_VOLUME_CONTROL /system/etc/AutoVolumeControl.txt: No such file or directory (2)
E/AudioHardwareMSM76XXA( 1144): setMode:mode = 0, status = -17
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(0, 0, 7)
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(6, 0, 7)
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(12, 0, 7)
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(3, 0, 7)
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(16, 0, 7)
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(25, 0, 7)
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(8, 0, 1)
E/AudioHardwareMSM76XXA( 1144): rpc_snd_set_volume(9, 0, 1)
E/QualcommCamera( 1144): Qint android::get_number_of_cameras(): E
I/QualcommCameraHardware( 1144): getCameraInfo: IN
I/QualcommCameraHardware( 1144): getCameraInfo: loading libqcamera at 0xb000ead8
V/QualcommCameraHardware( 1144):  Storing the current target type as 3
I/QualcommCameraHardware( 1144): getCameraInfo: numOfCameras = 1
I/QualcommCameraHardware( 1144): Camera sensor 0 info:
I/QualcommCameraHardware( 1144): camera_id: 0

Comment 3

[songsy]

software infomation:

buildid: 20130526124824
QC RIL version:
"ro.build.firmware_revision=V1.01.00.01.019.116"
gaia commit:
26d9430 Merge pull request #9982 from crdlc/bug-867045-v2
gecko commit:
5f6aa96 Bug 875933 - Add m.youtube.com to the STS preloaded list r=sicking, a=tef+

Comment 4

[songsy]

Hi, Jason

I think it is caused by fanotify event read. I have tried to disable it, and the fota update can work fine.

Thanks.

Comment 5

[[:fabrice] Fabrice Desré]

We are probably crashing here: https://mxr.mozilla.org/mozilla-central/source/hal/gonk/GonkDiskSpaceWatcher.cpp#238

That would be similar to bug 874148

Comment 7

[Fernando Jiménez Moreno [:ferjm]]

Attachment: v1

I've managed to check that the crash might be caused because we seem to not be properly handling the case were the fanotify event data file is busy.

Before applying this patch I was getting: 

I/Gecko   (  106): ==== Read 24 11 Try again
I/Gecko   (  106): ==== Read 24 11 Try again
I/Gecko   (  106): ==== Read 24 11 Try again
I/Gecko   (  106): ==== Read -1 26 Text file busy
I/Gecko   (  106): About to crash: fanotify_event_metadata read error. Length not multiple of fanotify_event_metadata
I/GeckoUpdater(  550): Progress [ =====                                              ]
I/GeckoUpdater(  550): Progress [ ==========                                         ]

(Where the debug messages was something like: "==== Read" + len + errno + strerror(errno)).

As you can see, we were getting errno 26, which is ETXTBSY, caused when the fanotify event file is busy. I guess that the file is busy cause the kernel is writing while we attempt to read. So IMO we shouldn't crash there, and instead just bail out, so we can attempt another read later.

With the attached patch, I've seen no crash so far and I am getting the following output, which seems to be correct:

I/Gecko   (  968): ==== Read 24 11 Try again 26773120
I/Gecko   (  968): ==== Read 24 11 Try again 26773120
I/Gecko   (  968): ==== Read -1 26 Text file busy 26773120
I/Gecko   (  968): ==== Read 24 26 Text file busy 26773120
I/Gecko   (  968): ==== Read 24 26 Text file busy 26773120
I/Gecko   (  968): ==== Read 24 26 Text file busy 26773120
I/Gecko   (  968): ==== Read 24 26 Text file busy 26773120
I/GeckoUpdater( 1107): Progress [ =====
I/GeckoUpdater( 1107): Progress [ ==========
I/Gecko   (  968): ==== Read 24 11 Try again 26773120
I/Gecko   (  968): ==== Read 24 11 Try again 26773120

(I've added a "pthread_self()" call to the debug message).

Comment 9

[Fernando Jiménez Moreno [:ferjm]]

http://hg.mozilla.org/projects/birch/rev/67ab06eeb62f

Comment 10

[Daniel Coloma:dcoloma]

It is very urgent to uplift this to 1.0.1 as it is a certification blocker. Can we please proceed with the uplift as soon as the test are passed on birch?

Comment 11

[[:fabrice] Fabrice Desré]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/27f35ec2fe0c
https://hg.mozilla.org/releases/mozilla-b2g18_v1_0_1/rev/bf45ce2ee851

Comment 12

[Andreas Gal :gal]

nice catch, thanks ferjm and thanks for the quick weekend review fabrice

Comment 13

[Johnny Stenback (:jst)]

Marking FIXED as this landed in bug 874148.

Comment 14

[Tony Chung [:tchung]]

hi songsy,  given that mozilla doesn't host FOTA, can you and your team verify this is fixed after you pick up this patch in your next build?  If fixed, please remove the keyword "verifyme", and leave a comment here that its verified on the specific build. 

Thanks!