Graal optimizations may break uberjar running

TuggyNE commented 9 months ago

I recently upgraded Timbre and Tufte (as I use lein-ancient as part of my release scripting) and was surprised to discover a runtime failure on deployment. Local running is fine, uberjar building is fine, but on the server I get a stack trace that looks like this:

Exception in thread "main" java.lang.NoSuchFieldError: taoensso/timbre__init.__thunk__0__
    at taoensso.timbre__init.load(Unknown Source)
    at taoensso.timbre__init.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clojure.lang.RT.loadClassForName(RT.java:2237)
    at clojure.lang.RT.load(RT.java:449)
    at clojure.lang.RT.load(RT.java:424)
    at clojure.core$load$fn__6908.invoke(core.clj:6161)
    at clojure.core$load.invokeStatic(core.clj:6160)
    at clojure.core$load.doInvoke(core.clj:6144)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.core$load_one.invokeStatic(core.clj:5933)
    at clojure.core$load_one.invoke(core.clj:5928)
    at clojure.core$load_lib$fn__6850.invoke(core.clj:5975)
    at clojure.core$load_lib.invokeStatic(core.clj:5974)
    at clojure.core$load_lib.doInvoke(core.clj:5953)
    at clojure.lang.RestFn.applyTo(RestFn.java:142)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$load_libs.invokeStatic(core.clj:6016)
    at clojure.core$load_libs.doInvoke(core.clj:6000)
    at clojure.lang.RestFn.applyTo(RestFn.java:137)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$require.invokeStatic(core.clj:6038)
    at clojure.core$require.doInvoke(core.clj:6038)
    at clojure.lang.RestFn.invoke(RestFn.java:421)
    at slf4j_timbre.adapter$loading__6737__auto____171.invoke(adapter.clj:1)
    at slf4j_timbre.adapter__init.load(Unknown Source)
    at slf4j_timbre.adapter__init.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clojure.lang.RT.loadClassForName(RT.java:2237)
    at clojure.lang.RT.load(RT.java:449)
    at clojure.lang.RT.load(RT.java:424)
    at clojure.core$load$fn__6908.invoke(core.clj:6161)
    at clojure.core$load.invokeStatic(core.clj:6160)
    at clojure.core$load.doInvoke(core.clj:6144)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.core$load_one.invokeStatic(core.clj:5933)
    at clojure.core$load_one.invoke(core.clj:5928)
    at clojure.core$load_lib$fn__6850.invoke(core.clj:5975)
    at clojure.core$load_lib.invokeStatic(core.clj:5974)
    at clojure.core$load_lib.doInvoke(core.clj:5953)
    at clojure.lang.RestFn.applyTo(RestFn.java:142)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$load_libs.invokeStatic(core.clj:6016)
    at clojure.core$load_libs.doInvoke(core.clj:6000)
    at clojure.lang.RestFn.applyTo(RestFn.java:137)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$require.invokeStatic(core.clj:6038)
    at clojure.core$require.doInvoke(core.clj:6038)
    at clojure.lang.RestFn.invoke(RestFn.java:421)
    at slf4j_timbre.factory$loading__6737__auto____4342.invoke(factory.clj:1)
    at slf4j_timbre.factory__init.load(Unknown Source)
    at slf4j_timbre.factory__init.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clojure.lang.RT.loadClassForName(RT.java:2237)
    at clojure.lang.RT.load(RT.java:449)
    at clojure.lang.RT.load(RT.java:424)
    at clojure.core$load$fn__6908.invoke(core.clj:6161)
    at clojure.core$load.invokeStatic(core.clj:6160)
    at clojure.core$load.doInvoke(core.clj:6144)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.lang.Var.invoke(Var.java:384)
    at clojure.lang.Util.loadWithClass(Util.java:251)
    at com.github.fzakaria.slf4j.timbre.TimbreLoggerFactory.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at slf4j_timbre.static_logger_binder$_getLoggerFactoryClassStr.<clinit>(static_logger_binder.clj:20)
    at slf4j_timbre.static_logger_binder__init.load(Unknown Source)
    at slf4j_timbre.static_logger_binder__init.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clojure.lang.RT.loadClassForName(RT.java:2237)
    at clojure.lang.RT.load(RT.java:449)
    at clojure.lang.RT.load(RT.java:424)
    at clojure.core$load$fn__6908.invoke(core.clj:6161)
    at clojure.core$load.invokeStatic(core.clj:6160)
    at clojure.core$load.doInvoke(core.clj:6144)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.lang.Var.invoke(Var.java:384)
    at clojure.lang.Util.loadWithClass(Util.java:251)
    at org.slf4j.impl.StaticLoggerBinder.<clinit>(Unknown Source)
    at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
    at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
    at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:417)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:362)
    at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155)
    at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132)
    at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:273)
    at org.apache.http.conn.ssl.AbstractVerifier.<init>(AbstractVerifier.java:61)
    at org.apache.http.conn.ssl.AllowAllHostnameVerifier.<clinit>(AllowAllHostnameVerifier.java:46)
    at org.apache.http.conn.ssl.SSLConnectionSocketFactory.<clinit>(SSLConnectionSocketFactory.java:151)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clj_http.conn_mgr__init.__init0(Unknown Source)
    at clj_http.conn_mgr__init.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clojure.lang.RT.loadClassForName(RT.java:2237)
    at clojure.lang.RT.load(RT.java:449)
    at clojure.lang.RT.load(RT.java:424)
    at clojure.core$load$fn__6908.invoke(core.clj:6161)
    at clojure.core$load.invokeStatic(core.clj:6160)
    at clojure.core$load.doInvoke(core.clj:6144)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.core$load_one.invokeStatic(core.clj:5933)
    at clojure.core$load_one.invoke(core.clj:5928)
    at clojure.core$load_lib$fn__6850.invoke(core.clj:5975)
    at clojure.core$load_lib.invokeStatic(core.clj:5974)
    at clojure.core$load_lib.doInvoke(core.clj:5953)
    at clojure.lang.RestFn.applyTo(RestFn.java:142)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$load_libs.invokeStatic(core.clj:6016)
    at clojure.core$load_libs.doInvoke(core.clj:6000)
    at clojure.lang.RestFn.applyTo(RestFn.java:137)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$require.invokeStatic(core.clj:6038)
    at clj_http.client$loading__6789__auto____795.invoke(client.clj:1)
    at clj_http.client__init.load(Unknown Source)
    at clj_http.client__init.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clojure.lang.RT.loadClassForName(RT.java:2237)
    at clojure.lang.RT.load(RT.java:449)
    at clojure.lang.RT.load(RT.java:424)
    at clojure.core$load$fn__6908.invoke(core.clj:6161)
    at clojure.core$load.invokeStatic(core.clj:6160)
    at clojure.core$load.doInvoke(core.clj:6144)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.core$load_one.invokeStatic(core.clj:5933)
    at clojure.core$load_one.invoke(core.clj:5928)
    at clojure.core$load_lib$fn__6850.invoke(core.clj:5975)
    at clojure.core$load_lib.invokeStatic(core.clj:5974)
    at clojure.core$load_lib.doInvoke(core.clj:5953)
    at clojure.lang.RestFn.applyTo(RestFn.java:142)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$load_libs.invokeStatic(core.clj:6016)
    at clojure.core$load_libs.doInvoke(core.clj:6000)
    at clojure.lang.RestFn.applyTo(RestFn.java:137)
    at clojure.core$apply.invokeStatic(core.clj:669)
    at clojure.core$require.invokeStatic(core.clj:6038)
    at <our.main-ns>$loading__6789__auto____171.invoke(main_ns.clj:1)
    at <our.main-ns>__init.load(Unknown Source)
    at <our.main-ns>__init.<clinit>(Unknown Source)
    at java.base/java.lang.Class.forNameImpl(Native Method)
    at java.base/java.lang.Class.forName(Class.java:407)
    at clojure.lang.RT.classForName(RT.java:2209)
    at clojure.lang.RT.classForName(RT.java:2218)
    at clojure.lang.RT.loadClassForName(RT.java:2237)
    at clojure.lang.RT.load(RT.java:449)
    at clojure.lang.RT.load(RT.java:424)
    at clojure.core$load$fn__6908.invoke(core.clj:6161)
    at clojure.core$load.invokeStatic(core.clj:6160)
    at clojure.core$load.doInvoke(core.clj:6144)
    at clojure.lang.RestFn.invoke(RestFn.java:408)
    at clojure.lang.Var.invoke(Var.java:384)
    at clojure.lang.Util.loadWithClass(Util.java:251)
    at <our.main-ns>.<clinit>(Unknown Source)

