Loggifier.unkrig.de

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 calls java.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()'), and 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: 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

Click here to take the fast track to Loggifier.

Tools

There are various tools to loggify your classes:

• At build time:
  • The LOGGIFIER command line tool
  • The LOGGIFIER ECLIPSE plug-in
  • The <de.unkrig.loggifier> ANT task
• At runtime:
  • The LoggifyingClassLoader
  • The LOGGIFIER Java agent

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 action. For each logging point, the relevant 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 parameters.

Logging actions

Each section of code is characterized by an 'Action'. For example, the JVM bytecodes PUTFIELD and PUTSTATIC are characterized by action PUT.

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 rule syntax

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

loggification-rule :=
    ( 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:

ALL=FINE
ENTRY=FINE
ARITH=FINE
LOAD,CONVERT,ARITH,STORE=FINE
ALL=FINE:class =* "de.*"

(=* is the 'glob matching operator', e.g. "hello" matches "he*".)

Loggification rule precedence

The sequence of checked rules for each logging point is as follows:

If the constructor or method being instrumented has a '@Loggify' annotation (not for action CLINIT)

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 plug-in

The levels on the "Loggifier" property page of each project. (This rule ALWAYS applies, hence the following rules are never executed).

If using the 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).

If the action is LOAD or STORE, and the local variable's name ends with '__'

FINER

If the action is GET or PUT, and the field's name ends with '__'

FINER

If the action is NEW, CAST or INSTANCEOF, and the target class's name ends with '__'

FINER

If the action is ENTRY, RETURN or THROW

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.

Discriminator expression

Discriminator expressions are implemented by means of de.unkrig.commons.text.expression.ExpressionEvaluator; find the expression syntax documented here.

Discriminator expression parameters

To provide fine-grained control over loggification, the properties of each loggification point are provided as parameters to the discriminator expression:

action

One of the documented logging actions

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. 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

The relevant type for the operation, e.g. pkg.Class, pkg.Class[][], int[][] (only for actions CAST, INSTANCEOF and NEW)

classAndField

The subject class and field, e.g. pkg.Class.field (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 on which level the event will be logged at runtime ('level'). This is achieved by checking the 'loggification rules'.

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".