6.0.1. breaks in GraalVM native-image

[borkdude]

Repro:

(ns test-clojure.graal
  (:gen-class)
  (:require [taoensso.timbre :refer [info]]))

(defn -main [& args]
  (info args))

Compiling this gives:

$ $GRAALVM_HOME/bin/native-image -cp "$(clojure -Spath)":classes test_clojure.graal --no-fallback --initialize-at-build-time=test_clojure,clojure
========================================================================================================================
GraalVM Native Image: Generating 'test_clojure.graal' (executable)...
========================================================================================================================
[1/7] Initializing...                                                                                    (4,1s @ 0,23GB)
 Version info: 'GraalVM 22.3.0 Java 11 CE'
 Java version info: '11.0.17+8-jvmci-22.3-b08'
 C compiler: cc (apple, arm64, 14.0.0)
 Garbage collector: Serial GC
[2/7] Performing analysis...  []                                                                         (5,4s @ 0,70GB)
   2.949 (74,58%) of  3.954 classes reachable
   3.368 (52,63%) of  6.400 fields reachable
  12.421 (43,20%) of 28.754 methods reachable
      30 classes,     0 fields, and   274 methods registered for reflection

Error: Classes that should be initialized at run time got initialized during image building:
 taoensso.timbre$default_output_fn was unintentionally initialized at build time. To see why taoensso.timbre$default_output_fn got initialized use --trace-class-initialization=taoensso.timbre$default_output_fn
taoensso.timbre.appenders.core$println_appender$fn__2600 was unintentionally initialized at build time. To see why taoensso.timbre.appenders.core$println_appender$fn__2600 got initialized use --trace-class-initialization=taoensso.timbre.appenders.core$println_appender$fn__2600
taoensso.timbre$_log_BANG_ was unintentionally initialized at build time. To see why taoensso.timbre$_log_BANG_ got initialized use --trace-class-initialization=taoensso.timbre$_log_BANG_
To see how the classes got initialized, use --trace-class-initialization=taoensso.timbre$default_output_fn,taoensso.timbre.appenders.core$println_appender$fn__2600,taoensso.timbre$_log_BANG_
Error: Use -H:+ReportExceptionStackTraces to print stacktrace of underlying exception

This can be prevented by delaying the instantiating of the java.util.Random object to the first call of the determistic-rand function.

cc @DerGuteMoritz

[ptaoussanis]

Hi @borkdude Michiel, thanks so much for the clear report and solution! Apologies for the trouble.

Could you please confirm that [com.taoensso/timbre "6.0.2-SNAPSHOT"] now works correctly on Graal? Will deploy 6.0.2 final as soon as I get your confirmation.

Relatedly, it'd be great to get a Graal compile included in Timbre's tests (and in my other projects) but I've never used Graal myself. Would you maybe be able to point me in the direction of a good example of how to do this?

Cheers!

[dekelpilli]

Hi, I raised the question around this in the Clojurians slack after running into this issue, and 6.0.2-SNAPSHOT has fixed it for me. Thanks for the (extremely) quick turnaround on this!

[ptaoussanis]

@dekelpilli Thanks a lot for the confirmation Dekel! Apologies for the trouble.

[com.taoensso/timbre "6.0.2"] is now up on Clojars 👍

Will keep this issue open until we have some kind of Graal unit test included (or we rule out that possibility).

[borkdude]

Fix looks good to me. Why was the random number needed in the log macro in the first place?

[ptaoussanis]

@borkdude Good question.

Basically we want a unique id for each logging call site (/ individual logging form). These ids can be useful for rate-limiting, etc.

But the arguments for a logging form aren't necessarily unique, so to uniquely identify each form we can use something like a counter or random number/uuid/gensym/etc.

Hope that makes sense?

[borkdude]

Yes. So a global counter would have been sufficient I guess. (rand) or (.nextDouble ...) can give you twice the same number (theoretically), a strictly increasing counter doesn't, although there the issue might be that eventually you will have to move to BigInteger: (inc' Long/MAX_VALUE)

[borkdude]

Ah, logging call site: those are fairly limited, so I would not expect that to hit BigInteger ever :)

[dekelpilli]

In the context of #354, using a global counter would also allow the change to also work for cljs

[ptaoussanis]

The likelihood of a ~64bit collision is small with the number of callsites, especially since the callsite id also incorporates other sources of entropy like the namespace, line, arg form, etc.

But a counter would indeed be simpler. This was a case of complexity growing organically over time :-) The initial choice of rand was quick+simple. Then the issue of determinism came up, then the GraalVM issue related to the determinism fix.

It was helpful of Michiel to re-check the original purpose: a counter is definitely the better choice now that we know we want determinism 👍

[borkdude]

Thanks @ptaoussanis !

[ptaoussanis]

Closing this issue, but have opened #361 re: adding Graal tests.