Sample program crashes at SplashActivity in lean mode with target-version 14

[kenrestivo]

 Changing the lein-droid sample application :target-version 14, I get this explosion with lean compile target when running on a android 4.0.4 device. Works fine on an android 4.4.4 device.

I ActivityManager(1338)       START {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=test.leindroid.sample/.SplashActivity} from pid 1521
W WindowManager(1338)         Failure taking screenshot for (195x135) to layer 21015
I ActivityManager(1338)       Start proc test.leindroid.sample for activity test.leindroid.sample/.SplashActivity: pid=2570 uid=10071 gids={}
I MultiDex(2570)          VM with version 1.6.0 does not have multidex support
I MultiDex(2570)          install
I MultiDex(2570)          MultiDexExtractor.load(/data/app/test.leindroid.sample-1.apk, false)
I MultiDex(2570)          loading existing secondary dex files
I MultiDex(2570)          load found 0 secondary dex files
I MultiDex(2570)          install done
I neko.App(2570)          DalvikDynamicClassLoader is not found, probably Skummet is used.
D dalvikvm(2570)          GC_FOR_ALLOC freed 130K, 4% free 6464K/6723K, paused 2ms
I dalvikvm-heap(2570)         Grow heap (frag case) to 6.708MB for 360012-byte allocation
D dalvikvm(2570)          GC_FOR_ALLOC freed 1K, 5% free 6814K/7111K, paused 2ms
D dalvikvm(2570)          GC_FOR_ALLOC freed 351K, 10% free 6620K/7303K, paused 4ms
D dalvikvm(2570)          GC_FOR_ALLOC freed <1K, 5% free 6972K/7303K, paused 2ms
D dalvikvm(2570)          GC_FOR_ALLOC freed 351K, 10% free 6778K/7495K, paused 3ms
D dalvikvm(2570)          GC_CONCURRENT freed <1K, 3% free 7285K/7495K, paused 1ms+0ms
W InputManagerService(1338)   Starting input on non-focused client com.android.internal.view.IInputMethodClient$Stub$Proxy@a094dfb8 (uid=10038 pid=1521)
I ActivityManager(1338)       Displayed test.leindroid.sample/.SplashActivity: +86ms
W dalvikvm(2570)          VFY: unable to resolve exception class 1170 (Ljava/lang/ReflectiveOperationException;)
W dalvikvm(2570)          VFY: unable to find exception handler at addr 0x55
W dalvikvm(2570)          VFY:  rejected Lclojure/lang/Var;.derefLean ()Ljava/lang/Object;
W dalvikvm(2570)          VFY:  rejecting opcode 0x0d at 0x0055
W dalvikvm(2570)          VFY:  rejected Lclojure/lang/Var;.derefLean ()Ljava/lang/Object;
W dalvikvm(2570)          Verifier rejected class Lclojure/lang/Var;
W dalvikvm(2570)          Exception Ljava/lang/VerifyError; thrown while initializing Lclojure/lang/RT;
W dalvikvm(2570)          threadid=11: thread exiting with uncaught exception (group=0xa000f180)
E AndroidRuntime(2570)        FATAL EXCEPTION: ClojureLoadingThread
E AndroidRuntime(2570)        java.lang.ExceptionInInitializerError
E AndroidRuntime(2570)          at neko.App.loadClojure(App.java:35)
E AndroidRuntime(2570)          at neko.App$1.run(App.java:52)
E AndroidRuntime(2570)          at java.lang.Thread.run(Thread.java:856)
E AndroidRuntime(2570)        Caused by: java.lang.VerifyError: clojure/lang/Var
E AndroidRuntime(2570)          at clojure.lang.RT.<clinit>(RT.java:181)
E AndroidRuntime(2570)          ... 3 more
W ActivityManager(1338)         Force finishing activity test.leindroid.sample/.SplashActivity

Runs fine in debug mode in target-version 14 on this android 4.0.4 device, but not in lean mode.

Is this fixable? I need to support ancient (cheap, used) devices with this app.

[kenrestivo]

Just to note: this is the bog-standard lein-droid sample application from the lein-droid repository, one line in the project.clj modified to change :target-version from 18 to 14

[alexander-yakushev]

Hm, I haven't really tested Skummet on older devices, so I'm not sure why this can happen. Apparently Dalvik rejects clojure.lang.Var for some reason.

I infer your lean build pipeline includes proguarding the classes. Can you try disabling it by setting :proguard-execute false?

[kenrestivo]

Sure. Tried that, still dies:

I ActivityManager(1339)       Start proc test.leindroid.sample for activity test.leindroid.sample/.SplashActivity: pid=2673 uid=10071 gids={}
I MultiDex(2673)          Detected that extraction must be performed.
I MultiDex(2673)          load found 0 secondary dex files
I MultiDex(2673)          install done
I neko.App(2673)          DalvikDynamicClassLoader is not found, probably Skummet is used.
D dalvikvm(2673)          GC_FOR_ALLOC freed 107K, 4% free 6470K/6723K, paused 2ms
I dalvikvm-heap(2673)         Grow heap (frag case) to 6.713MB for 360012-byte allocation
D dalvikvm(2673)          GC_FOR_ALLOC freed 4K, 5% free 6817K/7111K, paused 2ms
D dalvikvm(2673)          GC_FOR_ALLOC freed 352K, 10% free 6623K/7303K, paused 2ms
D dalvikvm(2673)          GC_CONCURRENT freed <1K, 3% free 7131K/7303K, paused 0ms+0ms
D dalvikvm(2673)          GC_FOR_ALLOC freed 352K, 8% free 7132K/7687K, paused 2ms
W dalvikvm(2673)          VFY: unable to resolve exception class 1197 (Ljava/lang/ReflectiveOperationException;)
W dalvikvm(2673)          VFY: unable to find exception handler at addr 0x55
W dalvikvm(2673)          VFY:  rejected Lclojure/lang/Var;.derefLean ()Ljava/lang/Object;
W dalvikvm(2673)          VFY:  rejecting opcode 0x0d at 0x0055
W dalvikvm(2673)          VFY:  rejected Lclojure/lang/Var;.derefLean ()Ljava/lang/Object;
W dalvikvm(2673)          Verifier rejected class Lclojure/lang/Var;
W dalvikvm(2673)          Exception Ljava/lang/VerifyError; thrown while initializing Lclojure/lang/RT;
W dalvikvm(2673)          threadid=12: thread exiting with uncaught exception (group=0xa000f180)
E AndroidRuntime(2673)        FATAL EXCEPTION: ClojureLoadingThread
E AndroidRuntime(2673)        java.lang.ExceptionInInitializerError
E AndroidRuntime(2673)          at neko.App.loadClojure(App.java:35)
E AndroidRuntime(2673)          at neko.App$1.run(App.java:52)
E AndroidRuntime(2673)          at java.lang.Thread.run(Thread.java:856)
E AndroidRuntime(2673)        Caused by: java.lang.VerifyError: clojure/lang/Var
E AndroidRuntime(2673)          at clojure.lang.RT.<clinit>(RT.java:181)
E AndroidRuntime(2673)          ... 3 more
W ActivityManager(1339)         Force finishing activity test.leindroid.sample/.SplashActivity
W ActivityManager(1339)         Force finishing activity com.android.settings/.Settings
W InputManagerService(1339)   Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@a09c8e70
I ActivityManager(1339)       No longer want com.android.packageinstaller (pid 2600): hidden #16
E SurfaceTexture(1339)        [test.leindroid.sample/test.leindroid.sample.SplashActivity] drainQueueLocked: SurfaceTexture has been abandoned!
D dalvikvm(1524)          GC_CONCURRENT freed 393K, 8% free 8040K/8647K, paused 0ms+0ms
E InputDispatcher(1339)       Motion event has invalid pointer count 0; value must be between 1 and 16.
E InputDispatcher(1339)       Motion event has invalid pointer count 0; value must be between 1 and 16.
I Process(2673)           Sending signal. PID: 2673 SIG: 9
D AudioHardware(1298)         AudioHardware pcm playback is exiting standby.
D AudioHardware(1298)         openPcmOut_l() mPcmOpenCnt: 0
I ActivityManager(1339)       Process test.leindroid.sample (pid 2673) has died.

[alexander-yakushev]

Hm, I have no other ideas yet. Unfortunately, I have too little time on my hands these days to investigate this myself. The only thing I can suggest to you is to google around what things might cause VerifyError on Dalvik and inspect clojure.lang.Var's bytecode inside Skummet's jar to search for possible causes.

[kenrestivo]

The actual cause appears to be this:

VFY: unable to resolve exception class 1197 (Ljava/lang/ReflectiveOperationException;)

So, maybe something is optimizing that class out, but only when target 14 is used? As time permits, I'll investigate further.

Thanks for Skummet though. I used it in an embedded project (not Android/Dalvik, just the Oracle JVM), and it dramatically improved startup time.

[alexander-yakushev]

That's really nice to hear! I'm planning to get back to active Skummet development to improve the startup time of our internal JVM projects. I'm glad someone has already tried that.

[kenrestivo]

I verified that the problem has something to do with the runtime.

An apk compiled to target level 14 runs fine on an android 5.0 device, but crashes on the 4.0.4 device as so:

W dalvikvm(2523)          VFY: unable to resolve exception class 1385 (Ljava/lang/ReflectiveOperationException;)
W dalvikvm(2523)          VFY: unable to find exception handler at addr 0x55
W dalvikvm(2523)          VFY:  rejected Lclojure/lang/Var;.derefLean ()Ljava/lang/Object;
W dalvikvm(2523)          VFY:  rejecting opcode 0x0d at 0x0055
W dalvikvm(2523)          VFY:  rejected Lclojure/lang/Var;.derefLean ()Ljava/lang/Object;
W dalvikvm(2523)          Verifier rejected class Lclojure/lang/Var;
W dalvikvm(2523)          Exception Ljava/lang/VerifyError; thrown while initializing Lclojure/lang/RT;
W dalvikvm(2523)          threadid=12: thread exiting with uncaught exception (group=0xa000f180)
E AndroidRuntime(2523)        FATAL EXCEPTION: ClojureLoadingThread
E AndroidRuntime(2523)        java.lang.ExceptionInInitializerError
E AndroidRuntime(2523)          at neko.App.loadClojure(App.java:35)
E AndroidRuntime(2523)          at neko.App$1.run(App.java:52)
E AndroidRuntime(2523)          at java.lang.Thread.run(Thread.java:856)
E AndroidRuntime(2523)        Caused by: java.lang.VerifyError: clojure/lang/Var
E AndroidRuntime(2523)          at clojure.lang.RT.<clinit>(RT.java:181)
E AndroidRuntime(2523)          ... 3 more

It's over my head at this point. I'll just set the minimum API level to the minimum device I can test on and get it to work, and put it out that way.

[kenrestivo]

I chased this down to at least this line: https://github.com/alexander-yakushev/clojure/blob/skummet/src/jvm/clojure/lang/RT.java#L181

final static public Var OUT =
        Var.intern(CLOJURE_NS, Symbol.intern("*out*"), new OutputStreamWriter(System.out)).setDynamic()

Baksmali says, with lean mode and skummet, it becomes:

    .line 181
    sget-object v8, Lclojure/lang/RT;->CLOJURE_NS:Lclojure/lang/Namespace;

    const-string v9, "*out*"

    invoke-static {v9}, Lclojure/lang/Symbol;->intern(Ljava/lang/String;)Lclojure/lang/Symbol;

    move-result-object v9

    new-instance v10, Ljava/io/OutputStreamWriter;

    sget-object v11, Ljava/lang/System;->out:Ljava/io/PrintStream;

    invoke-direct {v10, v11}, Ljava/io/OutputStreamWriter;-><init>(Ljava/io/OutputStream;)V

    invoke-static {v8, v9, v10}, Lclojure/lang/Var;->intern(Lclojure/lang/Namespace;Lclojure/lang/Symbol;Ljava/lang/Object;)Lclojure/lang/Var;

    move-result-object v8

    invoke-virtual {v8}, Lclojure/lang/Var;->setDynamic()Lclojure/lang/Var;

    move-result-object v8

    sput-object v8, Lclojure/lang/RT;->OUT:Lclojure/lang/Var;

With debug mode using regular clojure (not skummet), I found something interesting. RT.java decompiles into several RT$1.java RT$2.java etc files, as well as an RT.smali file. And in RT.smali, that problematic line has a much shorter implementation:

    .line 181
    const-string v5, "clojure.core"

    invoke-static {v5}, Lclojure/lang/Symbol;->intern(Ljava/lang/String;)Lclojure/lang/Symbol;

    move-result-object v5

    invoke-static {v5}, Lclojure/lang/Namespace;->findOrCreate(Lclojure/lang/Symbol;)Lclojure/lang/Namespace;

    move-result-object v5

    sput-object v5, Lclojure/lang/RT;->CLOJURE_NS:Lclojure/lang/Namespace;

I'm still way over my head, but maybe this could save someone else time if they had the same problem.

It also works in debug mode using regular clojure. One thing I haven't yet tried is to recompile skummet using the exact same compiler I'm using for this project. Maybe there's some problem with javac.

[alexander-yakushev]

The second bytecode you provided is actually for another command :)

CLOJURE_NS = Namespace.findOrCreate(Symbol.intern("clojure.core"));

It goes exactly before OUT = Var.intern(...); in static initialization. Since RT.java in Clojure and Skummet are slightly different, the lines are probably shifted by one so 181 in Skummet points to another line.

RT$x.class files is how Java presents anonymous inner classes in bytecode. There are same classes in both Clojure and Skummet jars.

What made you suspect this specific line?

[kenrestivo]

Oh. I was taking the stacktrace very literally:

 at clojure.lang.RT.<clinit>(RT.java:181)

And that's how I arrived at line 181.

And in regular Clojure it does point to the bytecode for defining OUT.

Still can't figure out why Android API 14 runtime choke on this though, while Android API 18 runtime does not?

[alexander-yakushev]

No ideas left, sorry:(.

[kenrestivo]

Just throwing this into the mix: http://dev.clojure.org/jira/browse/CLJ-1829

I should note, I am compiling using Java 8. I haven't tried compiling with earlier java versions yet, but that might fix it.

[alexander-yakushev]

Oh, absolutely. Only Java7 is supported on Android, anything else is a wobbly incompatibility.

[kenrestivo]

I downgraded java and javac to version 7. Cleaned and built again. Same error. So it's not dependent on java or javac version.