Loggifier.unkrig.de: Difference between revisions

From unkrig.de
Jump to navigation Jump to search
mNo edit summary
Line 1: Line 1:
== Getting started with LOGGIFIER ==
== Summary ==


Now you want to know how you can use the LOGGIFIER. I presume that you know what java.util.logging is and why you want
Have you ever wondered how much cleaner your code would look, if it weren't littered with all that logging code? And, when you're hunting bugs in production environments, do you produce tons of logging output, but often find that the critical bit of information that you need is missing?
to use logging at all (e.g. in favor of an interactive debugger).
 
If the answers are "no" and "no", then stop reading. Otherwise, LOGGIFIER may be the tool you need.
 
== Getting started ==
 
I presume that you know what <code>java.util.logging</code> is and why you want to use logging at all (e.g. in favor of an interactive debugger).


So let's start with a very simple program:
So let's start with a very simple program:


    '''import''' java.util.logging.Logger;
  '''import''' java.util.logging.Logger;
      
      
    '''public class''' Main {
  '''public class''' Main {
      
      
        '''private static final''' Logger LOGGER = Logger.getLogger("Main.USER");
      '''private static final''' Logger LOGGER = Logger.getLogger("Main.USER");
      
      
        '''public static void''' main(String[] args) {
      '''public static void''' main(String[] args) {
            System.out.println("HELLO WORLD");
          System.out.println("HELLO WORLD");
            LOGGER.fine("About to terminate");
          LOGGER.fine("About to terminate");
        }
      }
    }
  }
 
By default, java.util.logging is disabled, so we won't get any logging output:
 
    '''$ javac Main.java'''
    '''$ java Main'''
    HELLO WORLD
    '''$'''
 
Thus we need to create one more file
 
    # File 'my_logging.properties'.
    handlers = java.util.logging.ConsoleHandler
    java.util.logging.ConsoleHandler.level = FINEST
    .level = FINEST
 
, and run our program with the 'java.util.logging.config.file' system property set:


    '''$ java -Djava.util.logging.config.file=my_logging.properties Main'''
By default, java.util.logging is disabled, so we don't get any logging output:
    HELLO WORLD
    26.08.2011 11:01:53 Main main
    FINE: About to terminate
    '''$'''