It looks like it could be a subtle unexpected side effect of recent changes to optimize GraalVM builds.

It's possible that this only shows up when using the SLF4J adapter for Timbre, which is third-party. I don't have a great way to test without that currently, but I could work up a more minimal complete example if needed.

ptaoussanis commented 9 months ago

@TuggyNE Hi there, thanks for the report!

Requesting a bit more info please-

What SLF4J adapter are you using? Could you please link me to it?
Have you tried clearing all your build artifacts?
Besides updating Timbre and Tufte, did you update anything else? E.g. JVM, Graal options, etc.

Thanks!

TuggyNE commented 9 months ago

What SLF4J adapter are you using? Could you please link me to it?

https://github.com/fzakaria/slf4j-timbre

Have you tried clearing all your build artifacts?

Yes, but it doesn't help. (I did confirm it's not architecture or OS-dependent, though.)

Besides updating Timbre and Tufte, did you update anything else? E.g. JVM, Graal options, etc.

Nope, totally routine build. (I don't actually use GraalVM NI for anything on this project, it's just a plain uberjar.)

Thanks!

You're welcome, and thanks for the quick reply!

ptaoussanis commented 9 months ago

Can you share the version of Timbre that were you upgrading from? (May be helpful to pinpoint when an issue was introduced).

From your stacktrace, it looks to me like the problem might be with the appender, thought it's not immediately obvious to me what change/s might have caused trouble.

It looks like it could be a subtle unexpected side effect of recent changes to optimize GraalVM builds.

That change only affects unit tests, so I don't believe should affect your build.

I'd recommend opening an issue with slf4j-timbre. That project's maintainer can maybe more easily identify the problem from the stacktrace. If it turns out there was some kind of regression on Timbre's side, or if there's something I can do from Timbre's side to workaround the problem - I'll of course get right on it.

In the meantime am hoping they might be able to provide some guidance.

ptaoussanis commented 9 months ago

Relatedly, have also just opened https://github.com/fzakaria/slf4j-timbre/issues/71

rufoa commented 7 months ago

Thanks for bringing this up @TuggyNE!

Am I to understand that slf4j-timbre previously worked correctly under GraalVM? (I remember someone trying this out a while ago, but I don't recall the outcome.)

I'll aim to incorporate GraalVM into slf4j-timbre's integration tests so we can figure out any problems and avoid regressions.

ptaoussanis commented 4 months ago

Just an update to mention that I'm planning a major Timbre update around Jul-Aug that will include out-the-box SLF4J integration and that will be covered by Timbre's own test suite.

taoensso / timbre

Graal optimizations may break uberjar running #378