Editing Loggifier.unkrig.de

Jump to navigation Jump to search
Warning: You are not logged in. Your IP address will be publicly visible if you make any edits. If you log in or create an account, your edits will be attributed to your username, along with other benefits.

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:
<meta name="keywords" content="java, logging, inject, automated"></meta>
== Summary ==
<meta name="description" content="A tool for automated injection of logging code into Java class files"></meta>
== 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?
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.
If the answers are "no" and "no", then stop reading. Otherwise, LOGGIFIER may be the tool you need.


== Overview ==
== Getting started ==


The concept of LOGGIFIER is as follows:
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).


* Relevant class files are instrumented during the build process:<br />Code similar to
So let's start with a very simple program:
    <nowiki>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
        );
    }</nowiki>
: is inserted all over the place. (<code>Helper.logp()</code> eventually calls <code>java.util.logging.Logger.logp()</code>, after having done some pretty-printing on the message arguments.) Where exactly (in the example: At the top of 'MyClass.main()'), and at what log level (here: FINE) is controlled by the applicable [[#Loggification rules|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: The call to 'isLoggable()' is typically super fast).
* 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 selectively and thereby keep the amount of logging output reasonable.


== Getting started ==
  '''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");
      }
  }


Click [[Loggifier.unkrig.de / Getting Started|here]] to take the fast track to Loggifier.
By default, java.util.logging is disabled, so we don't get any logging output:


== Tools ==
  '''$ javac Main.java'''
  '''$ java Main'''
  HELLO WORLD
  '''$'''


There are various tools to loggify your classes:
To enable logging, we need to create one more file


* At build time:
  # File 'my_logging.properties'.
** The LOGGIFIER [[Loggifier.unkrig.de / Tools / Command line tool|command line tool]]
  handlers = java.util.logging.ConsoleHandler
** The LOGGIFIER [[Loggifier.unkrig.de / Tools / Eclipse plug-in|ECLIPSE plug-in]]
  java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
** The <code><de.unkrig.loggifier></code> [[Loggifier.unkrig.de / Tools / Ant task|ANT task]]
  java.util.logging.ConsoleHandler.level    = FINEST
* At runtime:
  java.util.logging.SimpleFormatter.format  = [%2$20s] %4$s: %5$s%n
** The [[Loggifier.unkrig.de / Tools / LoggifyingClassLoader|LoggifyingClassLoader]]
  .level = FINEST
** The LOGGIFIER [[Loggifier.unkrig.de / Tools / Java agent|Java agent]]


== Loggification ==
, and run our program with the <code>java.util.logging.config.file</code> system property set:


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|discriminator expression]], which has a set of [[#Discriminator expression parameters|parameters]].
  '''$ java -Djava.util.logging.config.file=my_logging.properties Main'''
  HELLO WORLD
  <span style="color:red;">[           Main main] FINE: About to terminate</span>
  '''$'''


=== Logging actions ===
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:


Each section of code is characterized by an 'Action'. For example, the JVM bytecodes <code>PUTFIELD</code> and <code>PUTSTATIC</code> are characterized by action '''PUT'''.
  '''$ 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
  '''$'''


{| class="wikitable"
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
|'''ALOAD'''    ||Log array type, array value, index and element value read from an array
any case, LOGGIFIER will modify the contained '.class' "in-place".
|-
|'''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 rule syntax ===
Now what logging do we get now?


A rule triggers if and only if
  '''$ java -Djava.util.logging.config.file=my_logging.properties -cp de.unkrig.loggifier-runtime.jar\;. Main'''
* It applies to the action of the loggification point (ENTRY, EXIT, THROW, ...)
  <span style="color:red;">[    Main <clinit>()] FINER: (Main.java:6) ENTRY args=()</span>
* 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)
  <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>
  '''$'''


The syntax of all loggification rules is:
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.


loggification-rule :=
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.
    ( action { ',' action } | 'ALL' ) '=' level [ ':' discriminator-expression ]
action :=
    (One of the actions documented above)
level :=
    'SEVERE' | 'WARNING' | 'INFO' | 'CONFIG' | 'FINE' | 'FINER' | 'FINEST'
discriminator-expression :=
    (Syntax defined below)


Examples of valid loggification rules are:
Effectively, we can now remove the hand-written logging code from our class, because the automatically injected logging
code now does the job:


ALL=FINE
  '''public class''' Main {
ENTRY=FINE
   
ARITH=FINE
      '''public static void''' main(String[] args) {
LOAD,CONVERT,ARITH,STORE=FINE
          System.out.println("HELLO WORLD");
ALL=FINE:class =* "de.*"
      }
  }


(<code>=*</code> is the 'glob matching operator', e.g. "hello" matches "he*".)
Now let's compile, loggify and run again:


=== Loggification rule precedence ===
  '''$ 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>
  '''$'''


The sequence of checked rules for each logging point is as follows:
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:


;If the constructor or method being instrumented has a '@Loggify' annotation (not for action CLINIT)
  import de.unkrig.loggifier.runtime.annotation.Loggify;
:Its values in reverse order (i.e. the last value/rule takes the highest precedence).
   
  @Loggify("ALL=FINE")
  public class Main {
      // ...


;If a field 'static final String $$loggifierRules = "xyz"' was declared before the contructor or method being instrumented
Then compile, loggify and run again:
: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
  '''$ javac Main.java -cp de.unkrig.loggifier-runtime.jar'''
:Its values of in reverse order (i.e. the last value/rule takes the highest precedence).
  '''$ 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>
  '''$'''


;If using the four-parameter [[Loggifier.unkrig.de / Tools / LoggifyingClassLoader|LoggifyingClassLoader]] constructor
(Notice that JAVAC now needs "de.unkrig.loggifier-runtime.jar" on the class path, because "@de.unkrig.loggifier.runtime.annotation.Loggify" lives there.)
:The 'logLevelCalculator' argument.


;If using the [[Loggifier.unkrig.de / Tools / Ant task|ANT task]]
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.
:<code><rule></code> subelements, in reverse order (i.e. the last <code><rule></code> takes the highest precedence).


;If using the [[Loggifier.unkrig.de / Tools / Command line tool|LOGGIFIER command line tool]]
== Usage ==
:The '-rule' options, in reverse order (i.e. the last '-rule' option takes the highest precedence).


;If using the [[Loggifier.unkrig.de / Tools / Eclipse plug-in|ECLIPSE plug-in]]
=== Command line tool ===
:The levels on the "Loggifier" property page of each project. (This rule ALWAYS applies, hence the following rules are never executed).


;If using the [[Loggifier.unkrig.de / Tools / Java agent|Java agent]]
  '''$ java -cp de.unkrig.loggifier.jar de.unkrig.loggifier.Main -help'''
:Its argument string passed to the agent, split at '\n', in reverse order (i.e. the last fragment/rule takes the highest precedence).
  Implants logging code into Java class files 'in-place', also in ZIP format
  files (zip, jar, war, ear, ...) files and nested ZIP format files.
  Usage:
    java de.unkrig.loggifier.Main [ &lt;option> ] ... &lt;dir-or-file>
    java de.unkrig.loggifier.Main [ &lt;option> ] ... &lt;dir-or-file> &lt;dir-or-file>
    java de.unkrig.loggifier.Main [ &lt;option> ] ... &lt;dir-or-file> ... &lt;dir>
 
  Valid options:
    -keep          Keep copies of original files
    -selector &lt;pattern>
                    Loggify only classes matching the &lt;pattern>
    -rule &lt;rule>    Add the given rule
  The rule format is as follows
    &lt;action>[,&lt;action>]...=&lt;level>[:&lt;expression>]
  &lt;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]
  &lt;level>      is one of [ OFF SEVERE WARNING INFO CONFIG FINE FINER FINEST ]
  &lt;expression> is like '(&lt;eq> || &lt;eq>) && !&lt;eq>', where
  &lt;eq>        is '&lt;var> == &lt;glob>', where
  &lt;var>        is one of [ class source line ] (for action 'STORE' also 'name').
  &lt;glob>      is a 'glob pattern' in single quotes like '*main*'.
 
  The exit status is 1 iff errors eccurred during loggification.


;If the action is LOAD or STORE, and the local variable's name ends with '__'
=== ECLIPSE Plugin ===
:FINER


;If the action is GET or PUT, and the field's name ends with '__'
When the plug-in is installed (see below), you will find a new page in the 'Project Properties...' dialog:
:FINER


;If the action is NEW, CAST or INSTANCEOF, and the target class's name ends with '__'
[[File:Loggifer_project_properties_page.png]]
:FINER


;If the action is ENTRY, RETURN or THROW
Here you can enable and configure loggification for the project.
:FINER


;Last resort (when none of the above rules triggered)
=== ANT task ===
: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 <code><clinit>()</code> method, which cannot be annotated in source code.
LOGGIFIER defines a new task.


=== Discriminator expression ===
==== Attributes ====


Discriminator expressions are implemented by means of <code>de.unkrig.commons.text.expression.ExpressionEvaluator</code>; find the expression syntax documented [http://commons.unkrig.de/javadoc/de/unkrig/commons/text/expression/Parser.html here].
;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').


=== Discriminator expression parameters ===
==== Subelements ====


To provide fine-grained control over loggification, the properties of each loggification point are provided as parameters to the discriminator expression:
;rule                                :A loggification rule, e.g. 'STORE=FINE'
;Resource Collection (<fileset> etc.) :The files to loggify (.class, .jar, .war, .ear, ...)


;action
==== Example ====
:One of the [[#Logging actions|documented logging actions]]
;source
:The name of the Java source file that JAVAC stores in each <code>.class</code> file if enabled by <code>-g:source</code>.
;classAccess
:The accessibility of the class being instrumented (<code>public</code>, <code>protected</code> or <code>private</code>)
;class
:The fully qualified name of the class being instrumented, e.g. <code>pkg.MyClass</code>
;methodAccess
:The accessibility of the method being instrumented (<code>public</code>, <code>protected</code> or <code>private</code>)
;method
:The enhanced, dequalified name of the method being instrumented, e.g. <code>meth(String, MyClass)</code> or <code><T extends IOException>meth(T, MyClass, List<T>)</code>
;line
:The line number related to the code point being instrumented that JAVAC stores in each .class file if enabled by <code>-g:lines</code>
;type
:The relevant type for the operation, e.g. <code>pkg.Class</code>, <code>pkg.Class[][]</code>, <code>int[][]</code> (only for actions '''CAST''', '''INSTANCEOF''' and '''NEW''')
;classAndField
:The subject class and field, e.g. <code>pkg.Class.field</code> (only for actions '''GET''' and '''PUT''')
;variable
:The name of the subject local variable (only for actions '''LOAD''' and '''STORE''')


At each loggification point, the LOGGIFIER determines if logging code is to be inserted or not ('discrimination') and
  <project>
on which level the event will be logged at runtime ('level'). This is achieved by checking the 'loggification
      <taskdef name="loggifier" classname="de.unkrig.loggifier.AntTask" classpath="lib/de.unkrig.loggifier.jar" />
rules'.
 
      <target name="default">
          <loggifier>
              <rule>ALL=FINE</rule>
              <fileset file="bin/Main.class" />
          </loggifier>
      </target>
  </project>


== Download ==
== Download ==
Please note that all contributions to unkrig.de may be edited, altered, or removed by other contributors. If you do not want your writing to be edited mercilessly, then do not submit it here.
You are also promising us that you wrote this yourself, or copied it from a public domain or similar free resource (see Unkrig.de:Copyrights for details). Do not submit copyrighted work without permission!
Cancel Editing help (opens in new window)