Logging in Fiji and ImageJ

Like many of us I follow a certain logging scheme. It is a mixture of things I accumulated over time and it does it’s job. My projects usually contain some logging console and I somehow redirect logging output to it.

Recently I’m trying to be a good citizen, meaning that I really try to use existing infrastructure instead of inventing the wheel over and over again. ImageJ2 provides a LogService – great, so let’s start using it.

You might want to read existing documentation like http://imagej.net/Logging, finding out that the existing ideas seem to make a lot of sense. So let’s find out if they can make me happy.

In order to be happy I’d like to…

  1. create projects that can run as standalone apps as well as Fiji/ImageJ2 plugins.
  2. I’d like to display logging information in an LoggingPanel which I can put anywhere in my GUI.
  3. stdout and stderr I would like to redirect to the LoggingPanel as well (don’t wanna miss anything!)
  4. when running as standalone app (e.g. from Eclipse or from an uber-JAR) I’d like to see all logging on the console too (stdout).
  5. additionally, could I redirect all logging information in a file ass well – great!
  6. all this should be conveniently configurable.

Ok, this list does not sound all to crazy I assume many of us have similar requirements. If you think I missed something important, please let me know!!!

After playing for some hours I’ve now put my findings on Github: https://github.com/fjug/IndagoLoggingWrapper

What works:

  • From within Eclipse: all points I raised above seem to be met.

What does not work:

  • As soon as I run from within Fiji things become ugly. The log4j.properties I specify in resources seem not to be used or overwritten by some properties that live in Fiji already. While

I am pretty sure that some/most/all issues my code has in Fiji can be fixed somehow, but here I really need help from someone. So… please help!

