IllegalStateException in logging framework when executing a script

[ctrueden]

During the first session of the sciview tutorial at I2K 2020:

Likely a bug in the SciJava logging framework.

CC @kephale @skalarproduktraum @maarzt

[imagejan]

What was the script run from the TextEditor to trigger this issue?

[ctrueden]

# @SciView sv

sv.addSphere()

print('My first script!')

On @kephale's Linux box.

Probably not too enlightening though... looks more like a race condition to me. Here's the relevant line:

https://github.com/scijava/script-editor/blob/script-editor-0.5.6/src/main/java/org/scijava/ui/swing/script/TextEditor.java#L2042

It's just a debug log statement during cleanup phase.

[ctrueden]

Huh.

https://github.com/scijava/scijava-common/blob/scijava-common-2.85.0/src/main/java/org/scijava/log/CallingClassUtils.java#L52-L62

Maybe the Thread.currentThread().getStackTrace() somehow fails, due to the multithreaded stuff going on? Seems like we should fail more gracefully here rather than throwing IllegalStateException.

[imagejan]

FWIW, I can reproduce the ClassNotFoundException (that presumably leads to this issue here) using the following Groovy script:

stackTrace = Thread.currentThread().getStackTrace()

className = stackTrace[1].getClassName()
println className

clazz = Class.forName(className)
println clazz

which throws:

java.lang.ClassNotFoundException: java_lang_Thread$getStackTrace$0

[ctrueden]

Ahh! I missed that Class.forName was being called. Yeah, that's not good. Thanks for catching that, @imagejan.

If we really need to do dynamic class lookup there, we should change it to Context.getClassLoader().findClass(className).

[maarzt]

I would suggest this fix #411

I failed to reproduce the problem. I therefor couldn't make sure that the fix really works.

[skalarproduktraum]

Thanks for the fix @maarzt! @kephale's Linux box is possessed by a mean-spirited entity that causes random errors, I suggested to him repeatedly to start fresh with it, therefore I am not totally surprised this is not reproducible 😏

[maarzt]

mean-spirited entity

Sounds like a conspiracy...

I could confirm that #411 fixes the bug. The exception can be triggered by the following script:

@LogService log
log.setLevel("net.imagej", 2)
log.warn("Hello World!")

[maarzt]

@ctrueden I needed to change the parameter annotation in the script from @LogService log to #@LogService log when I used the latest version of scijava-common. Is this intentional?

[imagejan]

@maarzt the syntax is either @LogService in a comment (i.e. # or // depending on the script language; that's the "old" syntax), or language-independently #@ LogService (without space between # and @; that's the recommended syntax since 3 years). The latter has the advantage that it can be used anywhere in the script, not only in the script header (so e.g. after a license header etc.).

It's possible that before #403, @LogService without a comment would actually work, but this option was never documented neither intended.