Log4j logging

README.md

@@ -230,6 +230,20 @@ In this case all the rules are used from both the internal and external action f
 In distributed environment when external action file is used you should take care on each node the action file is really can be accessed using the path.
 Otherwise the error is logged but the application continues: "TraceAgent does not find the external action file: <file>".
 
+#### Redirect output to  log4j logger.
+
+By adding this argument we can instruct the agent to add the file to log4j logger instead of stdout.
+
+```
+java -javaagent:target/trace-agent-1.0-SNAPSHOT.jar="use_log4j:true" -jar ../testartifact/target/testartifact-1.0-SNAPSHOT.jar
+
+21/03/15 16:57:47 INFO TraceAgent: TraceAgent (trace_args_with_method_call): public java.lang.Object org.apache.spark.sql.execution.SQLExecution$.withNewExecutionId(org.apache.spark.sql.SparkSession,org.apache.spark.sql.execution.QueryExecution,scala.Function0) parameter instance with index 1 method call "getAllTokens" returns with
+21/03/15 16:57:47 INFO TraceAgent: TraceAgent (trace_args): `public java.lang.String org.apache.spark.sql.execution.SQLExecution$.EXECUTION_ID_KEY() called with []
+```
+
+The default is to write to the stdout.
+
+
 # The counter action
 
 This action can be used to count the number of of method calls. It has one parameter `count_frequency` which specifies after how many calls there will be a printout.

pom.xml

@@ -29,6 +29,21 @@
       <artifactId>byte-buddy</artifactId>
       <version>1.10.10</version>
     </dependency>
+    <dependency>
+      <groupId>org.slf4j</groupId>
+      <artifactId>slf4j-log4j12</artifactId>
+      <version>1.7.25</version>
+    </dependency>
+    <dependency>
+      <groupId>org.apache.logging.log4j</groupId>
+      <artifactId>log4j-api</artifactId>
+      <version>2.14.1</version>
+    </dependency>
+    <dependency>
+      <groupId>org.apache.logging.log4j</groupId>
+      <artifactId>log4j-core</artifactId>
+      <version>2.14.1</version>
+    </dependency>
   </dependencies>
 
   <build>

src/main/java/net/test/ArgumentsCollection.java

@@ -41,4 +41,13 @@ public long parseLong(String key, long defaultValue) {
     }
     return valueLong;
   }
+
+  public boolean parseBoolean(String key, boolean defaultValue) {
+    String valueStr = this.get(key);
+    boolean valueBool = defaultValue;
+    if (valueStr != null) {
+      valueBool = Boolean.valueOf(valueStr);
+    }
+    return valueBool;
+  }
 }

src/main/java/net/test/CommonActionArgs.java

@@ -7,13 +7,21 @@
 import java.util.HashMap;
 import java.util.Map;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 public class CommonActionArgs {
   public static final String IS_DATE_LOGGED = "isDateLogged";
+  public static final String USE_LOG4J = "use_log4j";
+  private static Logger logger;
 
+  private boolean useLog4j;
   private final DateTimeFormatter dateTimeFormatter;
 
   public CommonActionArgs(Map<String, String> parsedActionArgs, DefaultArguments defaults) {
     final String isDateLoggedStr = parsedActionArgs.get(IS_DATE_LOGGED);
+    final String useLog4jStr = parsedActionArgs.get(USE_LOG4J);
+
     if (isDateLoggedStr == null) {
       if (defaults.isDateLogged()) {
         dateTimeFormatter = defaults.getDateTimeFormatter();
@@ -27,9 +35,14 @@ public CommonActionArgs(Map<String, String> parsedActionArgs, DefaultArguments d
         dateTimeFormatter = null;
       }
     }
+
+    if (useLog4jStr == null) useLog4j = defaults.useLog4j();
+    else useLog4j = Boolean.valueOf(useLog4jStr);
+
+    if (useLog4j) logger = LoggerFactory.getLogger("TraceAgent");
   }
 
-  public String addPrefix(String str) {
+  private String addPrefix(String str) {
     final String prefixed;
     if (dateTimeFormatter == null) {
       prefixed = str;
@@ -38,4 +51,10 @@ public String addPrefix(String str) {
     }
     return prefixed;
   }
+
+  public void printMsg(String msg) {
+
+    if (useLog4j) logger.info(msg);
+    else System.out.println(addPrefix(msg));
+  }
 }

src/main/java/net/test/DefaultArguments.java

@@ -11,4 +11,6 @@ public interface DefaultArguments {
   DateTimeFormatter getDateTimeFormatter();
 
   boolean isDateLogged();
+
+  boolean useLog4j();
 }

src/main/java/net/test/TraceAgentArgs.java

@@ -15,12 +15,16 @@ public class TraceAgentArgs implements DefaultArguments {
   private final DateTimeFormatter dateTimeFormatter;
 
   private final Boolean isDateLoggedFlag;
+  private final Boolean useLog4jFlag;
 
   public TraceAgentArgs(String arguments) {
     Map<String, String> parsedArgs =
         ArgUtils.parseOptionalArgs(
             Arrays.asList(
-                EXTERNAL_ACTION_FILE_PATH, DATE_TIME_FORMAT, CommonActionArgs.IS_DATE_LOGGED),
+                EXTERNAL_ACTION_FILE_PATH,
+                DATE_TIME_FORMAT,
+                CommonActionArgs.IS_DATE_LOGGED,
+                CommonActionArgs.USE_LOG4J),
             arguments);
     this.externalActionFilePath = parsedArgs.get(EXTERNAL_ACTION_FILE_PATH);
     final String dateTimeFormatStr = parsedArgs.get(DATE_TIME_FORMAT);
@@ -31,6 +35,7 @@ public TraceAgentArgs(String arguments) {
     }
     // parse the common arguments
     this.isDateLoggedFlag = Boolean.valueOf(parsedArgs.get(CommonActionArgs.IS_DATE_LOGGED));
+    this.useLog4jFlag = Boolean.valueOf(parsedArgs.get(CommonActionArgs.USE_LOG4J));
   }
 
   public String getExternalActionFilePath() {
@@ -44,4 +49,8 @@ public DateTimeFormatter getDateTimeFormatter() {
   public boolean isDateLogged() {
     return this.isDateLoggedFlag;
   }
+
+  public boolean useLog4j() {
+    return this.useLog4jFlag;
+  }
 }

src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java

@@ -22,7 +22,7 @@ public class AvgTimingInterceptorMs {
   private static String WINDOW_LENGTH = "window_length";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, WINDOW_LENGTH);
+      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, WINDOW_LENGTH, CommonActionArgs.USE_LOG4J);
 
   private CommonActionArgs commonActionArgs;
 
@@ -57,21 +57,22 @@ public Object intercept(@Origin Method method, @SuperCall Callable<?> callable)
       } else if (elapsedTime > this.window_max) {
         window_max = elapsedTime;
       }
+
       if (window_index == window_length) {
-        System.out.println(
-            commonActionArgs.addPrefix(
-                "TraceAgent ("
-                    + NAME
-                    + "): `"
-                    + method
-                    + "` window_length: "
-                    + window_length
-                    + " min: "
-                    + window_min
-                    + " avg: "
-                    + window_sum / window_length
-                    + " max: "
-                    + window_max));
+        commonActionArgs.printMsg(
+            "TraceAgent ("
+                + NAME
+                + "): `"
+                + method
+                + "` window_length: "
+                + window_length
+                + " min: "
+                + window_min
+                + " avg: "
+                + window_sum / window_length
+                + " max: "
+                + window_max);
+
         window_index = 0;
         window_sum = 0;
       }

