LaunchWrapper outputs a mile of error messages when legacy.debugClassLoading is enabled for WindowsAnsiOutputStream

[Pokechu22]

(n.b. the "mile" part isn't an exaggeration -- the output is 282602 lines long, and assuming 4 lines per inch, we have 5888 feet or 1.115 miles)

If legacy.debugClassLoading is enabled, a HUGE number of errors are output. This makes it very hard to use to actually find real errors. Here's my log: outlong.zip

The class that is failing is org.fusesource.jansi.WindowsAnsiOutputStream, and when it fails, it generated a VERY long error:

    17:44:12.235 [Test worker] ERROR LaunchWrapper - Exception encountered attempting classloading of org.fusesource.jansi.WindowsAnsiOutputStream
    java.lang.StackOverflowError: null
    	at java.lang.ClassLoader.defineClass1(Native Method) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.defineClass(ClassLoader.java:763) ~[?:1.8.0_131]
    	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142) ~[?:1.8.0_131]
    	at java.net.URLClassLoader.defineClass(URLClassLoader.java:467) ~[?:1.8.0_131]
    	at java.net.URLClassLoader.access$100(URLClassLoader.java:73) ~[?:1.8.0_131]
    	at java.net.URLClassLoader$1.run(URLClassLoader.java:368) ~[?:1.8.0_131]
    	at java.net.URLClassLoader$1.run(URLClassLoader.java:362) ~[?:1.8.0_131]
    	at java.security.AccessController.doPrivileged(Native Method) ~[?:1.8.0_131]
    	at java.net.URLClassLoader.findClass(URLClassLoader.java:361) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[?:1.8.0_131]
    	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:335) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.defineClass1(Native Method) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.defineClass(ClassLoader.java:763) ~[?:1.8.0_131]
    	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142) ~[?:1.8.0_131]
    	at java.net.URLClassLoader.defineClass(URLClassLoader.java:467) ~[?:1.8.0_131]
    	at java.net.URLClassLoader.access$100(URLClassLoader.java:73) ~[?:1.8.0_131]
    	at java.net.URLClassLoader$1.run(URLClassLoader.java:368) ~[?:1.8.0_131]
    	at java.net.URLClassLoader$1.run(URLClassLoader.java:362) ~[?:1.8.0_131]
    	at java.security.AccessController.doPrivileged(Native Method) ~[?:1.8.0_131]
    	at java.net.URLClassLoader.findClass(URLClassLoader.java:361) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[?:1.8.0_131]
    	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:335) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:1.8.0_131]
    	at java.lang.Class.forName0(Native Method) ~[?:1.8.0_131]
    	at java.lang.Class.forName(Class.java:348) ~[?:1.8.0_131]
    	at sun.reflect.generics.factory.CoreReflectionFactory.makeNamedType(CoreReflectionFactory.java:114) ~[?:1.8.0_131]
    	at sun.reflect.generics.visitor.Reifier.visitClassTypeSignature(Reifier.java:125) ~[?:1.8.0_131]
    	at sun.reflect.generics.tree.ClassTypeSignature.accept(ClassTypeSignature.java:49) ~[?:1.8.0_131]
    	at sun.reflect.annotation.AnnotationParser.parseSig(AnnotationParser.java:439) ~[?:1.8.0_131]
    	at sun.reflect.annotation.AnnotationParser.parseClassValue(AnnotationParser.java:420) ~[?:1.8.0_131]
    	at sun.reflect.annotation.AnnotationParser.parseMemberValue(AnnotationParser.java:349) ~[?:1.8.0_131]
    	at sun.reflect.annotation.AnnotationParser.parseAnnotation2(AnnotationParser.java:286) ~[?:1.8.0_131]
    	at sun.reflect.annotation.AnnotationParser.parseAnnotations2(AnnotationParser.java:120) ~[?:1.8.0_131]
    	at sun.reflect.annotation.AnnotationParser.parseAnnotations(AnnotationParser.java:72) ~[?:1.8.0_131]
    	at java.lang.Class.createAnnotationData(Class.java:3521) ~[?:1.8.0_131]
    	at java.lang.Class.annotationData(Class.java:3510) ~[?:1.8.0_131]
    	at java.lang.Class.getAnnotation(Class.java:3415) ~[?:1.8.0_131]
    	at org.apache.logging.log4j.core.config.plugins.visitors.PluginVisitors.findVisitor(PluginVisitors.java:45) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.injectFields(PluginBuilder.java:171) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:121) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:952) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:892) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:884) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:884) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:508) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:232) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:244) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:545) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:617) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:634) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:229) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:242) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174) ~[log4j-api-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:618) ~[log4j-api-2.8.1.jar:2.8.1]
    	at net.minecraft.launchwrapper.LogWrapper.configureLogging(LogWrapper.java:14) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LogWrapper.log(LogWrapper.java:28) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LogWrapper.finest(LogWrapper.java:66) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LaunchClassLoader.getClassBytes(LaunchClassLoader.java:360) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LaunchClassLoader.findClass(LaunchClassLoader.java:170) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:1.8.0_131]
    	at org.apache.logging.log4j.util.LoaderUtil.loadClass(LoaderUtil.java:139) ~[log4j-api-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.appender.ConsoleAppender.getOutputStream(ConsoleAppender.java:261) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.appender.ConsoleAppender.getDefaultManager(ConsoleAppender.java:226) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.appender.ConsoleAppender.createDefaultAppenderForLayout(ConsoleAppender.java:172) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.AbstractConfiguration.setToDefault(AbstractConfiguration.java:581) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.config.DefaultConfiguration.<init>(DefaultConfiguration.java:47) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.LoggerContext.<init>(LoggerContext.java:86) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.createContext(ClassLoaderContextSelector.java:171) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:145) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:74) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:227) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45) ~[log4j-core-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174) ~[log4j-api-2.8.1.jar:2.8.1]
    	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:618) ~[log4j-api-2.8.1.jar:2.8.1]
    	at net.minecraft.launchwrapper.LogWrapper.configureLogging(LogWrapper.java:14) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LogWrapper.log(LogWrapper.java:28) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LogWrapper.finest(LogWrapper.java:66) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LaunchClassLoader.getClassBytes(LaunchClassLoader.java:360) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at net.minecraft.launchwrapper.LaunchClassLoader.findClass(LaunchClassLoader.java:170) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[?:1.8.0_131]
    	at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:1.8.0_131]
