Add more trace prints to indicate when each Phase starts + re-word some info logs

src/launchwrapper/java/org/spongepowered/asm/service/mojang/MixinServiceLaunchWrapper.java

@@ -48,6 +48,7 @@
 import org.spongepowered.asm.launch.platform.container.ContainerHandleVirtual;
 import org.spongepowered.asm.launch.platform.container.IContainerHandle;
 import org.spongepowered.asm.logging.ILogger;
+import org.spongepowered.asm.logging.MethodLoggers;
 import org.spongepowered.asm.mixin.MixinEnvironment.CompatibilityLevel;
 import org.spongepowered.asm.mixin.MixinEnvironment.Phase;
 import org.spongepowered.asm.mixin.throwables.MixinException;
@@ -506,6 +507,7 @@ public byte[] getClassBytes(String className, boolean runTransformers) throws Cl
 
         Profiler profiler = Profiler.getProfiler("mixin");
         Section loadTime = profiler.begin(Profiler.ROOT, "class.load");
+        MethodLoggers.loggerAll.info("getClassBytes (and transform) {} aka {}", className, name);
         byte[] classBytes = this.getClassBytes(name, transformedName);
         loadTime.end();
 

src/main/java/org/spongepowered/asm/logging/MethodLoggers.java

@@ -0,0 +1,16 @@
+package org.spongepowered.asm.logging;
+
+import org.spongepowered.asm.service.MixinService;
+
+public class MethodLoggers {
+
+    public static final ILogger loggerCompat = MixinService.getService().getLogger("mixin.compat");
+
+    public static final ILogger loggerMeta = MixinService.getService().getLogger("mixin.meta");
+
+    public static final ILogger loggerProcessor = MixinService.getService().getLogger("mixin.processor");
+
+    public static final ILogger loggerAll = MixinService.getService().getLogger("mixin.all");
+
+    public static final ILogger loggerInjector = MixinService.getService().getLogger("mixin.injector");
+}

src/main/java/org/spongepowered/asm/mixin/MixinEnvironment.java

@@ -24,14 +24,7 @@
  */
 package org.spongepowered.asm.mixin;
 
-import java.util.ArrayList;
-import java.util.Collections;
-import java.util.HashMap;
-import java.util.HashSet;
-import java.util.List;
-import java.util.Locale;
-import java.util.Map;
-import java.util.Set;
+import java.util.*;
 
 import org.spongepowered.asm.logging.Level;
 import org.spongepowered.asm.logging.ILogger;
@@ -1033,7 +1026,7 @@ public void accept(Phase phase) {
     /**
      * Logger 
      */
-    private static final ILogger logger = MixinService.getService().getLogger("mixin");
+    public static final ILogger logger = MixinService.getService().getLogger("mixin");
 
     /**
      * Active transformer
@@ -1120,6 +1113,11 @@ private void printHeader(Object version) {
         String serviceName = this.service.getName();
         Side side = this.getSide();
         MixinEnvironment.logger.info("SpongePowered MIXIN Subsystem Version={} Source={} Service={} Env={}", version, codeSource, serviceName, side);
+        ArrayList<String> crap = new ArrayList();
+        for (int i = 0; i < options.length; i++) {
+            crap.add(Option.values()[i].name()+"="+options[i]);
+        }
+        MixinEnvironment.logger.info("Modes={} ", Arrays.toString(crap.toArray()));
 
         boolean verbose = this.getOption(Option.DEBUG_VERBOSE);
         if (verbose || this.getOption(Option.DEBUG_EXPORT) || this.getOption(Option.DEBUG_PROFILER)) {
@@ -1143,7 +1141,7 @@ private void printHeader(Object version) {
                 printer.kv(option.property, "%s<%s>", indent, option);
             }
             printer.hr().kv("Detected Side", side);
-            printer.print(System.err);
+            printer.print(System.out).log(MixinService.getService().getLogger("mixin"));
         }
     }
 
@@ -1357,6 +1355,7 @@ public boolean getOption(Option option) {
      * @param value New option value
      */
     public void setOption(Option option, boolean value) {
+        logger.info("option {} set {}", option, value);
         this.options[option.ordinal()] = value;
     }
 

src/main/java/org/spongepowered/asm/mixin/injection/callback/CallbackInjector.java

@@ -33,6 +33,8 @@
 import org.objectweb.asm.Opcodes;
 import org.objectweb.asm.Type;
 import org.objectweb.asm.tree.*;
+import org.spongepowered.asm.logging.MethodLoggers;
+import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.mixin.injection.Coerce;
 import org.spongepowered.asm.mixin.injection.Inject;
 import org.spongepowered.asm.mixin.injection.InjectionPoint;
@@ -227,7 +229,10 @@ private class Callback extends InsnList {
                     break;
                 }
             }
