723295 - Fennec crashes at startup (java.io.IOException: Unable to create mozilla directory at mozilla @ org.mozilla.gecko.GeckoDirProvider.ensureMozillaDirectory(GeckoDirProvider.java:140))

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect, P4)

Description

[(no longer active)]

Here's the logcat: https://gist.github.com/1719782

Comment 1

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

Thanks scoobi.  Ehsan, could you place in the device, android os, and buildid of fennec you used in the bug please?

Comment 2

[Brad Lassey [:blassey] (use needinfo?)]

Ehsan, do you have your profile on the sd card?

Comment 3

[(no longer active)]

(In reply to Naoki Hirata :nhirata from comment #1)
> Thanks scoobi.  Ehsan, could you place in the device, android os, and
> buildid of fennec you used in the bug please?

Sure.  Samsung Galaxy S (Vibrant -- the version offered by Bell Canada), running CyanogenMod latest.  I don't know how to get the build ID but it was the nightly I downloaded from nightly.mozilla.org yesterday.

(In reply to Brad Lassey [:blassey] from comment #2)
> Ehsan, do you have your profile on the sd card?

How can I tell?

Comment 4

[Kevin Brosnan [Ex-Mozilla]]

Open the Android manage applications window. Select Nightly from the list if the info page has a button that says move to sdcard then Firefox is installed to the phone and if it says move to phone then it is installed to the sdcard.

Comment 5

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

build id should be listed in about:firefox

Comment 6

[(no longer active)]

(In reply to Kevin Brosnan [:kbrosnan] from comment #4)
> Open the Android manage applications window. Select Nightly from the list if
> the info page has a button that says move to sdcard then Firefox is
> installed to the phone and if it says move to phone then it is installed to
> the sdcard.

The button says "Move to SD card".

(In reply to Naoki Hirata :nhirata from comment #5)
> build id should be listed in about:firefox

I filed this bug for a startup crash, which means that I can't get to about:firefox!

Comment 7

[Doug Turner (:dougt)]

kats, can you help Ehsan debug this?

We aren't seeing this in crash-stats

Comment 8

[Kartikaya Gupta (email:[e-mail])]

This looks it's happening because there's no SD card in the device. GeckoDirProvider.getFilesDir calls aContext.getExternalFilesDir() blindly without checking for a null return (which happens if there's no SD card in the device). Patch forthcoming.

Comment 9

[Kartikaya Gupta (email:[e-mail])]

Attachment: Fall back to getFilesDir() if sd card not found

Patch to guard against above scenario. I spun a build for ehsan to try; will flag this as needing review if he reports success.

Comment 10

[(no longer active)]

Kats gave me a test build, and here's what I get using that build:

I/ActivityManager(  205): Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.mozilla.fennec/.App } from pid 15957
I/ActivityManager(  205): Start proc org.mozilla.fennec for activity org.mozilla.fennec/.App: pid=12080 uid=10074 gids={3003, 1015, 1006}
D/szipinf (12080): Initializing inflate state
I/ActivityThread(12080): Pub org.mozilla.fennec.db.browser: org.mozilla.fennec.db.BrowserProvider
D/GeckoBrowserProvider(12080): Creating BrowserProvider
I/GeckoDirProvider(12080): Get profile dir for default
W/ApplicationContext(12080): Unable to create files directory
E/GeckoBrowserProvider(12080): Error getting profile dir
E/GeckoBrowserProvider(12080): java.io.IOException: Unable to create mozilla directory at mozilla
E/GeckoBrowserProvider(12080): 	at org.mozilla.gecko.GeckoDirProvider.ensureMozillaDirectory(GeckoDirProvider.java:140)
E/GeckoBrowserProvider(12080): 	at org.mozilla.gecko.GeckoDirProvider.getProfileDir(GeckoDirProvider.java:103)
E/GeckoBrowserProvider(12080): 	at org.mozilla.gecko.GeckoDirProvider.getProfileDir(GeckoDirProvider.java:71)
E/GeckoBrowserProvider(12080): 	at org.mozilla.fennec.db.BrowserProvider$1.run(BrowserProvider.java:587)
E/GeckoBrowserProvider(12080): 	at android.os.Handler.handleCallback(Handler.java:587)
E/GeckoBrowserProvider(12080): 	at android.os.Handler.dispatchMessage(Handler.java:92)
E/GeckoBrowserProvider(12080): 	at android.os.Looper.loop(Looper.java:130)
E/GeckoBrowserProvider(12080): 	at org.mozilla.gecko.GeckoAppShell$LooperThread.run(GeckoAppShell.java:185)
I/dalvikvm(12080): Could not find method android.app.DownloadManager.addCompletedDownload, referenced from method org.mozilla.gecko.GeckoApp.handleDownloadDone
W/dalvikvm(12080): VFY: unable to resolve virtual method 76: Landroid/app/DownloadManager;.addCompletedDownload (Ljava/lang/String;Ljava/lang/String;ZLjava/lang/String;Ljava/lang/String;JZ)J
D/dalvikvm(12080): VFY: replacing opcode 0x74 at 0x0017
D/AndroidRuntime(12080): Shutting down VM
W/dalvikvm(12080): threadid=1: thread exiting with uncaught exception (group=0x40015560)
E/AndroidRuntime(12080): FATAL EXCEPTION: main
E/AndroidRuntime(12080): java.lang.UnsatisfiedLinkError: Couldn't load mozglue: findLibrary returned null
E/AndroidRuntime(12080): 	at java.lang.Runtime.loadLibrary(Runtime.java:429)
E/AndroidRuntime(12080): 	at java.lang.System.loadLibrary(System.java:554)
E/AndroidRuntime(12080): 	at org.mozilla.gecko.GeckoApp.onCreate(GeckoApp.java:1460)
E/AndroidRuntime(12080): 	at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1047)
E/AndroidRuntime(12080): 	at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:1722)
E/AndroidRuntime(12080): 	at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:1784)
E/AndroidRuntime(12080): 	at android.app.ActivityThread.access$1500(ActivityThread.java:123)
E/AndroidRuntime(12080): 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:939)
E/AndroidRuntime(12080): 	at android.os.Handler.dispatchMessage(Handler.java:99)
E/AndroidRuntime(12080): 	at android.os.Looper.loop(Looper.java:130)
E/AndroidRuntime(12080): 	at android.app.ActivityThread.main(ActivityThread.java:3835)
E/AndroidRuntime(12080): 	at java.lang.reflect.Method.invokeNative(Native Method)
E/AndroidRuntime(12080): 	at java.lang.reflect.Method.invoke(Method.java:507)
E/AndroidRuntime(12080): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:847)
E/AndroidRuntime(12080): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:605)
E/AndroidRuntime(12080): 	at dalvik.system.NativeStart.main(Native Method)
W/ActivityManager(  205):   Force finishing activity org.mozilla.fennec/.App
W/ActivityManager(  205): Activity pause timeout for HistoryRecord{408930f0 org.mozilla.fennec/.App}
D/dalvikvm(11954): GC_EXPLICIT freed 69K, 48% free 3513K/6663K, external 0K/0K, paused 154ms
W/ActivityManager(  205): Activity destroy timeout for HistoryRecord{408930f0 org.mozilla.fennec/.App}
D/WifiService(  205): acquireWifiLockLocked: WifiLock{NetworkLocationLocator type=2 binder=android.os.BinderProxy@406ba050}
D/WifiService(  205): releaseWifiLockLocked: WifiLock{NetworkLocationLocator type=2 binder=android.os.BinderProxy@406ba050}
D/dalvikvm(12025): GC_FOR_MALLOC freed 239K, 45% free 3736K/6791K, external 0K/0K, paused 39ms
I/dalvikvm-heap(12025): Grow heap (frag case) to 6.189MB for 135960-byte allocation

