Logging part 2

JavaFAQ Home » Story by Dr. Kabutz

Author: Dr. Heinz M. Kabutz

You can subscribe from our home page: http://www.javaspecialists.co.za (which also hosts all previous issues, available free of charge

This free advanced Java newsletter is wholly funded by Maximum Solutions, your partner in Object Orientation and Java. How can we help you in your project? Heinz

Welcome to the fourth issue of "The Java™ Specialists' Newsletter" and the first issue this year, or as some ignoramuses believe, this millenium. Next week Dr. Christoph Jung will tell us how the new Java dynamic proxies work, don't miss it. It's an excellent piece of writing, so if you are not subscribed to this newsletter yet, make sure you don't miss it and subscribe. Please forward this newsletter to friends, family and fauna that you think might find it useful and interesting.

[If anything, read the second-last paragraph of this newsletter, you might end up winning a free lunch :]

Logging Part 2 of ... (still cannot decide

Last year I started talking about things that go wrong in our code. I probably sent the newsletter out too close to Christmas (merry to you, btw), because I had hardly any response. Alternatively you've added me to your junk-mail-auto-delete-mail-pest filter (sniff sniff) in which case you won't read this anyway. I hope your inbox is looking emptier and that you will find time to read this newsletter. Or maybe your code always works so there's nothing to Log [naah]

Over the past years, two very knowledgeable Java programmers asked me independently how one can find out within a method where the method was invoked from. This is particularly useful when you want to print out logging information, such as where in the program the log was printed from. My answer to them was both times a typical "consulting" answer in the form of "what an interesting problem, how would you solve it?" and then I went on to ramble about using JNI, parsing the stack trace, using the Visitor pattern or writing the whole thing with Jini. i.e. I didn't have a clue!

Graciously, one of these two men, Gary Plante, sent me some code the other day which he discovered could do just that. It works by parsing a stack trace, and I took the liberty of fiddling here and there with his code, so it probably looks nothing like what you sent me, Gary According to my tests, this whole idea is probably a bit on the slow side. Also, to make my code easier to understand, and to avoid relying on side-effects of the PrintWriter class, I removed most of Gary's performance optimisations with the result that my code may be a little bit more robust but it is 2.5 times slower than Gary's. I have included Gary's code "as is" to show you how it could also be done. We start counting lines at different indexes, beware.

/**
  The stack trace starts with the following lines:
  java.lang.Throwable
      at StackTrace2.getStackTraceAtLine(StackTrace2.java:19)

  It does not make sense to get these first 2 lines so we will
  ignore them.  The number we pass into the method is the depth
  of method calls, where 0 is the current line of code, 1 is the
  line of code that called this code, 2 is the line of code that
  called the line of code that called this code, etc.

  0:    at StackTrace2Test.g(StackTrace2Test.java:10)
  1:    at StackTrace2Test.f(StackTrace2Test.java:3)
  2:    at StackTrace2Test.main(StackTrace2Test.java:17)
 */
import java.io.*;
public class StackTrace2 {
  private static final Throwable tracer = new Throwable();
  private static final StringWriter sw =
    new StringWriter(1024);
  private static final PrintWriter out =
    new PrintWriter(sw, false);

  private StackTrace2() {} // Avoid direct creation

  public static String getCallStack(int depth) {
    synchronized (tracer) {
      if (depth < 0) throw new IllegalArgumentException();
      // skip the first 2 lines
      int lineOfInterest = depth + 3;
      // set the buffer back to zero
      sw.getBuffer().setLength(0);
      tracer.fillInStackTrace();
      tracer.printStackTrace(out);
      out.flush();
      LineNumberReader in = new LineNumberReader(
        new StringReader(sw.toString()));
      try {
        String result;
        while((result = in.readLine()) != null) {
          if (in.getLineNumber() == lineOfInterest)
            return beautify(result);
        }
      }
      catch(IOException ex) {} // we'll just return null
      return null;
    }
  }

  private static String beautify(String raw) {
    raw = raw.trim(); // we don't want any whitespace
    if (raw.startsWith("at ")) // we also cut off the "at "
      return raw.substring(3);
    return raw;
  }
}

You could use this information in a VERY simple Log class as follows:

public class Log {
    public static void it(String msg) {
        //caller of it()
        String source = StackTrace2.getCallStack(1);
        System.out.println(source + " : " + msg);
    }
}

An example of how this could be used is in

public class StackTrace2Test {
  public void f() {
    g();
  }
  public void g() {
    Log.it("where am I now?");
    System.out.println(StackTrace2.getCallStack(0));
    System.out.println(StackTrace2.getCallStack(1));
    System.out.println(StackTrace2.getCallStack(2));
    System.out.println(StackTrace2.getCallStack(3));
    System.out.println(StackTrace2.getCallStack(-1));
  }
  public static void main(String[] args) {
    new StackTrace2Test().f();
  }
}

The output would look as follows:

StackTrace2Test.g(StackTrace2Test.java:6) : where am I now?
StackTrace2Test.g(StackTrace2Test.java:7)
StackTrace2Test.f(StackTrace2Test.java:3)
StackTrace2Test.main(StackTrace2Test.java:15)
null
Exception in thread "main" java.lang.IllegalArgumentException
        at StackTrace2.getCallStack(StackTrace2.java:22)
        at StackTrace2Test.g(StackTrace2Test.java:11)
        at StackTrace2Test.f(StackTrace2Test.java:3)
        at StackTrace2Test.main(StackTrace2Test.java:15)

Attached you can find the other StackTrace.java and StackTraceTest.java files which are quite a bit more difficult to understand, but at least they do not create a new LineNumberReader each time you ask it for your line number.

Attached you can find the other StackTrace.java and StackTraceTest.java files which are quite a bit more difficult to understand, but as mentioned above, they are 2.5 times faster. If performance of your logging system is a problem you can easily have a boolean in your Log class that turns this level of detailed processing off.

The best solution is probably to do this type of low-level access in JNI. I will invite the first person who sends me a correct solution that uses JNI and is really fast, to join me for a steak over lunch at the Cattle Baron (non-CapeTown residents will have to fly to Cape Town at their own expense!)

Right, I hope you found this information interesting, I always appreciate your feedback, both positive and negative.

Heinz

Copyright 2000-2003 Maximum Solutions, South Africa

Reprint Rights. Copyright subsists in all the material included in this email, but you may freely share the entire email with anyone you feel may be interested, and you may reprint excerpts both online and offline provided that you acknowledge the source as follows: This material from The Java(tm) Specialists' Newsletter by Maximum Solutions (South Africa). Please contact Maximum Solutions for more information.

Java and Sun are trademarks or registered trademarks of Sun Microsystems, Inc. in the United States and other countries. Maximum Solutions is independent of Sun Microsystems, Inc.

Custom Search