New feature - Logging the thread name

README.md

@@ -193,6 +193,22 @@ Tue Jun 23 12:39:25 CEST 2020
 2020-06-23T12:39:25.875 TraceAgent (trace_retval): `public int net.test.TestClass2nd.methodWithArgs(java.lang.String,int) returns with 12
 ```
 
+### Example for common argument (both global and action argument): `isThreadnameLogged`
+The `isThreadnameLogged` can be used to request the current thread name to be contained as prefix in the actions logs.
+This is especially useful in multithreaded applications.
+This is false by default but via setting it globally this default can be changed:
+
+```
+$  java -javaagent:target/trace-agent-1.0-SNAPSHOT.jar="isDateLogged:true,isThreadnameLogged:true" -jar ../testartifact/target/testartifact-1.0-SNAPSHOT.jar
+Hello World!
+2020-06-23T12:34:27.746 [main] TraceAgent (timing): `public void net.test.TestClass.test()` took 101212548 nano
+...
+```
+The `isThreadnameLogged` can be enabled on action level too if needed:
+
+```
+elapsed_time_in_nano net.test.TestClass test isThreadnameLogged:true
+```
 ### Trace agent global only parameters
 
 There are parameters which configures the trace agent globally.
@@ -527,6 +543,7 @@ Heapdump file names follows the following patttern:
 * `isDateLogged` (scope: both `global` and `action`) The `isDateLogged` can be used to request the current date time to be contained as prefix in the actions logs.
 * `dateTimeFormat` (scope: `global`) Can be used to specify formatting for datetimes. The default is [ISO_LOCAL_DATE_TIME](https://docs.oracle.com/javase/8/docs/api/java/time/format/DateTimeFormatter.html#ISO_LOCAL_DATE_TIME).
   For the details and valid patterns please check: [DateTimeFormatter](https://docs.oracle.com/javase/8/docs/api/java/time/format/DateTimeFormatter.html).
+* `isThreadnameLogged` (scope: both `global` and `action`) The `isThreadnameLogged` can be used to request the current thread name to be contained as prefix in the actions logs.
 * `log_threshold_ms` (scope: multiple actions) This threshold represents the elapsed number of milliseconds after there will be a printout. The default is `0`, which means it should printout on every call. For example, if we only like to log an action when it takes more than 1 second to complete: `elapsed_time_in_ms net.test.TestClass test log_threshold_ms:1000`
 * `log_threshold_nano` (scope: only for `elapsed_time_in_nano`) Similar to `log_threshold_ms` but in nanoseconds.
 * `limit_count` (scope: only for `stack_trace`) Trace only the first `limit_count` number of calls. This limit is turned off by default by set it to -1.
@@ -544,17 +561,17 @@ All actions have the following set of arguments
 
 Here is the full list of actions and supported `params`
 
-| Action                      | Supported arguments                           |
-| --------------------------- | --------------------------------------------- |
-| elapsed_time_in_nano        | isDateLogged, log_threshold_nano              |
-| elapsed_time_in_ms          | isDateLogged, log_threshold_ms                |
-| stack_trace                 | isDateLogged, log_threshold_ms, limit_count   |
-| trace_args                  | isDateLogged, log_threshold_ms                |
-| trace_retval                | isDateLogged, log_threshold_ms                |
-| trace_args_with_method_call | isDateLogged, param_index, method_to_call     |
-| counter                     | isDateLogged, count_frequency                 |
-| avg_timing                  | isDateLogged, window_length                   |
-| trace_login_config          | isDateLogged, entry_name                      |
+| Action                      | Supported arguments                                   |
+| --------------------------- |-------------------------------------------------------|
+| elapsed_time_in_nano        | isDateLogged, isThreadnameLogged, log_threshold_nano |
+| elapsed_time_in_ms          | isDateLogged, isThreadnameLogged, log_threshold_ms                        |
+| stack_trace                 | isDateLogged, isThreadnameLogged, log_threshold_ms, limit_count           |
+| trace_args                  | isDateLogged, isThreadnameLogged, log_threshold_ms                        |
+| trace_retval                | isDateLogged, isThreadnameLogged, log_threshold_ms                        |
+| trace_args_with_method_call | isDateLogged, isThreadnameLogged, param_index, method_to_call             |
+| counter                     | isDateLogged, isThreadnameLogged, count_frequency                         |
+| avg_timing                  | isDateLogged, isThreadnameLogged, window_length                           |
+| trace_login_config          | isDateLogged, isThreadnameLogged, entry_name                              |
 
 
 # Some complex examples how to specify a javaagent

trace-agent-it/test_exec/src/test/java/TestTraceAgent.java

@@ -27,7 +27,18 @@ public class TestTraceAgent {
               + "\" "
               + "-jar ../sampleApp/target/sampleApp-1.0-SNAPSHOT.jar");
 
+  private static CommandLine cmdWithThreadNameArgs =
+      CommandLine.parse(
+          "java -XX:NativeMemoryTracking=detail -javaagent:../../trace-agent/target/trace-agent-1.0-SNAPSHOT.jar=\"isThreadnameLogged:true,actionsFile:./"
+              + ACTION_FILE_NAME
+              + "\" "
+              + "-jar ../sampleApp/target/sampleApp-1.0-SNAPSHOT.jar");
+
   private String runTraceAgent(String... actions) throws IOException {
+    return runTraceAgent(false, actions);
+  }
+
+  private String runTraceAgent(boolean isThreadNameLogged, String... actions) throws IOException {
     String res = "";
     try (ByteArrayOutputStream outputStream = new ByteArrayOutputStream()) {
       DefaultExecutor executor = new DefaultExecutor();
@@ -38,7 +49,11 @@ private String runTraceAgent(String... actions) throws IOException {
           actionWriter.append(a + "\n");
         }
         actionWriter.close();
-        executor.execute(cmd);
+        if (isThreadNameLogged) {
+          executor.execute(cmdWithThreadNameArgs);
+        } else {
+          executor.execute(cmd);
+        }
       } finally {
         actionFile.delete();
       }
@@ -164,4 +179,24 @@ public void testDiagnosticCommandNativeMemory() throws IOException {
         streamSupplier.get().anyMatch(s -> s.equals("TraceAgent (diagnostic_command / vmNativeMemory): at the beginning of `public void net.test.TestClass2nd.anotherMethod()`:")));
     assertTrue(streamSupplier.get().anyMatch(s -> s.equals("Native Memory Tracking:")));
   }
+
+  @Test
+  public void testTraceArgsWithThreadNameAsJVMArg() throws IOException {
+    String output = runTraceAgent(true, "trace_args net.test.TestClass2nd methodWithArgs");
+    Supplier<Stream<String>> streamSupplier = toStreamSupplier(output);
+    assertTrue(
+        streamSupplier
+            .get()
+            .anyMatch(s -> s.contains("[main] TraceAgent (trace_args pre): `public int net.test.TestClass2nd.methodWithArgs(java.lang.String,int) called with [secret, 42]")));
+  }
+
+  @Test
+  public void testTraceArgsWithThreadNameAsActionArg() throws IOException {
+    String output = runTraceAgent("trace_args net.test.TestClass2nd methodWithArgs isThreadnameLogged:true");
+    Supplier<Stream<String>> streamSupplier = toStreamSupplier(output);
+    assertTrue(
+        streamSupplier
+            .get()
+            .anyMatch(s -> s.contains("[main] TraceAgent (trace_args pre): `public int net.test.TestClass2nd.methodWithArgs(java.lang.String,int) called with [secret, 42]")));
+  }
 }

trace-agent/src/main/java/net/test/CommonActionArgs.java

@@ -7,8 +7,12 @@
 public class CommonActionArgs {
   public static final String IS_DATE_LOGGED = "isDateLogged";
 
+  public static final String IS_THREADNAME_LOGGED = "isThreadnameLogged";
+
   private final DateTimeFormatter dateTimeFormatter;
 
+  private final boolean threadnameLogged;
+
   public CommonActionArgs(Map<String, String> parsedActionArgs, DefaultArguments defaults) {
     final String isDateLoggedStr = parsedActionArgs.get(IS_DATE_LOGGED);
     if (isDateLoggedStr == null) {
@@ -24,15 +28,23 @@ public CommonActionArgs(Map<String, String> parsedActionArgs, DefaultArguments d
         dateTimeFormatter = null;
       }
     }
+    final String isThreadNameLoggedStr = parsedActionArgs.get(IS_THREADNAME_LOGGED);
+    if (isThreadNameLoggedStr == null) {
+      threadnameLogged = defaults.isThreadNameLogged();
+    } else {
+      threadnameLogged = Boolean.valueOf(isThreadNameLoggedStr);
+    }
   }
 
   public String addPrefix(String str) {
-    final String prefixed;
-    if (dateTimeFormatter == null) {
-      prefixed = str;
-    } else {
-      prefixed = dateTimeFormatter.format(LocalDateTime.now()) + " " + str;
+    StringBuilder prefixed = new StringBuilder();
+    if (dateTimeFormatter != null) {
+      prefixed.append(dateTimeFormatter.format(LocalDateTime.now())).append(" ");
+    }
+    if (threadnameLogged) {
+      prefixed.append("[").append(Thread.currentThread().getName()).append("] ");
     }
-    return prefixed;
+    prefixed.append(str);
+    return prefixed.toString();
   }
 }

trace-agent/src/main/java/net/test/DefaultArguments.java

@@ -1,14 +1,12 @@
 package net.test;
 
 import java.time.format.DateTimeFormatter;
-import java.util.ArrayList;
-import java.util.List;
-import java.util.HashMap;
-import java.util.Map;
 
 public interface DefaultArguments {
 
   DateTimeFormatter getDateTimeFormatter();
 
   boolean isDateLogged();
+
+  boolean isThreadNameLogged();
 }

trace-agent/src/main/java/net/test/TraceAgentArgs.java

@@ -20,11 +20,15 @@ public class TraceAgentArgs implements DefaultArguments {
 
   private final Boolean isDateLoggedFlag;
 
+  private final Boolean isThreadNameLoggedFlag;
+
   private final PrintStream targetStream;
 
   public TraceAgentArgs(String arguments) {
     Map<String, String> parsedArgs =
-        ArgUtils.parseOptionalArgs(Arrays.asList(EXTERNAL_ACTION_FILE_PATH, ENABLE_AGENT_LOG, DATE_TIME_FORMAT, CommonActionArgs.IS_DATE_LOGGED, TARGET_STREAM), arguments);
+        ArgUtils.parseOptionalArgs(
+            Arrays.asList(EXTERNAL_ACTION_FILE_PATH, ENABLE_AGENT_LOG, DATE_TIME_FORMAT, CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, TARGET_STREAM),
+            arguments);
     this.externalActionFilePath = parsedArgs.get(EXTERNAL_ACTION_FILE_PATH);
     if (parsedArgs.getOrDefault(TARGET_STREAM, "stdout").equals("stderr")) {
       this.targetStream = System.err;
@@ -42,6 +46,7 @@ public TraceAgentArgs(String arguments) {
 
     // parse the common arguments
     this.isDateLoggedFlag = Boolean.valueOf(parsedArgs.get(CommonActionArgs.IS_DATE_LOGGED));
+    this.isThreadNameLoggedFlag = Boolean.valueOf(parsedArgs.get(CommonActionArgs.IS_THREADNAME_LOGGED));
   }
 
   public String getExternalActionFilePath() {
@@ -60,6 +65,10 @@ public boolean isDateLogged() {
     return this.isDateLoggedFlag;
   }
 
+  public boolean isThreadNameLogged() {
+    return this.isThreadNameLoggedFlag;
+  }
+
   public PrintStream getTargetStream() {
     return targetStream;
   }

trace-agent/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);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, WINDOW_LENGTH);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/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);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, COUNT_FREQUENCY);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/src/main/java/net/test/interceptor/DiagnosticCommandInterceptor.java

@@ -44,7 +44,7 @@ private static ObjectName createDiagObj() {
 
   private static String LIMIT_OUTPUT_LINES = "limit_output_lines";
 
-  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, COMMAND, LIMIT_OUTPUT_LINES, WHERE, WITH_GC);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, COMMAND, LIMIT_OUTPUT_LINES, WHERE, WITH_GC);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/src/main/java/net/test/interceptor/HeapDumpCommandInterceptor.java

@@ -42,7 +42,7 @@ private static void dumpHeap(String filePath, boolean live) {
 
   private static String LIVE_OBJECTS = "live_objects";
 
-  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, WHERE, LIVE_OBJECTS);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, WHERE, LIVE_OBJECTS);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/src/main/java/net/test/interceptor/TimingInterceptorMs.java

@@ -22,7 +22,7 @@ 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);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_MILLISECONDS);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/src/main/java/net/test/interceptor/TimingInterceptorNano.java

@@ -23,7 +23,7 @@ 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);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_NANO);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/src/main/java/net/test/interceptor/TraceArgsInterceptor.java

@@ -24,7 +24,7 @@ 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);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_MILLISECONDS);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/src/main/java/net/test/interceptor/TraceArgsWithMethodCallInterceptor.java

@@ -23,7 +23,7 @@ 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);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, PARAM_INDEX, METHOD_TO_CALL);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/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);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, ENTRY_NAME);
 
   private CommonActionArgs commonActionArgs;
 

trace-agent/src/main/java/net/test/interceptor/TraceRetValueInterceptor.java

@@ -20,7 +20,7 @@ public class TraceRetValueInterceptor {
 
   private static String LOG_THRESHOLD_MILLISECONDS = "log_threshold_ms";
 
-  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, LOG_THRESHOLD_MILLISECONDS);
+  private static List<String> KNOWN_ARGS = Arrays.asList(CommonActionArgs.IS_DATE_LOGGED, CommonActionArgs.IS_THREADNAME_LOGGED, LOG_THRESHOLD_MILLISECONDS);
 
   private CommonActionArgs commonActionArgs;