java.util.logging (jdk14 logging) oddities explained (and fixed)

// April 1st, 2012 // bubble, design

Usually when you add logging to your application you create a java.util.logging.Logger that has the same name as the class you use the Logger in. Your code might look like this:

package some.test;

import java.util.logging.Logger;

public class Main {
  private static Logger log = Logger.getLogger(Main.class.getName());

  public static void main(final String[] args) {
    log.info("test");
  }
}

This works well and you get something like this as the log output:

01.04.2012 19:10:39 some.test.Main main
INFO: test

Now we can easily change the configuration of this logger and change the Loglevel. So for instance when we don’t like any logging we can disable logging for this class either using a configuration file or do it directly from code like so:

Logger.getLogger("some.test").setLevel(Level.OFF);

and the class will not log anymore.

Sometimes doing this in Nifty and using the name “de.lessvoid.nifty” for instance to shut off the logging refused to work. Some classes simply didn’t stop logging at all. What’s going on?

After a long headache we’ve finally found out!

Nifty used some special logger names for eventbus and inputevent logging. Both loggers used special names that did not relate to any class because there where several classes that would need to log those events. So a special name, like “NiftyEventBusLog” made sense for me.

In some places we had code like that:

package some.test;

import java.util.logging.Logger;

public class Main {
  private static Logger differentLog = Logger.getLogger("SpecialLog");

  public static void main(final String[] args) {
    differentLog.info("test");
  }
}

I somehow expected the loggername in the log to be “SpecialLog” since it’s the name of the logger. But in fact we get something else:

01.04.2012 19:24:41 some.test.Main main
INFO: test

O_o

The information still shows “some.test.Main” since this is the class that actually logged!

If you now try to disable logging for this class, like we’ve seen above:

Logger.getLogger("some.test").setLevel(Level.OFF);

YOU WOULD STILL SEE THE LINE IN THE LOG – even though you’ve disabled it (kinda) :-)

Of course to fix this you would need to disable the “SpecialLog” additionaly to “some.test.Main” but that’s pretty odd since you usually don’t know the exact names of all loggers beforehand.

So to make a long story short Nifty now (current git) removed all the special loggers and always only uses the logger with the name of the current class. When you now disable a logger you should be pretty sure that you really disable any output with that name ;-)

void

EDIT

I just realized that it would be very helpful to give you the actual logger names you need to disable when you still use Nifty 1.3.1:

  • “NiftyInputEventHandlingLog”
  • “NiftyEventBusLog”
  • “NiftyImageManager”