(If you don't like the two-line output format, then you can configure a different log formatter, e.g.
  '''$ javac Main.java'''
'de.unkrig.commons.util.logging.formatter.PrintfFormatter', contained in [http://loggifier.unkrig.de/download/ de.unkrig.commons.jar], in the 'my_logging.properties' file:
  '''$ java Main'''
  HELLO WORLD
  '''$'''


    java.util.logging.ConsoleHandler.formatter = de.unkrig.commons.util.logging.formatter.PrintfFormatter
To enable logging, we need to create one more file
    de.unkrig.commons.util.logging.formatter.PrintfFormatter.format = COMPACT


Then you'll get:
  # File 'my_logging.properties'.
  handlers = java.util.logging.ConsoleHandler
  java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
  java.util.logging.ConsoleHandler.level    = FINEST
  java.util.logging.SimpleFormatter.format  = [%2$20s] %4$s: %5$s%n
  .level = FINEST


    '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.commons.jar\;. Main'''
, and run our program with the <code>java.util.logging.config.file</code> system property set:
    HELLO WORLD
    FINE Main::main About to terminate
    '''$'''


But that's only a matter of taste.)
  '''$ java -Djava.util.logging.config.file=my_logging.properties Main'''
  HELLO WORLD
  <span style="color:red;">[          Main main] FINE: About to terminate</span>
  '''$'''


So now let's loggify the 'Main' class! Get 'de.unkrig.loggifier.jar' and 'de.unkrig.loggifier-runtime.jar' from [http://loggifier.unkrig.de/download/] and run:
So now let's loggify the 'Main' class! Get 'de.unkrig.loggifier.jar' and 'de.unkrig.loggifier-runtime.jar' from [http://loggifier.unkrig.de/download/] and run:


    '''$ ls -l'''
  '''$ ls -l'''
    -rwx------+ 1 H7DA016 Kein 969 Aug 26 11:23 Main.class
  -rwx------+ 1 aunkrig users 969 Aug 26 11:23 Main.class
    '''$ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main Main.class'''
  '''$ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main Main.class'''
    '''$ ls -l'''
  '''$ ls -l'''
    -rwx------+ 1 H7DA016 Kein 2314 Aug 26 11:23 Main.class
  -rwx------+ 1 aunkrig users 2314 Aug 26 11:23 Main.class
    '''$'''
  '''$'''


Not only can you pass class files to LOGGIFER, but also directories, files in ZIP format that contain '.class' files
Not only can you pass class files to LOGGIFER, but also directories, files in ZIP format that contain '.class' files
Line 70: Line 61:
Now what logging do we get now?
Now what logging do we get now?


    '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.commons.jar\;de.unkrig.loggifier-runtime.jar\;. Main'''
  '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main'''
     FINER Main::<clinit>() (Main.java:5) ENTRY  args=()
  <span style="color:red;">[     Main <clinit>()] FINER: (Main.java:6) ENTRY  args=()</span>
     FINER Main::<clinit>() (Main.java:5) RETURN
  <span style="color:red;">[     Main <clinit>()] FINER: (Main.java:6) RETURN</span>
    FINER Main::main(String[]) (Main.java:8) ENTRY  args=(String[0])
  <span style="color:red;">[ Main main(String[])] FINER: (Main.java:9) ENTRY  args=(args=String[0])</span>
    HELLO WORLD
  HELLO WORLD
    FINE Main::main About to terminate
  <span style="color:red;">[          Main main] FINE: About to terminate</span>
    FINER Main::main(String[]) (Main.java:10) RETURN
  <span style="color:red;">[ Main main(String[])] FINER: (Main.java:12) RETURN</span>
    '''$'''
  '''$'''


Notice that you now need to have the (very small) 'de.unkrig.loggifier-runtime.jar' on the class path, because the
Notice that you now need to have the (very small) 'de.unkrig.loggifier-runtime.jar' on the class path, because the
injected logging code needs that.
injected logging code needs that.


By default, LOGGIFIER injects a 'reasonable' amount of logging: You can see how the class initializer of the 'Main'
By default, LOGGIFIER injects a 'reasonable' amount of logging: You can see how the class initializer of the 'Main' class is executed, then the 'main()' method. Notice how the hand-written logging seamlessly mixes with the automatically injected logging.
class is executed, then how the 'main()' method is executed. Notice how the hand-written logging seamlessly mixes with
the automatically injected logging.


Effectively, we can now remove the hand-written logging code from our class, because the automatically injected logging
Effectively, we can now remove the hand-written logging code from our class, because the automatically injected logging
code now does the job:
code now does the job:


    '''public class''' Main {
  '''public class''' Main {
      
      
        '''public static void''' main(String[] args) {
      '''public static void''' main(String[] args) {
            System.out.println("HELLO WORLD");
          System.out.println("HELLO WORLD");
        }
      }
    }
  }


Now let's compile, loggify and run again:
Now let's compile, loggify and run again:


    '''$ javac Main.java'''
  '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main'''
    '''$ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main Main.class'''
  <span style="color:red;">[     Main <clinit>()] FINER: (Main.java:6) ENTRY  args=()</span>
    '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.commons.jar\;de.unkrig.loggifier-runtime.jar\;. Main'''
  <span style="color:red;">[     Main <clinit>()] FINER: (Main.java:6) RETURN</span>
     FINER Main::<clinit>() (Main.java:5) ENTRY  args=()
  <span style="color:red;">[ Main main(String[])] FINER: (Main.java:9) ENTRY  args=(args=String[0])</span>
     FINER Main::<clinit>() (Main.java:5) RETURN
  HELLO WORLD
    FINER Main::main(String[]) (Main.java:8) ENTRY  args=(String[0])
  <span style="color:red;">[ Main main(String[])] FINER: (Main.java:12) RETURN</span>
    HELLO WORLD
  '''$'''
    FINER Main::main(String[]) (Main.java:10) RETURN
    '''$'''


For demonstration, we now set the amount of logging to the highest possible level. There are several ways to configure
For demonstration, we now set the amount of logging to the highest possible level. There are several ways to configure
the injection of logging code: We can pass a 'rule' to the LOGGIFER like '-rule ALL=FINE', or add a '@Loggify'
the injection of logging code: We can pass a 'loggification rule' to the LOGGIFER like '-rule ALL=FINE', or through a '@Loggify'
annotation to any class or method declaration:
annotation to any class or method declaration:


    import de.unkrig.loggifier.runtime.annotation.Loggify;
  import de.unkrig.loggifier.runtime.annotation.Loggify;
      
      
    @Loggify("ALL=FINE")
  @Loggify("ALL=FINE")
    public class Main {
  public class Main {
        // ...
      // ...


Then compile, loggify and run again:
Then compile, loggify and run again:


    '''$ javac Main.java -cp de.unkrig.loggifier-runtime.jar'''
  '''$ javac Main.java -cp de.unkrig.loggifier-runtime.jar'''
    '''$ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main Main.class'''
  '''$ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main Main.class'''
    '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;de.unkrig.commons.jar\;. Main'''
  '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main'''
     FINE Main::<clinit>() (Main.java:1) CLINIT Main
  <span style="color:red;">[     Main <clinit>()] FINE: (Main.java:1) CLINIT Main</span>
     FINE Main::<clinit>() (Main.java:7) ENTRY  args=()
  <span style="color:red;">[     Main <clinit>()] FINE: (Main.java:9) ENTRY  args=()</span>
     FINE Main::<clinit>() (Main.java:7) CONST  "Main.USER"
  <span style="color:red;">[     Main <clinit>()] FINE: (Main.java:9) CONST  "Main.USER"</span>
     FINE Main::<clinit>() (Main.java:7) INVOKE Logger.getLogger(String): args=("Main.USER")
  <span style="color:red;">[     Main <clinit>()] FINE: (Main.java:9) INVOKE Logger.getLogger(String): args=("Main.USER")</span>
     FINE Main::<clinit>() (Main.java:7) RESULT Logger.getLogger(String) => java.util.logging.Logger@156ee8e
  <span style="color:red;">[     Main <clinit>()] FINE: (Main.java:9) RESULT Logger.getLogger(String) => java.util.logging.Logger@53c60f74</span>
     FINE Main::<clinit>() (Main.java:7) PUT    Main.LOGGER <== java.util.logging.Logger@156ee8e
  <span style="color:red;">[     Main <clinit>()] FINE: (Main.java:9) PUT    java.util.logging.Logger@53c60f74 => Main.LOGGER</span>
     FINE Main::<clinit>() (Main.java:7) RETURN
  <span style="color:red;">[     Main <clinit>()] FINE: (Main.java:9) RETURN</span>
    FINE Main::main(String[]) (Main.java:10) ENTRY  args=(String[0])
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) ENTRY  args=(args=String[0])</span>
    FINE Main::main(String[]) (Main.java:10) GET    System.out ==> java.io.PrintStream@47b480
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) GET    System.out => java.io.PrintStream@7020b3a3</span>
    FINE Main::main(String[]) (Main.java:10) CONST  "HELLO WORLD"
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) CONST  "HELLO WORLD"</span>
    FINE Main::main(String[]) (Main.java:10) INVOKE PrintStream.println(String): target=java.io.PrintStream@47b480, args=("HELLO WORLD")
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) INVOKE PrintStream.println(String): target=java.io.PrintStream@7020b3a3, args=("HELLO WORLD")</span>
    HELLO WORLD
  HELLO WORLD
    FINE Main::main(String[]) (Main.java:10) RESULT PrintStream.println(String)
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) RESULT PrintStream.println(String)</span>
    FINE Main::main(String[]) (Main.java:12) RETURN
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:14) GET    Main.LOGGER => java.util.logging.Logger@53c60f74</span>
    '''$'''
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:14) CONST  "About to terminate"</span>
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:14) INVOKE Logger.fine(String): target=java.util.logging.Logger@53c60f74, args=("About to terminate")</span>
  <span style="color:red;">[          Main main] FINE: About to terminate</span>
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:14) RESULT Logger.fine(String)</span>
  <span style="color:red;">[ Main main(String[])] FINE: (Main.java:15) RETURN</span>
  '''$'''