-            Injector.logger.debug("{} does{} use it's CallbackInfo{}", info, seenCallbackInfoUse ? "" : "n't", Type.VOID_TYPE == target.returnType ? "" : "Returnable");
+            MethodLoggers.loggerInjector.debug("callback {} from {}",
+                    seenCallbackInfoUse ? "USED" : "NOT USED",
+                    info,
+                    Type.VOID_TYPE == target.returnType ? "" : "Returnable");
             if (!seenCallbackInfoUse && !Bytecode.isStatic(handler) && (handler.access & Opcodes.ACC_FINAL) == 0 && (target.classNode.access & Opcodes.ACC_FINAL) == 0) {
                 //Although the CallbackInfo appears unused, there is the possibility that the handler is overridden, so we'll have to check
                 String handlerName = handler instanceof MethodNodeEx ? ((MethodNodeEx) handler).getOriginalName() : handler.name;
@@ -243,7 +248,7 @@ private class Callback extends InsnList {
                     }
                 }
 
-                Injector.logger.debug("{} w{} be passed a CallbackInfo{} as a result", info, seenCallbackInfoUse ? "ill" : "on't", Type.VOID_TYPE == target.returnType ? "" : "Returnable");
+                MethodLoggers.loggerInjector.debug("{} w{} be passed a CallbackInfo{} as a result", info, seenCallbackInfoUse ? "ill" : "on't", Type.VOID_TYPE == target.returnType ? "" : "Returnable");
             }
             usesCallbackInfo = seenCallbackInfoUse;
         }
@@ -659,7 +664,7 @@ private void printLocals(final Callback callback) {
         }
         printer.add().add("/**").add(" * Expected callback signature").add(" * /");
         printer.add("%s {", handlerSig);
-        printer.add("    // Method body").add("}").add().print(System.err);
+        printer.add("    // Method body").add("}").add().print(System.err).log(MixinEnvironment.logger);
     }
 
     /**

src/main/java/org/spongepowered/asm/mixin/injection/code/Injector.java

@@ -166,7 +166,7 @@ public String toString() {
     /**
      * Log more things
      */
