Maven and Groovy

[rnc]

Integrating sysout-over-slf4j as a dependency to the gmaven plugin which has some groovy code (that calls a third party library that has some system out calls) gives

[WARN] Your logging framework class org.sonatype.gossip.Gossip$LoggerImpl is not known - if it needs access to the standard println methods on the console you will need to register it by calling registerLoggingSystemPackage
[WARN] Unfortunately it is not possible to set up Sysout over SLF4J on this system without introducing a class loader memory leak.
If you never need to discard the current class loader [ClassRealm[plugin>org.codehaus.gmaven:gmaven-plugin:1.5, parent: sun.misc.Launcher$AppClassLoader@766c570c]] this will not be a problem and you can suppress this warning.
In the worst case discarding the current class loader may cause all subsequent attempts to print to System.out or err to throw an exception.
[INFO] Replaced standard System.out and System.err PrintStreams with SLF4JPrintStreams

[Mahoney]

The first warning is only really an issue if you are getting StackOverflowErrors because the org.sonatype.gossip.Gossip$LoggerImpl tries to log by printing to System.out/err, which is in turn directed to SLF4J, which delegates to org.sonatype.gossip.Gossip$LoggerImpl and so on.

If this is happening it can be fixed by adding the following before you initialise sysout-over-slf4j:

SysOutOverSLF4J.registerLoggingSystem("org.sonatype.gossip");
// Initialise now
SysOutOverSLF4J.sendSystemOutAndErrToSLF4J();

That will mean any class whose package starts with org.sonatype.gossip will print direct to the console rather than sending output to SLF4J, preventing an endless loop.

If it is not happening (perhaps because they are just a wrapper around another logging system, like Logback or Log4J) then you can suppress this warning by raising the log level of Logger uk.org.lidalia.sysoutslf4j.context.SysOutOverSLF4JInitialiser to ERROR rather than WARN in the underlying log configuration.

[Mahoney]

The second warning is telling you that now that the java.lang.System class has a static reference to an instance of a sysout-over-slf4j class, the ClassLoader that loaded sysout-over-slf4j cannot be garbage collected. This would be an issue if you had initialised sysout-over-slf4j in, for instance, a war file in Tomcat that you were regularly reloading without restarting the JVM; a ClassLoader maintains a reference to all Classes it has loaded, so you would have a steadily increasing number of classes you no longer use held in memory and would eventually fall over with an OutOfMemoryError.

I have no idea how big a deal that is for gmaven - probably not much? After all Maven typically runs once then exits, so even if you do discard classloaders, resulting memory leaks are of less importance. Again you can suppress it by raising the level of uk.org.lidalia.sysoutslf4j.context.PrintStreamCoordinatorFactory to ERROR.

[Mahoney]

I suppose the long and short of it is, are you actually seeing either an OutOfMemoryError or a StackOverflowError?

[rnc]

I have tried doing the below

SysOutOverSLF4J.registerLoggingSystem("org.sonatype.gossip");

but looking at the code SysOutOverSLF4J clinit calls sysOutOverSLF4JInitialiser.initialise which is before I can call registerLoggingSystem

You are correct I am not currently seeing any fatal errors - but currently I am still experimenting ;-)

[rnc]

Regarding the classloader .... I agree its probably not critical in the context of maven. Could you clarify how "java.lang.System class has a static reference to an instance of a sysout-over-slf4j class" has happened? i.e. is this because you are replacing the System streams ? What about when you reset them back (using a try/finally pattern) ?

How would you suggest changing the log.warn to e.g. debug in PrintStreamCoordinatorFactory ?

[Mahoney]

but looking at the code SysOutOverSLF4J clinit calls sysOutOverSLF4JInitialiser.initialise which is before I can call registerLoggingSystem

Good spot... Missing a test there. I'll fix that up.

And in the process I've found that the gnarliest bit of the problem (deducing from the stack trace what the calling class was and whether it was printing an exception) has been broken by changes in the JDK in such a way that exceptions will not be logged, which is a bit critical. In fact it raises severe questions about the safety of using sysout-over-slf4j at all; I'm beginning to wonder if I should stick a big "using this may be a mistake" sign on the front page now...

I'm really struggling to find a robust way of solving that problem, which may be a smell that it's not a clever one to have ever tried to solve.

