003Logging Part 1

Author: Dr. Heinz M. KabutzDate: 2000-12-14Java Version: 1.1Category: Language

Abstract: In this newsletter we look at how we can write a TeeOutputStream that works similarly to the unix "tee" utility and pipes the output to two different OutputStreams. We can then reassign System.out to be written to a file and to the old System.out.

Welcome to the third The Java(tm) Specialists' Newsletter, a low-volume newsletter that is aimed at Java programmers who are facing the real world every day. I hope you are enjoying reading this information and that it will help you to be more productive in your work. I want to thank Java-Guru-In-The-Making Dr. Christoph Jung for volunteering to write a piece on dynamic proxies in an upcoming newsletter. Please let me know if there are topics that you would like discussed or if you would like to share some of your own experiences through this newsletter. This newsletter is distributed free of charge to anyone interested, so please forward it to friends and colleagues who might find the information in this newsletter useful.

I drew some fire from respectable quarters that some of the code I presented in the last newsletter was a little bit on the obscure side. The Thread example was meant to illustrate the concept of making an anonymous inner class and immediately putting it to use, as opposed to just using it as a parameter. The most probable place you would find code as shown in the last newsletter would be in the unit tests of my code. If you have a method that requires as a parameter a Vector, you can use the example from the previous newsletter to succintly pass it test data. Even though the examples might seem a bit obscure at first glance, I believe that once you've seen the "Anonymous Inner Class Init Block" example, you will begin to recognise it easily enough so it will lose most of its obscurity.

