Closed Bug 1089260 Opened 5 years ago Closed 5 years ago

crash in java.lang.Exception: Error loading gecko libraries at org.mozilla.gecko.mozglue.GeckoLoader.loadGeckoLibsNative(Native Method)

Categories

(Firefox for Android :: General, defect, critical)

36 Branch
ARM
Android
defect
Not set
critical

Tracking

()

RESOLVED FIXED
Tracking Status
firefox36 --- affected
fennec + ---

People

(Reporter: aaronmt, Assigned: esawin)

References

Details

(Keywords: crash, topcrash-android-armv7)

Crash Data

Attachments

(2 files)

This bug was filed from the Socorro interface and is 
report bp-520c3da7-5ee2-4c74-9a2c-428ea2141024.
=============================================================

java.lang.Exception: Error loading gecko libraries
	at org.mozilla.gecko.mozglue.GeckoLoader.loadGeckoLibsNative(Native Method)
	at org.mozilla.gecko.mozglue.GeckoLoader.loadGeckoLibs(GeckoLoader.java:515)
	at org.mozilla.gecko.GeckoThread.initGeckoEnvironment(GeckoThread.java:117)
	at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:171)

#1 on Firefox 36
This is happening on infra: Bug 1086513.
Might be related to Bug 984366, too.
Any logcats from these reports?
Flags: needinfo?(mark.finkle)
http://ftp.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android/1414240945/mozilla-inbound_panda_android_test-robocop-1-bm100-tests1-panda-build2245.txt.gz