A more general question to end this post: if me make my example work, wouldn’t that be something we could use in Fiji (and maybe ImageJ) per default? Every time a plugin writes on stderr the Console pops up which is most of the time simply annoying. (For example it pops up frequently during updates saying “Trying to start the new updater” or something like this. Also it is currently not possible to cut and paste from the Console. It would be great if it would be replaced by a new console that provides some options menu from where you can (for example)

  1. specify when the window should open (e.g. stderr output, or log level ERROR, etc.)
  2. open and edit the log4j.preference file or modify parts of it somehow.

It is clear that this would need someone investing some time, and I would be happy to be this person… but… before I would need to dive deep enough into the existing infrastructure. Obviously I cannot even get my simple logging test (see above) to work as I want within Fiji… so… maybe we do one thing after the other… :smiley:

Thanks for your thoughts and your help,
Florian

2 Likes

Isn’t this exactly what the current Console gives you? When running standalone, you can just lean on the existing SciJava Console window. When running within Fiji, do you want to have a separate window just for your plugin? Or share the Console window with other plugins?

What about sources other than yours that produce messages on stdout or stderr? Surely you don’t want to redirect those?

Keep in mind that stdout and stderr are global. I think it is better to avoid them completely in favor of a context-sensitive logging mechanism—this is what logging frameworks like Log4j give you by creating e.g. a separate logger object for each class.

All of that is solved by logging frameworks like Log4j. You can write a logging configuration file that defines exactly the behavior you describe above.

As usual with the classpath, if more than one duplicate thing is found, the first one takes precedence. Did you remove jars/scijava-config.jar? Otherwise, the config file inside there is probably winning.

I know it is annoying. But the alternative is that users do not see errors, which is unacceptable. I got tired of the “it doesn’t work, and there is no error message” style of bug reports. If you do not want the Console window to pop up, then do not write to stderr.

The offending line is here. But it is an info line, so it will no longer pop up the Console window after I upload the bug-fix I did for you last weekend.

If you see annoying pop-ups like this, the fix is to correct the logging, not change how the Console works. Please report such annoyances as bugs.

Which platform? It works for me on OS X with Cmd+C to copy.

Why not enhance the existing Console window, instead of “replacing” it? Or do you know of a nice general-purpose reusable console component we could depend on?

It is very important to understand the separation between using a logging system at the library/component level, vs. configuring a logging system at the end-user/application level. Libraries and components should not presume to configure how logging it handled—it should merely issue logging messages at various levels. The application is responsible for shipping the logging configuration that defines where those messages go, how they are formatted, etc.

So with that in mind, in your use case above, there are two separate considerations:

  1. How to configure logging in your standalone app (what is launched from Eclipse).
  2. Whether and how to improve ImageJ’s logging configuration to meet everyone’s needs.

There are many related things we could discuss:

  • It would be nice to have a user-facing options dialog for configuring logging behavior like “do logging messages also go to a file?” and “what is the current logging level?”
  • The Console window does not save its position the way most ImageJ windows do. This would be easy to implement.
  • In what ways can we maximize the reusability of the Console pane in standalone apps besides ImageJ?

We can also imagine a much smarter Console window which is more closely tied to the LogService. The current approach is:

  1. The default LogService issues messages to stdout and stderr.
  2. The ConsoleService consumes stdout and stderr and republishes to the Console window.

The advantage of this approach is that many plugins which write directly to stdout and/or stderr will also appear in the Console window as desired.

However, the disadvantage is that metadata about the log messages—which level, from which class—is lost in the transition. We could certainly imagine something nicer, so that e.g. the Console window could filter messages by package, class and level. Do you need that? Are you able to invest time in implementing it?

Lastly, I took a look at your code on GitHub, but I do not understand exactly what you want to accomplish. The demo mixes together ideas from different layers, so I am not sure which functionality you want to make available where. The log package looks like it reinvents many of the same things I did in scijava-common to originally support the Console window.

In conclusion: Let’s not use stdout and stderr for our beautiful logging system. They are too global. Redirecting them is too disruptive. We can make the Console smarter about consuming log events directly. Or decide that the Console window is just for stderr and stdout, and instead focus on a smarter Log window for the good stuff.

What do you think?

3 Likes

I meant the code on GitHub to be a ‘minimal working example’. It comes with a Command Plugin and standalone App one can start from Eclipse, so one can quickly test both modes.
The log package is indeed something like the code you wrote for scijava-common.

First and foremost: yes, I have some time to implement an improved solution. (And yes, I did in fact mean to extend existing when I wrote ‘replace’ in my original post…) Still, we should come to a solid opinion about what ‘a better solution’ really looks like… :wink:

Clear is, that a running ImageJ/Fiji instance needs a Console window. This Console also needs to be able to consume stdout and stderr (since many plugins are and will use this for their outputs). It must be possible to create additional instances to be used inside GUI heavy plugins (like ClearVolume and tr2d, but also maybe things like Weka Segmenter or MaMuT or TackMate or TrakEM2 etc.).
Now it gets more interesting: these additional instances should be configurable in a way that they receive only log messages coming from certain packages and classes.

In order not to loose the metadata, as the current solution does, we could do something along the lines my ‘minimal working example’ on github does. In the highlighted line I let a SLF4J LocationAwareLogger know, that this call is issued from within a wrapper, so the location information provided in the log metadata will NOT be the wrapper itself but the caller of it. This, I think, is not yet used in your scijava implementation, at least I do receive a ton of DEBUG level output that all come from SLF4JLogService.java:67.

I am not sure though how we could go about filtering log messages. If everybody that wants to use the LogService would register himself could be retrieved and a subset of this list could be given to a Console window. The mother Console window if ImageJ/Fiji would receive the complete list by default.

You also mentioned that …

I have to look into this a bit more. Does the current LogService already support such context-sensitive logging? How would I set this up?

I do not see this very clear yet, but maybe you have an idea for how to go about all this. And again, once I have the feeling we both see a way to make all this happen I will be happy to code it up + document it accordingly.
(We might then release it at the MPI-CBG hackathon in December… :wink: )

Thanks for you first round of feedback,
looking forward to the next,
Florian

FYI, the SciJava logging system determines the calling class like so, in order to perform package- and class-specific logging.

Right now, the LogService does not publish events using the EventService. Doing so would have a high performance cost.

However, there is a service that does that: the StatusService. The plan currently is to extend the StatusService into a new TaskService so that each plugin can create Tasks (which can recursively contain sub-Tasks etc.) that track progress on operations. The existing ImageJ status bar would then be the simplest and most naive way of displaying progress on tasks, but we would also probably create a Tasks window that displays the progress task by task, similar to Eclipse’s Tasks view.

Maybe what you/we want here is not logging, but rather tasks? scijava/scijava-common#35

Great. Let me know what you think about the TaskService and whether something like that would fill the niche here.

I’m replying again quickly, because I want to emphasize one point which I have neglected to frame clearly. The log system is targeting developers, whereas the status + task system is intended for end users. I think trying to shoehorn end user notifications into the log system will result in some conflicting requirements, whereas keeping them distinct will help each system fulfill its core requirements better. Does that make sense?

1 Like

Quick reply before I will have to spend more time on figuring out a more in-depth proposal…

I agree, logging is for developers and I would like to not mix it up with status + task. I would really like to see the rather dull Console window being pimped up to

  1. show all log messages + stderr + stdout fiji/imagej2 wide.
  2. coming with at least some convenience UI stuff like text-based filtering and/or filtering by logging source.
  3. allow instantiation of additional Console panels that rich plugins can use in their respective GUI.

I’ll try to cook something up and will come back to you.

(Anybody with opinions, please speak up!) :wink:

I have been staring at the code, and remembering how things are laid out. Based on that, here are some details I’d like to clarify, and some corresponding new thoughts:

  • The ConsoleService, and associated graphical Console pane+window, is very much focused on being a place to show stdout and stderr. It is intended to be a graphical version of the terminal window which would be there if ImageJ had been launched from the command line.

  • Therefore, the reason that that the Console shows messages from the LogService is because the default LogService implementation writes logging messages to stdout/stderr.

  • The LogService knows the level of each logging message, and is capable of discerning the calling class by analyzing the call stack. But directly tying that to the ConsoleService might not be the way to go here.

Actually, I’m coming around to your original perspective that we might need a new thing instead—something like a souped up version of ImageJ 1.x’s Log window. We could update the default LogService to publish a lightweight event (not on the event bus, but rather using a classic Java listener model) for each logged message. Then, a Log pane component associated with a specific UI could act on those events as desired. We could have all the goodies, particularly filtering by class/package as well as level.

In a nutshell, my current intuition is that we should not bake all this into the existing console logic, since that is very much stdout/stderr-oriented only.

Here I am with a concrete proposal for how to solve the logging issue.
So far I had two main perspectives in mind

  • Usability for developers: it should be easy to use logging without that you need to know much about what happens behind the scenes.
  • Extendability of (initial) basic features that is in-line with the ideas behind slf4j and logback.

So let’s jump right in…

Developer Perspective (how to use it)

Use log service (no change to how it is so far)

// GET THE GLOBAL LOGGER
log = context.getService( LogService.class );
log.info( "I can use it!" );
log.warn( "It goes to the imagej2 global log though..." );

// GET A PERSONAL LOGGER (e.g. for my project)
myapplog = LoggerFactory.getLogger( "myapp" );
myapplog.trace( "trace message" );
myapplog.debug( "debug message" );
myapplog.error( "error message");

Show output of certain loggers, filtered by log level

final LoggingPanel myappLogPanel = new LoggingPanel();
myappLogPanel.registerToReceiveFrom( "TRACE", myapplog );

You can make as many of those as you want…

final LoggingPanel mySecondLogPanel = new LoggingPanel();
mySecondLogPanel.registerToReceiveFrom( "WARN", myapplog, mysecondlog, MyLibraryLog.log );

If you want to have a LoggingPanel that receives from everyone using the LogService just do…

final LoggingPanel bigbrotherLogPanel = new LoggingPanel();
bigbrotherLogPanel.registerToReceiveFrom( "TRACE" ); // no logger given --> get all the stuff

The last-mentioned option is what for example Fiji would do for the ‘mother of all logging windows’.

Wanna see it work?

From Eclipse

Easy! Just start LoggingDemoApp from within Eclipse. Two windows will pop up. One mother logger receiving all, one app specific logger that doesn’t. Additionally you see that the eclipse console still receives ALL outputs. This is because there is an additional console appender in the logback config.

From Fiji

Not that easy…
Easy is: use mvn similar to how I do it in this one-line bash script to ‘install’ the demo plugin. Then you can start the plugin LoggingDemo by using the CommandFinder in Fiji (keyboard shortcut ‘l’).
Not so easy is: you must also modify the logback config and add the appender hooks as I described above.

Under the hood – how it’s done

Please have a look here: https://github.com/fjug/IndagoLoggingWrapper
(And ignore repo name, readme, etc.)

All starts with a few lines in the logback configuration file:

<configuration>

  <!-- HERE I LEFT OUT ALL THE STUFF OF THE CURRENT CONFIGURATION -->

  <appender name="INFO" class="com.indago.log.LogbackPanelAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="TRACE" class="com.indago.log.LogbackPanelAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <!-- ROOT LEVEL MUST BE SET TO TRACE, BUT APPENDERS CAN FILTER AS SHOWN ABOVE -->
  <root level="trace">
    <appender-ref ref="INFO" />
    <appender-ref ref="TRACE" />
    <appender-ref ref="STDOUT" />
  </root>
  
</configuration>

The basic idea here is to create log-level hooks by using appenders (here named “INFO” and “TRACE”, but I suggest having one per log-level). The appenders used you can find here: https://github.com/fjug/IndagoLoggingWrapper/blob/master/src/main/java/com/indago/log/LogbackPanelAppender.java

The code says it all, but the most important idea in few words:

  • I took inspiration by an existing appender implementation that comes with logback.
  • When my appender (LogbackPanelAppender) start up, I retrieve the singleton instance a LoggingHub (see here). (This logging hub gets created lazily).
  • The LoggingHub follows the Singleton pattern, so there is ONE to rule them all!
  • The LogbackPanelAppender I wrote calls the receive method in the LoggingHub for each logging event flying in.
  • The LoggingHub also filters on the basis of the given loggers (see examples above).

I like about all this, that the log-level filtering is still done by logback, not by us. Very much in-line with the overall logback philosophy we create an interface to our logging panel world by implementing one dedicated appender.

From this appender onwards we are in ‘our own space’ where the LoggingHub manages all panels + the filtering on the bases of registered loggers per panel. (Alternatives exist, but I will not discuss them here because I think they have no-go type downsides.)

What would ImageJ2 / Fiji have to do to enable all this?

In order to enable anybody to use this concept:

  • SLF4J and logback must be in the class path (so far, only logback is, so we have one lib more in there).
  • Including the LoggingPanelAppender and the implementation of the LoggingHub and LoggingPanel from some artifact we’ll have to create. (Adding another dependency…)
  • Putting a few lines in the logback configuration file to hook up to the LoggingPanelAppender (as shown above).

In order to make use of this concept itself:

  • Create a LoggingPanel that receives from all loggers – as shown early on in this post (third example) but maybe hooking in at a different log-level (e.g. ‘WARN’ or ‘INFO’).
  • Use this panel somewhere, e.g. in one frame with the current console, or instead of it by bending stdout and stderr to it.

Do you think it is a requirement for such “personal loggers” to be excluded from the main log mechanism?

If not, we can probably already achieve this without needing to add explicit API for personal loggers. The default LogService already knows the calling class, and can classify log messages accordingly.

As an aside: if we do decide we want to add support for personal loggers, my suggested API would be something like:

log = context.service(LogService.class);
myLog = log.logger("myapp"); // or perhaps: log.logger(getClass());
myLog.debug("Here we go");

I don’t have time to test out your LoggingPanel stuff now, but will try to do so soon.

My current thinking is that we should keep the Console window as it is: for showing stdout and stderr messages. But introduce this new Log panel with smart filtering, etc., and change the default LogService to stop writing to stdout and stderr in favor of writing to the Log panel instead. And configure all existing logging mechanisms (SLF4J, logback, etc.) to pipe to SciJava logging, so that the Log panel is universally used. (Hence, the Console would only show messages written using raw System.out.println et. al.) We could also, in the ImageJ Legacy component, unify the ImageJ 1.x Log window with our new Log window, although this would be more work.

All of that said, I could be convinced to bend stdout and stderr into the SciJava log mechanism as well, although I have intuitive misgivings about it.

Hmmm… I do not see why.
This said, it would be simple to enable not only a white list (as I do now), but also a blacklist.

I am not quite sure what you mean… could you elaborate on this?

The official way to get a logger from SLF4j is:

LoggerFactory.getLogger( "nameAsString" );
LoggerFactory.getLogger( getClass() );

If I saw it right the LoggerFactory already does everything such that the LogService is happy.
Since everybody knowing SLF4J would automatically use the LoggerFactory (and it works very smoothly with the LogService already, I would suggest to stick with the known way.

This is a ImageJ2 / Fiji type of decision and I am happy to let you make these decisions.
Personally I think ImageJ/Fiji should strive towards ONE place to contain all logging and sysout. Even if this would be one window containing two tabs (so essentially being two places) users would win from at least perceived simplicity. At the moment Fiji opens all kind of log windows while one uses it (which is of course mostly because all kinds of plugins use all kinds of self-made log mechanisms (e.g. the Trainable Weka Segmenter, just to give one example).

I would love to see this incorporated in Fiji soon. What do you think – will it happen? If: when?

My thinking is: I went to great pains to avoid an SLF4J dependency in the core SciJava Common library. To link SciJava logging with SLF4J, we have the scijava-log-slf4j component. I was assuming you wanted to add support for “personal loggers” to the core SJC API, and not the SLF4J-specific approach. If so, we need a new API that resembles SLF4J—which scijava-log-slf4j can easily implement—but which does not use SLF4J directly. Or do you think it is sufficient to require scijava-log-slf4j in order to support personal logging?

Pragmatically, you are probably right. I don’t like the mixture of concerns, but I’ll give it some more thought.

I am sorry to say that my time till the end of the year is extremely sparse. Maybe we can tackle this together in Dresden in December? I will try my best to be there.

@fjug Confirmed that I attend the hackathon for the week of Dec 12 - 16. So are you on board with this plan?