Java PrintWriter Error

Question

I'm a long time reader, but first time writer.

I am currently trying to implement a logger with AspectJ in our codebase. AspectJ seems to work well, but I am encountering extremely weird Java errors. I am a longtime C++ and .Net developer who is still adapting to the world of Java, so I apologize if this is a dumb question.

My code is trying to trap exceptions, and log the pertinent info to a text file. The trapping works fine, but I noticed that when I deployed, I am not getting any data. I opened my class file in a Java decompiler, and noticed that the PrintWriter seems to be generating an error. I have never seen a problem like this, so I am hoping one you might have any insight.

package mil.uscg.c3cen.vic.aspect;

import java.io.BufferedWriter;
import java.io.File;
import java.io.FileWriter;
import java.io.IOException;
import java.io.PrintWriter;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.JoinPoint;

@Aspect
public class LoggingAspect
{
    private final String LOG_FILE = "aspectLog.txt";
    private final File file = new File(LOG_FILE);

    private LoggingAspect() 
    { 

    }

    private void logException(String msg) 
    {
        try 
        {
            if(!file.exists())
                file.createNewFile();
        }
        catch(IOException e) 
        {

        }

        try (FileWriter fw = new FileWriter(file); 
               BufferedWriter bw = new BufferedWriter(fw);
               PrintWriter pw = new PrintWriter(bw)) 
        {
            pw.println(msg);
        }
        catch(IOException e)
        {

        }
    }

    private String getSimpleFunctionInfo(String className, String     function, Object[] args)
    {
        StringBuilder builder = new StringBuilder();
        builder.append(". Method: ");
        builder.append(className);
        builder.append(".");
        builder.append(function);

        if(args.length == 0)
        {
            builder.append("()");
            return builder.toString();
        }

        builder.append("(");

        for(Object o : args)
        {
            builder.append(o.toString());
            builder.append(",");
        }
        // Replace the comma for the last param with a closing parenthesis
        int len = builder.length();
        builder.replace(len -1, len, ")");

        return builder.toString();
    }

    // Returns a formatted exception. "Exception.ErrorMessage"
    private String getSimpleExceptionInfo(String name, String msg)
    {
        StringBuilder builder = new StringBuilder();
        builder.append("Exception caught: ");
        builder.append(name);
        builder.append(". Message: ");
        builder.append(msg);
        return builder.toString();
    }


   @AfterThrowing(pointcut = "execution(* mil.uscg.c3cen.*.*.*(..)) "
       //+ "&& !within(mil.uscg.c3cen.vic.aspect.*) "
       , throwing = "excep")
    public void afterThrowing(JoinPoint jp, Throwable excep) throws Throwable
    {
        String ex = getSimpleExceptionInfo(excep.getClass().getSimpleName(), 
                                                             excep.getMessage());

        String name = getSimpleFunctionInfo(jp.getSignature().getDeclaringType().getSimpleName(), 
                                                               jp.getSignature().getName(), 
                                                               jp.getArgs());

        StringBuilder builder = new StringBuilder();
        builder.append(ex);
        builder.append(name);

        logException(builder.toString());
    } 
}

Everything looks as you would expect in the class file, except for the function logException.

/* Error */
  private void logException(String msg)
  {
    // Byte code:
    //   0: aload_0
    //   1: getfield 25 mil/uscg/c3cen/vic/aspect/LoggingAspect:file    Ljava/io/File;
    //   4: invokevirtual 32    java/io/File:exists ()Z
    //   7: ifne +15 -> 22
    //   10: aload_0
    //   11: getfield 25    mil/uscg/c3cen/vic/aspect/LoggingAspect:file    Ljava/io/File;
    //   14: invokevirtual 36   java/io/File:createNewFile  ()Z
    //   17: pop
    //   18: goto +4 -> 22
    //   21: pop
    //   22: aconst_null
    //   23: astore_2
    //   24: aconst_null
    //   25: astore_3
    //   26: new 39 java/io/FileWriter
    //   29: dup
    //   30: aload_0
    //   31: getfield 25    mil/uscg/c3cen/vic/aspect/LoggingAspect:file    Ljava/io/File;
    //   34: invokespecial 41   java/io/FileWriter:<init>   (Ljava/io/File;)V
    //   37: astore 4
    //   39: new 44 java/io/BufferedWriter
    //   42: dup
    //   43: aload 4
    //   45: invokespecial 46   java/io/BufferedWriter:<init>   (Ljava/io/Writer;)V
    //   48: astore 5
    //   50: new 49 java/io/PrintWriter
    //   53: dup
    //   54: aload 5
    //   56: invokespecial 51   java/io/PrintWriter:<init>  (Ljava/io/Writer;)V
    //   59: astore 6
    //   61: aload 6
    //   63: aload_1
    //   64: invokevirtual 52   java/io/PrintWriter:println (Ljava/lang/String;)V
    //   67: aload 6
    //   69: ifnull +24 -> 93
    //   72: aload 6
    //   74: invokevirtual 55   java/io/PrintWriter:close   ()V
    //   77: goto +16 -> 93
    //   80: astore_2
    //   81: aload 6
    //   83: ifnull +8 -> 91
    //   86: aload 6
    //   88: invokevirtual 55   java/io/PrintWriter:close   ()V
    //   91: aload_2
    //   92: athrow
    //   93: aload 5
    //   95: ifnull +43 -> 138
    //   98: aload 5
    //   100: invokevirtual 58  java/io/BufferedWriter:close    ()V
    //   103: goto +35 -> 138
    //   106: astore_3
    //   107: aload_2
    //   108: ifnonnull +8 -> 116
    //   111: aload_3
    //   112: astore_2
    //   113: goto +13 -> 126
    //   116: aload_2
    //   117: aload_3
    //   118: if_acmpeq +8 -> 126
    //   121: aload_2
    //   122: aload_3
    //   123: invokevirtual 59  java/lang/Throwable:addSuppressed   (Ljava/lang/Throwable;)V
    //   126: aload 5
    //   128: ifnull +8 -> 136
    //   131: aload 5
    //   133: invokevirtual 58  java/io/BufferedWriter:close    ()V
    //   136: aload_2
    //   137: athrow
    //   138: aload 4
    //   140: ifnull +66 -> 206
    //   143: aload 4
    //   145: invokevirtual 65  java/io/FileWriter:close    ()V
    //   148: goto +58 -> 206
    //   151: astore_3
    //   152: aload_2
    //   153: ifnonnull +8 -> 161
    //   156: aload_3
    //   157: astore_2
    //   158: goto +13 -> 171
    //   161: aload_2
    //   162: aload_3
    //   163: if_acmpeq +8 -> 171
    //   166: aload_2
    //   167: aload_3
    //   168: invokevirtual 59  java/lang/Throwable:addSuppressed   (Ljava/lang/Throwable;)V
    //   171: aload 4
    //   173: ifnull +8 -> 181
    //   176: aload 4
    //   178: invokevirtual 65  java/io/FileWriter:close    ()V
    //   181: aload_2
    //   182: athrow
    //   183: astore_3
    //   184: aload_2
    //   185: ifnonnull +8 -> 193
    //   188: aload_3
    //   189: astore_2
    //   190: goto +13 -> 203
    //   193: aload_2
    //   194: aload_3
    //   195: if_acmpeq +8 -> 203
    //   198: aload_2
    //   199: aload_3
    //   200: invokevirtual 59  java/lang/Throwable:addSuppressed   (Ljava/lang/Throwable;)V
    //   203: aload_2
    //   204: athrow
    //   205: pop
    //   206: return
    // Line number table:
    //   Java source line #28   -> byte code offset #0
    //   Java source line #29   -> byte code offset #10
    //   Java source line #30   -> byte code offset #18
    //   Java source line #31   -> byte code offset #21
    //   Java source line #36   -> byte code offset #22
    //   Java source line #36   -> byte code offset #26
    //   Java source line #37   -> byte code offset #39
    //   Java source line #38   -> byte code offset #50
    //   Java source line #40   -> byte code offset #61
    //   Java source line #41   -> byte code offset #67
    //   Java source line #42   -> byte code offset #205
    //   Java source line #46   -> byte code offset #206
    // Local variable table:
    //   start  length  slot    name    signature
    //   0  207 0   this    LoggingAspect
    //   0  207 1   msg String
    //   23 1   2   localObject1    Object
    //   80 28  2   localObject2    Object
    //   112    92  2   localObject3    Object
    //   25 1   3   localObject4    Object
    //   106    17  3   localThrowable1 Throwable
    //   151    17  3   localThrowable2 Throwable
    //   183    17  3   localThrowable3 Throwable
    //   37 140 4   fw  java.io.FileWriter
    //   48 84  5   bw  java.io.BufferedWriter
    //   59 28  6   pw  java.io.PrintWriter
    //   21 1   12  localIOException1   java.io.IOException
    //   205    1   13  localIOException2   java.io.IOException
    // Exception table:
    //   from   to  target  type
    //   0  18  21  java/io/IOException
    //   61 67  80  finally
    //   50 93  106 finally
    //   39 138 151 finally
    //   26 183 183 finally
    //   22 205 205 java/io/IOException
  }

This has really stumped me, so any information will be extremely appreciated. Thanks!

Answer 1

Okay, I tried with Java 8 and current AspectJ 1.8.8. Your aspect works as expected (I compiled it without any changes). It is just a bit over-complicated and should be simplified. Furthermore, you might just have mis-counted the number of .* in your pointcut.

If I add System.out.println(jp); at the beginning of your advice method so as to see something on the console and run your aspect against this sample driver class ...

package mil.uscg.c3cen.foo;

public class Application {
    public static void main(String[] args) {
        for (int i = 0; i < 3; i++) {
            try {
                doSomething();
            }
            catch (Exception e) {}
        }
    }

    public static void doSomething() {
        System.out.println("Calculation result = " + multiply(add(3, 4), 5));
        System.out.println("Calculation result = " + divide(add(5, 6), 0));
    }

    private static int add(int summand1, int summand2) {
        return summand1 + summand2;
    }

    private static int multiply(int factor1, int factor2) {
        return factor1 * factor2;
    }

    private static int divide(int dividend, int divisor) {
        return dividend / divisor;
    }
}

... the console log looks like this:

Calculation result = 35
execution(int mil.uscg.c3cen.foo.Application.divide(int, int))
execution(void mil.uscg.c3cen.foo.Application.doSomething())
Calculation result = 35
execution(int mil.uscg.c3cen.foo.Application.divide(int, int))
execution(void mil.uscg.c3cen.foo.Application.doSomething())
Calculation result = 35
execution(int mil.uscg.c3cen.foo.Application.divide(int, int))
execution(void mil.uscg.c3cen.foo.Application.doSomething())

As you can see, only the methods throwing the exception up the call hierarchy (until they are caught) are logged, as expected. The log file aspectLog.txt has this content:

Exception caught: ArithmeticException. Message: / by zero. Method: Application.main([Ljava.lang.String;@f6f4d33)

What to improve:

• Maybe you want to have a more stable pointcut targetting all subpackages of mil.uscg.c3cen. The syntax for "all method executions within that package and all its subpackages" would be execution(* mil.uscg.c3cen..*(..)).
• There is a bug in your log file usage logic: Whenever the very first exception occurs and the log file does not exist yet, it gets logged and the log file immediately closed. Any subsequent exception will never be logged, which is probably not what you want. You probably want multiple exceptions logged into the same file as long as the JVM is up and running. Thus, you do not want to close the log file after each write but take care of that in a JVM shutdown hook at the end of the JVM lifetime. Try with (auto-closeable) resources is only useful if you really want to close them after running a certain part of the code. BTW, you can avoid the shutdown hook by flushing the writer on a regular basis, e.g. after each println call.
• I am not discussing threading and synchronisation issues here, that would require even more care. Let us assume you have a single-threaded application.
• Maybe you also want to intercept exceptions in constructors and add that to your pointcut.

Improved & simplified aspect:

package mil.uscg.c3cen.vic.aspect;

import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.PrintWriter;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;

@Aspect
public class LoggingAspect {
    private static final String LOG_FILE = "aspectLog.txt";

    private final PrintWriter logWriter; 

    public LoggingAspect() throws FileNotFoundException {
        logWriter = new PrintWriter(new FileOutputStream(LOG_FILE));
        Runtime.getRuntime().addShutdownHook(new Thread() {
            @Override
            public void run() {
                logWriter.close();
            }
        });
    }

    @AfterThrowing(
        pointcut =
            "(execution(* mil.uscg.c3cen..*(..)) || execution(mil.uscg.c3cen..new(..)))" +
            " && !within(mil.uscg.c3cen.vic.aspect..*) ",
        throwing = "excep"
    )
    public void afterThrowing(JoinPoint jp, Throwable excep) throws Throwable {
        //System.out.println(excep + " -> " + jp);
        logWriter.println(excep + " -> " + jp);
    }
}

Extended code sample with a constructor throwing an exception:

package mil.uscg.c3cen.foo;

public class Application {
    public Application() {
        System.out.println(1/0);
    }

    public static void doSomething() {
        System.out.println("Calculation result = " + multiply(add(3, 4), 5));
        System.out.println("Calculation result = " + divide(add(5, 6), 0));
    }

    private static int add(int summand1, int summand2) {
        return summand1 + summand2;
    }

    private static int multiply(int factor1, int factor2) {
        return factor1 * factor2;
    }

    private static int divide(int dividend, int divisor) {
        return dividend / divisor;
    }

    public static void main(String[] args) {
        for (int i = 0; i < 3; i++) {
            try {
                doSomething();
            }
            catch (Exception e) {}
        }
        try {
            new Application();
        }
        catch (Exception e) {}
    }
}

Console log:

Calculation result = 35
Calculation result = 35
Calculation result = 35

Log file:

java.lang.ArithmeticException: / by zero -> execution(int mil.uscg.c3cen.foo.Application.divide(int, int))
java.lang.ArithmeticException: / by zero -> execution(void mil.uscg.c3cen.foo.Application.doSomething())
java.lang.ArithmeticException: / by zero -> execution(int mil.uscg.c3cen.foo.Application.divide(int, int))
java.lang.ArithmeticException: / by zero -> execution(void mil.uscg.c3cen.foo.Application.doSomething())
java.lang.ArithmeticException: / by zero -> execution(int mil.uscg.c3cen.foo.Application.divide(int, int))
java.lang.ArithmeticException: / by zero -> execution(void mil.uscg.c3cen.foo.Application.doSomething())
java.lang.ArithmeticException: / by zero -> execution(mil.uscg.c3cen.foo.Application())

Look at the last line, there you see the exception in the constructor.

If you want to beautify the exception logging output a bit, similar to what your original aspect does, do this:

logWriter.println(excep.getClass().getSimpleName() + " -> " + jp.getSignature());

Then the log file becomes:

ArithmeticException -> int mil.uscg.c3cen.foo.Application.divide(int, int)
ArithmeticException -> void mil.uscg.c3cen.foo.Application.doSomething()
ArithmeticException -> int mil.uscg.c3cen.foo.Application.divide(int, int)
ArithmeticException -> void mil.uscg.c3cen.foo.Application.doSomething()
ArithmeticException -> int mil.uscg.c3cen.foo.Application.divide(int, int)
ArithmeticException -> void mil.uscg.c3cen.foo.Application.doSomething()
ArithmeticException -> mil.uscg.c3cen.foo.Application()