diff --git a/agent/src/main/java/com/appland/appmap/Agent.java b/agent/src/main/java/com/appland/appmap/Agent.java index 3de302b7..2aca22a0 100644 --- a/agent/src/main/java/com/appland/appmap/Agent.java +++ b/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); diff --git a/agent/src/main/java/com/appland/appmap/config/AppMapConfig.java b/agent/src/main/java/com/appland/appmap/config/AppMapConfig.java index 846d962a..cc49f313 100644 --- a/agent/src/main/java/com/appland/appmap/config/AppMapConfig.java +++ b/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(); } } diff --git a/agent/src/main/java/com/appland/appmap/output/v1/Parameters.java b/agent/src/main/java/com/appland/appmap/output/v1/Parameters.java index dd3779fa..be04629e 100644 --- a/agent/src/main/java/com/appland/appmap/output/v1/Parameters.java +++ b/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 { private static final TaggedLogger logger = AppMapConfig.getLogger(null); - private final ArrayList values = new ArrayList(); + private final ArrayList 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 The Java Virtual Machine Specification: The LocalVariableTable Attribute + */ + 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,26 +181,16 @@ 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; } } @@ -199,16 +198,12 @@ public Value get(String name) throws 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)); diff --git a/agent/src/main/java/com/appland/appmap/transform/ClassFileTransformer.java b/agent/src/main/java/com/appland/appmap/transform/ClassFileTransformer.java index 34764ffc..2a84a138 100644 --- a/agent/src/main/java/com/appland/appmap/transform/ClassFileTransformer.java +++ b/agent/src/main/java/com/appland/appmap/transform/ClassFileTransformer.java @@ -189,9 +189,7 @@ private void processClass(CtClass ctClass) { } } - private boolean applyHooks(CtBehavior behavior) { - boolean traceClass = tracePrefix == null || behavior.getDeclaringClass().getName().startsWith(tracePrefix); - + private Set applyHooks(CtBehavior behavior, boolean traceClass) { try { List hookSites = getHookSites(behavior); @@ -199,37 +197,16 @@ private boolean applyHooks(CtBehavior behavior) { 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 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 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); } diff --git a/agent/src/main/java/com/appland/appmap/transform/annotations/Hook.java b/agent/src/main/java/com/appland/appmap/transform/annotations/Hook.java index 3ff0e28e..5a695ef4 100644 --- a/agent/src/main/java/com/appland/appmap/transform/annotations/Hook.java +++ b/agent/src/main/java/com/appland/appmap/transform/annotations/Hook.java @@ -2,6 +2,7 @@ import java.util.Arrays; import java.util.Comparator; +import java.util.EnumSet; import java.util.HashSet; import java.util.List; import java.util.Map; @@ -73,7 +74,7 @@ public void buildParameters() { } public Parameters getRuntimeParameters(HookBinding binding) { - Parameters runtimeParameters = this.staticParameters.clone(); + Parameters runtimeParameters = this.staticParameters.freshCopy(); Stream.concat(Stream.of(this.sourceSystem), this.optionalSystems.stream()) .sorted(Comparator.comparingInt(ISystem::getParameterPriority)) .forEach(system -> { @@ -107,25 +108,72 @@ public HookSite prepare(CtBehavior targetBehavior, Map hookConte return new HookSite(this, behaviorOrdinal, binding); } - public static void apply(CtBehavior targetBehavior, List hookSites) { + public enum ApplicationAction { + MARKED, + INSTRUMENTED + } + + // We only log the first exception to avoid flooding the logs at the debug level. + // Note this variable is not thread safe, but this is okay; the worst that can happen is + // that we log more than one exception in a multi-threaded scenario. + private static boolean exceptionLogged = false; + + public static Set apply(CtBehavior targetBehavior, List hookSites, boolean traceClass) { + Set actions = EnumSet.noneOf(ApplicationAction.class); MethodInfo methodInfo = targetBehavior.getMethodInfo(); AnnotationsAttribute attr = (AnnotationsAttribute)methodInfo.getAttribute(AnnotationsAttribute.visibleTag); - // If the behavior is marked as an app method, update the annotation with - // the behavior ordinals so the bytebuddy transformer can instrument it. - if (attr.getAnnotation(AppMapAppMethod.class.getName()) != null) { - setBehaviorOrdinals(targetBehavior, hookSites); - } + if (attr != null) { + // If the behavior is marked as an app method, update the annotation with + // the behavior ordinals so the bytebuddy transformer can instrument it. + if (attr.getAnnotation(AppMapAppMethod.class.getName()) != null) { + setBehaviorOrdinals(targetBehavior, hookSites); + actions.add(ApplicationAction.MARKED); + if (traceClass) { + logger.debug("tracing {}.{}{}", + targetBehavior.getDeclaringClass().getName(), + targetBehavior.getName(), + targetBehavior.getMethodInfo().getDescriptor()); + } + } - // If it's (also) marked as an agent method, it needs to be instrumented - // by javassist. - if (attr.getAnnotation(AppMapAgentMethod.class.getName()) != null) { - instrument(targetBehavior, hookSites); + // If it's (also) marked as an agent method, it needs to be instrumented + // by javassist. + if (attr.getAnnotation(AppMapAgentMethod.class.getName()) != null) { + try { + instrument(targetBehavior, hookSites); + actions.add(ApplicationAction.INSTRUMENTED); + if (traceClass) { + String hooks = hookSites.stream() + .map(h -> h.getHook().toString()) + .collect(Collectors.joining(", ")); + logger.debug("{}.{}{} instrumented with hooks: {}", + targetBehavior.getDeclaringClass().getName(), + targetBehavior.getName(), + targetBehavior.getMethodInfo().getDescriptor(), + hooks); + } + } catch (CannotCompileException | NotFoundException e) { + String msg = String.format("failed to instrument %s.%s: %s", + targetBehavior.getDeclaringClass().getName(), targetBehavior.getName(), e.getMessage()); + if (!exceptionLogged) { + logger.debug(e, msg); + exceptionLogged = true; + } else { + // Log at trace level after the first one to avoid flooding the debug logs + logger.trace(e, msg); + logger.debug(msg); + } + } + } } + + return actions; } - public static void instrument(CtBehavior targetBehavior, List hookSites) { + public static void instrument(CtBehavior targetBehavior, List hookSites) + throws CannotCompileException, NotFoundException { final CtClass returnType = getReturnType(targetBehavior); final Boolean returnsVoid = (returnType == CtClass.voidType); @@ -150,44 +198,36 @@ public static void instrument(CtBehavior targetBehavior, List hookSite } - try { - String beforeSrcBlock = beforeSrcBlock(uniqueLocks.toString(), - invocations[MethodEvent.METHOD_INVOCATION.getIndex()]); - logger.trace("{}: beforeSrcBlock:\n{}", targetBehavior::getName, beforeSrcBlock::toString); - targetBehavior.insertBefore( - beforeSrcBlock); - - String afterSrcBlock = afterSrcBlock(invocations[MethodEvent.METHOD_RETURN.getIndex()]); - logger.trace("{}: afterSrcBlock:\n{}", targetBehavior::getName, afterSrcBlock::toString); - - targetBehavior.insertAfter( - afterSrcBlock); - - ClassPool cp = AppMapClassPool.get(); - String exitEarlyCatchSrc = "{com.appland.appmap.process.ThreadLock.current().exit();return;}"; - if (returnsVoid) { - targetBehavior.addCatch(exitEarlyCatchSrc, - cp.get("com.appland.appmap.process.ExitEarly")); - } else if (!returnType.isPrimitive()) { - exitEarlyCatchSrc = "{com.appland.appmap.process.ThreadLock.current().exit();return(" - + returnType.getName() + ")$e.getReturnValue();}"; - targetBehavior - .addCatch(exitEarlyCatchSrc, cp.get("com.appland.appmap.process.ExitEarly")); - } - logger.trace("{}: catch1Src:\n{}", targetBehavior::getName, exitEarlyCatchSrc::toString); - - String catchSrcBlock = catchSrcBlock(invocations[MethodEvent.METHOD_EXCEPTION.getIndex()]); - targetBehavior.addCatch( - catchSrcBlock, - cp.get("java.lang.Throwable")); - logger.trace("{}: catchSrcBlock:\n{}", targetBehavior::getName, catchSrcBlock::toString); - - } catch (CannotCompileException e) { - logger.debug(e, "failed to compile {}.{}", targetBehavior.getDeclaringClass().getName(), - targetBehavior.getName()); - } catch (NotFoundException e) { - logger.debug(e); + String beforeSrcBlock = beforeSrcBlock(uniqueLocks.toString(), + invocations[MethodEvent.METHOD_INVOCATION.getIndex()]); + logger.trace("{}: beforeSrcBlock:\n{}", targetBehavior::getName, beforeSrcBlock::toString); + targetBehavior.insertBefore( + beforeSrcBlock); + + String afterSrcBlock = afterSrcBlock(invocations[MethodEvent.METHOD_RETURN.getIndex()]); + logger.trace("{}: afterSrcBlock:\n{}", targetBehavior::getName, afterSrcBlock::toString); + + targetBehavior.insertAfter( + afterSrcBlock); + + ClassPool cp = AppMapClassPool.get(); + String exitEarlyCatchSrc = "{com.appland.appmap.process.ThreadLock.current().exit();return;}"; + if (returnsVoid) { + targetBehavior.addCatch(exitEarlyCatchSrc, + cp.get("com.appland.appmap.process.ExitEarly")); + } else if (!returnType.isPrimitive()) { + exitEarlyCatchSrc = "{com.appland.appmap.process.ThreadLock.current().exit();return(" + + returnType.getName() + ")$e.getReturnValue();}"; + targetBehavior + .addCatch(exitEarlyCatchSrc, cp.get("com.appland.appmap.process.ExitEarly")); } + logger.trace("{}: catch1Src:\n{}", targetBehavior::getName, exitEarlyCatchSrc::toString); + + String catchSrcBlock = catchSrcBlock(invocations[MethodEvent.METHOD_EXCEPTION.getIndex()]); + targetBehavior.addCatch( + catchSrcBlock, + cp.get("java.lang.Throwable")); + logger.trace("{}: catchSrcBlock:\n{}", targetBehavior::getName, catchSrcBlock::toString); } private static void setBehaviorOrdinals(CtBehavior behavior,