06:47:36     INFO -  10-25 06:47:33.070 I/ActivityManager( 1401): START {act=android.intent.action.MAIN flg=0x10000000 cmp=org.mozilla.fennec/org.mozilla.gecko.BrowserApp (has extras)} from pid 3770
06:47:36     INFO -  10-25 06:47:33.078 I/ActivityThread( 3770): Pub org.mozilla.fennec.profiles: org.mozilla.gecko.GeckoProfilesProvider
06:47:36     INFO -  10-25 06:47:33.078 I/ActivityThread( 3770): Pub org.mozilla.fennec.db.home: org.mozilla.gecko.db.HomeProvider
06:47:36     INFO -  10-25 06:47:33.101 W/NetworkManagementSocketTagger( 1401): setKernelCountSet(10047, 1) failed with errno -2
06:47:36     INFO -  10-25 06:47:33.117 D/GeckoApp( 3770): Enabling Android StrictMode
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): Gecko environment env0: MOZ_CRASHREPORTER=1
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env1: XPCOM_DEBUG_BREAK=stack
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env2: MOZ_HIDE_RESULTS_TABLE=1
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env3: MOZ_DISABLE_NONLOCAL_CONNECTIONS=1
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env4: MOZ_CRASHREPORTER_NO_REPORT=1
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env5: MOZ_WIN_INHERIT_STD_HANDLES_PRE_VISTA=1
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env6: NSPR_LOG_FILE=/mnt/sdcard/tests/nspr/nspr-testBookmarksPanel.log
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env7: XPCOM_MEM_BLOAT_LOG=/mnt/sdcard/tests/profile/runtests_leaks.log
06:47:36     INFO -  10-25 06:47:33.148 D/GeckoLoader( 3770): env8: null
06:47:36     INFO -  10-25 06:47:33.148 E/GeckoLibLoad( 3770): Load sqlite start
06:47:36     INFO -  10-25 06:47:33.156 D/GeckoSharedPrefs( 3770): Current version = 1, prefs version = 1
06:47:36     INFO -  10-25 06:47:33.156 W/GeckoLinker( 3770): /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: unhandled flags #8 not handled
06:47:36     INFO -  10-25 06:47:33.164 I/SUTAgentAndroid( 1908): onTrimMemory20
06:47:36     INFO -  10-25 06:47:33.164 I/SUTAgentAndroid( 1908): PA:720011264, FREE: 500256768
06:47:36     INFO -  10-25 06:47:33.171 W/GeckoLinker( 3770): /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: Relocation to NULL @0x0014ac68
06:47:36     INFO -  10-25 06:47:33.171 I/SUTAgentAndroid( 1908): 10047	3770	org.mozilla.fennec
06:47:36     INFO -  10-25 06:47:33.171 W/GeckoLinker( 3770): /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: Relocation to NULL @0x0014afdc for symbol "__cxa_begin_cleanup"
06:47:36     INFO -  10-25 06:47:33.171 W/GeckoLinker( 3770): /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: Relocation to NULL @0x0014afe0 for symbol "__cxa_type_match"
06:47:36     INFO -  10-25 06:47:33.179 E/GeckoLibLoad( 3770): Load sqlite done
06:47:36     INFO -  10-25 06:47:33.179 E/GeckoLibLoad( 3770): Load nss start
06:47:36     INFO -  10-25 06:47:33.179 E/GeckoLibLoad( 3770): Load nss done
06:47:36     INFO -  10-25 06:47:33.187 E/GeckoLinker( 3770): Malformed or broken seekable zstream
06:47:36     INFO -  10-25 06:47:33.187 E/GeckoLibLoad( 3770): Couldn't get a handle to libxul!
06:47:36     INFO -  10-25 06:47:33.187 E/GeckoLibLoad( 3770): Throw
06:47:36     INFO -  10-25 06:47:33.203 W/dalvikvm( 3770): threadid=14: thread exiting with uncaught exception (group=0x40b761f8)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 138 ("Gecko")
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770): java.lang.Exception: Error loading gecko libraries
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770): 	at org.mozilla.gecko.mozglue.GeckoLoader.loadGeckoLibsNative(Native Method)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770): 	at org.mozilla.gecko.mozglue.GeckoLoader.loadGeckoLibs(GeckoLoader.java:515)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770): 	at org.mozilla.gecko.GeckoThread.initGeckoEnvironment(GeckoThread.java:117)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770): 	at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:171)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770): Main thread (1) stack:
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     org.mozilla.gecko.mozglue.ByteBufferInputStream.read(ByteBufferInputStream.java:44)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:168)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     java.io.BufferedInputStream.read(BufferedInputStream.java:309)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.graphics.BitmapFactory.nativeDecodeStream(Native Method)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.graphics.BitmapFactory.decodeStream(BitmapFactory.java:493)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.graphics.BitmapFactory.decodeStream(BitmapFactory.java:549)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.graphics.drawable.BitmapDrawable.<init>(BitmapDrawable.java:157)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     org.mozilla.gecko.util.GeckoJarReader.getBitmapDrawable(GeckoJarReader.java:47)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     org.mozilla.gecko.util.GeckoJarReader.getBitmap(GeckoJarReader.java:32)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     org.mozilla.gecko.favicons.Favicons.loadBrandingBitmap(Favicons.java:513)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     org.mozilla.gecko.favicons.Favicons.initializeWithContext(Favicons.java:491)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     org.mozilla.gecko.GeckoApp.onCreate(GeckoApp.java:1257)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     org.mozilla.gecko.BrowserApp.onCreate(BrowserApp.java:440)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.app.Activity.performCreate(Activity.java:4465)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1049)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.app.ActivityThread.performLaunchActivity(ActivityThread.java:1920)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:1981)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.app.ActivityThread.access$600(ActivityThread.java:123)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.app.ActivityThread$H.handleMessage(ActivityThread.java:1147)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.os.Handler.dispatchMessage(Handler.java:99)
06:47:36     INFO -  10-25 06:47:33.203 E/GeckoCrashHandler( 3770):     android.os.Looper.loop(Looper.java:137)
06:47:36     INFO -  10-25 06:47:33.210 E/GeckoCrashHandler( 3770):     android.app.ActivityThread.main(ActivityThread.java:4424)
06:47:36     INFO -  10-25 06:47:33.210 E/GeckoCrashHandler( 3770):     java.lang.reflect.Method.invokeNative(Native Method)
06:47:36     INFO -  10-25 06:47:33.210 E/GeckoCrashHandler( 3770):     java.lang.reflect.Method.invoke(Method.java:511)
06:47:36     INFO -  10-25 06:47:33.210 E/GeckoCrashHandler( 3770):     com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:784)
06:47:36     INFO -  10-25 06:47:33.210 E/GeckoCrashHandler( 3770):     com.android.internal.os.ZygoteInit.main(ZygoteInit.java:551)
06:47:36     INFO -  10-25 06:47:33.210 E/GeckoCrashHandler( 3770):     dalvik.system.NativeStart.main(Native Method)
06:47:36     INFO -  10-25 06:47:33.226 D/GeckoScreenOrientation( 3770): updating to new orientation LANDSCAPE_PRIMARY
06:47:36     INFO -  10-25 06:47:33.226 I/ActivityManager( 1401): START {act=org.mozilla.gecko.reportCrash cmp=org.mozilla.fennec/org.mozilla.gecko.CrashReporter (has extras)} from pid 3770
Can anyone else reproduce this? Why is this all of a sudden skyrocketing on socorro?
06:47:36     INFO -  10-25 06:47:33.187 E/GeckoLinker( 3770): Malformed or broken seekable zstream

suggests a build/packaging change. Build folks, any ideas?
Flags: needinfo?(nalexander)
Flags: needinfo?(gps)
Assignee: nobody → snorp
tracking-fennec: ? → +
glandium and mshal have a better handle on this area than I do.
Flags: needinfo?(mshal)
Flags: needinfo?(mh+mozilla)
Flags: needinfo?(gps)
There has been no packaging change that could explain that. The only change that could have affected the szip process is bug 1059797 but it landed after the log from comment 4.
Moreover, if there was a packaging problem triggering this, it would cause problems on *all* tests for the given build, not just one.
Flags: needinfo?(mh+mozilla)
(In reply to Richard Newman [:rnewman] from comment #6)
> 06:47:36     INFO -  10-25 06:47:33.187 E/GeckoLinker( 3770): Malformed or
> broken seekable zstream
> 
> suggests a build/packaging change. Build folks, any ideas?

I know of nothing that would have changed this.  Further questions in the TBPL bug.
Flags: needinfo?(nalexander)
Is it possible to add more debug? It might be helpful if the "Couldn't get a handle to libxul!" message included the message from dlerror() (if the dlopen wrapper supports that). And the "Malformed or broken seekable zstream" makes 7 different checks - it would be nice to know which one in particular is failing.

Are these messages also real errors or just noise?

1) 06:47:36     INFO -  10-25 06:47:33.156 W/GeckoLinker( 3770): /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: unhandled flags #8 not handled

2) 06:47:36     INFO -  10-25 06:47:33.171 W/GeckoLinker( 3770): /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: Relocation to NULL @0x0014afdc for symbol "__cxa_begin_cleanup"
Flags: needinfo?(mshal)
(In reply to Michael Shal [:mshal] from comment #10)
> Is it possible to add more debug? It might be helpful if the "Couldn't get a
> handle to libxul!" message included the message from dlerror() (if the
> dlopen wrapper supports that). And the "Malformed or broken seekable
> zstream" makes 7 different checks - it would be nice to know which one in
> particular is failing.

I'm confident we could add additional debug logging.  I'd prefer not to do it myself right now, but if this languishes I can do it.

> Are these messages also real errors or just noise?
> 
> 1) 06:47:36     INFO -  10-25 06:47:33.156 W/GeckoLinker( 3770):
> /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: unhandled flags #8
> not handled
> 
> 2) 06:47:36     INFO -  10-25 06:47:33.171 W/GeckoLinker( 3770):
> /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: Relocation to NULL
> @0x0014afdc for symbol "__cxa_begin_cleanup"

I treat these two as noise; they've been present for me for at least 12 months.
(In reply to Michael Shal [:mshal] from comment #10)
> Is it possible to add more debug? It might be helpful if the "Couldn't get a
> handle to libxul!" message included the message from dlerror() (if the
> dlopen wrapper supports that). And the "Malformed or broken seekable
> zstream" makes 7 different checks - it would be nice to know which one in
> particular is failing.

It's actually not interesting to know that. That data comes straight from a read-only mmap of the apk, so the question is more why that data is corrupted than what specific bit doesn't match. That, is, we first need to know what is mapped (file, offset) at that address and check if that matches the location of libxul in the apk.

> Are these messages also real errors or just noise?
> 
> 1) 06:47:36     INFO -  10-25 06:47:33.156 W/GeckoLinker( 3770):
> /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: unhandled flags #8
> not handled
> 
> 2) 06:47:36     INFO -  10-25 06:47:33.171 W/GeckoLinker( 3770):
> /data/app/org.mozilla.fennec-1.apk!/assets/libnss3.so: Relocation to NULL
> @0x0014afdc for symbol "__cxa_begin_cleanup"

Those are warnings. They don't matter, but hiding them could hide important information. That's just not relevant in the present case.
Also note that there is no evidence that the crashes for which this bug was opened and what's happening on infra are the same thing. We don't collect logcat in crashes do we?
The infrae log link indicates that infra does record logcats in process crashes:

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=508907&repo=mozilla-central

2152 19:33:14 WARNING - PROCESS-CRASH | java-exception | java.lang.Exception: Error loading gecko libraries at org.mozilla.gecko.mozglue.GeckoLoader.loadGeckoLibsNative(Native Method)
2159 19:33:15 WARNING - PROCESS-CRASH | Automation Error: Missing end of test marker (process crashed?)
2324 19:33:16 INFO - 10-20 19:33:11.398 E/GeckoLinker( 3848): Malformed or broken seekable zstream
But yes, we don't know if the cause of the failure to load libraries is the same. Certainly seems like a coincidence, though.
Discussion about the failure on infra should move to a separate bug then. Or a separate bug should be filed for the crashes from socorro.
We've always had this crash, but are just now seeing it on crash-stats due to reporting changes. Google Play has shown this for a long time, but I think we had (clearly incorrect) assumptions that it was due to Play messing up an upgrade or something. We need to try to track this down. Do the failing builds from infra reproduce reliably? Meaning, is the APK messed up? Or as :glandium said, is this some problem with the mappings that occurs sporadically?
Assignee: snorp → esawin
Flags: needinfo?(mark.finkle)
This is happening a lot on my Nexus 10.  It's new in the last week or two.  Usually happens when switching back to nightly after selecting a link from g+ or elsewhere
I suggest getting that device into an android dev's hands to take a look
(In reply to Aaron Train [:aaronmt] from comment #19)
> I suggest getting that device into an android dev's hands to take a look

Sorry, I'm remote and really can't lose a second tablet to Mozilla (I use it constantly).  ;-)

However, I can load up test code, adb, gdb, etc as needed, though I haven't done much myself on android recently (mostly b2g).

I haven't seen a crash (yet) since it took the latest nightly; I'd gotten ~5 over 4-5 days all with this signature:
bp-0fed9d0f-6d7b-4427-bdca-b7cc92141110 11/09/14 19:52
bp-fe6162d5-c16b-4793-a90c-3346f2141110 11/09/14 19:08
bp-d4bee6be-a20e-4586-86af-ce8022141109 11/08/14 21:22
bp-4cbe53a5-c352-41c0-aead-e6f0e2141107 11/06/14 20:54
bp-e86f0289-c45c-4db0-8dfb-d67022141106 11/05/14 19:16
Note: all were 10/26 builds.  Due to @%@!@~!# Verizon and Netflix disagreeing over peering, updates of Nightly & Aurora are extremely hit-and-miss and often fail (downloads at 5-10K/s instead of my normal speed of 1-5MB/s)
According to crash reports, this isn't specific to some devices. I see a lot of the crashes reported on Nexus 5 and 7, but I fail to reproduce it on either.

Randell, can you still trigger it by opening links from apps like g+?
The crash has been declining rapidly on crash reports in the past week and it's not reproducing on Nexus 7 or 5 for me, which are among the top crashing devices. Randell, is it still reproducing for you on nightly?
Flags: needinfo?(rjesup)
Just cleaning up some overlooked stuff from bug 855824. I can spin off a bug for that, if that's preferred.
Attachment #8523919 - Flags: review?(mh+mozilla)
(In reply to Eugen Sawin [:esawin] from comment #23)
> The crash has been declining rapidly on crash reports in the past week and
> it's not reproducing on Nexus 7 or 5 for me, which are among the top
> crashing devices. Randell, is it still reproducing for you on nightly?

I don't think I got any crashes from it that weren't from one version (10/26? 23?) since auto-update of Nightly frequently fails here (mozilla's gateway to Verizon is fubar for months now - 3/4 times you get <15KB/s, often just totally failing in a large download)
Flags: needinfo?(rjesup)
From my understanding, the issue can be caused by either a wrong offset (Zip::GetStream setting wrong file?) or a corrupted mapping (correct offset but wrong size? buffer issues?).

Independent from the present case, it doesn't hurt to provide more detailed error state logs when failing to initialize the zstream.
Zip::GetStream does seem to have good debug log coverage, we might just log the actual offset here for manual inspection.

Anything else that might be helpful?
Attachment #8523928 - Flags: feedback?(mh+mozilla)
Comment on attachment 8523919 [details] [diff] [review]
gecko-loader-cleanup

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

I think both should go in separate bugs.

::: mozglue/android/APKOpen.cpp
@@ -300,5 @@
>      return SUCCESS;
>  
>    chdir(getenv("GRE_HOME"));
>  
> -  RefPtr<Zip> zip = ZipCollection::GetZip(apkName);

Indeed, those are useless since bug 855824

::: mozglue/linker/Mappable.cpp
@@ +377,5 @@
>  MappableSeekableZStream::Create(const char *name, Zip *zip,
>                                  Zip::Stream *stream)
>  {
>    MOZ_ASSERT(stream->GetType() == Zip::Stream::STORE);
> +  UniquePtr<MappableSeekableZStream> mappable(new MappableSeekableZStream(zip));

nice cleanup
Attachment #8523919 - Flags: review?(mh+mozilla) → review+
Comment on attachment 8523928 [details] [diff] [review]
gecko-loader-error-logs

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

cf. comment 12, that's not really interesting.
Attachment #8523928 - Flags: feedback?(mh+mozilla) → feedback-
Fixed by https://hg.mozilla.org/mozilla-central/rev/44c6d392bbc8.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
FYI, this has returned - filed bug 1283629.
See Also: → 1337290
You need to log in before you can comment on or make changes to this bug.