Comment 11

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 594826 [details] [diff] [review]
Fall back to getFilesDir() if sd card not found

Turns out this works after all; ehsan tried the wrong build. Requesting review.

Comment 12

[Kartikaya Gupta (email:[e-mail])]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a8a93012f474

Comment 13

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/e2db006298c2 - it's difficult to tell with Android tests, where I can just merrily keep going starring builds which will never ever even start, but that looked pretty busted.

The last few pushes before you were only getting partial (or no) test runs, but they had 1 failure in 33 runs. On your push, it was 9 of 28, the next push had 11 failures and the one after that has 5 so far.

Comment 14

[Kartikaya Gupta (email:[e-mail])]

I don't see how this could have caused the errors, but from the tbpl status it makes sense to have backed out the change. I've pushed it to try to see if the failures are reproducible. https://tbpl.mozilla.org/?tree=Try&rev=fdfbf24b1094

Comment 15

[Kartikaya Gupta (email:[e-mail])]

Ok, so I was looking through some of this file-related code and it's pretty rotten, leading to unnecessary complexity and unreliable behaviour. I'm going to yank it out and rewrite it, so this will be a bigger patch than I originally thought.

Comment 16

[Kartikaya Gupta (email:[e-mail])]

Try run with this patch rebased on top of cruft-removal/cleanup patches was green: https://tbpl.mozilla.org/?tree=Try&rev=8df1f33bb1c1

