LogService issue with jython-slim-2.7.2 and scripting-jython-1.0.0

Hello, I am running into an issue using LogService (through a script parameter) within a Jython script in the Script Editor. I have jython-slim-2.7.2 and scripting-jython-1.0.0 jars installed, and had previously removed jython-shaded-2.7.1 due to an issue with the subprocess module described here. Note that the issue only appeared after removing jython-shaded.

The issue is only with the log.info() method.

#@LogService log

for i in range(6):
	# These all function as expected
	log.log(i, "test log level {}".format(i))
	
log.debug("test debug")
log.warn("test warn")
log.error("test error")
log.trace("test trace")
log.info("test info") # fails here

This produces the following trace

TypeError: 'org.scijava.plugin.PluginInfo' object is not callable

	at org.python.core.Py.TypeError(Py.java:236)
	at org.python.core.PyObject.__call__(PyObject.java:396)
	at org.python.core.PyObjectDerived.__call__(PyObjectDerived.java:1032)
	at org.python.core.PyObject.__call__(PyObject.java:461)
	at org.python.core.PyObject.__call__(PyObject.java:465)
	at org.python.pycode._pyx10.f$0(New_.py:11)
	at org.python.pycode._pyx10.call_function(New_.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:173)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1687)
	at org.python.core.__builtin__.eval(__builtin__.java:497)
	at org.python.core.__builtin__.eval(__builtin__.java:501)
	at org.python.util.PythonInterpreter.eval(PythonInterpreter.java:255)
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:57)
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:31)
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
	at org.scijava.script.ScriptModule.run(ScriptModule.java:157)
	at org.scijava.module.ModuleRunner.run(ModuleRunner.java:165)
	at org.scijava.module.ModuleRunner.call(ModuleRunner.java:124)
	at org.scijava.module.ModuleRunner.call(ModuleRunner.java:63)
	at org.scijava.thread.DefaultThreadService.lambda$wrap$2(DefaultThreadService.java:225)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

Calling log.info() works in a Groovy script, however.

4 Likes

That’s an interesting observation.

I assume the issue is caused by a clash between the info() methods defined in Logger:

… and the private field info inherited from AbstractRichPlugin:

The private field should never be visible and accessed only via setInfo(), getInfo(), but somehow Jython seems to get confused… requires further digging on the Jython side, I believe.

@ctrueden have you encountered similar issues before?

2 Likes

I have seen a similar error using pyimagej in jupyter notebooks. Not with the Logger but similar conflict. It seems that python doesn’t respect privacy. The only solution we could come up with was changing the variable name to be something different from the method name. I would be very interested to know if there is a better solution.

2 Likes

Are there any news on this. This issue prevents Fiji execution inside our Docker container when using ther latest Fiji. But it works fine with older versions of Fiji inside containers, e.g. it works when using docker pull czsip/fiji_linux64_baseimage:1.3.1 while the latest 1.3.2 throws the error below.

(base) C:\Users\m1srh\Documents\Apeer_Modules\measure_3d_objects_034c0dd4-efa5-4731-9b45-a0ae9306dfc9>docker run -it --rm -v c:\Temp\input:/input -v c:\Temp\output:/output --env-file wfe.env test/apeer_test_3d_measure:latest
Java HotSpot(TM) 64-Bit Server VM warning: ignoring option PermSize=128m; support was removed in 8.0
Java HotSpot(TM) 64-Bit Server VM warning: Using incremental CMS is deprecated and will likely be removed in a future release
[INFO] Overriding BIOP Run Macro...; identifier: command:ch.epfl.biop.macrorunner.B_Run_Macro; jar: file:/Fiji.app/plugins/BIOP/B_Run_Macro-1.0.0-SNAPSHOT.jar
[INFO] Overriding Get Spine From Circle Rois; identifier: command:Cirlces_Based_Spine; jar: file:/Fiji.app/plugins/Max_Inscribed_Circles-1.1.0.jar
[INFO] Overriding Visualise vector field (experimental); identifier: command:net.haesleinhuepf.clijx.piv.visualisation.VisualiseVectorFieldsPlugin; jar: file:/Fiji.app/plugins/clijx_-0.29.1.11.jar
[ERROR] Traceback (most recent call last):
  File "/Fiji.app/scripts/apeer_3d_measure.py", line 220, in <module>
    log.info('Starting ...')
TypeError: 'org.scijava.plugin.PluginInfo' object is not callable

        at org.python.core.Py.TypeError(Py.java:236)
        at org.python.core.PyObject.__call__(PyObject.java:396)
        at org.python.core.PyObjectDerived.__call__(PyObjectDerived.java:1032)
        at org.python.core.PyObject.__call__(PyObject.java:461)
        at org.python.core.PyObject.__call__(PyObject.java:465)
        at org.python.pycode._pyx0.f$0(/Fiji.app/scripts/apeer_3d_measure.py:283)
        at org.python.pycode._pyx0.call_function(/Fiji.app/scripts/apeer_3d_measure.py)
        at org.python.core.PyTableCode.call(PyTableCode.java:173)
        at org.python.core.PyCode.call(PyCode.java:18)
        at org.python.core.Py.runCode(Py.java:1687)
        at org.python.core.__builtin__.eval(__builtin__.java:497)
        at org.python.core.__builtin__.eval(__builtin__.java:501)
        at org.python.util.PythonInterpreter.eval(PythonInterpreter.java:255)
        at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:57)
        at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:31)
        at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
        at org.scijava.script.ScriptModule.run(ScriptModule.java:157)
        at org.scijava.module.ModuleRunner.run(ModuleRunner.java:165)
        at org.scijava.module.ModuleRunner.call(ModuleRunner.java:124)
        at org.scijava.module.ModuleRunner.call(ModuleRunner.java:63)
        at org.scijava.thread.DefaultThreadService.lambda$wrap$2(DefaultThreadService.java:225)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