-    protected static final ILogger logger = MixinService.getService().getLogger("mixin");
+    protected static final ILogger logger = MixinService.getService().getLogger("mixin.injector");
 
     /**
      * Injection info

src/main/java/org/spongepowered/asm/mixin/injection/modify/ModifyVariableInjector.java

@@ -33,6 +33,7 @@
 import org.objectweb.asm.tree.InsnList;
 import org.objectweb.asm.tree.MethodNode;
 import org.objectweb.asm.tree.VarInsnNode;
+import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.mixin.injection.InjectionPoint;
 import org.spongepowered.asm.mixin.injection.InjectionPoint.RestrictTargetLevel;
 import org.spongepowered.asm.mixin.injection.ModifyVariable;
@@ -243,7 +244,7 @@ private void printLocals(Target target, Context context) {
             .kv("Match name(s)", this.discriminator.hasNames() ? this.discriminator.getNames() : "any")
             .kv("Args only", this.discriminator.isArgsOnly()).hr()
             .add(context)
-            .print(System.err);
+            .print(System.err).log(MixinEnvironment.logger);
     }
 
     /**

src/main/java/org/spongepowered/asm/mixin/injection/selectors/dynamic/DescriptorResolver.java

@@ -33,6 +33,7 @@
 import org.objectweb.asm.Type;
 import org.objectweb.asm.tree.ClassNode;
 import org.objectweb.asm.tree.MethodNode;
+import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.mixin.injection.Desc;
 import org.spongepowered.asm.mixin.injection.Descriptors;
 import org.spongepowered.asm.mixin.injection.selectors.ISelectorContext;
@@ -250,7 +251,7 @@ public void visit(String coordinate, Object element, String detail) {
 
         @Override
         public void postResolve() {
-            this.printer.print();
+            this.printer.print().log(MixinEnvironment.logger);
         }
 
     }        

src/main/java/org/spongepowered/asm/mixin/transformer/ClassInfo.java

@@ -45,6 +45,7 @@
 import org.objectweb.asm.tree.InnerClassNode;
 import org.objectweb.asm.tree.MethodInsnNode;
 import org.objectweb.asm.tree.MethodNode;
+import org.spongepowered.asm.logging.MethodLoggers;
 import org.spongepowered.asm.mixin.Final;
 import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.mixin.Mutable;
@@ -2029,7 +2030,7 @@ public static ClassInfo forName(String className) {
 
             // Put null in the cache if load failed
             ClassInfo.cache.put(className, info);
-            ClassInfo.logger.trace("Added class metadata for {} to metadata cache", className);
+            MethodLoggers.loggerMeta.trace("Added class metadata for {} to metadata cache", className);
         }
 
         return info;

src/main/java/org/spongepowered/asm/mixin/transformer/MixinApplicatorStandard.java

@@ -35,6 +35,7 @@
 import org.objectweb.asm.signature.SignatureReader;
 import org.objectweb.asm.signature.SignatureVisitor;
 import org.objectweb.asm.tree.*;
+import org.spongepowered.asm.logging.MethodLoggers;
 import org.spongepowered.asm.mixin.Final;
 import org.spongepowered.asm.mixin.Intrinsic;
 import org.spongepowered.asm.mixin.MixinEnvironment;
@@ -288,7 +289,7 @@ final void apply(SortedSet<MixinInfo> mixins) {
         for (Iterator<MixinInfo> iter = mixins.iterator(); iter.hasNext();) {
             MixinInfo mixin = iter.next();
             try {
-                this.logger.log(mixin.getLoggingLevel(), "Mixing {} from {} into {}", mixin.getName(), mixin.getParent(), this.targetName);
+                MethodLoggers.loggerProcessor.log(mixin.getLoggingLevel(), "Mixing {} from {} into {}", mixin.getName(), mixin.getParent(), this.targetName);
                 mixinContexts.add(mixin.createContextFor(this.context));
                 if (this.auditTrail != null) {
                     this.auditTrail.onApply(this.targetName, mixin.toString());

src/main/java/org/spongepowered/asm/mixin/transformer/MixinConfig.java

@@ -36,6 +36,7 @@
 import org.spongepowered.asm.launch.MixinInitialisationError;
 import org.objectweb.asm.tree.ClassNode;
 import org.objectweb.asm.tree.InsnList;
+import org.spongepowered.asm.logging.MethodLoggers;
 import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.mixin.MixinEnvironment.CompatibilityLevel;
 import org.spongepowered.asm.mixin.MixinEnvironment.Option;
@@ -578,7 +579,7 @@ void checkCompatibilityLevel(MixinInfo mixin, int majorVersion, int minorVersion
         String message = majorVersion > CompatibilityLevel.MAX_SUPPORTED.getClassMajorVersion()
                 ? "the current version of Mixin" : "the declared compatibility level";
         this.warnedClassVersion = majorVersion;
-        this.logger.log(logLevel, "{}: Class version {} required is higher than the class version supported by {} ({} supports class version {})",
+        MethodLoggers.loggerCompat.log(logLevel, "{}: Class version {} required is higher than the class version supported by {} ({} supports class version {})",
                 mixin, majorVersion, message, this.compatibilityLevel, this.compatibilityLevel.getClassMajorVersion());
     }
 

src/main/java/org/spongepowered/asm/mixin/transformer/MixinPreProcessorStandard.java

@@ -129,7 +129,7 @@ public String toString() {
     /**
      * Logger
      */