17 Responses to “java.util.logging (jdk14 logging) oddities explained (and fixed)”

  1. Tony Ivanov says:
    April 2, 2012 at 2:34 pm

    Good job solving that one! :D
    I ended up googling the same problem when I first got into nifty.
    That means I should be able to remove that infamous logger squelch workaround,
    Thanks!

    Reply
  2. Dom says:
    April 16, 2012 at 6:54 am

    Hi,
    First of all: SorryI’m posting here, it’s a little offtopic, but I haven’t found another way to communicate with you ;)

    I’ve been using niftygui on a project for my university (jme3 game) and I’d loved it. You do an absolutely great job here, dude!

    Now I thought about a little Java-App I want to create. No Game, so I think using jme3 would be a little “over the top”. But I want to use NiftyGUI for my Java-App, so my question is: Is itpossible to use NiftyGUI for a “normal” Java-App? And if yes, how? (Or is there anything I should know which makes Swing or anything else a better choice for my approach ;) ) It would be great if you could answer this question for me.

    Greetings and keep up your awesome work,
    Dominik

    Reply
    • void says:
      April 16, 2012 at 9:53 pm

      That greatly depends on what exactly you need to do :) Nifty has a Java2d renderer which could be used when you don’t want or can’t use OpenGL. I’m not sure in what state the Java2d renderer currently is though (I’ve not written it myself) but it might be worth to check it out. I’d recommend to use the native LWJGL with Nifty since that’s what I’m using :) but this would mean you need to go the whole OpenGL Display creation way. You can use OpenGL/LWJGL in a “normal” Java-App but again this depends on what context you’re in. Nifty is not suited for every possible GUI :) Maybe take a look at JavaFX 2.0?

      Reply
  3. jmaasing says:
    June 7, 2012 at 7:11 pm

    You could of course alos have named your special loggers something like Logger.getLogger(“de.lessvoid.logger.SpecialLog”) and not have to tie them to a class name but still be able to shut off all loggers but I guess you wanted to keep the same pattern with getClass().getName() everywhere.

    Reply
    • void says:
      June 7, 2012 at 8:44 pm

      Well, that would work too but the main oddity here is that in the actual logfile you’d still see the class (!) that called the jdk14 logger (independenly of the logger name). So you’d still have the problem that if a class “some.package.A” logs using “de.lessvoid.logger.SpecialLog” you would still see “some.package.A” in the log. And you wouldn’t be able to turn that log off using “some.package” ;-)

      Reply
      • jmaasing says:
        July 13, 2012 at 11:49 pm

        Entering the realm of speculation here since I haven’t actually tested this but I think the entries in the log file are determined by the SimpleFormatter and you might be able to turn the class name off if you set up the formatter for the special logs. Something like:
        java.util.logging.SimpleFormatter.format=”%4$s: %3$s – %5$s ”

        http://docs.oracle.com/javase/7/docs/api/java/util/logging/SimpleFormatter.html

        But as I said, idle speculation only :-)

        Reply
        • void says:
          July 14, 2012 at 1:19 am

          Thanks for this tip! I think this really could work :) On the other hand the special logs are not really that important I think. I’m considering sl4fj as the future logging framework for Nifty which will only add 26 KB which should be ok and would be more flexible. What do you think? =)

          Reply
          • hash says:
            July 15, 2012 at 2:18 am

            Switching to slf4j would make me pretty happy, if you’re interested in a random two cents. Right now I deal with nifty’s logging via the jul-over-slf4j bridge.

          • void says:
            July 15, 2012 at 12:52 pm

            I am interested! :) Appreciated! Thank you! Probably not in 1.3.x but really considering this for 1.4 or 2.x :)

          • jmaasing says:
            July 21, 2012 at 6:35 pm

            slf4j or logback (http://logback.qos.ch/). JDK logging is nice since it means no extra dependecies but in general it is the weakest (least flexible) of the log frameworks. So +1 for switching to anything :-)

          • void says:
            July 22, 2012 at 12:22 am

            hehe .. full ack!

          • Julien says:
            July 30, 2012 at 3:18 pm

            The standard logging API is enough for your needs, isn’t it? I don’t see the interest of adding another dependency (sl4fj or logback), really. Developers are free to use bridges if they are not satisfied by your choice but if you use a third party library in Nifty GUI, we will all be forced to use it. Please don’t do that.

          • toolforger says:
            August 1, 2012 at 8:09 am

            You use logback in the nifty libs and tell application programmers to install log4j.
            Pros and Cons:
            + log4j won’t do any message formatting unless the message is going to be logged (j.u.l. can’t do that), so you can riddle the code with logging calls with marginal overhead. Heavy j.u.l. logging will either slow down the code, or require checking the log level before each call.
            - log4j+logback is far more complicated to set up.
            + log4j allows you to combine j.u.l., commons logging, and logback in one application and control them from a single configuration file. I.e. as soon as another library is added, log4j may be required anyway.

          • void says:
            August 1, 2012 at 10:56 pm

            Great points but we’re talking slf4j which would allow you – the Nifty user – to decide the actual logging framework. When you’re using log4j already in your code Nifty will use log4j. If you’re using java.util.logging then yeah, that would be fine for Nifty as well. As long as a slf4j adapter exists for the logging framework of your choice (and I bet one exists!) Nifty would happily use it :)

            That is still an appealing idea to me although I tend to agree with Julien that simply sticking with vanilla java.util.logging would work for Nifty as well.

            Any more opinions?

  4. 3xp0n3nt says:
    June 12, 2012 at 7:22 am

    I really appreciate this fix, keep up the great work.

    Reply
  5. Nico says:
    October 2, 2012 at 4:46 am

    Nifty is really great and the new version (new for me, cause I was using 1.2 ;) is really wonderful!

    By the way, what do you think about a mailing list for users of nifty? I think it could help. Or there is one already available?

    Regards and thanks for nifty!

    Reply

Leave a Reply