[Mahoney]

Could you clarify how "java.lang.System class has a static reference to an instance of a sysout-over-slf4j class" has happened? i.e. is this because you are replacing the System streams ?

Yes, that's exactly it - the System streams are replaced with sysout-over-slf4j's custom subtype of PrintStream, which is loaded by

What about when you reset them back (using a try/finally pattern) ?

If you did that with SysOutOverSLF4J.restoreOriginalSystemOutputs() you should be OK.

How would you suggest changing the log.warn to e.g. debug in PrintStreamCoordinatorFactory ?

That's going to be totally dependent on your logging system's implementation - what does org.sonatype.gossip.Gossip$LoggerImpl do? Presumably it chooses what level to log at, and that is configurable? In Logback or Log4J it would be a case of setting the logger's level in logback.xml/log4j.properties or getting a reference to the Logger instance and calling setLevel on it.

[rnc]

Given a try/finally pattern negates the class loader problem is the warning (in that scenario) not applicable?

It might be nice if it was possible to automatically embed/wrap the sendSystemOutAndErrToSLF4J / restoreOriginalSystemOutputs. However that might require an API enhancement to do e.g. https://stackoverflow.com/questions/8657941/java-annotation-for-wrapping-a-method so that a method callback could be passed in.

Regarding the logging - I am using Maven's default logging. What I actually meant was changing the PrintStreamCoordinatorFactory from warn to debug - but in might not be needed at all given the above callback suggestion.

[rnc]

In fact it raises severe questions about the safety of using sysout-over-slf4j at all; I'm beginning to wonder if I should stick a big "using this may be a mistake" sign on the front page now...

Ouch :-( Could you clarify whereabouts in the code you are referring to ?

[Mahoney]

It's in here:
https://github.com/Mahoney/sysout-over-slf4j/blob/1.0-maintenance/src/main/java/uk/org/lidalia/sysoutslf4j/system/CallOrigin.java

Issue occurs because the first stack line outside sysout-over-slf4j is no longer in Throwable.class but in an inner class of Throwable.class. Result (I think) is that sysout-over-slf4j concludes that that inner class originated the call to print to the console and that sysout-over-slf4j thinks it is not part of printing a stacktrace.

I need to explore further what the implications are. My initial thought is that it means Throwable.printStackTrace() is being logged at INFO level on a Logger called java.lang.Thread$WrappedPrintStream, which is not good but perhaps not as disastrous as I thought at first.

[Mahoney]

Raised issue #5 to track the incorrectly routed exceptions.

[Mahoney]

It might be nice if it was possible to automatically embed/wrap the sendSystemOutAndErrToSLF4J / restoreOriginalSystemOutputs. However that might require an API enhancement to do e.g. https://stackoverflow.com/questions/8657941/java-annotation-for-wrapping-a-method so that a method callback could be passed in.

I'm afraid I'm really not a believer in Annotations for control flow. I wouldn't necessarily mind adding a function as so:

public static <T> T withSystemOutAndErrSentToSLF4J(Callable<T> work) throws Exception {
  try {
    sendSystemOutAndErrToSLF4J();
    return work.call();
  } finally {
    restoreOriginalSystemOutputs();
  }
}

which would be relatively light to use in Java 8:

withSystemOutAndErrSentToSLF4J(() -> {
    // Do work here
  }
);

[Mahoney]

Regarding the logging - I am using Maven's default logging. What I actually meant was changing the PrintStreamCoordinatorFactory from warn to debug - but in might not be needed at all given the above callback suggestion.

That's not currently possible, and it's not really the way SLF4J expects things to work. The library writer decides on the probable importance of a log message by statically choosing trace/debug/info/warn/error, and if the end user decides they aren't interested in that particular message they alter the behaviour of the logging system to suppress it rather than altering the behaviour of the library to log it at a different level.

I'd much rather see this handled in Maven's logging system than make it dynamically configurable in sysout-over-slf4j.

[Mahoney]

In fact it raises severe questions about the safety of using sysout-over-slf4j at all; I'm beginning to wonder if I should stick a big "using this may be a mistake" sign on the front page now...

Ouch :-( Could you clarify whereabouts in the code you are referring to ?

This is less serious than I had thought, and I have a fix I'm relatively comfortable with, though I would appreciate review. Discussion moved to issue #5.