TUSCANY-2641 Enhancements to Tuscany Logging and tracing

git-svn-id: http://svn.us.apache.org/repos/asf/tuscany@705368 13f79535-47bb-0310-9956-ffa450edef68

5 files changed, 150 insertions, 74 deletions

diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java
index 8ad64d498b..630bcb285b 100644
--- a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java
+++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java
@@ -32,6 +32,8 @@ import org.aspectj.lang.annotation.Before;
 import org.aspectj.lang.annotation.Pointcut;
 
 /**
+ * LoggingAspect performs standard logging of method signatures, arguments, and
+ * return values. All Tuscany methods, constructors, and statics are logged.
  * @version $Rev$ $Date$
  */
 @Aspect
@@ -50,44 +52,54 @@ public class LoggingAspect {
     
     @Pointcut("cflow(anyMethodExecution()) && anyLogCall()")
     public void anyLog() {
-        
     }
-    
-    // @Around("anyMethodCall() || anyLog()")
-    @Around("anyLog()")
-    public Object around(ProceedingJoinPoint jp) throws Throwable {
-        System.out.println("Around: " + jp);
-        long start = System.currentTimeMillis();
-        try {
-            return jp.proceed();
-        } finally {
-            long end = System.currentTimeMillis();
-            System.out.println("Roundtrip is " + (end - start) + "ms for " + jp.getSignature());
-        }
 
+    @Pointcut("call(org.apache.tuscany.sca..*.new(..))")
+    public void anyConstructor() {
     }
 
-    @Before("anyMethodCall()")
-    public void before(JoinPoint jp) {
-        System.out.println("Before: " + jp);
-        System.out.println("Location: " + jp.getSourceLocation());
-        System.out.println("This: " + jp.getThis());
-        System.out.println("Target: " + jp.getTarget());
-        System.out.println("Input: " + Arrays.asList(jp.getArgs()));
+    // e.g. org.apache.tuscany.sca.implementation.java.introspect.impl.JavaIntrospectionHelper
+    @Pointcut("staticinitialization(org.apache.tuscany.sca.implementation..*)")
+    public void anyStatic() {
     }
 
-    @After("anyMethodCall()")
-    public void after(JoinPoint jp) {
-        System.out.println("After: " + jp);
+    @Before("anyMethodCall()")
+    public void before(JoinPoint jp) {
+        // System.out.println("Logging anyMethodCall before jp=" + jp);
+        // System.out.println("Logging anyMethodCall before jp.getSourceLocation=" + jp.getSourceLocation());
+        // System.out.println("Logging anyMethodCall before jp.getThis=" + jp.getThis());
+        // System.out.println("Logging anyMethodCall before jp.getTarget=" + jp.getTarget());
+        System.out.println("Logging Before anyMethodCall jp.getSignature=" + jp.getSignature());
+        java.lang.Object[] args = jp.getArgs();
+        if (( args != null ) && ( args.length > 0 )) {
+           System.out.println("Logging Before anyMethodCall jp.getArgs=" + Arrays.asList(args));
+        }
     }
 
     @AfterReturning(pointcut = "anyMethodCall()", returning = "result")
     public void afterReturning(JoinPoint jp, Object result) {
-        System.out.println("After returning: " + jp + " " + result);
+        // Note that result is null for methods with void return.
+        System.out.println("Logging AfterReturning anyMethodCall jp=" + jp + ", result=" + result);
+    }
+
+    @AfterThrowing(pointcut = "anyMethodCall()", throwing = "t")
+    public void afterThrowing(JoinPoint jp, Throwable t) {
+        System.out.println("Logging AfterThrowing anyMethodCall jp=" + jp + ", t=" + t);
+    }
+
+    @Before("anyConstructor()")
+    public void beforeConstructor(JoinPoint jp) {
+        System.out.println("Logging Before anyConstructor jp.getSignature=" + jp.getSignature());
+        java.lang.Object[] args = jp.getArgs();
+        if (( args != null ) && ( args.length > 0 )) {
+           System.out.println("Logging Before anyConstructor jp.getArgs=" + Arrays.asList(args));
+        }
     }
 
-    @AfterThrowing(pointcut = "anyMethodCall()", throwing = "e")
-    public void afterThrowing(Exception e) {
+    @Before("anyStatic()")
+    public void beforeStatic(JoinPoint jp) {
+        System.out.println("Logging Before anyStatic before jp=" + jp);
+        System.out.println("Logging anyMethodCall before jp.getSourceLocation=" + jp.getSourceLocation());
     }
 
 }
diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java
index d8feefe079..965cfa5b5d 100644
--- a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java
+++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java
@@ -26,57 +26,62 @@ import org.aspectj.lang.annotation.Aspect;
 import org.aspectj.lang.annotation.Pointcut;
 
 /**
+ * SimpleTraceAspect performs tracing of method signatures, arguments, and
+ * return values. All Tuscany methods, constructors, and statics are traced.
+ * 
  * @version $Rev$ $Date$
  */
 @Aspect
 public class SimpleTracingAspect extends TracingAspect {
 
-    public SimpleTracingAspect() {
-        super();
-    }
-
-    @Override
-    protected void completeLog() {
-        System.out.println("<<< ----------------------------------------------------");
-    }
-
     @Pointcut("execution(public * org.apache.tuscany.sca..*.*(..))")
+    // @Pointcut("call(* org.apache.tuscany.sca..*(..))")
     protected void entry() {
     }
 
-    @Pointcut("within(org.apache.tuscany.sca..*) && !within(org.apache.tuscany.sca.aspectj.*Aspect)")
+    @Pointcut("within(org.apache.tuscany.sca..*) && !within(org.apache.tuscany.sca.aspectj..*Aspect)")
     protected void withinScope() {
     }
 
     @Override
-    protected void logEnter(JoinPoint jp) {
-        System.out.println("> " + jp.getSignature());
-        if (jp.getArgs().length != 0) {
-            System.out.println("Input: " + Arrays.asList(jp.getArgs()));
-        }
+    protected void startLog() {
+        System.out.println(">>> ----------------------------------------------------");
     }
 
     @Override
-    protected void logExit(JoinPoint jp) {
-        // System.out.println("> " + jp.getSignature());
+    protected void completeLog() {
+        System.out.println("<<< ----------------------------------------------------");
     }
 
     @Override
-    protected void logException(JoinPoint jp, Throwable throwable) {
-        System.out.println("! " + jp.getSignature() + " " + throwable.getMessage());
+    protected void logEnter(JoinPoint jp) {
+        System.out.println("> logEnter jp.getSignature=" + jp.getSignature());
+        java.lang.Object[] args = jp.getArgs();
+        if (( args != null ) && ( args.length > 0 )) {
+       	// See http://www.eclipse.org/aspectj/doc/released/progguide/pitfalls-infiniteLoops.html
+           // System.out.println("Logging anyMethodCall before jp.getArgs=" + Arrays.asList(args));
+           System.out.print("  logEnter jp.getArgs(" + args.length + ")=[" );
+           for ( int i = 0; i < args.length; i++ ){
+        	  if ( i > 0 ) System.out.print( ",");
+        	  System.out.print( args[ i ]);
+           }
+           System.out.println("]" );
+        }
     }
 
     @Override
     protected void logExit(JoinPoint jp, Object result) {
-        System.out.println("< " + jp.getSignature());
-        if (!jp.getSignature().toString().startsWith("void ")) {
-            System.out.println("Output: " + result);
-        }
+        // Note that result is null for methods with void return.
+        System.out.println("< logExit jp.getSignature=" + jp.getSignature() +", result=" + result );        
     }
 
     @Override
-    protected void startLog() {
-        System.out.println(">>> ----------------------------------------------------");
+    protected void logThrowable(JoinPoint jp, Throwable throwable) {
+    	while ( throwable.getCause() != null )
+    		throwable = throwable.getCause();
+        System.out.println("! logThrowable jp.getSignature=" + jp.getSignature() + ", throwable=" + throwable);
+        // System.out.println("! logThowable stackTrace=" ); 
+        // throwable.printStackTrace( System.out );
     }
 
 }
diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TimingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TimingAspect.java
new file mode 100644
index 0000000000..262742e867
--- /dev/null
+++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TimingAspect.java
@@ -0,0 +1,60 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ * 
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.    
+ */
+
+package org.apache.tuscany.sca.aspectj;
+
+import java.util.Arrays;
+
+import org.aspectj.lang.JoinPoint;
+import org.aspectj.lang.ProceedingJoinPoint;
+import org.aspectj.lang.annotation.After;
+import org.aspectj.lang.annotation.AfterReturning;
+import org.aspectj.lang.annotation.AfterThrowing;
+import org.aspectj.lang.annotation.Around;
+import org.aspectj.lang.annotation.Aspect;
+import org.aspectj.lang.annotation.Before;
+import org.aspectj.lang.annotation.Pointcut;
+
+/**
+ * The TimingAspect is used to perform timing metrics on various calls.
+ * The Pointcut "timedCall" is not defined here, but rather in the aop.xml
+ * configuration file. You may provide a point cut to state which type
+ * of call you would like timed and reported in the output files.
+ * 
+ * @version $Rev$ $Date$
+ */
+@Aspect
+public abstract class TimingAspect {
+	// Abstract pointcut. Pointcut is defined in aop.xml file.
+    @Pointcut
+    public void timedCall() {
+    }    
+    	    
+    @Around("timedCall()")
+    public Object timedSection(ProceedingJoinPoint jp) throws Throwable {
+        System.out.println("Timing Around timedSection jp=" + jp);
+        long start = System.currentTimeMillis();
+        try {
+            return jp.proceed();
+        } finally {
+            long end = System.currentTimeMillis();
+            System.out.println("Timing Around timedSection Roundtrip is " + (end - start) + "ms for jp.getSignature=" + jp.getSignature());
+        }
+    }
+}
diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java
index ae3f8f93d5..0178ebdb6e 100644
--- a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java
+++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java
@@ -37,7 +37,6 @@ public abstract class TracingAspect {
     @Pointcut("")
     protected abstract void entry();
 
-    /** ignore join points outside this scope - use within(..) */
     @Pointcut("")
     protected abstract void withinScope();
 
@@ -49,8 +48,9 @@ public abstract class TracingAspect {
     void start() {
     }
 
-    // @Pointcut("withinScope() && cflow(entry()) && !cflow(exit()) && !within(org.apache.tuscany.sca.aspectj.*Aspect)")
-    @Pointcut("withinScope() && entry() && !within(org.apache.tuscany.sca.aspectj.*Aspect)")
+    // @Pointcut("withinScope() && cflow(entry()) && !cflow(exit()) && !within(org.apache.tuscany.sca.aspectj.*Aspect) && !within(*.toString)")
+    @Pointcut("withinScope() && entry()")
+    // @Pointcut("withinScope() && entry()&& !cflow(execution(String toString())")
     void trace() {
     }
 
@@ -67,12 +67,7 @@ public abstract class TracingAspect {
     public void beforeTrace(JoinPoint jp) {
         logEnter(jp);
     }
-
-    @After("trace() && supportsAfterAdvice()")
-    public void afterTrace(JoinPoint jp) {
-        logExit(jp);
-    }
-    
+   
     @AfterReturning(pointcut = "trace() && supportsAfterAdvice()", returning = "result")
     public void afterReturning(JoinPoint jp, Object result) {
         logExit(jp, result);
@@ -80,7 +75,7 @@ public abstract class TracingAspect {
 
     @AfterThrowing(pointcut = "trace() && supportsAfterAdvice()", throwing = "e")
     public void afterThrowing(JoinPoint jp, Throwable e) {
-        logException(jp, e);
+        logThrowable(jp, e);
     }
 
     @After("start()")
@@ -89,13 +84,9 @@ public abstract class TracingAspect {
     }
 
     protected abstract void logEnter(JoinPoint jp);
-
-    protected abstract void logExit(JoinPoint jp);
     protected abstract void logExit(JoinPoint jp, Object result);
-    protected abstract void logException(JoinPoint jp, Throwable throwable);
+    protected abstract void logThrowable(JoinPoint jp, Throwable throwable);
 
     protected abstract void startLog();
-
     protected abstract void completeLog();
-
 }
diff --git a/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml b/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml
index 60c0132e9a..f699a140e3 100644
--- a/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml
+++ b/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml
@@ -1,16 +1,24 @@
 <aspectj>
 
     <aspects>
-        <!-- declare two existing aspects to the weaver -->
-        <aspect name="org.apache.tuscany.sca.aspectj.SimpleTracingAspect" />
-        <!-- 
-        <aspect name="org.apache.tuscany.sca.aspectj.LoggingAspect" />
-         -->
-
+        <!-- Uncomment either of these two aspects to perform standard logging -->
+        <!-- or standard tracing on the Tuscany runtime.                       -->
+        <!-- <aspect name="org.apache.tuscany.sca.aspectj.SimpleTracingAspect" /> -->   
+        <!-- <aspect name="org.apache.tuscany.sca.aspectj.LoggingAspect" /> --> 
+        
+        <!-- Following is a concrete-aspect that defines the point cut for   -->
+        <!-- the TimingAspect. Which ever calls you define in this pointcut  -->
+        <!-- will be timed and displayed in the logs.                        -->
+        <concrete-aspect name="org.apache.tuscany.sca.aspectj.UserTimingAspect"
+           extends="org.apache.tuscany.sca.aspectj.TimingAspect"
+           precedence="org.apache.tuscany.sca.aspectj.UserTimingAspect, *">
+           <pointcut name="timedCall" 
+              expression="call(* java.util.logging.Logger.info(..))"/>
+        </concrete-aspect>
     </aspects>
-
+  
     <!--weaver options="-verbose -debug -showWeaveInfo"-->
-    <weaver options="">
+    <weaver options="-verbose">
         <include within="org.apache.tuscany.sca..*" />
     </weaver>