Loggifier.unkrig.de: Difference between revisions
mNo edit summary |
|||
Line 1: | Line 1: | ||
== | == 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? | |||
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; | |||
'''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 <code>java.util.logging.config.file</code> system property set: | |||
'''$ 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''' | |||
-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 | 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.loggifier-runtime.jar\;. Main''' | |||
<span style="color:red;">[ Main <clinit>()] FINER: (Main.java:6) ENTRY args=()</span> | |||
<span style="color:red;">[ Main <clinit>()] FINER: (Main.java:6) RETURN</span> | |||
<span style="color:red;">[ Main main(String[])] FINER: (Main.java:9) ENTRY args=(args=String[0])</span> | |||
HELLO WORLD | |||
<span style="color:red;">[ Main main] FINE: About to terminate</span> | |||
<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 | |||
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 static void''' main(String[] args) { | |||
System.out.println("HELLO WORLD"); | |||
} | |||
} | |||
Now let's compile, loggify and run again: | Now let's compile, loggify and run again: | ||
'''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main''' | |||
<span style="color:red;">[ Main <clinit>()] FINER: (Main.java:6) ENTRY args=()</span> | |||
<span style="color:red;">[ Main <clinit>()] FINER: (Main.java:6) RETURN</span> | |||
<span style="color:red;">[ Main main(String[])] FINER: (Main.java:9) ENTRY args=(args=String[0])</span> | |||
HELLO WORLD | |||
<span style="color:red;">[ Main main(String[])] FINER: (Main.java:12) RETURN</span> | |||
'''$''' | |||
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 | 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; | |||
@Loggify("ALL=FINE") | |||
public class Main { | |||
// ... | |||
Then compile, loggify and run again: | 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''' | |||
<span style="color:red;">[ Main <clinit>()] FINE: (Main.java:1) CLINIT Main</span> | |||
<span style="color:red;">[ Main <clinit>()] FINE: (Main.java:9) ENTRY args=()</span> | |||
<span style="color:red;">[ Main <clinit>()] FINE: (Main.java:9) CONST "Main.USER"</span> | |||
<span style="color:red;">[ Main <clinit>()] FINE: (Main.java:9) INVOKE Logger.getLogger(String): args=("Main.USER")</span> | |||
<span style="color:red;">[ Main <clinit>()] FINE: (Main.java:9) RESULT Logger.getLogger(String) => java.util.logging.Logger@53c60f74</span> | |||
<span style="color:red;">[ Main <clinit>()] FINE: (Main.java:9) PUT java.util.logging.Logger@53c60f74 => Main.LOGGER</span> | |||
<span style="color:red;">[ Main <clinit>()] FINE: (Main.java:9) RETURN</span> | |||
<span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) ENTRY args=(args=String[0])</span> | |||
<span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) GET System.out => java.io.PrintStream@7020b3a3</span> | |||
<span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) CONST "HELLO WORLD"</span> | |||
<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 | |||
<span style="color:red;">[ Main main(String[])] FINE: (Main.java:12) RESULT PrintStream.println(String)</span> | |||
<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 | 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".