pyimage forces logging to console

[jluethi]

I want my application using pyimagej to log some important information to a file. I've set my logging up in a basic way according to the logging documentation. If I also initialize imagej in this script (or in a module that gets imported), the logging only goes to the console. Here is a simple example of this. Without initializing ij, it logs all 3 statements to the example.log file. If ij is initialized, it prints info & warning to the console and ignores debug. So something in pyimagej or its imports seems to mess with the logging configuration (both saving to file and logging level are overwritten).

import logging
import imagej

ij = imagej.init('sc.fiji:fiji:2.0.0-pre-10+ch.fmi:faim-ij2-visiview-processing:0.0.1')

logging.basicConfig(filename='example.log', level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

I first thought that may just be an issue with the root logger, so I would use a named logger like logger = logging.getLogger(__name__) and just log to this logger. But that does not work either.

Maybe this is related to the warnings I get when initializing imagej about log4j not being initialized properly?

log4j:WARN No appenders could be found for logger (org.bushe.swing.event.EventService).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

Edit: Also, if the java side initialization of the logger is the issue, I would need some way to fix this on the python side, without manually setting classpaths. The application should be deployed easily to new machines, without a necessity of setting these kind of paths if possible.

[imagejan]

Which version of pyimagej are you using? If you installed the latest release, it might not yet include commit https://github.com/imagej/pyimagej/commit/cd7f77ca93a977b135a2c15039685913124ae937 on master.

I'm not sure though if it fixes this specific issue you're seeing...

Regarding log4j, I think to remember from previous discussions that this is brought in by some third-party dependency, and is also seen in other contexts when running ImageJ headlessly. @ctrueden might be able to explain.

[jluethi]

@imagejan Thanks for the idea. I did run v0.4.0 before. I now updated to the current master (v0.4.1.dev0). This does not change anything in the behavior mentioned above. I'm a bit confused, because the source code of pyimagej seems to follow best practices and is defining its own logger with _logger = logging.getLogger(__name__), thus this shouldn't interfere with the normal logging. This is why I'm suspecting something either on the Java side or in the way jnius is running is messing with the python logging system.

[imagejan]

(See also this unanswered post on the forum describing the same issue.)

[ctrueden]

Maybe this is related to the warnings I get when initializing imagej about log4j not being initialized properly?

@jluethi I would be very surprised if the log4j warnings are related in any way. That is about the Java-side logging, whereas what you are talking about is Python-side logging. I filed #41 to remind myself to fix that log4j warning (which can be safely ignored in the meantime).

I'm a bit confused, because the source code of pyimagej seems to follow best practices and is defining its own logger with _logger = logging.getLogger(__name__), thus this shouldn't interfere with the normal logging

Right. Thank you for testing with master. I do not know why your problems persists. If you suspect an issue with jnius/Java in general, you could try testing with plain import jnius; from jnius import autoclass; System = autoclass('java.lang.System') calls to do things with the standard JVM—i.e. leave ImageJ out of it—and see if you can still reproduce the problems with logging.

Regarding log4j, I think to remember from previous discussions that this is brought in by some third-party dependency, and is also seen in other contexts when running ImageJ headlessly.

I think what's happening is that SciJava's event service depends on a library called EventBus, which uses log4j internally, somehow without declaring a dependency on it (probably via reflection? But I didn't check). And so then when a log4j binding is missing, that warning is logged. Properly, we should include a log4j binding on the classpath anyway when using imagej.init().

Now that I wrote the previous paragraph, I'm a little skeptical though, because sc.fiji:fiji does ship a binding—logback-classic—and the fact that that's not being picked up on during initialization is a bit weird...

[jluethi]

@ctrueden Thank you for the explanation and the idea to test jnius/Java in general. Using import jnius; from jnius import autoclass; System = autoclass('java.lang.System') does not interfere with the logging. Importing imagej also does not interfere with the logging. Only when initializing imagej as imagej.init('sc.fiji:fiji:2.0.0-pre-10+ch.fmi:faim-ij2-visiview-processing:0.0.1') does it interfere with the logging. It also happens when initializing with ij = imagej.init('/Applications/Fiji.app'), so it seems to be something in the imagej.init function that is interfering with the python logging.

I then went line-by-line through the imagej.init function. It turns out, the line that interferes with the logging is import imglyb. Within imglyb, the call that messes with the logging is import scyjava. Within scyjava, the call that messes with the logging is import jgo. Within jgo, the call that messes with the logging is from .jgo import resolve_dependencies, jgo_main as main, specifically when I locally call from jgo import resolve_dependencies

The problem in jgo is that it hard-codes a logging configuration here. The python documentation strongly advises that libraries do not hard code the logging in this way. Therefore, I tested a local installation of jgo without the lines 29-33 in jgo.py and that solves this issue. I don't think removing the logging handlers should interfere with how the library performs any action and when I test this local modified version, my program using jgo via pyimagej still runs fine. If used on its own, the user would need to specify logging handles to get the INFO level logs, but this should not be done on this global level of the jgo.py.

Therefore, I create a pull request for removing the hard-coded logging from jgo.

[ctrueden]

@jluethi Thanks to your PR scijava/jgo#39, and subsequent release of jgo 0.4.0, this issue is now solved and can be closed—right? If not, please reopen with a quick summary of any remaining problems.