Comment 17

[Kartikaya Gupta (email:[e-mail])]

https://hg.mozilla.org/integration/mozilla-inbound/rev/0dc734db4a13

Comment 18

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/0dc734db4a13

Comment 19

[Cristian Nicolae (:xti)]

Verified fixed on:

Firefox 13.0a1 (2012-02-29)
20120229031108
http://hg.mozilla.org/mozilla-central/rev/30b4f99a137c

--
Device: Samsung Galaxy S2
OS: Android 2.3.4

Comment 20

[(no longer active)]

I still can reproduce:

D/SettingsAppWidgetProvider( 1393): Widget is from a previous version... Let's update
D/SettingsAppWidgetProvider( 1393): No instances yet... Wait for at least one instance to exist before adding global settings
W/InputManagerService(  205): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@4089cad8
D/dalvikvm( 1249): GC_EXPLICIT freed 303K, 48% free 3273K/6279K, external 0K/0K, paused 781ms
I/Gmail   ( 1221): MainSyncRequestProto: lowestBkwdConvoId: 0, highestHandledServerOp: 9484620, normalSync: true
D/dalvikvm( 1221): GC_EXPLICIT freed 124K, 55% free 4025K/8839K, external 1052K/1371K, paused 27ms
I/Gmail   ( 1221): MainSyncRequestProto: lowestBkwdConvoId: 0, highestHandledServerOp: 9484620, normalSync: true
I/ActivityManager(  205): Starting: Intent { act=com.android.launcher.action.launcheraction flg=0x10000000 cmp=com.android.launcher/.CustomShirtcutActivity bnds=[192,723][288,800] (has extras) } from pid 314
W/InputManagerService(  205): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@4052f450
D/dalvikvm(  314): GC_EXTERNAL_ALLOC freed 278K, 56% free 3578K/8007K, external 7730K/7732K, paused 89ms
D/dalvikvm( 1006): GC_EXPLICIT freed 16K, 38% free 7607K/12231K, external 1568K/2032K, paused 95ms
I/ActivityManager(  205): Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.mozilla.fennec/.App } from pid 314
D/szipinf (  205): Initializing inflate state
I/ActivityManager(  205): Start proc org.mozilla.fennec for activity org.mozilla.fennec/.App: pid=4170 uid=10074 gids={3003, 1015, 1006}
D/szipinf ( 4170): Initializing inflate state
I/ActivityThread( 4170): Pub org.mozilla.fennec.db.passwords: org.mozilla.fennec.db.PasswordsProvider
I/ActivityThread( 4170): Pub org.mozilla.fennec.db.browser: org.mozilla.fennec.db.BrowserProvider
W/ApplicationContext( 4170): Unable to create files directory
E/GeckoProfile( 4170): Error getting profile dir
E/GeckoProfile( 4170): java.io.IOException: Unable to create mozilla directory at /mozilla
E/GeckoProfile( 4170): 	at org.mozilla.gecko.GeckoProfile.ensureMozillaDirectory(GeckoProfile.java:292)
E/GeckoProfile( 4170): 	at org.mozilla.gecko.GeckoProfile.getDir(GeckoProfile.java:70)
E/GeckoProfile( 4170): 	at org.mozilla.fennec.db.BrowserProvider$1.run(BrowserProvider.java:752)
E/GeckoProfile( 4170): 	at android.os.Handler.handleCallback(Handler.java:587)
E/GeckoProfile( 4170): 	at android.os.Handler.dispatchMessage(Handler.java:92)
E/GeckoProfile( 4170): 	at android.os.Looper.loop(Looper.java:130)
E/GeckoProfile( 4170): 	at org.mozilla.gecko.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
I/dalvikvm( 4170): Failed resolving Lorg/mozilla/gecko/gfx/SurfaceTextureLayer; interface 98 'Landroid/graphics/SurfaceTexture$OnFrameAvailableListener;'
W/dalvikvm( 4170): Link of class 'Lorg/mozilla/gecko/gfx/SurfaceTextureLayer;' failed
I/dalvikvm( 4170): Could not find method org.mozilla.gecko.gfx.SurfaceTextureLayer.create, referenced from method org.mozilla.gecko.GeckoApp.createSurface
W/dalvikvm( 4170): VFY: unable to resolve static method 6897: Lorg/mozilla/gecko/gfx/SurfaceTextureLayer;.create ()Lorg/mozilla/gecko/gfx/SurfaceTextureLayer;
D/dalvikvm( 4170): VFY: replacing opcode 0x71 at 0x000c
D/dalvikvm( 4170): VFY: dead code 0x000f-0019 in Lorg/mozilla/gecko/GeckoApp;.createSurface ()Landroid/view/Surface;
I/dalvikvm( 4170): Could not find method android.app.DownloadManager.addCompletedDownload, referenced from method org.mozilla.gecko.GeckoApp.handleDownloadDone
W/dalvikvm( 4170): VFY: unable to resolve virtual method 78: Landroid/app/DownloadManager;.addCompletedDownload (Ljava/lang/String;Ljava/lang/String;ZLjava/lang/String;Ljava/lang/String;JZ)J
D/dalvikvm( 4170): VFY: replacing opcode 0x74 at 0x0017
I/dalvikvm( 4170): Failed resolving Lorg/mozilla/gecko/gfx/SurfaceTextureLayer; interface 98 'Landroid/graphics/SurfaceTexture$OnFrameAvailableListener;'
W/dalvikvm( 4170): Link of class 'Lorg/mozilla/gecko/gfx/SurfaceTextureLayer;' failed
E/dalvikvm( 4170): Could not find class 'org.mozilla.gecko.gfx.SurfaceTextureLayer', referenced from method org.mozilla.gecko.GeckoApp.showSurface
W/dalvikvm( 4170): VFY: unable to resolve check-cast 1313 (Lorg/mozilla/gecko/gfx/SurfaceTextureLayer;) in Lorg/mozilla/gecko/GeckoApp;
D/dalvikvm( 4170): VFY: replacing opcode 0x1f at 0x002c
D/dalvikvm( 4170): VFY: dead code 0x002e-0049 in Lorg/mozilla/gecko/GeckoApp;.showSurface (Landroid/view/Surface;IIIIZZLjava/lang/String;)V
D/AndroidRuntime( 4170): Shutting down VM
W/dalvikvm( 4170): threadid=1: thread exiting with uncaught exception (group=0x40015560)
E/AndroidRuntime( 4170): FATAL EXCEPTION: main
E/AndroidRuntime( 4170): java.lang.UnsatisfiedLinkError: Couldn't load mozglue: findLibrary returned null
E/AndroidRuntime( 4170): 	at java.lang.Runtime.loadLibrary(Runtime.java:429)
E/AndroidRuntime( 4170): 	at java.lang.System.loadLibrary(System.java:554)
E/AndroidRuntime( 4170): 	at org.mozilla.gecko.GeckoApp.onCreate(GeckoApp.java:1662)
E/AndroidRuntime( 4170): 	at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1047)
E/AndroidRuntime( 4170): 	at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:1722)
E/AndroidRuntime( 4170): 	at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:1784)
E/AndroidRuntime( 4170): 	at android.app.ActivityThread.access$1500(ActivityThread.java:123)
E/AndroidRuntime( 4170): 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:939)
E/AndroidRuntime( 4170): 	at android.os.Handler.dispatchMessage(Handler.java:99)
E/AndroidRuntime( 4170): 	at android.os.Looper.loop(Looper.java:130)
E/AndroidRuntime( 4170): 	at android.app.ActivityThread.main(ActivityThread.java:3835)
E/AndroidRuntime( 4170): 	at java.lang.reflect.Method.invokeNative(Native Method)
E/AndroidRuntime( 4170): 	at java.lang.reflect.Method.invoke(Method.java:507)
E/AndroidRuntime( 4170): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:847)
E/AndroidRuntime( 4170): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:605)
E/AndroidRuntime( 4170): 	at dalvik.system.NativeStart.main(Native Method)
W/ActivityManager(  205):   Force finishing activity org.mozilla.fennec/.App
W/ActivityManager(  205): Activity pause timeout for HistoryRecord{409daf28 org.mozilla.fennec/.App}
I/ActivityManager(  205): No longer want com.android.browser (pid 2783): hidden #16
I/WindowManager(  205): WIN DEATH: Window{408b70c8 com.android.browser/com.android.browser.BrowserActivity paused=false}

Comment 21

[Kartikaya Gupta (email:[e-mail])]

I looked at Ehsan's device and he had /data/data/org.mozilla.fennec symlinked to /data/org.mozilla.fennec (since apparently there's more space on that partition), but the symlink was owned by some other user. This made fennec unable to write to the directory, resulting the crash. Getting rid of the symlinked fixed the problem.