src/main/java/net/test/interceptor/CounterInterceptor.java

@@ -24,7 +24,7 @@ public class CounterInterceptor {
   private static String COUNT_FREQUENCY = "count_frequency";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, COUNT_FREQUENCY);
+      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.USE_LOG4J, COUNT_FREQUENCY);
 
   private CommonActionArgs commonActionArgs;
 
@@ -44,7 +44,7 @@ public Object intercept(
       throws Exception {
     counter++;
     if (counter % countFrequency == 0) {
-      System.out.println(commonActionArgs.addPrefix("TraceAgent (counter): " + counter));
+      commonActionArgs.printMsg("TraceAgent (counter): " + counter);
     }
     return callable.call();
   }

src/main/java/net/test/interceptor/StackTraceInterceptor.java

@@ -16,6 +16,7 @@
 import java.util.List;
 import java.util.Map;
 import java.util.concurrent.Callable;
+import java.util.stream.Collectors;
 
 class MyException extends Exception {
 
@@ -39,7 +40,11 @@ public class StackTraceInterceptor {
   private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_MILLISECONDS, LIMIT_COUNT);
+      Arrays.asList(
+          CommonActionArgs.IS_DATE_LOGGED,
+          CommonActionArgs.USE_LOG4J,
+          LOG_THRESHOLD_MILLISECONDS,
+          LIMIT_COUNT);
 
   private CommonActionArgs commonActionArgs;
 
@@ -76,10 +81,14 @@ public Object intercept(@Origin Method method, @SuperCall Callable<?> callable)
         }
 
         if (doPrint) {
-          Exception e = new MyException(commonActionArgs.addPrefix("TraceAgent (stack trace)"));
-          StackTraceElement[] stElements = Thread.currentThread().getStackTrace();
-          e.setStackTrace(Arrays.copyOfRange(stElements, 2, stElements.length));
-          e.printStackTrace(System.out);
+          List<StackTraceElement> stElements =
+              Arrays.asList(Thread.currentThread().getStackTrace());
+          String st =
+              stElements.stream()
+                  .filter(elt -> elt != null)
+                  .map(elt -> elt.toString())
+                  .collect(Collectors.joining("\n\t"));
+          commonActionArgs.printMsg("TraceAgent (stack trace)" + st);
         }
       }
     }

src/main/java/net/test/interceptor/TimingInterceptorMs.java

