throws exception when closing editors

[martinlippert]

Applied a Spring Boot upgrade, then quickly closed a bunch of open editors. Popup appears, showing an error for textDocument/definition:

java.util.concurrent.CompletionException: java.lang.NullPointerException: Cannot invoke "org.eclipse.jdt.core.dom.CompilationUnit.getPosition(int, int)" because "cu" is null
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture.completeThrowable(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NullPointerException: Cannot invoke "org.eclipse.jdt.core.dom.CompilationUnit.getPosition(int, int)" because "cu" is null
	at org.springframework.ide.vscode.boot.java.JavaDefinitionHandler.lambda$handle$0(JavaDefinitionHandler.java:60)
	at org.springframework.ide.vscode.boot.java.utils.CompilationUnitCache.withCompilationUnit(CompilationUnitCache.java:237)
	at org.springframework.ide.vscode.boot.java.JavaDefinitionHandler.handle(JavaDefinitionHandler.java:58)
	at org.springframework.ide.vscode.languageserver.starter.LanguageServerAutoConf.lambda$registerDefinitionHandler$2(LanguageServerAutoConf.java:97)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleTextDocumentService.lambda$definition$6(SimpleTextDocumentService.java:371)
	... 5 more

[martinlippert]

another exception found in the log in the same area, but not related to the textDocument/definition request:

14:22:34.015 [pool-5-thread-4] ERROR o.s.i.v.boot.app.SpringSymbolIndex - {}
java.lang.NullPointerException: Cannot invoke "org.eclipse.jdt.core.dom.CompilationUnit.accept(org.eclipse.jdt.core.dom.ASTVisitor)" because the return value of "org.springframework.ide.vscode.boot.java.utils.SpringIndexerJavaContext.getCu()" is null
	at org.springframework.ide.vscode.boot.java.utils.SpringIndexerJava.scanAST(SpringIndexerJava.java:589)
	at org.springframework.ide.vscode.boot.java.utils.SpringIndexerJava.lambda$computeSymbols$14(SpringIndexerJava.java:354)
	at org.springframework.ide.vscode.boot.java.utils.CompilationUnitCache.withCompilationUnit(CompilationUnitCache.java:237)
	at org.springframework.ide.vscode.boot.java.utils.SpringIndexerJava.computeSymbols(SpringIndexerJava.java:331)
	at org.springframework.ide.vscode.boot.app.SpringSymbolIndex.getSymbols(SpringSymbolIndex.java:697)
	at org.springframework.ide.vscode.boot.java.BootJavaLanguageServerComponents.lambda$new$0(BootJavaLanguageServerComponents.java:162)
	at org.springframework.ide.vscode.commons.languageserver.composable.CompositeLanguageServerComponents$4.handle(CompositeLanguageServerComponents.java:137)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleTextDocumentService.lambda$documentSymbol$10(SimpleTextDocumentService.java:432)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)

[martinlippert]

Further analysis for the second case:

This seems to happen sometime before:

14:22:19.720 [pool-4-thread-2] INFO  o.s.i.v.b.j.u.CompilationUnitCache - Started parsing CU for file:///Users/mlippert/workspace/projects-demos-issues/spring-petclinic-sb3-conversion/src/main/java/org/springframework/samples/petclinic/owner/OwnerController.java

which is followed by:

14:22:19.737 [pool-4-thread-2] ERROR o.s.i.v.boot.java.utils.CUResolver - {}
java.lang.reflect.InvocationTargetException: null
	at jdk.internal.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at org.springframework.ide.vscode.boot.java.utils.CUResolver.resolve(CUResolver.java:273)
	at org.springframework.ide.vscode.boot.java.utils.CompilationUnitCache.parse2(CompilationUnitCache.java:287)
	at org.springframework.ide.vscode.boot.java.utils.CompilationUnitCache.lambda$requestCU$3(CompilationUnitCache.java:249)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NullPointerException: Cannot invoke "java.util.zip.ZipFile.entries()" because "this.zipFile" is null
	at org.eclipse.jdt.internal.compiler.batch.ClasspathJar.getModulesDeclaringPackage(ClasspathJar.java:244)
	at org.eclipse.jdt.internal.compiler.batch.ClasspathLocation.isPackage(ClasspathLocation.java:184)
	at org.eclipse.jdt.internal.compiler.batch.ClasspathJar.findClass(ClasspathJar.java:119)
	at org.eclipse.jdt.internal.compiler.batch.FileSystem.internalFindClass(FileSystem.java:493)
	at org.eclipse.jdt.internal.compiler.batch.FileSystem.findClass(FileSystem.java:435)
	at org.eclipse.jdt.internal.compiler.batch.FileSystem.findType(FileSystem.java:532)
	at org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.lambda$0(LookupEnvironment.java:240)
	at org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.askForTypeFromModules(LookupEnvironment.java:375)
	at org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.askForType(LookupEnvironment.java:239)
	at org.eclipse.jdt.internal.compiler.lookup.UnresolvedReferenceBinding.resolve(UnresolvedReferenceBinding.java:116)
	at org.eclipse.jdt.internal.compiler.lookup.BinaryTypeBinding.resolveType(BinaryTypeBinding.java:251)
	at org.eclipse.jdt.internal.compiler.lookup.ParameterizedTypeBinding.resolve(ParameterizedTypeBinding.java:1242)
	at org.eclipse.jdt.internal.compiler.lookup.BinaryTypeBinding.resolveType(BinaryTypeBinding.java:222)
	at org.eclipse.jdt.internal.compiler.lookup.BinaryTypeBinding.superInterfaces(BinaryTypeBinding.java:2434)
	at org.eclipse.jdt.internal.compiler.lookup.ParameterizedTypeBinding.superInterfaces(ParameterizedTypeBinding.java:1476)
	at org.eclipse.jdt.internal.compiler.lookup.ParameterizedTypeBinding.getExactMethod(ParameterizedTypeBinding.java:778)
	at org.eclipse.jdt.internal.compiler.lookup.Scope.findExactMethod(Scope.java:1329)
	at org.eclipse.jdt.internal.compiler.lookup.Scope.getMethod(Scope.java:3054)
	at org.eclipse.jdt.internal.compiler.ast.MessageSend.findMethodBinding(MessageSend.java:1020)
	at org.eclipse.jdt.internal.compiler.ast.MessageSend.resolveType(MessageSend.java:835)
	at org.eclipse.jdt.internal.compiler.ast.Expression.resolveTypeExpecting(Expression.java:1147)
	at org.eclipse.jdt.internal.compiler.ast.IfStatement.resolveIfStatement(IfStatement.java:288)
	at org.eclipse.jdt.internal.compiler.ast.IfStatement.resolve(IfStatement.java:317)
	at org.eclipse.jdt.internal.compiler.ast.AbstractMethodDeclaration.resolveStatements(AbstractMethodDeclaration.java:662)
	at org.eclipse.jdt.internal.compiler.ast.MethodDeclaration.resolveStatements(MethodDeclaration.java:388)
	at org.eclipse.jdt.internal.compiler.ast.AbstractMethodDeclaration.resolve(AbstractMethodDeclaration.java:571)
	at org.eclipse.jdt.internal.compiler.ast.TypeDeclaration.resolve(TypeDeclaration.java:1506)
	at org.eclipse.jdt.internal.compiler.ast.TypeDeclaration.resolve(TypeDeclaration.java:1631)
	at org.eclipse.jdt.internal.compiler.ast.CompilationUnitDeclaration.resolve(CompilationUnitDeclaration.java:667)
	at org.eclipse.jdt.core.dom.CompilationUnitResolver.resolve(CompilationUnitResolver.java:1318)
	... 10 common frames omitted

then:

14:22:19.740 [pool-4-thread-2] ERROR o.s.i.v.boot.java.utils.CUResolver - {}
java.lang.reflect.InvocationTargetException: null
	at jdk.internal.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at org.springframework.ide.vscode.boot.java.utils.CUResolver.convert(CUResolver.java:322)
	at org.springframework.ide.vscode.boot.java.utils.CompilationUnitCache.parse2(CompilationUnitCache.java:294)
	at org.springframework.ide.vscode.boot.java.utils.CompilationUnitCache.lambda$requestCU$3(CompilationUnitCache.java:249)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NullPointerException: Cannot read field "scope" because "compilationUnitDeclaration" is null
	at org.eclipse.jdt.core.dom.CompilationUnitResolver.convert(CompilationUnitResolver.java:334)
	at org.eclipse.jdt.core.dom.CompilationUnitResolver.convert(CompilationUnitResolver.java:299)
	... 10 common frames omitted
