Loggifier.unkrig.de / Getting Started

From unkrig.de
Jump to navigation Jump to search

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 can either edit $JAVA_HOME/jre/lib/logging.properties, or create a file

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

, 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
 $

Now let the magic begin! There are different tools to loggify code; here we would use the Java agent.

Get de.unkrig.loggifier.jar and and run:

 $ java -javaagent:de.unkrig.loggifier.jar -Djava.util.logging.config.file=my_logging.properties 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
 $

By default, LOGGIFIER injects a 'reasonable' amount of logging: You can see how the class initializer of the Main class is executed, then how the main() method is entered and how it returns. Notice how the hand-written logging ("About to terminate") 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 run it again:

 $ java -javaagent:de.unkrig.loggifier.jar -Djava.util.logging.config.file=my_logging.properties 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. Loggification is controlled by 'loggification rules', and there are several ways to declare them: We can pass them on the command line like

 $ java -javaagent:de.unkrig.loggifier.jar=ALL=FINE -Djava.util.logging.config.file=my_logging.properties Main

or add a @Loggify annotation to any class, constructor or method declaration:

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

Then compile and run again:

 $ javac Main.java -cp de.unkrig.loggifier-runtime.jar
 $ java -javaagent:de.unkrig.loggifier.jar -Djava.util.logging.config.file=my_logging.properties Main
 [     Main <clinit>()] FINE: (Main.java:1) CLINIT Main
 [ 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:15) RETURN
 $

(Notice that JAVAC now needs "de.unkrig.loggifier-runtime.jar" on the class path, because "@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.