@@ -22,7 +22,8 @@ public class TimingInterceptorMs {
   private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_MILLISECONDS);
+      Arrays.asList(
+          CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.USE_LOG4J, LOG_THRESHOLD_MILLISECONDS);
 
   private CommonActionArgs commonActionArgs;
 
@@ -42,9 +43,8 @@ public Object intercept(@Origin Method method, @SuperCall Callable<?> callable)
     } finally {
       long end = System.currentTimeMillis();
       if (this.logThresholdMs == 0 || end - start >= this.logThresholdMs) {
-        System.out.println(
-            commonActionArgs.addPrefix(
-                "TraceAgent (timing): `" + method + "` took " + (end - start) + " ms"));
+        commonActionArgs.printMsg(
+            "TraceAgent (timing): `" + method + "` took " + (end - start) + " ms");
       }
     }
   }

src/main/java/net/test/interceptor/TimingInterceptorNano.java

@@ -23,10 +23,12 @@ public class TimingInterceptorNano {
   private static String LOG_THRESHOLD_NANO = "log_threshold_nano";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_NANO);
+      Arrays.asList(
+          CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.USE_LOG4J, LOG_THRESHOLD_NANO);
 
   private CommonActionArgs commonActionArgs;
 
+  private boolean useLog4j;
   private final long logThresholdNano;
 
   public TimingInterceptorNano(String actionArgs, DefaultArguments defaults) {
@@ -43,9 +45,8 @@ public Object intercept(@Origin Method method, @SuperCall Callable<?> callable)
     } finally {
       long end = System.nanoTime();
       if (this.logThresholdNano == 0 || end - start >= this.logThresholdNano) {
-        System.out.println(
-            commonActionArgs.addPrefix(
-                "TraceAgent (timing): `" + method + "` took " + (end - start) + " nano"));
+        commonActionArgs.printMsg(
+            "TraceAgent (timing): `" + method + "` took " + (end - start) + " nano");
       }
     }
   }

src/main/java/net/test/interceptor/TraceArgsInterceptor.java

@@ -24,7 +24,8 @@ public class TraceArgsInterceptor {
   private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_MILLISECONDS);
+      Arrays.asList(
+          CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.USE_LOG4J, LOG_THRESHOLD_MILLISECONDS);
 
   private CommonActionArgs commonActionArgs;
 
@@ -46,12 +47,11 @@ public Object intercept(
     } finally {
       long end = (this.logThresholdMs == 0) ? 0 : System.currentTimeMillis();
       if (this.logThresholdMs == 0 || end - start >= this.logThresholdMs) {
-        System.out.println(
-            commonActionArgs.addPrefix(
-                "TraceAgent (trace_args): `"
-                    + method
-                    + " called with "
-                    + Arrays.toString(allArguments)));
+        commonActionArgs.printMsg(
+            "TraceAgent (trace_args): `"
+                + method
+                + " called with "
+                + Arrays.toString(allArguments));
       }
     }
   }

src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java

@@ -23,7 +23,8 @@ public class TraceArgsWithMethodCallInterceptor {
   private static String METHOD_TO_CALL = "method_to_call";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, PARAM_INDEX, METHOD_TO_CALL);
+      Arrays.asList(
+          CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.USE_LOG4J, PARAM_INDEX, METHOD_TO_CALL);
 
   private CommonActionArgs commonActionArgs;
 
@@ -57,16 +58,17 @@ public Object intercept(
               + " but max index is "
               + (allArguments.length - 1);
     }
-    System.out.println(
-        commonActionArgs.addPrefix(
-            "TraceAgent (trace_args_with_method_call): "
-                + method
-                + " parameter instance with index "
-                + paramIndex
-                + " method call \""
-                + methodToCallName
-                + "\" returns with \n"
-                + retVal));
+
+    commonActionArgs.printMsg(
+        "TraceAgent (trace_args_with_method_call): "
+            + method
+            + " parameter instance with index "
+            + paramIndex
+            + " method call \""
+            + methodToCallName
+            + "\" returns with \n"
+            + retVal);
+
     return callable.call();
   }
 }

src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java

@@ -24,7 +24,7 @@ public class TraceLoginConfigInterceptor {
   private static String ENTRY_NAME = "entry_name";
 
   private static List<String> KNOWN_ARGS =
-      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, ENTRY_NAME);
+      Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.USE_LOG4J, ENTRY_NAME);
 
   private CommonActionArgs commonActionArgs;
 
@@ -55,14 +55,15 @@ public Object intercept(
     if (entries.isEmpty()) {
       entries = "Not Found";
     }
-    System.out.println(
-        commonActionArgs.addPrefix(
-            "TraceAgent (trace_login_config): `"
-                + method
-                + " login config for entry \""
-                + entryName
-                + "\"\n"
-                + entries));
+
+    commonActionArgs.printMsg(
+        "TraceAgent (trace_login_config): `"
+            + method
+            + " login config for entry \""
+            + entryName
+            + "\"\n"
+            + entries);
+
     return callable.call();
   }
 }