... skipping several hundred lines ...
        at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[?:1.8.0_131]
        at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:1.8.0_131]
        at org.apache.logging.log4j.util.LoaderUtil.loadClass(LoaderUtil.java:139) ~[log4j-api-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.appender.ConsoleAppender.getOutputStream(ConsoleAppender.java:261) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.appender.ConsoleAppender.getDefaultManager(ConsoleAppender.java:226) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.appender.ConsoleAppender.createDefaultAppenderForLayout(ConsoleAppender.java:172) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.config.AbstractConfiguration.setToDefault(AbstractConfiguration.java:581) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.config.DefaultConfiguration.<init>(DefaultConfiguration.java:47) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.LoggerContext.<init>(LoggerContext.java:86) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.createContext(ClassLoaderContextSelector.java:171) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:145) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:74) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:227) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45) ~[log4j-core-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174) ~[log4j-api-2.8.1.jar:2.8.1]
        at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:618) ~[log4j-api-2.8.1.jar:2.8.1]
        at net.minecraft.launchwrapper.LogWrapper.configureLogging(LogWrapper.java:14) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]
        at net.minecraft.launchwrapper.LogWrapper.log(LogWrapper.java:28) ~[launchwrapper-1.13-SNAPSHOT-with16.jar:?]

The following ones are all NullPointerExceptions, but I'm not sure whether it's actually an NPE or just a stack overflow in disguise. They're for the same class, though.

Granted, these issues do not happen when the property is disabled. However, I still think 30 megabytes of error message is a bit excessive, even if the user normally cannot see it. Also, these errors probably negatively impact start times (although they aren't logged, they still happen).

These errors do go away if the system property log4j.skipJansi is set to true (mentioned on https://stackoverflow.com/a/29879464/3991344).

It's worth noting that these errors are not captured into the game output log — but that's to be expected, as it's while log4j is loading. In this case I captured it using my test case from here with systemProperty 'legacy.debugClassLoading', 'true' in the test block of the buildscript and ./gradlew test --info, but it can also happen in the actual launcher with -Dlegacy.debugClassLoading=true. As a second note, this is with the fix from #16; otherwise the actual class is obscured.

[thiakil]

Assuming by your mention of the PR that you're using a custom compiled version, have you tried adding org.fusesource.jansi to addClassLoaderExclusion in the LaunchClassLoader constructor?

[Pokechu22]

That does seem to solve it (I added addClassLoaderExclusion("org.fusesource.jansi."); to it).

[Hallowizer]

Can you send the full mile? I thought I found something useful but it was cut off by your “skipping several hundred lines”.

[Pokechu22]

It should be in the outlong.zip I linked before the bit, but I'm not 100% sure (it's been a while).

[Hallowizer]

I found the problem, I will fix it soon.

[thiakil]

What problem? the "mile long" log is caused by it trying to classload a Log4J related class through the LaunchClassLoader while its trying to use it itself, which just won't work. The fix for it is commented in this thread & linked via a commit on a branch