Loggifier.unkrig.de: Difference between revisions
mNo edit summary |
No edit summary |
||
Line 218: | Line 218: | ||
</target> | </target> | ||
</project> | </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:de.unkrig.loggifier-all.jar ... | |||
The LOGGIFIER plugs into the <a href="http://docs.oracle.com/javase/7/docs/api/java/lang/instrument/package-summary.html">"Java programming language agents" API</a> (available since Java 5). It implements loggification at class-loading time. | |||
== Loggification events == | |||
Generally the LOGGIFER considers various points in the code that could be subject to loggification. Each of these | |||
points is identified by | |||
:action ;E.g. 'method entry', 'local variable assignment', 'arithmetic operation', see | |||
de.unkrig.loggifier.LoggifyingContentsTransformer.Action) | |||
:source ;The name of the Java source file that JAVAC stores in each .class file if enabled by '-g:source'. | |||
:classAccess ;The accessibility of the class being instrumented ('public', 'protected' or 'private') | |||
:class ;The fully qualified name of the class being instrumented, e.g. '{@code pkg.MyClass}' | |||
:methodAccess ;The accessibility of the method being instrumented ('public', 'protected' or 'private') | |||
:method ;The enhanced, dequalified name of the method being instrumented, e.g. | |||
'meth(String, MyClass)' or '<T extends IOException>meth(T, MyClass, List<T>)' | |||
:line ;The line number related to the code point being instrumented that JAVAC stores in each .class file if | |||
enabled by '-g:lines'. | |||
:type (only for actions CAST, INSTANCEOF and NEW) | |||
;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. 'pkg.Class.field' | |||
:variable (only for actions LOAD and STORE) | |||
;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 | |||
on which level the event will be logged at runtime ('level'). This is achieved by checking the 'loggification | |||
rules'. | |||
== 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 == | |||
To each loggification point a sequence of loggification rules applies. The first rule that triggers determines the | |||
level on which the point will be logged at runtime. (If the level evaluates to 'OFF' then no logging code is | |||
inserted.) | |||
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: | |||
;All actions except CLINIT: If the constructor or method being instrumented has a '@Loggify' annotation: | |||
:Its values in reverse order (i.e. the last value/rule takes the highest precedence). | |||
;If a field 'static final String $$loggifierRules = "xyz"' was declared before the contructor or method being instrumented: | |||
:Its value, split at '\n', in reverse order (i.e. the last fragment/rule takes the highest precedence). | |||
;If the class or interface being instrumented has a '@Loggify' annotation: | |||
:Its values of in reverse order (i.e. the last value/rule takes the highest precedence). | |||
;If using the four-parameter LoggifyingClassLoader constructor: | |||
:The 'logLevelCalculator' argument. | |||
;If using the ANT task: | |||
:'<rule>' subelements, in reverse order (i.e. the last <rule> takes the highest precedence). | |||
;If using the LOGGIFIER command line tool: | |||
:The '-rule' options, in reverse order (i.e. the last '-rule' option takes the highest precedence). | |||
;If using the ECLIPSE builder: | |||
:The levels on the "Loggifier" property page of each project. (This rule ALWAYS applies, hence the following rules are never executed). | |||
;Accesses to local variable who's name ends with '__': | |||
:FINER | |||
;Accesses to fields who's name ends with '__': | |||
:FINER | |||
;Instantiations of a class who's name ends with '__': | |||
:FINER | |||
;Last resort (when none of the above rules triggered): | |||
OFF | |||
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. | |||
== Download == | == Download == |
Revision as of 14:14, 1 September 2013
Motivation
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.
Overview
The concept of LOGGIFIER is as follows:
- Relevant class files are instrumented during the build process:
Code similar to
if (MyClass.__logger123.isLoggable(Level.FINE)) { Helper.logp( MyClass.__logger123, // logger Level.FINE, // level "com.acme.MyClass", // sourceClass "main(String[])", // sourceMethod "MyClass.java", // source 120, // lineNumber "ENTRY args=(args={0})", // message new Object[] { arg1 } // parameters ); }
- is inserted all over the place. (
Helper.logp()
eventually callsjava.util.logging.Logger.logp()
, after having done some pretty-printing on the message arguments.) Where exactly (in the example: At the top of 'MyClass.main()'), an at what log level (here: FINE) is controlled by the applicable 'loggification rules'. In typical scenarios, the default rules should generate a reasonable amount of logging points.
- The instrumentation remains even in production. This is possible because the instrumentation is optimized for very low overhead (as you can see in the code above).
- Alternatively you loggify the code only when you start debugging. This is often less practical, because it requires that you either have access to the .jar/.war/.ear files in the target environment., or restart the JVM with loggification activated. Also, the restart or the loggification may influence the problems that you want to track down.
- Then, when it comes to debugging, you enable logging at runtime, e.g. by editing the 'logging.properties' file, or by connecting to the running JVM through JMX. LOGGIFIER does not have one single Logger or one Logger per class, but separate loggers for all classes, methods and events. (Loggers are cheap, so the cost for having hundreds of them is low.) Hence you can enable the logging very fine and thereby keep the amount of logging output reasonable.
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'. .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
$
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
files "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.
Usage
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:
Here you can enable and configure loggification for the project.
ANT task
LOGGIFIER defines a new task that loggifies your code just like the command line tool.
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.
.MyClass.class.orig
and.MyJar.jar.orig
).
Subelements
- rule
- A loggification rule, e.g. 'STORE=FINE'
- Resource Collection (<fileset> etc.)
- The files to loggify (.class, .jar, .war, .ear, ...)
Example
<project> <taskdef name="loggifier" classname="de.unkrig.loggifier.AntTask" classpath="lib/de.unkrig.loggifier.jar" /> <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 de.unkrig.loggifier.LoggifyingClassLoader
.
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:de.unkrig.loggifier-all.jar ...
The LOGGIFIER plugs into the <a href="http://docs.oracle.com/javase/7/docs/api/java/lang/instrument/package-summary.html">"Java programming language agents" API</a> (available since Java 5). It implements loggification at class-loading time.
Loggification events
Generally the LOGGIFER considers various points in the code that could be subject to loggification. Each of these points is identified by
- action ;E.g. 'method entry', 'local variable assignment', 'arithmetic operation', see
de.unkrig.loggifier.LoggifyingContentsTransformer.Action)
- source ;The name of the Java source file that JAVAC stores in each .class file if enabled by '-g:source'.
- classAccess ;The accessibility of the class being instrumented ('public', 'protected' or 'private')
- class ;The fully qualified name of the class being instrumented, e.g. '{@code pkg.MyClass}'
- methodAccess ;The accessibility of the method being instrumented ('public', 'protected' or 'private')
- method ;The enhanced, dequalified name of the method being instrumented, e.g.
'meth(String, MyClass)' or '<T extends IOException>meth(T, MyClass, List<T>)'
- line ;The line number related to the code point being instrumented that JAVAC stores in each .class file if
enabled by '-g:lines'.
- type (only for actions CAST, INSTANCEOF and NEW)
;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. 'pkg.Class.field'
- variable (only for actions LOAD and STORE)
;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 on which level the event will be logged at runtime ('level'). This is achieved by checking the 'loggification rules'.
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
To each loggification point a sequence of loggification rules applies. The first rule that triggers determines the level on which the point will be logged at runtime. (If the level evaluates to 'OFF' then no logging code is inserted.)
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:
- All actions except CLINIT
- If the constructor or method being instrumented has a '@Loggify' annotation:
- Its values in reverse order (i.e. the last value/rule takes the highest precedence).
- If a field 'static final String $$loggifierRules = "xyz"' was declared before the contructor or method being instrumented
- Its value, split at '\n', in reverse order (i.e. the last fragment/rule takes the highest precedence).
- If the class or interface being instrumented has a '@Loggify' annotation
- Its values of in reverse order (i.e. the last value/rule takes the highest precedence).
- If using the four-parameter LoggifyingClassLoader constructor
- The 'logLevelCalculator' argument.
- If using the ANT task
- '<rule>' subelements, in reverse order (i.e. the last <rule> takes the highest precedence).
- If using the LOGGIFIER command line tool
- The '-rule' options, in reverse order (i.e. the last '-rule' option takes the highest precedence).
- If using the ECLIPSE builder
- The levels on the "Loggifier" property page of each project. (This rule ALWAYS applies, hence the following rules are never executed).
- Accesses to local variable who's name ends with '__'
- FINER
- Accesses to fields who's name ends with '__'
- FINER
- Instantiations of a class who's name ends with '__'
- FINER
- Last resort (when none of the above rules triggered)
OFF
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.
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".