If you are not writing unit test for your code, why not? There are two good books that contain information on unit tests, Refactoring by Martin Fowler and eXtreme Programming by Kent Beck. Unit tests have saved my butt a number of times, because I am not a very "good" programmer, in that I make mistakes all the time and end up messing up old working code in the process - does that sound familiar? (So, if you let me work on some of your code and you don't have unit tests, BEWARE!) When people ask me what my job is I tell them I am a professional bug writer, because that's what I'm best at. Unit tests only work if the whole development team is using the concept, much like CASE tools such as Rational Rose. I fought a losing battle 2 years ago when most of the team, on a project I was on, stopped using Rational Rose and I spent most of my time updating other developers' diagrams.

Talking of unit tests, it is possible to use the Robot (java.awt.Robot) to write unit tests for GUI's.

javaspecialists.teachable.com: Please visit our new self-study course catalog to see how you can upskill your Java knowledge.

Logging Part 1 of ... (haven't decided yet ;-)

While we are on the topic of things going wrong, we should always expect things to go wrong in the field and it is very important to be able to remotely figure out what went wrong and to prevent it from going wrong in future. An example of a remote fix was the Mars bug that had to be debugged and repaired remotely (not by me ;-) - the Risks digest had some interesting articles on that. With the internet being so widely accessible, we have a great challenge because our programs might fail somewhere in a remote part of this planet that might not be very pleasant for a support team to visit, for example amongst a man-eating pygmy tribe in Java (non-tm). Preferably we would ask them to email us a log of what went wrong so that we can look at the log and determine what the problem was.

When you start with a new project it is very easy to give logging too little thought, with unpleasant consequences. It is also possible to give it too much thought and design such a complex logging system that the rest of the programming team cannot wait and starts writing their own logging functions (System.out.println springs to mind). In that case you are back to the first problem of too little thought, because each developer develops his method as he goes along. This newsletter is not going to tell you which way is best, you have to decide for yourself, but it will show you some tricks and gotcha's that I've seen several times.

In designing a logging system, there are several questions we have to face:

1. How do we show when the event happened?
2. What if the log size gets too big?
3. How do you switch off logging?
4. Are we willing to make the client code messy to improve performance?

The combination of these factors can sway your logging system in various ways, which is why I will not say which is best. I will now present the first of a series of case studies of logging systems that one might want to write:

Case Study 1:

Frank the Unix hacker has been writing a 3-tier application server that uses several third-party libraries which output logging information such as "Connected to ISAP" or "Disconnected from AISN" or "State changed to TLA". Since Frank is a hacker, he knows about JAD.EXE and is forever grateful to Pavel for making all CLASS files open-source, but he is a bit worried about rewriting the third-party code to output to his logging system because of something called "copyright law", whatever that is. The problem is that he needs to know exactly in which order things happen in respect to his own application server, so perferably the log should show all output to the console in the same order in which it appeared. Since Frank is a UNIX hacker, he remembers a little utility called "tee" that would represent a t-piece in a pipe of output so that you could send piping to two destinations.

For example:

echo hello world | tee output > output2

would send the string "hello world" to two output files, "output" and "output2".

Frank decides to write an IO stream decorator that behaves as a TeeOutputStream. (Disclaimer: I wrote my first TeePrintStream in the middle of 1997 - I have since seen the same thing published in a magazine.) If you don't understand decorators, have a look at the IO chapter of the excellent book "Thinking in Java" by Bruce Eckel or visit a good Java course.

The TeeOutputStream would look something like this:

// TeeOutputStream
import java.io.*;
public class TeeOutputStream extends FilterOutputStream {
  private final OutputStream out2;
  public TeeOutputStream(OutputStream out1, OutputStream out2) {
    super(out1);
    this.out2 = out2;
  }
  public void write(int b) throws IOException {
    super.write(b);
    out2.write(b);
  }
  public void flush() throws IOException {
    super.flush();
    out2.flush();
  }
  public void close() throws IOException {
    super.close();
    out2.close();
  }
}

The TeeOutputStream would now be able to take two output streams and send the same information to both of them as shown in the main method.

// ... the main class that starts up the application server
  public static void main(String[] args) {
    PrintStream out1 = System.out;
    OutputStream out2 = new BufferedOutputStream(
        new FileOutputStream("LOG"));
    TeeOutputStream newOut = new TeeOutputStream(out1, out2);
    System.setOut(new PrintStream(newOut, true));
    out1 = System.err;
    newOut = new TeeOutputStream(out1, out2);
    System.setErr(new PrintStream(newOut, true));
    // ... some more code...
  }

My personal preferance would be to re-write those lines as follows, but you should do what is most comfortable to you:

// ... the main class that starts up the application server
  public static void main(String[] args) {
    OutputStream log = new BufferedOutputStream(
        new FileOutputStream("LOG"));
    System.setOut(
      new PrintStream(new TeeOutputStream(System.out,log),true));
    System.setErr(
      new PrintStream(new TeeOutputStream(System.err,log),true));
    // ... some more code...
  }

The astute among you should now be jumping up and down pointing at the glaringly obvious mistake in the above code. There is no provision for the log file growing and filling up the hard disk. Frank (correctly) assumes that his program is never going to run for a long enough period that the size of the log file would be bigger than 10 KB, but once all his bugs are removed, something should be done to prevent the big log file. The biggest log file that an advanced support man sent me was 1.1 GB in size when I used Frank's TeeOutputStream system.

Anyway, the beauty with Frank's approach is that whenever he wants to print to the log he just does a "System.out.println()" or exception.printStackTrace(). Anything that goes to the console also goes to his log in the same order in which it appeared to the user. He can also switch off logging to a file by not setting the System.out PrintStream to print to the tee, or he can set his program to only print to the log.

If we look back at the questions we face with the logging system, we see that we don't have a default way of showing WHEN the event occured, although that could be added by changing the write() method of the FileOutputStream to print the date/time after each newline. The size of the log file can be monitored by implementing a different FileOutputStream. The logging to file can be switched off easily. The client code is very simple - System.out.println("Changed to state TLA");

That's the end of Frank's logging system. As you have seen, there is a lot of scope for changing it, depending on your requirements, but there is no right answer that fits all scenarios. Next week I will present another scenario with different advantages...

Please remember to forward this free newsletter to whoever you think may be interested.

With regards

Heinz

Comments

We are always happy to receive comments from our readers. Feel free to send me a comment via email or discuss the newsletter in our JavaSpecialists Slack Channel (Get an invite here)

Related Articles

Browse the Newsletter Archive