-    private static final ILogger logger = MixinService.getService().getLogger("mixin");
+    private static final ILogger logger = MixinService.getService().getLogger("mixin.processor");
 
     /**
      * The mixin

src/main/java/org/spongepowered/asm/mixin/transformer/MixinProcessor.java

@@ -31,6 +31,7 @@
 import org.spongepowered.asm.logging.ILogger;
 import org.objectweb.asm.tree.AnnotationNode;
 import org.objectweb.asm.tree.ClassNode;
+import org.spongepowered.asm.logging.MethodLoggers;
 import org.spongepowered.asm.mixin.Mixin;
 import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.mixin.MixinEnvironment.Option;
@@ -488,6 +489,7 @@ private void select(MixinEnvironment environment) {
      * @param environment Environment to query
      */
     private void selectConfigs(MixinEnvironment environment) {
+        MixinProcessor.logger.info("Selecting config of {} configs", Mixins.getConfigs().size());
         for (Iterator<Config> iter = Mixins.getConfigs().iterator(); iter.hasNext();) {
             Config handle = iter.next();
             try {
@@ -514,7 +516,8 @@ private void selectConfigs(MixinEnvironment environment) {
      */
     private int prepareConfigs(MixinEnvironment environment, Extensions extensions) {
         int totalMixins = 0;
-
+
+        MixinProcessor.logger.info("Begin adding {} coprocessors to {} pendingConfigs", coprocessors.size(), pendingConfigs.size());
         final IHotSwap hotSwapper = this.hotSwapper;
         for (MixinConfig config : this.pendingConfigs) {
             for (MixinCoprocessor coprocessor : this.coprocessors) {
@@ -533,10 +536,11 @@ public void onInit(MixinInfo mixin) {
                 });
             }
         }
-
+
+        MixinProcessor.logger.info("Begin pendingConfigs preparing: total {}", pendingConfigs.size());
         for (MixinConfig config : this.pendingConfigs) {
             try {
-                MixinProcessor.logger.log(this.verboseLoggingLevel, "Preparing {} ({})", config, config.getDeclaredMixinCount());
+                MethodLoggers.loggerProcessor.log(this.verboseLoggingLevel, "Preparing {} ({})", config, config.getDeclaredMixinCount());
                 config.prepare(extensions);
                 totalMixins += config.getMixinCount();
             } catch (InvalidMixinException ex) {
@@ -546,7 +550,8 @@ public void onInit(MixinInfo mixin) {
                 MixinProcessor.logger.error("Error encountered whilst initialising mixin config '" + config.getName() + "' from mod '"+org.spongepowered.asm.mixin.FabricUtil.getModId(config)+"': " + message, ex);
             }
         }
-
+
+        MixinProcessor.logger.info("Begin scanning other targets of {} pendingConfigs", pendingConfigs.size());
         for (MixinConfig config : this.pendingConfigs) {
             IMixinConfigPlugin plugin = config.getPlugin();
             if (plugin == null) {
@@ -563,6 +568,7 @@ public void onInit(MixinInfo mixin) {
             plugin.acceptTargets(config.getTargetsSet(), Collections.<String>unmodifiableSet(otherTargets));
         }
 
+        MixinProcessor.logger.info("Begin postInitialise pendingConfigs: total {}", pendingConfigs.size());
         for (MixinConfig config : this.pendingConfigs) {
             try {
                 config.postInitialise(this.extensions);
@@ -573,11 +579,12 @@ public void onInit(MixinInfo mixin) {
                 MixinProcessor.logger.error("Error encountered during mixin config postInit step '" + config.getName() + "' from mod '"+org.spongepowered.asm.mixin.FabricUtil.getModId(config)+ "': " + message, ex);
             }
         }
-
+
+        MixinProcessor.logger.info("Begin sorting pendingConfigs: total {}", pendingConfigs.size());
         this.configs.addAll(this.pendingConfigs);
         Collections.sort(this.configs);
         this.pendingConfigs.clear();
-
+        MixinProcessor.logger.info("Mixin prepare complete for total {}", configs.size());
         return totalMixins;
     }
 

src/main/java/org/spongepowered/asm/mixin/transformer/ext/Extensions.java

@@ -31,17 +31,20 @@
 import java.util.Map;
 
 import org.objectweb.asm.tree.ClassNode;
+import org.spongepowered.asm.logging.ILogger;
 import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.service.ISyntheticClassRegistry;
 
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableList.Builder;
+import org.spongepowered.asm.service.MixinService;
 
 /**
  * Mixin transformer extensions and common modules such as class generators
  */
 public final class Extensions implements IExtensionRegistry {
-
+
+    static final ILogger logger = MixinService.getService().getLogger("mixin");
     /**
      * All transformer extensions
      */
@@ -136,7 +139,7 @@ public ISyntheticClassRegistry getSyntheticClassRegistry() {
      */
     public void select(MixinEnvironment environment) {
         Builder<IExtension> activeExtensions = ImmutableList.<IExtension>builder();
-
+        MixinEnvironment.logger.info("Selecting extensions: total {}", extensions.size());
         for (IExtension extension : this.extensions) {
             if (extension.checkActive(environment)) {
                 activeExtensions.add(extension);

src/main/java/org/spongepowered/asm/mixin/transformer/ext/extensions/ExtensionCheckInterfaces.java

@@ -202,7 +202,7 @@ public void postApply(ITargetClassContext context) {
 
         if (missingMethodCount > 0) {
             printer.hr().add("%82s%s: %d", "", "Total unimplemented", missingMethodCount);
-            printer.print(System.err);
+            printer.print(System.err).log(MixinEnvironment.logger);
             this.appendToTextReport(printer);
         }
     }
@@ -231,7 +231,7 @@ private void appendToTextReport(PrettyPrinter printer) {
             fos = new FileOutputStream(this.report, true);
             PrintStream stream = new PrintStream(fos);
             stream.print("\n");
-            printer.print(stream);
+            printer.print(stream).log(MixinEnvironment.logger);
         } catch (Exception ex) {
             // never mind
         } finally {

src/main/java/org/spongepowered/asm/util/PrettyPrinter.java

@@ -34,6 +34,7 @@
 
 import org.spongepowered.asm.logging.ILogger;
 import org.spongepowered.asm.logging.Level;
+import org.spongepowered.asm.mixin.MixinEnvironment;
 import org.spongepowered.asm.service.MixinService;
 
 import com.google.common.base.Strings;
@@ -1177,7 +1178,7 @@ private static String getDefaultLoggerName() {
      * prints to stderr in pretty-printed format.
      */
     public static void dumpStack() {
-        new PrettyPrinter().add(new Exception("Stack trace")).print(System.err);
+        new PrettyPrinter().add(new Exception("Stack trace")).print(System.err).log(MixinEnvironment.logger);
     }
 
     /**
@@ -1186,7 +1187,7 @@ public static void dumpStack() {
      * @param th Throwable to log
      */
     public static void print(Throwable th) {
-        new PrettyPrinter().add(th).print(System.err);
+        new PrettyPrinter().add(th).print(System.err).log(MixinEnvironment.logger);
     }
 
 }