Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Class loading is broken with Spring Boot's DevTools again. #396

Closed
michael-simons opened this issue Jan 6, 2020 · 17 comments
Closed

Class loading is broken with Spring Boot's DevTools again. #396

michael-simons opened this issue Jan 6, 2020 · 17 comments

Comments

@michael-simons
Copy link
Contributor

michael-simons commented Jan 6, 2020

Hello Luke,

Sadly #331 introduced a regression of #267.

That became apparent in a change of Neo4j-OGM where we now rely on ClassGraph being able to find scanned classes.

Find attached a reproducer:

try(ScanResult r = new ClassGraph()
			.ignoreClassVisibility()
			.whitelistPackages("com.example.gh729.domain")
			.scan()) {

			for(ClassInfo classInfo : r.getAllClasses()) {
				if("com.example.gh729.domain.SomeClass".equals(classInfo.getName())) {
					SomeClass f = (SomeClass) classInfo.loadClass().getConstructor().newInstance();
				}
			}
		}

This works in 4.8.17 and starts to fail in 4.8.19 again (as before my contribution).

This is the expected order of class loaders withorg.springframework.boot.devtools.restart.classloader.RestartClassLoader present

image

This is now what I get in 4.8.19+

image

Both screenshots from debugging into io.github.classgraph.ClassGraphClassLoader and displaying the order of class loaders used.

Find the reproducer attached. Open in your IDE and run Gh729Application.

gh729.zip

Related OGM ticket is neo4j/neo4j-ogm#729

@lukehutch
Copy link
Member

Hi Michael,

#331 is about shutdown hooks, and ClassGraph doesn't use those anymore. It's that the issue you meant to link?

I don't use or really know anything about Spring, and I'm currently traveling internationally. Do you know how to solve the issue, or would you be able to dig into it please?

@michael-simons
Copy link
Contributor Author

Yes, this is the correct issue. Things break between 4.8.17 and 4.8.19 (4.8.18 seems not to be available in Maven central). You even address the original issue here #331 (comment)

That's not that much about Spring to know, the order of class loaders is wrong again after some commit between 4.8.17 and 4.8.19.

I cannot fix this myself, but we can only work around in OGM by not using the class loading mechanism of ClassGraph, which is kinda sad.

@lukehutch
Copy link
Member

It doesn't look like just a delegation issue, since RestartClassLoader is not even present in the second case. What do the ClassGraph verbose logs say is happening with RestartClassLoader?

@michael-simons
Copy link
Contributor Author

The restart class loader is used by the application. We have been there before. The parent last mechanism doesn't seem to work at all anymore… ClassGraph recognises the RestartClassLoader of Spring Boot but does handles it's parents first now.

Here are some excerpt from the verbose output I think are relevant:

2020-01-07T08:54:06.773+0100	ClassGraph	Operating system: Mac OS X 10.15.2 x86_64
2020-01-07T08:54:06.773+0100	ClassGraph	Java version: 1.8.0_192 / 1.8.0_192-b12 (Oracle Corporation)
2020-01-07T08:54:06.773+0100	ClassGraph	Java home: /Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre
2020-01-07T08:54:06.776+0100	ClassGraph	JRE rt.jar:
2020-01-07T08:54:06.776+0100	ClassGraph	-- /Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/rt.jar
2020-01-07T08:54:06.779+0100	ClassGraph	ScanSpec:
2020-01-07T08:54:06.779+0100	ClassGraph	-- packageWhiteBlackList: whitelist: ["com.example.gh729.domain"]; whitelistPrefixes: ["", "/", "com.", "com.example.", "com.example.gh729.", "com.example.gh729.domain."]
2020-01-07T08:54:06.780+0100	ClassGraph	-- packagePrefixWhiteBlackList: whitelistPrefixes: ["com.example.gh729.domain."]
2020-01-07T08:54:06.780+0100	ClassGraph	-- pathWhiteBlackList: whitelist: ["com/example/gh729/domain/"]; whitelistPrefixes: ["", "/", "com/", "com/example/", "com/example/gh729/", "com/example/gh729/domain/"]
2020-01-07T08:54:06.780+0100	ClassGraph	-- pathPrefixWhiteBlackList: whitelistPrefixes: ["com/example/gh729/domain/"]
2020-01-07T08:54:06.780+0100	ClassGraph	-- classWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- classfilePathWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- classPackageWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- classPackagePathWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- moduleWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- jarWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- classpathElementResourcePathWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- libOrExtJarWhiteBlackList: 
2020-01-07T08:54:06.780+0100	ClassGraph	-- performScan: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- scanJars: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- scanNestedJars: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- scanDirs: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- scanModules: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableClassInfo: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableFieldInfo: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableMethodInfo: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableAnnotationInfo: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableStaticFinalFieldConstantInitializerValues: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableInterClassDependencies: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableExternalClasses: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- enableSystemJarsAndModules: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- ignoreClassVisibility: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- ignoreFieldVisibility: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- ignoreMethodVisibility: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- disableRuntimeInvisibleAnnotations: false
2020-01-07T08:54:06.781+0100	ClassGraph	-- extendScanningUpwardsToExternalClasses: true
2020-01-07T08:54:06.781+0100	ClassGraph	-- allowedURLSchemes: null
2020-01-07T08:54:06.781+0100	ClassGraph	-- addedClassLoaders: null
2020-01-07T08:54:06.782+0100	ClassGraph	-- overrideClassLoaders: null
2020-01-07T08:54:06.782+0100	ClassGraph	-- addedModuleLayers: null
2020-01-07T08:54:06.782+0100	ClassGraph	-- overrideModuleLayers: null
2020-01-07T08:54:06.782+0100	ClassGraph	-- overrideClasspath: null
2020-01-07T08:54:06.782+0100	ClassGraph	-- classpathElementFilters: null
2020-01-07T08:54:06.782+0100	ClassGraph	-- initializeLoadedClasses: false
2020-01-07T08:54:06.782+0100	ClassGraph	-- removeTemporaryFilesAfterScan: false
2020-01-07T08:54:06.782+0100	ClassGraph	-- ignoreParentClassLoaders: false
2020-01-07T08:54:06.782+0100	ClassGraph	-- ignoreParentModuleLayers: false
2020-01-07T08:54:06.782+0100	ClassGraph	-- modulePathInfo: 
2020-01-07T08:54:06.782+0100	ClassGraph	Number of worker threads: 8
2020-01-07T08:54:06.787+0100	ClassGraph	Finding classpath
2020-01-07T08:54:06.788+0100	ClassGraph	-- Finding classpath and modules
2020-01-07T08:54:06.790+0100	ClassGraph	---- Found ClassLoaders:
2020-01-07T08:54:06.790+0100	ClassGraph	------ org.springframework.boot.devtools.restart.classloader.RestartClassLoader
2020-01-07T08:54:06.790+0100	ClassGraph	------ sun.misc.Launcher$AppClassLoader
2020-01-07T08:54:06.791+0100	ClassGraph	---- System jars:
// in full log
2020-01-07T08:54:06.792+0100	ClassGraph	---- ClassLoaderHandlers:
2020-01-07T08:54:06.796+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.AntClassLoaderHandler
2020-01-07T08:54:06.796+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.EquinoxClassLoaderHandler
2020-01-07T08:54:06.796+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.EquinoxContextFinderClassLoaderHandler
2020-01-07T08:54:06.796+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.FelixClassLoaderHandler
2020-01-07T08:54:06.796+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.JBossClassLoaderHandler
2020-01-07T08:54:06.796+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.WeblogicClassLoaderHandler
2020-01-07T08:54:06.796+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.WebsphereLibertyClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.WebsphereTraditionalClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.OSGiDefaultClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.SpringBootRestartClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.TomcatWebappClassLoaderBaseHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.PlexusClassWorldsClassRealmClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.ParentLastDelegationOrderTestClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.JPMSClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	------ nonapi.io.github.classgraph.classloaderhandler.URLClassLoaderHandler
2020-01-07T08:54:06.797+0100	ClassGraph	---- Finding unique classloaders in delegation order
2020-01-07T08:54:06.798+0100	ClassGraph	---- Obtaining URLs from classloaders in delegation order
2020-01-07T08:54:06.798+0100	ClassGraph	------ Classloader sun.misc.Launcher$ExtClassLoader@19e1023e is handled by nonapi.io.github.classgraph.classloaderhandler.URLClassLoaderHandler
2020-01-07T08:54:06.798+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/sunec.jar
2020-01-07T08:54:06.798+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/nashorn.jar
2020-01-07T08:54:06.798+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/cldrdata.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/jfxrt.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/dnsns.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/localedata.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/jaccess.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/zipfs.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/System/Library/Java/Extensions/MRJToolkit.jar
2020-01-07T08:54:06.799+0100	ClassGraph	------ Classloader sun.misc.Launcher$AppClassLoader@18b4aac2 is handled by nonapi.io.github.classgraph.classloaderhandler.URLClassLoaderHandler
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/charsets.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Found classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/deploy.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/cldrdata.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/dnsns.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/jaccess.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/jfxrt.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/localedata.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/nashorn.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/sunec.jar
2020-01-07T08:54:06.799+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar
2020-01-07T08:54:06.800+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar
2020-01-07T08:54:06.800+0100	ClassGraph	-------- Ignoring duplicate classpath element: file:/Library/Java/JavaVirtualMachines/jdk1.8.0_192.jdk/Contents/Home/jre/lib/ext/zipfs.jar
// No more entries of class loaders

verbose-log.txt

@lukehutch
Copy link
Member

I tried your example project. Your SomeClass f loads fine:

com.example.gh729.domain.SomeClass@5fb09678

Any ideas as to why it works for me but not for you?

@lukehutch
Copy link
Member

@michael-simons I took a stab in the dark and guessed that maybe in your case, one of the context classloaders is the same as the restart classloader's parent. Please test the above change -- fingers crossed it will fix the issue.

@michael-simons
Copy link
Contributor Author

