From 07d26abf4b32a5ef37766940015f2d349cce8f2a Mon Sep 17 00:00:00 2001 From: bimalc Date: Mon, 15 Mar 2021 17:06:16 -0700 Subject: [PATCH 1/3] Option to send messages to log4j logger. --- pom.xml | 15 +++++++++ .../java/net/test/ArgumentsCollection.java | 9 ++++++ src/main/java/net/test/CommonActionArgs.java | 21 ++++++++++++- src/main/java/net/test/DefaultArguments.java | 2 ++ src/main/java/net/test/TraceAgentArgs.java | 11 ++++++- .../interceptor/AvgTimingInterceptorMs.java | 31 ++++++++++--------- .../test/interceptor/CounterInterceptor.java | 4 +-- .../interceptor/StackTraceInterceptor.java | 19 +++++++++--- .../test/interceptor/TimingInterceptorMs.java | 8 ++--- .../interceptor/TimingInterceptorNano.java | 9 +++--- .../interceptor/TraceArgsInterceptor.java | 14 ++++----- .../TraceArgsWithMethodCallInterceptor.java | 24 +++++++------- .../TraceLoginConfigInterceptor.java | 19 ++++++------ .../interceptor/TraceRetValueInterceptor.java | 8 ++--- 14 files changed, 131 insertions(+), 63 deletions(-) diff --git a/pom.xml b/pom.xml index 7662074..5d6696d 100644 --- a/pom.xml +++ b/pom.xml @@ -29,6 +29,21 @@ byte-buddy 1.10.10 + + org.slf4j + slf4j-log4j12 + 1.7.25 + + + org.apache.logging.log4j + log4j-api + 2.14.1 + + + org.apache.logging.log4j + log4j-core + 2.14.1 + diff --git a/src/main/java/net/test/ArgumentsCollection.java b/src/main/java/net/test/ArgumentsCollection.java index e88a459..6709582 100644 --- a/src/main/java/net/test/ArgumentsCollection.java +++ b/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; + } } diff --git a/src/main/java/net/test/CommonActionArgs.java b/src/main/java/net/test/CommonActionArgs.java index 43571d0..e540c4a 100644 --- a/src/main/java/net/test/CommonActionArgs.java +++ b/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 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 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)); + } } diff --git a/src/main/java/net/test/DefaultArguments.java b/src/main/java/net/test/DefaultArguments.java index 513eb17..27babe6 100644 --- a/src/main/java/net/test/DefaultArguments.java +++ b/src/main/java/net/test/DefaultArguments.java @@ -11,4 +11,6 @@ public interface DefaultArguments { DateTimeFormatter getDateTimeFormatter(); boolean isDateLogged(); + + boolean useLog4j(); } diff --git a/src/main/java/net/test/TraceAgentArgs.java b/src/main/java/net/test/TraceAgentArgs.java index a9e8f0b..dbd87ef 100644 --- a/src/main/java/net/test/TraceAgentArgs.java +++ b/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 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; + } } diff --git a/src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java b/src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java index 3897fee..5777be4 100644 --- a/src/main/java/net/test/interceptor/AvgTimingInterceptorMs.java +++ b/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 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; } diff --git a/src/main/java/net/test/interceptor/CounterInterceptor.java b/src/main/java/net/test/interceptor/CounterInterceptor.java index c553122..6765bd2 100644 --- a/src/main/java/net/test/interceptor/CounterInterceptor.java +++ b/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 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(); } diff --git a/src/main/java/net/test/interceptor/StackTraceInterceptor.java b/src/main/java/net/test/interceptor/StackTraceInterceptor.java index f2f2945..3dee368 100644 --- a/src/main/java/net/test/interceptor/StackTraceInterceptor.java +++ b/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 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 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); } } } diff --git a/src/main/java/net/test/interceptor/TimingInterceptorMs.java b/src/main/java/net/test/interceptor/TimingInterceptorMs.java index 5c0f94e..31a92ea 100644 --- a/src/main/java/net/test/interceptor/TimingInterceptorMs.java +++ b/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 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"); } } } diff --git a/src/main/java/net/test/interceptor/TimingInterceptorNano.java b/src/main/java/net/test/interceptor/TimingInterceptorNano.java index c7fad4c..c2ffac8 100644 --- a/src/main/java/net/test/interceptor/TimingInterceptorNano.java +++ b/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 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"); } } } diff --git a/src/main/java/net/test/interceptor/TraceArgsInterceptor.java b/src/main/java/net/test/interceptor/TraceArgsInterceptor.java index 27557a5..ea6aa1c 100644 --- a/src/main/java/net/test/interceptor/TraceArgsInterceptor.java +++ b/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 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)); } } } diff --git a/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java b/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java index 318f024..4b3e15e 100644 --- a/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java +++ b/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 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(); } } diff --git a/src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java b/src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java index 7257bda..98a0d93 100644 --- a/src/main/java/net/test/interceptor/TraceLoginConfigInterceptor.java +++ b/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 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(); } } diff --git a/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java b/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java index ad3812d..da83f35 100644 --- a/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java +++ b/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java @@ -21,7 +21,8 @@ public class TraceRetValueInterceptor { private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms"; private static List 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; @@ -51,9 +52,8 @@ public Object intercept( } else { retValStr = "null"; } - System.out.println( - commonActionArgs.addPrefix( - "TraceAgent (trace_retval): `" + method + " returns with " + retValStr)); + commonActionArgs.printMsg( + "TraceAgent (trace_retval): `" + method + " returns with " + retValStr); } return retVal; } From 7e603c840c4a247d19dff91c4c3c4a989abe6ec4 Mon Sep 17 00:00:00 2001 From: bimalc Date: Mon, 15 Mar 2021 18:09:31 -0700 Subject: [PATCH 2/3] OPtion to direct output to log4j logger. --- README.md | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/README.md b/README.md index dbc6ec3..34d2ba3 100644 --- a/README.md +++ b/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: ". +#### Use log4j logger to add the output to log file instead of stdout. + +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. From b38e9b93cc4e4bcfa2c70a74b5c26fd3443b8009 Mon Sep 17 00:00:00 2001 From: bimalc Date: Mon, 15 Mar 2021 18:21:32 -0700 Subject: [PATCH 3/3] Option to use log4j to direct output to log4j logger. --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 34d2ba3..dbbe626 100644 --- a/README.md +++ b/README.md @@ -230,7 +230,7 @@ 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: ". -#### Use log4j logger to add the output to log file instead of stdout. +#### Redirect output to log4j logger. By adding this argument we can instruct the agent to add the file to log4j logger instead of stdout.