1 Like

Are there any news on this topic? Or has anyone a suggestion what could be done to find a solution? Enter a bug at Github?

Hi all,

I tried again to run a python script in Fiji and got still got stuck with the same error. This issue seems still open but it blocks me even when running script in normal mode (not headless).

Started 3d_analytics_adv.py at Tue Oct 20 08:50:50 CEST 2020
Traceback (most recent call last):
  File "C:\Users\m1srh\Documents\Fiji\scripts\3d_analytics_adv.py", line 285, in <module>
    log.info('Starting pipeline ...')
TypeError: 'org.scijava.plugin.PluginInfo' object is not callable

	at org.python.core.Py.TypeError(Py.java:236)
	at org.python.core.PyObject.__call__(PyObject.java:396)
	at org.python.core.PyObjectDerived.__call__(PyObjectDerived.java:1032)
	at org.python.core.PyObject.__call__(PyObject.java:461)
	at org.python.core.PyObject.__call__(PyObject.java:465)
	at org.python.pycode._pyx6.f$0(C:/Users/m1srh/Documents/Fiji/scripts/3d_analytics_adv.py:353)
	at org.python.pycode._pyx6.call_function(C:/Users/m1srh/Documents/Fiji/scripts/3d_analytics_adv.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:173)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1687)
	at org.python.core.__builtin__.eval(__builtin__.java:497)
	at org.python.core.__builtin__.eval(__builtin__.java:501)
	at org.python.util.PythonInterpreter.eval(PythonInterpreter.java:255)
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:57)
	at org.python.jsr223.PyScriptEngine.eval(PyScriptEngine.java:31)
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
	at org.scijava.script.ScriptModule.run(ScriptModule.java:157)
	at org.scijava.module.ModuleRunner.run(ModuleRunner.java:165)
	at org.scijava.module.ModuleRunner.call(ModuleRunner.java:124)
	at org.scijava.module.ModuleRunner.call(ModuleRunner.java:63)
	at org.scijava.thread.DefaultThreadService.lambda$wrap$2(DefaultThreadService.java:225)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

@sebi06 If I understand correctly, this error comes from log.info(“message”) calls in your script. This happens because the object log has a variable info that jython sees and this this block calling of the info( method.

As a workaround maybe you could replace all your log.info(…) calls with calls directly to log:

log.log(org.scijava.log.LogLevel.INFO,"message")

This should have the same outcome but bypasses the info method. I haven’t tested this but I think it should work.

Does this help?

2 Likes

The nasty thing is that my scripts has at least 30 or more of those log.info(...) statements.

But it works - :slight_smile:

from org.scijava.log import LogLevel

#log.info('Starting pipeline ...')
log.log(LogLevel.INFO, 'Starting pipeline ...')

# this works and prints the correct output inside the console

1 Like

Great that you found a workaround. As I wrote on the GitHub issue you opened, the problem is specific to jython-slim-2.7.2, as replacing it by jython-shaded-2.7.1.1 fixes the issue.

So it should be reported to the Jython folks.

I just did.

1 Like

Hi all, especially @sebi06 and @karlduderstadt

I have (obviously) been facing the same issue, as many of my scripts are heavily relying on proper logging to work. Replacing jyhon-slim by jython-shaded doesn’t sound very attractive / sustainable to me, as it would require manual work on each and every Fiji installation.

Therefore I was taking the hint of @karlduderstadt and implemented a workaround in my jython-scijava-logging module. The latest version 0.5.2 has been adjusted to avoid the messed-up calls to the log.info() method and use log.log() instead.

In case you’re interested you can give it a try - either download it from the releases page and drop the file into Fiji’s jars/ folder or simply enable the IMCF Uni Basel update site.

It uses the SciJava logging feature as a target (sink) for Python’s built-in logging module. For initializing it, all you need to do is to pass on the LogService object. As an added benefit you will be able to see log messages from underlying Python (Jython) modules as well in Fiji’s Console / Log window, as they are using the same mechanism (Python’s built-in logging).

A very simple example looks like this:

#@ LogService sjlog

import sjlogging

log = sjlogging.setup_logger(sjlog)

log.warn("warning")
log.warn("works %s like %s Python logging", "just", "real")  # <- this is Python "native" logging!

In case you want to increase the loglevel, it has convenience functions that allow you to specify the level by using a name:

sjlogging.set_loglevel("INFO")
log.info("info")

Cheers,
Niko

1 Like