Editing Loggifier.unkrig.de
Jump to navigation
Jump to search
The edit can be undone. Please check the comparison below to verify that this is what you want to do, and then publish the changes below to finish undoing the edit.
Latest revision | Your text | ||
Line 1: | Line 1: | ||
== Motivation == | == Motivation == | ||
Line 31: | Line 29: | ||
== Getting started == | == 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: | |||
'''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, <code>java.util.logging</code> is disabled, so we don't get any logging output: | |||
'''$ javac Main.java''' | |||
'''$ java Main''' | |||
HELLO WORLD | |||
'''$''' | |||
To enable logging, we can either edit <code>$JAVA_HOME/jre/lib/logging.properties</code>, 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 <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> | |||
'''$''' | |||
Now let the magic begin! There are different [[#Tools|tools]] to loggify code; here we would use the [[#Java Agent|Java agent]]. | |||
Get <code>de.unkrig.loggifier.jar</code> and and run: | |||
'''$ java -javaagent:de.unkrig.loggifier.jar -Djava.util.logging.config.file=my_logging.properties 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> | |||
'''$''' | |||
By default, LOGGIFIER injects a 'reasonable' amount of logging: You can see how the class initializer of the <code>Main</code> class is executed, then how the <code>main()</code> 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''' | |||
<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. 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<span style="color:blue">=ALL=FINE</span> -Djava.util.logging.config.file=my_logging.properties Main''' | |||
or add a <code>@Loggify</code> 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''' | |||
<span style="color:red">[ Main <clinit>()] FINE: (Main.java:1) CLINIT Main</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:15) RETURN</span> | |||
'''$''' | |||
(Notice that JAVAC now needs "de.unkrig.loggifier-runtime.jar" on the class path, because "@Loggify" lives there.) | |||
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. | |||
== Tools == | == Tools == | ||
Line 38: | Line 138: | ||
* At build time: | * At build time: | ||
** The LOGGIFIER [[ | ** The LOGGIFIER [[#Command line tool|command line tool]] | ||
** The LOGGIFIER [[ | ** The LOGGIFIER [[#ECLIPSE Plugin|ECLIPSE plug-in]] | ||
** The | ** The <de.unkrig.loggifier> [[#ANT task|ANT task]] | ||
* At runtime: | * At runtime: | ||
** The [[ | ** The [[#LoggifyingClassLoader|LoggifyingClassLoader]] | ||
** The | ** With a [[#Java Agent|Java agent]] | ||
=== Command line tool === | |||
'''$ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main -help''' | |||
Implants logging code into Java class files 'in-place', also in ZIP format | |||
files (zip, jar, war, ear, ...) and nested ZIP format files. | |||
Usage: | |||
java de.unkrig.loggifier.Main [ <option> ] ... <dir-or-file> | |||
java de.unkrig.loggifier.Main [ <option> ] ... <dir-or-file> <dir-or-file> | |||
java de.unkrig.loggifier.Main [ <option> ] ... <dir-or-file> ... <dir> | |||
Valid options: | |||
-keep Keep copies of original files | |||
-selector <glob> | |||
Loggify only files matching the <glob>, e.g. '**.jar!**Test*.class' | |||
-rule <rule> Add the given rule | |||
The rule format is as follows | |||
<action>[,<action>]...=<level>[:<expression>] | |||
<action> is one of [ALOAD, ARITH, ASTORE, CAST, CATCH, CLINIT, CONST, CONVERT, ENTRY, GET, INVOKE, INSTANCEOF, | |||
LENGTH, LOAD, NEW, PUT, RESULT, RETURN, STORE, SWITCH, THROW] | |||
<level> is one of [ OFF SEVERE WARNING INFO CONFIG FINE FINER FINEST ] | |||
<expression> is like '(<eq> || <eq>) && !<eq>', where | |||
<eq> is '<var> == <glob>', where | |||
<var> is one of [ class source line ] (for action 'STORE' also 'name'). | |||
<glob> is a 'glob pattern' in single quotes like '*main*'. | |||
The exit status is 1 iff errors eccurred during loggification. | |||
=== ECLIPSE Plugin === | |||
When the plug-in is installed (see below), you will find a new page in the 'Project Properties' dialog: | |||
[[File:Loggifer_project_properties_page.png]] | |||
Here you can enable and configure loggification for the project. | |||
=== ANT task === | |||
LOGGIFIER defines a new task "<de.unkrig.loggifier>" that loggifies your code just like the command line tool. See the [[#Example|example]] to see how to make the new task accessible from inside your ANT script. | |||
==== Attributes ==== | |||
;selector :Which class files to instrument, e.g. "~**Test*.class". Default is "all files". | |||
;out :Where to write the output file or directory. Default is to perform an "in-place" loggification | |||
;keepOriginals :Keep copies of the original files (e.g. <code>.MyClass.class.orig</code> and <code>.MyJar.jar.orig</code>). | |||
==== Subelements ==== | |||
;rule :A loggification rule, e.g. 'STORE=FINE' | |||
;Resource Collection (<fileset> etc.) :The files to loggify (.class, .jar, .war, .ear, ...) | |||
==== Example ==== | |||
== | <project> | ||
<taskdef classpath="lib/de.unkrig.loggifier.jar" resource="de/unkrig/loggifier/ant.properties" /> | |||
<target name="default"> | |||
<loggifier> | |||
<rule>ALL=FINE</rule> | |||
<fileset file="bin/Main.class" /> | |||
</loggifier> | |||
</target> | |||
</project> | |||
=== LoggifyingClassLoader === | |||
From inside a running JVM, you can load loggified classes with the help of the <code>de.unkrig.loggifier.LoggifyingClassLoader</code>. | |||
=== Java Agent === | |||
Probably the most convenient way to loggify classes at runtime is to start the JVM with the following command line option: | |||
$ java -javaagent:path/to/de.unkrig.loggifier.jar ... | |||
The LOGGIFIER plugs into the [http://docs.oracle.com/javase/7/docs/api/java/lang/instrument/package-summary.html "Java programming language agents" API] (available since Java 5) and implements loggification at class-loading time. | |||
The agent interprets its argument as newline-separated loggification rules: | |||
$ java '-javaagent:path/to/de.unkrig.loggifier.jar<span style="color:blue">=CLINIT=INFO | |||
ALL=FINER</span>' ... | |||
== Loggification == | |||
The LOGGIFIER loads a class file and analyzes the bytecode of the class's constructors and methods. Looking at the code, it identifies "interesting" points where logging code could be inserted. Each of the logging points is characterized by an [[#Logging actions|action]]. For each logging point, the relevant [[#Loggification rules|loggification rules]] are executed, and the first that matches determines at what level the logging event is to be logged (or if no logging code is injected for this logging point). Loggification rules optionally have a "discriminator expression", which has a set of [[#Loggification rule parameters|parameters]]. | |||
=== Logging actions === | |||
;ALOAD :Log array type, array value, index and element value read from an array | |||
;ARITH :Log operands, operator (+, -, ...) and result of an arithmetic operation | |||
;ASTORE :Log the array, the index and the value being stored in an array | |||
;CAST :Log the type to which the operand is casted | |||
;CATCH :Log the declared catch type and the actually caught exception | |||
;CLINIT :Log the name of a class that is initialized | |||
;CONST :Log the value of a constant being pushed on the operand stack | |||
;CONVERT :Log a value that is arithmetically converted and the conversion result | |||
;ENTRY :Log the target object (if non-static) and the arguments as a method begins execution | |||
;GET :Log declaring class of, name of, source instance of (if non-static) and value read from a field | |||
;INVOKE :Log signature, target object (if non-static) and arguments right before a method is invoked | |||
;INSTANCEOF:Log the type to which the operand type is compared | |||
;LENGTH :Log the array who's length is determined | |||
;LOAD :Log type of, name of and value read from a local variable | |||
;NEW :Log the type of a new object being instantiated | |||
;PUT :Log declaring class of, name of, target instance of (if non-static) and value assigned to field | |||
;RESULT :Log method signature and invocation result (if not 'void') | |||
;RETURN :Log the value that is being returned by a method (if not 'void') | |||
;STORE :Log value assigned to, type of and name of a local variable | |||
;SWITCH :Log the integer value that a switch is being executed on | |||
;THROW :Log an exception right before it is thrown | |||
=== Loggification rules === | |||
A rule triggers if and only if | |||
* It applies to the action of the loggification point (ENTRY, EXIT, THROW, ...) | |||
* Its discriminator expression (if any) evaluates to TRUE for the actual point (who's properties are availables as variables in the discriminator expression, see above) | |||
The sequence of checked rules for each logging point is as follows: | The sequence of checked rules for each logging point is as follows: | ||
Line 141: | Line 271: | ||
:Its values of in reverse order (i.e. the last value/rule takes the highest precedence). | :Its values of in reverse order (i.e. the last value/rule takes the highest precedence). | ||
;If using the four-parameter [[ | ;If using the four-parameter [[#LoggifyingClassLoader|LoggifyingClassLoader]] constructor | ||
:The 'logLevelCalculator' argument. | :The 'logLevelCalculator' argument. | ||
;If using the [[ | ;If using the [[#ANT task|ANT task]] | ||
: | :'<rule>' subelements, in reverse order (i.e. the last <rule> takes the highest precedence). | ||
;If using the [[ | ;If using the [[#Command line tool|LOGGIFIER command line tool]] | ||
:The '-rule' options, in reverse order (i.e. the last '-rule' option takes the highest precedence). | :The '-rule' options, in reverse order (i.e. the last '-rule' option takes the highest precedence). | ||
;If using the [[ | ;If using the [[#ECLIPSE Plugin|ECLIPSE builder]] | ||
:The levels on the "Loggifier" property page of each project. (This rule ALWAYS applies, hence the following rules are never executed). | :The levels on the "Loggifier" property page of each project. (This rule ALWAYS applies, hence the following rules are never executed). | ||
;If using the [[ | ;If using the [[#Java Agent|Java agent]] | ||
:Its argument string passed to the agent, split at '\n', in reverse order (i.e. the last fragment/rule takes the highest precedence). | :Its argument string passed to the agent, split at '\n', in reverse order (i.e. the last fragment/rule takes the highest precedence). | ||
; | ;Accesses to local variable who's name ends with '__' | ||
:FINER | :FINER | ||
; | ;Accesses to fields who's name ends with '__' | ||
:FINER | :FINER | ||
; | ;Instantiations of a class who's name ends with '__' | ||
:FINER | :FINER | ||
Line 171: | Line 301: | ||
:OFF | :OFF | ||
Notice that non-static fields (a.k.a. 'instance variables | Notice that non-static fields (a.k.a. 'instance variables) are initialized by the class's constructors. Static fields ('class variables') are initialized by the synthetic '<clinit>()' method, which cannot be annotated in source code. | ||
=== | === Loggification rule parameters === | ||
Generally the LOGGIFER considers various points in the code that could be subject to loggification. Each of these | |||
points is identified by | |||
;action | ;action | ||
: | :E.g. 'method entry', 'local variable assignment', 'arithmetic operation' (see [[#Logging actions|logging actions]]) | ||
;source | ;source | ||
:The name of the Java source file that JAVAC stores in each | :The name of the Java source file that JAVAC stores in each .class file if enabled by '-g:source'. | ||
;classAccess | ;classAccess | ||
:The accessibility of the class being instrumented ( | :The accessibility of the class being instrumented ('public', 'protected' or 'private') | ||
;class | ;class | ||
:The fully qualified name of the class being instrumented, e.g. | :The fully qualified name of the class being instrumented, e.g. '{@code pkg.MyClass}' | ||
;methodAccess | ;methodAccess | ||
:The accessibility of the method being instrumented ( | :The accessibility of the method being instrumented ('public', 'protected' or 'private') | ||
;method | ;method | ||
:The enhanced, dequalified name of the method being instrumented, e.g. | :The enhanced, dequalified name of the method being instrumented, e.g. 'meth(String, MyClass)' or '<T extends IOException>meth(T, MyClass, List<T>)' | ||
;line | ;line | ||
:The line number related to the code point being instrumented that JAVAC stores in each .class file if enabled by | :The line number related to the code point being instrumented that JAVAC stores in each .class file if enabled by '-g:lines'. | ||
;type | ;type (only for actions CAST, INSTANCEOF and NEW) | ||
:The relevant type for the operation, e.g. | :The relevant type for the operation, e.g. 'pkg.Class', 'pkg.Class[][]', 'int[][]' | ||
;classAndField (only for actions GET and PUT) | |||
:The subject class and field, e.g. | :The subject class and field, e.g. 'pkg.Class.field' | ||
;variable (only for actions LOAD and STORE) | |||
:The name of the subject local variable | :The name of the subject local variable | ||
At each loggification point, the LOGGIFIER determines if logging code is to be inserted or not ('discrimination') and | At each loggification point, the LOGGIFIER determines if logging code is to be inserted or not ('discrimination') and |