(Notice that JAVAC now needs "de.unkrig.loggifier-runtime.jar" on the class path, because "@de.unkrig.loggifier.runtime.annotation.Loggify" lives there.)
(Notice that JAVAC now needs "de.unkrig.loggifier-runtime.jar" on the class path, because "@de.unkrig.loggifier.runtime.annotation.Loggify" lives there.)


Now you also get informed how the 'System.out' field is read and the string constant "HELLO WORLD" is used - if
Now you can watch how the <code>System.out</code> field is read and the string constant <code>"HELLO WORLD"</code> is used - if you're interested.
you're interested.


LOGGIFIER is not only available as a command-line tool, but also as an ECLIPSE plug-in and an ANT task.
LOGGIFIER is not only available as a command-line tool, but also as an ECLIPSE plug-in and an ANT task.

Revision as of 09:48, 23 August 2013

Summary

Have you ever wondered how much cleaner your code would look, if it weren't littered with all that logging code? And, when you're hunting bugs in production environments, do you produce tons of logging output, but often find that the critical bit of information that you need is missing?

If the answers are "no" and "no", then stop reading. Otherwise, LOGGIFIER may be the tool you need.

Getting started

I presume that you know what java.util.logging is and why you want to use logging at all (e.g. in favor of an interactive debugger).

So let's start with a very simple program:

 import java.util.logging.Logger;
   
 public class Main {
   
     private static final Logger LOGGER = Logger.getLogger("Main.USER");
   
     public static void main(String[] args) {
         System.out.println("HELLO WORLD");
         LOGGER.fine("About to terminate");
     }
 }

By default, java.util.logging is disabled, so we don't get any logging output:

 $ javac Main.java
 $ java Main
 HELLO WORLD
 $

To enable logging, we need to create one more file

 # File 'my_logging.properties'.
 handlers = java.util.logging.ConsoleHandler
 java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
 java.util.logging.ConsoleHandler.level     = FINEST
 java.util.logging.SimpleFormatter.format   = [%2$20s] %4$s: %5$s%n
 .level = FINEST

, and run our program with the java.util.logging.config.file system property set:

 $ java -Djava.util.logging.config.file=my_logging.properties Main
 HELLO WORLD
 [           Main main] FINE: About to terminate
 $

So now let's loggify the 'Main' class! Get 'de.unkrig.loggifier.jar' and 'de.unkrig.loggifier-runtime.jar' from [1] and run:

 $ ls -l
 -rwx------+ 1 aunkrig users 969 Aug 26 11:23 Main.class
 $ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main Main.class
 $ ls -l
 -rwx------+ 1 aunkrig users 2314 Aug 26 11:23 Main.class
 $

Not only can you pass class files to LOGGIFER, but also directories, files in ZIP format that contain '.class' files (e.g. JAR and WAR files), and even ZIP files that contain nested ZIP files with '.class' files (e.g. EAR files). In any case, LOGGIFIER will modify the contained '.class' "in-place".

Now what logging do we get now?

 $ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main
 [     Main <clinit>()] FINER: (Main.java:6) ENTRY  args=()
 [     Main <clinit>()] FINER: (Main.java:6) RETURN
 [ Main main(String[])] FINER: (Main.java:9) ENTRY  args=(args=String[0])
 HELLO WORLD
 [           Main main] FINE: About to terminate
 [ Main main(String[])] FINER: (Main.java:12) RETURN
 $

Notice that you now need to have the (very small) 'de.unkrig.loggifier-runtime.jar' on the class path, because the injected logging code needs that.

By default, LOGGIFIER injects a 'reasonable' amount of logging: You can see how the class initializer of the 'Main' class is executed, then the 'main()' method. Notice how the hand-written logging seamlessly mixes with the automatically injected logging.

Effectively, we can now remove the hand-written logging code from our class, because the automatically injected logging code now does the job:

 public class Main {
   
     public static void main(String[] args) {
         System.out.println("HELLO WORLD");
     }
 }

Now let's compile, loggify and run again:

 $ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main
 [     Main <clinit>()] FINER: (Main.java:6) ENTRY  args=()
 [     Main <clinit>()] FINER: (Main.java:6) RETURN
 [ Main main(String[])] FINER: (Main.java:9) ENTRY  args=(args=String[0])
 HELLO WORLD
 [ Main main(String[])] FINER: (Main.java:12) RETURN
 $

For demonstration, we now set the amount of logging to the highest possible level. There are several ways to configure the injection of logging code: We can pass a 'loggification rule' to the LOGGIFER like '-rule ALL=FINE', or through a '@Loggify' annotation to any class or method declaration:

 import de.unkrig.loggifier.runtime.annotation.Loggify;
   
 @Loggify("ALL=FINE")
 public class Main {
     // ...

Then compile, loggify and run again:

 $ javac Main.java -cp de.unkrig.loggifier-runtime.jar
 $ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main Main.class
 $ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main
 [     Main <clinit>()] FINE: (Main.java:1) CLINIT Main
 [     Main <clinit>()] FINE: (Main.java:9) ENTRY  args=()
 [     Main <clinit>()] FINE: (Main.java:9) CONST  "Main.USER"
 [     Main <clinit>()] FINE: (Main.java:9) INVOKE Logger.getLogger(String): args=("Main.USER")
 [     Main <clinit>()] FINE: (Main.java:9) RESULT Logger.getLogger(String) => java.util.logging.Logger@53c60f74
 [     Main <clinit>()] FINE: (Main.java:9) PUT    java.util.logging.Logger@53c60f74 => Main.LOGGER
 [     Main <clinit>()] FINE: (Main.java:9) RETURN
 [ Main main(String[])] FINE: (Main.java:12) ENTRY  args=(args=String[0])
 [ Main main(String[])] FINE: (Main.java:12) GET    System.out => java.io.PrintStream@7020b3a3
 [ Main main(String[])] FINE: (Main.java:12) CONST  "HELLO WORLD"
 [ Main main(String[])] FINE: (Main.java:12) INVOKE PrintStream.println(String): target=java.io.PrintStream@7020b3a3, args=("HELLO WORLD")
 HELLO WORLD
 [ Main main(String[])] FINE: (Main.java:12) RESULT PrintStream.println(String)
 [ Main main(String[])] FINE: (Main.java:14) GET    Main.LOGGER => java.util.logging.Logger@53c60f74
 [ Main main(String[])] FINE: (Main.java:14) CONST  "About to terminate"
 [ Main main(String[])] FINE: (Main.java:14) INVOKE Logger.fine(String): target=java.util.logging.Logger@53c60f74, args=("About to terminate")
 [           Main main] FINE: About to terminate
 [ Main main(String[])] FINE: (Main.java:14) RESULT Logger.fine(String)
 [ Main main(String[])] FINE: (Main.java:15) RETURN
 $

(Notice that JAVAC now needs "de.unkrig.loggifier-runtime.jar" on the class path, because "@de.unkrig.loggifier.runtime.annotation.Loggify" lives there.)

Now you can watch how the System.out field is read and the string constant "HELLO WORLD" is used - if you're interested.

LOGGIFIER is not only available as a command-line tool, but also as an ECLIPSE plug-in and an ANT task.

Download

To get the LOGGIFIER ECLIPSE plugins, define an update site

   http://loggifier.unkrig.de/update/

in "Help / Install new software...".

To get the JAR files mentioned above, download them from

   http://loggifier.unkrig.de/download/

The source code is available through SVN:

   https://svn.code.sf.net/p/loggifier/code

License

LOGGIFIER is published under the "New BSD License".