14:22:19.740 [pool-4-thread-2] INFO  o.s.i.v.b.j.u.CompilationUnitCache - Parsed successfully CU for file:///Users/mlippert/workspace/projects-demos-issues/spring-petclinic-sb3-conversion/src/main/java/org/springframework/samples/petclinic/owner/OwnerController.java

It looks suspicious that those exceptions are being thrown (looks like the parser can't do its job), but then a Parsed successfully message appears. Maybe there is an entry put into the cache even in case that there was an exception during parsing (and no CU has been produced), so that trying to use the entry in the cache later on results in further errors, like the exception mentioned above (NPE).

[martinlippert]

Ok, I think I know what is going on here. The high level summary is:

• the CompilationUnitCache keeps a cache of CompletableFuture objects, not the CompilationUnit objects directly.
• when there is no entry in the cache, a future is created, which async does the parsing and creation of the CompilationUnit(the AST basically) - and this future is being put into the cache

Now, the parsing itself throws a bunch of exceptions internally (due to various reasons, but things like that could happen anytime, especially because parallel things could happen anytime, like a local maven build removing JARs from disc that belonged to the classpath, source files being deleted, whatever). There is no way to ensure that the parsing will succeed, so we need to deal with the failure situation.

At the moment, the cache keeps the CompletableFuture, even if the computation of the AST failed and therefore the result of the future is null. So on future invocations of the CompilationUnitCache, the .get() call on the future will return null. It looks like - in that case - the requestors apply method is not being invoked with null, just nothing happens - which is strange, since the feature that is invoking this will just not work and will not directly recover.

On an additional note, if the project object that is passed into the CompilationUnitCache is null, the requestor will be invoked with null for the CompilationUnit, which might cause the above mentioned exceptions in the SpringIndexerJava or the JavaDefinitionHandler.

I think we need to do two things here:

• make the users of the CompilationUnitCache safe for CompilationUnitobjects that are null
• somehow let the cache invalidate the CompletableFuture objects, if the parsing fails, so that the cache will recover automatically and try again next time.

There might still be the case where the user of the CompilationUnitCache gets a null back and therefore the functionality is broken, but gets a valid object the next time it invokes the cache. Interesting question how to improve this situation as well.

(cc. @BoykoAlex )

[BoykoAlex]

Perhaps completing the CU future exceptionally and then if it has completed exceptionally chain something to the future to invalidate the cache entry...

	private synchronized CompletableFuture<CompilationUnit> requestCU(IJavaProject project, URI uri) throws ExecutionException {
		CompletableFuture<CompilationUnit> cuFuture = uriToCu.getIfPresent(uri);
		if (cuFuture == null) {
			cuFuture = CompletableFuture.supplyAsync(() -> {
				
				try {
					logger.info("Started parsing CU for " + uri);
					Tuple2<List<Classpath>, INameEnvironmentWithProgress> lookupEnvTuple = loadLookupEnvTuple(project);
					String utiStr = uri.toASCIIString();
					String unitName = utiStr.substring(utiStr.lastIndexOf("/"));
					CompilationUnit cUnit = parse2(fetchContent(uri).toCharArray(), utiStr, unitName, lookupEnvTuple.getT1(), lookupEnvTuple.getT2());

					logger.debug("CU Cache: created new AST for {}", uri.toASCIIString());

					logger.info("Parsed successfully CU for " + uri);
					return cUnit;
				} catch (Exception e) {
					// Complete future exceptionally
					throw new CompletionException(e);
				}
			}, createCuExecutorThreadPool);
			// Cache the future
			uriToCu.put(uri, cuFuture);
			// If CU future completed exceptionally invalidate the cache entry
			cuFuture.exceptionally(t -> {
				logger.error("", t);
				uriToCu.invalidate(uri);
				return null;
			});
		}
		return cuFuture;
	}

[BoykoAlex]

Here is the branch with a candidate fix: https://github.com/spring-projects/sts4/tree/cu-cache-fix
I have tried artificial exception with combination of time consuming parsing with THROTTLE and DEBOUNCE reconcile strategy. Seemed to work so far...

[BoykoAlex]

Lets try the fix: 4ce4f02 - seems harmless and likely to help with the issue above