See the pom, I attached a version that worked. You have to change it to something >= 4.8.19

Than run with ./mvnw spring-boot:run. Fails immediate.

@michael-simons
Copy link
Contributor Author

Still fails with your patch.

[INFO] 
[INFO] -------------------------< com.example:gh729 >--------------------------
[INFO] Building gh729 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO] 
[INFO] --- maven-dependency-plugin:3.1.1:tree (default-cli) @ gh729 ---
[INFO] com.example:gh729:jar:0.0.1-SNAPSHOT
[INFO] +- org.springframework.boot:spring-boot-starter:jar:2.2.2.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot:jar:2.2.2.RELEASE:compile
[INFO] |  |  \- org.springframework:spring-context:jar:5.2.2.RELEASE:compile
[INFO] |  |     +- org.springframework:spring-aop:jar:5.2.2.RELEASE:compile
[INFO] |  |     +- org.springframework:spring-beans:jar:5.2.2.RELEASE:compile
[INFO] |  |     \- org.springframework:spring-expression:jar:5.2.2.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot-autoconfigure:jar:2.2.2.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.2.2.RELEASE:compile
[INFO] |  |  +- ch.qos.logback:logback-classic:jar:1.2.3:compile
[INFO] |  |  |  +- ch.qos.logback:logback-core:jar:1.2.3:compile
[INFO] |  |  |  \- org.slf4j:slf4j-api:jar:1.7.29:compile
[INFO] |  |  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.12.1:compile
[INFO] |  |  |  \- org.apache.logging.log4j:log4j-api:jar:2.12.1:compile
[INFO] |  |  \- org.slf4j:jul-to-slf4j:jar:1.7.29:compile
[INFO] |  +- jakarta.annotation:jakarta.annotation-api:jar:1.3.5:compile
[INFO] |  +- org.springframework:spring-core:jar:5.2.2.RELEASE:compile
[INFO] |  |  \- org.springframework:spring-jcl:jar:5.2.2.RELEASE:compile
[INFO] |  \- org.yaml:snakeyaml:jar:1.25:runtime
[INFO] +- org.springframework.boot:spring-boot-devtools:jar:2.2.2.RELEASE:runtime (optional) 
[INFO] \- io.github.classgraph:classgraph:jar:4.8.60-SNAPSHOT:compile
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  3.439 s
[INFO] Finished at: 2020-01-07T12:35:19+01:00
[INFO] ------------------------------------------------------------------------

Executed with ./mvnw spring-boot:run.

@lukehutch
Copy link
Member

I changed the version in the pom to 4.8.19. It succeeds using both ./mvnw spring-boot:run and running inside Eclipse.

@lukehutch
Copy link
Member

OK, I figured out how to reproduce it. It can only be reproduced on JDK 7/8.

@lukehutch
Copy link
Member

Strangely though in JDK 8, if I run Gh729Application in the Eclipse debugger, it never runs the Reproducer component. (It does if I run it in JDK 12.) So I don't know how to debug this. I have tried several things, but can't figure out how to get the Reproducer to run anywhere but the commandline...

@lukehutch
Copy link
Member

I figured it out. I erroneously assumed that the Restart classloader didn't actually do any classloading itself, but only delegated to the context classloader first, and then the parent classloader last. Turns out there are cases where there is no context classloader other than the Restart classloader, and in that case, it does its own classloading. Fixed and released in 4.8.60. Sorry for the trouble!

@lukehutch
Copy link
Member

lukehutch commented Jan 8, 2020

Actually now that I understand the Restart classloader better, I made some further cleanups to simplify the ClassLoaderHandler in the last commit. Please check also that 4.8.61-SNAPSHOT (the git master version) works for you in addition to 4.8.60. (The master version should also work fine.)

@michael-simons
Copy link
Contributor Author

Great work, Luke! I can confirm both 4.8.60 and 4.8.61-SNAPSHOT works.

@lukehutch
Copy link
Member

Great! Thanks for the bug report, test case, and testing!

@lbjzz-hash
Copy link

Title: Issue with ClassGraph Version 4.8.29 on Specific Server Machines
Hello,

I encountered an issue with ClassGraph when using version 4.8.29 on my server cluster. Some of the machines in the cluster fail to use ClassGraph classes correctly, while others operate without any problems. It seems that this issue is related to the specific models of the machines. The machines that fail produce the following error: "a fault occurred in a recent unsafe memory access operation in compiled Java code."LogicalZipFile.readCentralDirectory(LogiclaZipFile.java439)

Interestingly, when I upgrade the ClassGraph jar to version 4.8.60, this problem no longer occurs. It seems that something in the update from 4.8.29 to 4.8.60 has resolved the issue.

I am curious to know what changes were made in version 4.8.60 that might have addressed this problem. Any insights or information would be greatly appreciated.

Thank you.

@lukehutch
Copy link
Member

@lbjzz-hash Version 4.8.60 is 105 minor releases behind the latest version. I would only look this far back in the release history if I needed to do a git bisect to figure out where something specific broke. Can you please test with the latest release, and then open a new bug if you still see an issue?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants