Strange JVM Error with ICS

I am gaving a strange problem with a code. The task is quite simple, from native code I call a java function, which gets a param from prefs, and returns to c++, the method is with no params and returns a string.

Even stranger, it runs nicely on the first run, but the second time I call the whole native procedure from java when the c++ routine tries to contact the java method it crashes. which tells me it's a memory corruption but I have no idea why it happens.

Ok. So, in the onLoad method in the lib I make a ref to the javaVM, like so :

JNIEnv *env;
LOGI("JNI_OnLoad called");
if (vm->GetEnv((void**) &env, JNI_VERSION_1_4) != JNI_OK) {
    LOGE("Failed to get the environment using GetEnv()");
    return -1;
}
MY_NAMESPACE::VMHandler::getInstance()->init(env);

Init actually just saves the pointer in the running instance and give's me no problems in the later run since I call it multiple times.

next, I call the java method, getTime()

LOGE("get TIME called");

//getting a pointer to the VM
JNIEnv * env = VMHandler::getInstance()->getJava();
LOGE("1");
if (env==NULL) {
    LOGE("1.0");
}else{
    LOGE("1.0 OK");
}

if (dao==NULL) {
    LOGE("1.1");
}else{
    LOGE("1.1 OK");

}
if (jgetTime==NULL) {
    LOGE("1.2");
}else{
    LOGE("1.2 OK");

}

jstring time = (jstring) env->CallObjectMethod(dao,jgetTime);
LOGE("2");

Interestingly enough, I get the following log from first run :

E/app-cpp(7121): 1
E/app-cpp(7121): 1.0 OK
E/app-cpp(7121): 1.1 OK
E/app-cpp(7121): 1.2 OK
E/Settings(7121): Java received : getTime()
E/Settings(7121): Java returning : 1341250295

and then second run...

E/app-cpp(1941): get TIME called
E/app-cpp(1941): 1
E/app-cpp(1941): 1.0 OK
E/app-cpp(1941): 1.1 OK
E/app-cpp(1941): 1.2 OK
A/libc(1941): Fatal signal 11 (SIGSEGV) at 0x0000008d (code=1)

and the complete dump is :

07-02 17:08:20.948: E/my-cpp(1941): 1
07-02 17:08:20.958: E/my-cpp(1941): 1.0 OK
07-02 17:08:20.958: E/my-cpp(1941): 1.1 OK
07-02 17:08:20.958: E/my-cpp(1941): 1.2 OK
07-02 17:08:20.958: A/libc(1941): Fatal signal 11 (SIGSEGV) at 0x0000008d (code=1)
07-02 17:08:20.967: D/debug(1941): LoaderCalled!
07-02 17:08:21.298: D/dalvikvm(78): GC_CONCURRENT freed 296K, 13% free 11332K/12935K, paused 4ms+28ms
07-02 17:08:21.407: I/Process(78): Sending signal. PID: 1941 SIG: 3
07-02 17:08:21.407: I/dalvikvm(1941): threadid=3: reacting to signal 3
07-02 17:08:21.417: I/dalvikvm(1941): Wrote stack traces to '/data/anr/traces.txt'
07-02 17:08:21.477: D/debug(1941): mSwitcher:android.widget.TextSwitcher@41495318
07-02 17:08:21.487: I/DEBUG(3844): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
07-02 17:08:21.487: I/DEBUG(3844): Build fingerprint: 'generic/sdk/generic:4.0.4/MR1/302030:eng/test-keys'
07-02 17:08:21.487: I/DEBUG(3844): pid: 1941, tid: 2162  >>> com.myapp <<<
07-02 17:08:21.487: I/DEBUG(3844): signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0000008d
07-02 17:08:21.487: I/DEBUG(3844):  r0 00238040  r1 1d200222  r2 00000001  r3 0000008c
07-02 17:08:21.487: I/DEBUG(3844):  r4 4a5db590  r5 004ea2e8  r6 4a5db590  r7 49cc1bc4
07-02 17:08:21.487: I/DEBUG(3844):  r8 49cc1bc4  r9 49ab4f64  10 495f752c  fp 49cc1bdc
07-02 17:08:21.487: I/DEBUG(3844):  ip 40003108  sp 49cc17b8  lr 4a02a79b  pc 4a029fb0  cpsr 00000030
07-02 17:08:21.487: I/DEBUG(3844):  d0  42c8000042b6aa73  d1  3ff0000000b23680
07-02 17:08:21.487: I/DEBUG(3844):  d2  3ff0000000000000  d3  4197d78400000000
07-02 17:08:21.487: I/DEBUG(3844):  d4  3ff0000000000000  d5  4028000000000000
07-02 17:08:21.487: I/DEBUG(3844):  d6  00c31fe000000000  d7  0000005b4e8b3a94
07-02 17:08:21.487: I/DEBUG(3844):  d8  3f8000003f800000  d9  43d2000000000000
07-02 17:08:21.487: I/DEBUG(3844):  d10 000000004479f062  d11 0000000000000000
07-02 17:08:21.487: I/DEBUG(3844):  d12 0000000000000000  d13 0000000000000000
07-02 17:08:21.487: I/DEBUG(3844):  d14 0000000000000000  d15 0000000000000000
07-02 17:08:21.487: I/DEBUG(3844):  scr 20000012
07-02 17:08:21.717: I/ActivityManager(78): Displayed com.myapp/.ui.activities.Loader: +831ms
07-02 17:08:22.437: I/DEBUG(3844):          #00  pc 00367fb0  /data/data/com.myapp/lib/libwrapper.so (_ZN7_JNIEnv16CallObjectMethodEP8_jobjectP10_jmethodIDz)
07-02 17:08:22.437: I/DEBUG(3844):          #01  lr 4a02a79b  /data/data/com.myapp/lib/libwrapper.so
07-02 17:08:22.437: I/DEBUG(3844): code around pc:
07-02 17:08:22.437: I/DEBUG(3844): 4a029f90 1c0347a0 b0041c18 46c0bd10 b510b40c  .G.........F....
07-02 17:08:22.437: I/DEBUG(3844): 4a029fa0 9001b084 ab079100 9b019302 238c681a  .............h.#
07-02 17:08:22.437: I/DEBUG(3844): 4a029fb0 980158d4 9a069900 47a09b02 93031c03  .X.........G....
07-02 17:08:22.437: I/DEBUG(3844): 4a029fc0 1c189b03 bc10b004 b002bc08 46c04718  .............G.F
07-02 17:08:22.437: I/DEBUG(3844): 4a029fd0 b510b40c 9001b084 ab079100 9b019302  ................
07-02 17:08:22.437: I/DEBUG(3844): code around lr:
07-02 17:08:22.437: I/DEBUG(3844): 4a02a778 1c112006 f3e91c1a 4b40fbe7 681a58e3  . ........@K.X.h
07-02 17:08:22.437: I/DEBUG(3844): 4a02a788 58e34b43 9904681b 1c111c08 f7ff1c1a  CK.X.h..........
07-02 17:08:22.437: I/DEBUG(3844): 4a02a798 1c03fc01 4b439305 1c1a447b 447b4b42  ......CK{D..BK{D
07-02 17:08:22.437: I/DEBUG(3844): 4a02a7a8 1c112006 f3e91c1a 9a04fbcf 1c109b05  . ..............
07-02 17:08:22.437: I/DEBUG(3844): 4a02a7b8 22001c19 fbaaf7f5 93061c03 447b4b3b  ..."........;K{D
07-02 17:08:22.437: I/DEBUG(3844): stack:
07-02 17:08:22.437: I/DEBUG(3844):     49cc1778  00000000  
07-02 17:08:22.437: I/DEBUG(3844):     49cc177c  0038d96c  [heap]
07-02 17:08:22.437: I/DEBUG(3844):     49cc1780  0023c108  [heap]
07-02 17:08:22.437: I/DEBUG(3844):     49cc1784  49cc1884  
07-02 17:08:22.437: I/DEBUG(3844):     49cc1788  4a5d28d0  /data/data/com.myapp/lib/libwrapper.so
07-02 17:08:22.437: I/DEBUG(3844):     49cc178c  001a1f20  [heap]
07-02 17:08:22.437: I/DEBUG(3844):     49cc1790  001a1f28  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc1794  001a1f28  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc1798  001c7580  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc179c  001c7588  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc17a0  001c7588  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc17a4  00483ccc  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc17a8  0023c540  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc17ac  4004c4b0  
07-02 17:08:22.457: I/DEBUG(3844):     49cc17b0  df0027ad  
07-02 17:08:22.457: I/DEBUG(3844):     49cc17b4  00000000  
07-02 17:08:22.457: I/DEBUG(3844): #00 49cc17b8  1d200222  
07-02 17:08:22.457: I/DEBUG(3844):     49cc17bc  00238040  [heap]
07-02 17:08:22.457: I/DEBUG(3844):     49cc17c0  49cc17d4  
07-02 17:08:22.457: I/DEBUG(3844):     49cc17c4  4a5db590  /data/data/com.myapp/lib/libwrapper.so
07-02 17:08:22.457: I/DEBUG(3844):     49cc17c8  4a5db590  /data/data/com.myapp/lib/libwrapper.so
07-02 17:08:22.457: I/DEBUG(3844):     49cc17cc  4a02a79b  /data/data/com.myapp/lib/libwrapper.so
07-02 17:08:22.457: I/DEBUG(3844):     49cc17d0  44e313c0  /dev/ashmem/dalvik-LinearAlloc (deleted)
07-02 17:08:22.467: I/DEBUG(3844):     49cc17d4  44e313c0  /dev/ashmem/dalvik-LinearAlloc (deleted)
07-02 17:08:22.467: I/DEBUG(3844):     49cc17d8  49cc1bc4  
07-02 17:08:22.467: I/DEBUG(3844):     49cc17dc  0023c710  [heap]
07-02 17:08:22.467: I/DEBUG(3844):     49cc17e0  495f752c  /data/dalvik-cache/data@app@com.myapp-1.apk@classes.dex
07-02 17:08:22.467: I/DEBUG(3844):     49cc17e4  0023c108  [heap]
07-02 17:08:22.467: I/DEBUG(3844):     49cc17e8  00238040  [heap]
07-02 17:08:22.467: I/DEBUG(3844):     49cc17ec  4a5db590  /data/data/com.myapp/lib/libwrapper.so
07-02 17:08:22.467: I/DEBUG(3844):     49cc17f0  49cc1bc4  
07-02 17:08:22.467: I/DEBUG(3844):     49cc17f4  0023c108  [heap]
07-02 17:08:22.467: I/DEBUG(3844):     49cc17f8  0023c108  [heap]
07-02 17:08:22.467: I/DEBUG(3844):     49cc17fc  4a3c579f  /data/data/com.myapp/lib/libwrapper.so
07-02 17:08:27.908: I/BootReceiver(78): Copying /data/tombstones/tombstone_07 to DropBox (SYSTEM_TOMBSTONE)

So, the problem was that the following: !! I cached the JNIEnv pointer provided by the javaVM, in the onload method. !!

and this pointer is invalidated per thread (not exactly clear what this meant when I ran on it on the net. )

but it got me thinking when I got an error trying to get a pointer just before I call the method. So I recache the JNIEnv on every function call and rereference all the methods and classes. in essence just re-calling my

MY_NAMESPACE::VMHandler::getInstance()->init(env);

method did the trick...

an interesting thing to notice about references is the following :

A local is only usable from the thread it was originally handed to, and is valid until either an explicit call to DeleteLocalRef() or, more commonly, until you return from your native method. When a native method returns, all local references are automatically deleted.

Found : Here

But I guess in my case the JNIenv pointer was invalidated...