would it make sense to check if the logger comes from the jruby-classloader
and then keep the customization ? just a thought !

@mkristian

Thanks for the reply. In all honesty I am very new to JRuby so I cannot speak with authority on your proposal being a working solution. This is mainly because I am not certain how / when the JRuby ClassLoader is used.

My thought is that this would not actually resolve the issue since in a web application all of the JRuby classes (including the JRuby ClassLoader) are loaded via the web application's ClassLoader. This means that there would still be a leak.

To avoid the leak we need to ensure nothing is added to the Logger that was created by a ClassLoader other than the system ClassLoader (since the system ClassLoader is what created java.util.logging). Perhaps a better check would be to see if the ClassLoader of JavaUtilLoggingLogger is the same as the ClassLoader of java.util.logging.Logger.

My real question is why would JRuby want to force users into using this setup in the first place? It seems that most users would want to be able to configure their logging. By overriding the Logger it seems we are restricting users to only using ConsoleHandler with a specific Formatter.

Admittedly a check of the ClassLoader's could provide passivity for some users, but it also seems to be adding unnecessary complexity to the code. Again this perception may be due to lack of understanding in what that code is trying to accomplish, so please feel free to correct me.

PS: Yet another solution would be to use the SimpleFormatter as mentioned on #1266

you convinced me, jruby could be somewhere in the class-loader hierarchy
and it is difficult to decide when the jruby default shall be applied or
not. I also have a project where I launch maven from within jruby and the
whole logging gets messed up since jruby applies its default.

I am not to deep into that part of t he code, but you have my
+1
for the patch ;)

This article seems to cover this issue in quite a bit of detail:

http://frankkieviet.blogspot.com/2006/10/classloader-leaks-dreaded-permgen-space.html

This is a good change, but we don't want to use the default formatting. It's way too verbose:

$ jruby -Xinvokedynamic.log.binding=true -e "def foo; 1 + 1; end; foo"
Nov 26, 2013 8:14:44 PM org.jruby.util.log.JavaUtilLoggingLogger info
INFO: []    bound to native method [#671 Hash]: IRubyObject RubyHash.op_aref(ThreadContext,IRubyObject)
Nov 26, 2013 8:14:44 PM org.jruby.util.log.JavaUtilLoggingLogger info
INFO: []    triggered site #1 bind (/Users/headius/projects/jruby/lib/ruby/shared/rubygems/specification.rb:1500)
Nov 26, 2013 8:14:44 PM org.jruby.util.log.JavaUtilLoggingLogger info
INFO: foo   bound to Ruby method [#5932 Object]: static IRubyObject __dash_e__.method__0$RUBY$foo(__dash_e__,ThreadContext,IRubyObject,Block)
Nov 26, 2013 8:14:44 PM org.jruby.util.log.JavaUtilLoggingLogger info
INFO: foo   triggered site #2 bind (-e:1)
Nov 26, 2013 8:14:44 PM org.jruby.util.log.JavaUtilLoggingLogger info
INFO: fixnum_op_plus_one    Fixnum operation at site #3 (-e:1) bound directly

I'll look at using SimpleFormatter to do the same as our custom one.

Ok...so I do not see a way to make the logging output less verbose without a custom logger. However, I have also discovered that at some point during Java 7, the logger cache was modified to use weak references.

Here's is the Red Hat / Iced Tea bug + CVE for an issue that included this fix, as near as I can tell from the revision history: https://bugzilla.redhat.com/show_bug.cgi?id=907344

So here's the situation then...

• On versions of Java before the logger cache fix (all public Java 6 releases, Java 7 releases up until that fix) creating a custom formatter will cause the classloader to be rooted forever.
• The default and SimpleFormatter output (which appear to be the same) are very verbose, outputting an extra line with full date/time, the full logger class name, and the type of log entry.

I want to fix this but that output is terrible. Perhaps we don't need to fix it on newer JDK?

well the classloader issue was one point and the second is that jruby adds
a console handler, i.e. if I want to log into a remote log service BUT
jruby also logs into the console. so basically from the application point
of view I do not have the control over the logging - jruby takes over part
of the control. and this I have seen in other situation where when jruby
comes into play the output changes to a totally different format. at least
I want to be able to tell jruby NOT to change any
formatter/handler/log-target !

hope I do not mix up things here ;)

to illustrate my point of jruby taking over the logger config:
https://gist.github.com/mkristian/7680803
assuming everyone knows how a regular maven console log looks like.

Perhaps we should just drop all custom logic from JavaUtilLoggingLogger and create our own slf4j logger that formats to console the way we want. Then if you really want j.u.l logging you would point slf4j at j.u.l and go from there.

Does that seem reasonable?

@headius switching from one logging framework to another might not be the solution. but SLF4J but help, I would propose something like this (knowing the current implementation just by staring a while at the code):

• if there is a org.slf4j.LoggerFactory in the classloader take a logger from there and just use it
• if not and if provided take the class from the options or system properties - 'jruby.logger.class'
• or finally use a console logger producing the jruby format

and as you said: if someone wants jruby to log into java.util.logging or log4j or commons-logging they have to setup slf4j in that manner.

sounds like a task for me ;)

@mkristian Sorry, I got my wires crossed. At one point we considered supporting SLF4J, but on recommendation from @qmx we opted to just build our own loggers that could be backed by anything. The JavaUtilLoggingLogger was our default option because the backend is always built-in, but the verbosity is less than desirable. Perhaps we should just revert to StandardErrorLogger as our default and make the JavaUtilLoggingLogger just pass through without customization.

that is OK with me as long there is an easy way to get rid of those verbose
output when some other application is configuring logging.

anyways I will see if find the right place to get the StandardErrorLogger
as default again and see what my embedded maven jruby launcher makes out of
it ;)

d745108 should keep the current output but removes all references to java.util.logging.

my maven logging problem was not related to this here - I just did not add the usual logging config to the way I executed maven :(

think that keeps all sides happy now :)

Thanks the changes look like they will resolve the issues I was having :)