feat: Improve agent logging and refactor internals

agent/src/main/java/com/appland/appmap/Agent.java

@@ -72,8 +72,7 @@ public static void premain(String agentArgs, Instrumentation inst) {
     logger.info("Agent version {}, current time mills: {}",
             implementationVersion, start);
     logger.info("config: {}", AppMapConfig.get());
-    logger.info("System properties: {}", System.getProperties());
-    logger.debug(new Exception(), "whereAmI");
+    logger.debug("System properties: {}", System.getProperties());
 
     addAgentJars(agentArgs, inst);
 

agent/src/main/java/com/appland/appmap/config/AppMapConfig.java

@@ -317,6 +317,8 @@ public static TaggedLogger configureLogging() {
     // tinylog freezes its configuration after the first call to any of its
     // methods other than those in Configuration. So, get everything ready
     // before returning the logger for this class;
+    Configuration.set("writer.format", "{date:yyyy-MM-dd HH:mm:ss} [{thread}] AppMap {level}: {message}");
+
     if (Properties.Debug) {
       Configuration.set("level", "debug");
     }
@@ -365,6 +367,25 @@ private static Path findDefaultOutputDirectory(FileSystem fs) {
 
   @Override
   public String toString() {
-    return JSON.toJSONString(this, true);
+    StringBuilder sb = new StringBuilder();
+    sb.append("name: ").append(name).append("\n");
+    if (configFile != null) {
+      sb.append("configFile: ").append(configFile).append("\n");
+    }
+    sb.append("packages: ");
+    if (packages == null || packages.length == 0) {
+      sb.append("[]");
+    } else {
+      for (AppMapPackage pkg : packages) {
+        sb.append("\n  - path: ").append(pkg.path);
+        if (pkg.shallow) {
+          sb.append("\n    shallow: true");
+        }
+        if (pkg.exclude != null && pkg.exclude.length > 0) {
+          sb.append("\n    exclude: ").append(Arrays.toString(pkg.exclude));
+        }
+      }
+    }
+    return sb.toString();
   }
 }

agent/src/main/java/com/appland/appmap/output/v1/Parameters.java

@@ -7,11 +7,10 @@
 import java.util.stream.Collectors;
 import java.util.stream.Stream;
 
+import javassist.bytecode.AttributeInfo;
 import org.tinylog.TaggedLogger;
 
 import com.appland.appmap.config.AppMapConfig;
-import com.appland.appmap.config.Properties;
-import com.appland.appmap.util.Logger;
 
 import javassist.CtBehavior;
 import javassist.CtClass;
@@ -30,7 +29,7 @@
 public class Parameters implements Iterable<Value> {
   private static final TaggedLogger logger = AppMapConfig.getLogger(null);
 
-  private final ArrayList<Value> values = new ArrayList<Value>();
+  private final ArrayList<Value> values = new ArrayList<>();
 
   public Parameters() { }
 
@@ -48,7 +47,7 @@ public Parameters(CtBehavior behavior) {
       "." + behavior.getName() +
       methodInfo.getDescriptor();
 
-    CtClass[] paramTypes = null;
+    CtClass[] paramTypes;
     try {
       paramTypes = behavior.getParameterTypes();
     } catch (NotFoundException e) {
@@ -71,51 +70,11 @@ public Parameters(CtBehavior behavior) {
       return;
     }
 
-    CodeAttribute codeAttribute = methodInfo.getCodeAttribute();
-    LocalVariableAttribute locals = null;
-    if (codeAttribute != null) {
-      locals = (LocalVariableAttribute) codeAttribute.getAttribute(javassist.bytecode.LocalVariableAttribute.tag);
-    } else {
-      logger.debug("No code attribute for {}", fqn);
-    }
-
+    String[] paramNames = getParameterNames(methodInfo, paramTypes);
     int numParams = paramTypes.length;
-    String[] paramNames = new String[numParams];
-    if (locals != null && numParams > 0) {
-      int numLocals = locals.tableLength();
-
-      // This is handy when debugging this code, but produces too much
-      // noise for general use.
-      if (Properties.DebugLocals) {
-        logger.debug("local variables for {}", fqn);
-        for (int idx = 0; idx < numLocals; idx++) {
-          logger.debug("  {} {} {}", idx, locals.variableName(idx), locals.index(idx));
-        }
-      }
-
-      // Iterate through the local variables to find the ones that match the argument slots.
-      // Arguments are pushed into consecutive slots, starting at 0 (for this or the first argument),
-      // and then incrementing by 1 for each argument, unless the argument is an unboxed long or double,
-      // in which case it takes up two slots.
-      int slot = Modifier.isStatic(behavior.getModifiers()) ? 0 : 1; // ignore `this`
-      for (int i = 0; i < numParams; i++) {
-        try {
-          // note that the slot index is not the same as the
-          // parameter index or the local variable index
-          paramNames[i] = locals.variableNameByIndex(slot);
-        } catch (Exception e) {
-          // the debug info might be corrupted or partial, let's not crash in this case
-          logger.debug(e, "Failed to get local variable name for slot {} in {}", slot, fqn);
-        } finally {
-          // note these only correspond to unboxed types — boxed double and long will still have width 1
-          int width = paramTypes[i] == CtClass.doubleType || paramTypes[i] == CtClass.longType ? 2 : 1;
-          slot += width;
-        }
-      }
-    }
 
     Value[] paramValues = new Value[numParams];
-    for (int i = 0; i < paramTypes.length; ++i) {
+    for (int i = 0; i < numParams; ++i) {
       // Use a real parameter name if we have it, a fake one if we
       // don't.
       String paramName = paramNames[i];
@@ -130,11 +89,61 @@ public Parameters(CtBehavior behavior) {
       paramValues[i] = param;
     }
 
-    for (int i = 0; i < paramValues.length; ++i) {
-      this.add(paramValues[i]);
+    for (Value paramValue : paramValues) {
+      this.add(paramValue);
     }
   }
 
+  /**
+   * Iterate through the LocalVariableTables to get parameter names.
+   * Local variable tables are debugging metadata containing information about local variables.
+   * Variables are organized into slots; first slots are used for parameters, then for local variables.
+   *
+   * @param methodInfo for the method
+   * @param paramTypes types of the parameters (used to calculate slot positions)
+   * @return Array of parameter names (ignoring this), with null for any names that could not be determined.
+   * Length of the array matches length of paramTypes.
+   * @see <a href="https://docs.oracle.com/javase/specs/jvms/se7/html/jvms-4.html#jvms-4.7.13">The Java Virtual Machine Specification: The LocalVariableTable Attribute</a>
+   */
+  private static String[] getParameterNames(MethodInfo methodInfo, CtClass[] paramTypes) {
+    String[] paramNames = new String[paramTypes.length];
+
+    CodeAttribute codeAttribute = methodInfo.getCodeAttribute();
+    if (codeAttribute != null) {
+      boolean isStatic = Modifier.isStatic(methodInfo.getAccessFlags());
+
+      // count number of slots taken by all the parameters
+      int slotCount = isStatic ? 0 : 1; // account for `this`
+      for (CtClass paramType : paramTypes) {
+        slotCount += (paramType == CtClass.doubleType || paramType == CtClass.longType) ? 2 : 1;
+      }
+
+      String[] namesBySlot = new String[slotCount];
+
+      for (AttributeInfo attr : codeAttribute.getAttributes()) {
+        if (attr instanceof LocalVariableAttribute) {
+          LocalVariableAttribute localVarAttr = (LocalVariableAttribute) attr;
+
+          for (int i = 0; i < localVarAttr.tableLength(); i++) {
+            int index = localVarAttr.index(i);
+            if (index < slotCount) {
+              namesBySlot[index] = localVarAttr.variableName(i);
+            }
+          }
+        }
+      }
+
+      int slot = isStatic ? 0 : 1; // ignore `this`
+      for (int i = 0; i < paramTypes.length; i++) {
+        paramNames[i] = namesBySlot[slot];
+        int width = paramTypes[i] == CtClass.doubleType || paramTypes[i] == CtClass.longType ? 2 : 1;
+        slot += width;
+      }
+    }
+
+    return paramNames;
+  }
+
   /**
    * Get an iterator for each {@link Value}.
    * @return A {@link Value} iterator
@@ -172,43 +181,29 @@ public int size() {
     return this.values.size();
   }
 
-
   /**
-   * Clears the internal value array.
-   */
-  public void clear() {
-    this.values.clear();
-  }
-
-  /**
-   * Gets a {@Value} object stored by this Parameters object by name/identifier.
+   * Gets a {@link Value} object stored by this Parameters object by name/identifier.
    * @param name The name or identifier of the @{link Value} to be returned
    * @return The {@link Value} object found
-   * @throws NoSuchElementException If no @{link Value} object is found
+   * @throws NoSuchElementException If no {@link Value} object is found
    */
   public Value get(String name) throws NoSuchElementException {
-    if (this.values != null) {
-      for (Value param : this.values) {
-        if (param.name.equals(name)) {
-          return param;
-        }
+    for (Value param : this.values) {
+      if (param.name.equals(name)) {
+        return param;
       }
     }
 
     throw new NoSuchElementException();
   }
 
   /**
-   * Gets a {@Value} object stored by this Parameters object by index.
+   * Gets a {@link Value} object stored by this Parameters object by index.
    * @param index The index of the @{link Value} to be returned
    * @return The {@link Value} object at the given index
-   * @throws NoSuchElementException if no @{link Value} object is found at the given index
+   * @throws NoSuchElementException if no {@link Value} object is found at the given index
    */
   public Value get(Integer index) throws NoSuchElementException {
-    if (this.values == null) {
-      throw new NoSuchElementException();
-    }
-
     try {
       return this.values.get(index);
     } catch (NullPointerException | IndexOutOfBoundsException e) {
@@ -233,10 +228,10 @@ public Boolean validate(Integer index, String type) {
   }
 
   /**
-   * Performs a deep copy of the Parameters object and all of its values.
+   * Creates a copy of the parameters object with the value types, kinds and names preserved.
    * @return A new Parameters object
    */
-  public Parameters clone() {
+  public Parameters freshCopy() {
     Parameters clonedParams = new Parameters();
     for (Value param : this.values) {
       clonedParams.add(new Value(param));

agent/src/main/java/com/appland/appmap/transform/ClassFileTransformer.java

@@ -189,47 +189,24 @@ private void processClass(CtClass ctClass) {
     }
   }
 
-  private boolean applyHooks(CtBehavior behavior) {
-    boolean traceClass = tracePrefix == null || behavior.getDeclaringClass().getName().startsWith(tracePrefix);
-
+  private Set<Hook.ApplicationAction> applyHooks(CtBehavior behavior, boolean traceClass) {
     try {
       List<HookSite> hookSites = getHookSites(behavior);
 
       if (hookSites == null) {
         if (traceClass) {
           logger.trace("no hook sites");
         }
-        return false;
+        return java.util.Collections.emptySet();
       }
 
-      Hook.apply(behavior, hookSites);
-
-      if (logger.isDebugEnabled()) {
-        for (HookSite hookSite : hookSites) {
-          final Hook hook = hookSite.getHook();
-          String className = behavior.getDeclaringClass().getName();
-          if (tracePrefix != null && !className.startsWith(tracePrefix)) {
-            continue;
-          }
-
-          if (traceClass) {
-            logger.trace("hooked {}.{}{} on ({},{}) with {}",
-                className,
-                behavior.getName(),
-                behavior.getMethodInfo().getDescriptor(),
-                hook.getMethodEvent().getEventString(),
-                hook.getPosition(),
-                hook);
-          }
-        }
-      }
-      return true;
+      return Hook.apply(behavior, hookSites, traceClass);
 
     } catch (NoSourceAvailableException e) {
       Logger.println(e);
     }
 
-    return false;
+    return java.util.Collections.emptySet();
   }
 
   public List<HookSite> getHookSites(CtBehavior behavior) {
@@ -292,7 +269,7 @@ public byte[] transform(ClassLoader loader,
       try {
         ClassPool classPool = AppMapClassPool.get();
         if (traceClass) {
-          logger.debug("className: {}", className);
+          logger.trace("className: {}", className);
         }
 
         ctClass = classPool.makeClass(new ByteArrayInputStream(bytes));
@@ -317,7 +294,8 @@ public byte[] transform(ClassLoader loader,
         return null;
       }
 
-      boolean hookApplied = false;
+      boolean bytecodeModified = false;
+      boolean needsByteBuddy = false;
       for (CtBehavior behavior : ctClass.getDeclaredBehaviors()) {
         if (traceClass) {
           logger.trace("behavior: {}", behavior.getLongName());
@@ -331,24 +309,27 @@ public byte[] transform(ClassLoader loader,
         }
 
         methodsExamined++;
-        if (this.applyHooks(behavior)) {
-          hookApplied = true;
+        Set<Hook.ApplicationAction> actions = this.applyHooks(behavior, traceClass);
+        if (!actions.isEmpty()) {
+          bytecodeModified = true;
           methodsHooked++;
+          if (actions.contains(Hook.ApplicationAction.MARKED)) {
+            needsByteBuddy = true;
+          }
         }
       }
 
-      if (hookApplied) {
-        // One or more of the methods in the the class were marked as needing to
+      if (bytecodeModified) {
+        // One or more of the methods in the class were marked as needing to
         // be instrumented. Mark the class so the bytebuddy transformer will
         // know it needs to be instrumented.
-        ClassFile classFile = ctClass.getClassFile();
-        ConstPool constPool = classFile.getConstPool();
-        Annotation annot = new Annotation(AppMapInstrumented.class.getName(), constPool);
-        AnnotationUtil.setAnnotation(new AnnotatedClass(ctClass), annot);
-
-        if (traceClass) {
-          logger.trace("hooks applied to {}", className);
+        if (needsByteBuddy) {
+          ClassFile classFile = ctClass.getClassFile();
+          ConstPool constPool = classFile.getConstPool();
+          Annotation annot = new Annotation(AppMapInstrumented.class.getName(), constPool);
+          AnnotationUtil.setAnnotation(new AnnotatedClass(ctClass), annot);
         }
+
         if (logger.isDebugEnabled()) {
           packagesHooked.compute(ctClass.getPackageName(), (k, v) -> v == null ? 1 : v + 1);
         }