FretlessMayhem
Reputation: 61
Java PrintWriter Error
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!
Upvotes: 6
Views: 3236
Answers (2)
kriegaex
Reputation: 67437
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 beexecution(* 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
printlncall. - 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()
Upvotes: 2
Zbynek Vyskovsky - kvr000
Reputation: 18855
Well, you didn't really tell what the issue is. If you have problem with uncaught exception in logException then just catch it and investigate. Most probably it's permission issue when opening the file or maybe (on windows for example) the OS doesn’t allow access to the file by several threads.
For the second question - byte code is quit clear. First part is quite straightforward and follows the code you wrote. The second part handles closing the resources and adding potentially caught exceptions as suppressed ones to already raised exception. It's a bit long but again follows the resource initialization in opposite direction.
Upvotes: 0
Related Questions
- How do I efficiently iterate over each entry in a Java Map?
- How do I avoid checking for nulls in Java?
- How do I read / convert an InputStream into a String in Java?
- Is Java "pass-by-reference" or "pass-by-value"?
- How can I create a memory leak in Java?
- How do I generate random integers within a specific range in Java?
- When to use LinkedList over ArrayList in Java?
- What are the differences between a HashMap and a Hashtable in Java?
- How do I convert a String to an int in Java?
- What is the difference between public, protected, package-private and private in Java?