Closed maxandersen closed 10 months ago
example of what in the log files:
'Caused by: java.lang.NullPointerException: Cannot invoke "org.eclipse.jdt.ls.core.internal.preferences.PreferenceManager.getPreferences()" because the return value of "org.eclipse.jdt.ls.core.internal.JavaLanguageServerPlugin.getPreferencesManager()" is null\n' +
'\tat org.eclipse.jdt.ls.core.internal.preferences.Preferences.setJavaCompletionFavoriteMembers(Preferences.java:1360)\n' +
'\tat org.eclipse.jdt.ls.core.internal.preferences.Preferences.createFrom(Preferences.java:1120)\n' +
note -excat same issue in vscode folder.
Was there some bug in the release of vscode java on 26-27th september?
Do you follow the pre-release stream of vscode-java ? The date seems to be a day or 2 before the last release but it's happening in code that was introduced at the starts of 2023. The error itself is a strange way to fail as the preference manager should definitely not be null at that point.
Question with similar/same error message on Stack Overflow: Visual Studio Code code completion for Java not working. Might want to look at the repro-ish details there.
Same thing happening for me, when opening a folder which has never been opened before: after activating java extension pack log gets spammed hard. Can we get at least some kind of fix which stop spamming stacktraces in rate of 10+ per second?
stacktrace:
message: říj 30, 2023 4:13:59 ODP. org.eclipse.lsp4j.jsonrpc.RemoteEndpoint fallbackResponseError
SEVERE: Internal error: java.lang.reflect.InvocationTargetException
java.lang.RuntimeException: java.lang.reflect.InvocationTargetException
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$recursiveFindRpcMethods$0(GenericEndpoint.java:67)
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.request(GenericEndpoint.java:120)
at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.handleRequest(RemoteEndpoint.java:261)
at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.consume(RemoteEndpoint.java:190)
at org.eclipse.jdt.ls.core.internal.ParentProcessWatcher.lambda$1(ParentProcessWatcher.java:144)
at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.handleMessage(StreamMessageProducer.java:194)
at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:94)
at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.base/java.util.concurrent.FutureTask.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.reflect.InvocationTargetException
at jdk.internal.reflect.GeneratedMethodAccessor8.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.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$recursiveFindRpcMethods$0(GenericEndpoint.java:65)
... 12 more
Caused by: java.lang.NullPointerException: Cannot invoke "org.eclipse.jdt.ls.core.internal.preferences.PreferenceManager.getPreferences()" because the return value of "org.eclipse.jdt.ls.core.internal.JavaLanguageServerPlugin.getPreferencesManager()" is null
at org.eclipse.jdt.ls.core.internal.preferences.Preferences.setJavaCompletionFavoriteMembers(Preferences.java:1378)
at org.eclipse.jdt.ls.core.internal.preferences.Preferences.createFrom(Preferences.java:1126)
at org.eclipse.jdt.ls.core.internal.handlers.BaseInitHandler.handleInitializationOptions(BaseInitHandler.java:113)
at org.eclipse.jdt.ls.core.internal.handlers.InitHandler.handleInitializationOptions(InitHandler.java:105)
at org.eclipse.jdt.ls.core.internal.handlers.BaseInitHandler.initialize(BaseInitHandler.java:64)
at org.eclipse.jdt.ls.core.internal.handlers.JDTLanguageServer.initialize(JDTLanguageServer.java:284)
... 16 more
level: info,
timestamp: 2023-10-30 16:13:59.597
I notice @maxandersen's original post involved "Cursor" so that might be something to test out but there's links above to people using just the extension.
@snjeza , any insight / a way to reproduce this would be great here. There are 2 pieces of code at work :
JavaLanguageServerPlugin.getPreferencesManager()
shouldn't be null
.initialize
request in the posted stacktraces.In my basic testing, I cannot get (2) to occur before (1). In fact it doesn't even make sense because the actual communication between client/server happens after (1). I would think that the language client (vscode-java & vscode-languageserver-node) send initialize
at the appropriate time, only once the connection has been established. Could that be failing ?
Another possibility is maybe something results in the stop()
being called on jdt.ls.core
plugin while the initialization is happening. Could there be some contributed bundle messing with the globals ?
@Nightenom , with java.trace.server
set to verbose
, do you see anything in your "Language Support For Java" logs regarding "bundles" entries ? There should be a bunch of entries for vscode-java-{test,debug,dependency} if you're using the extension pack, but just wondering if there's anything else in there.
Update: Fred mentioned he believed there may be an error that occurs before this that brings down the LS, and the client wrongly attempts to recover (call initialize
), but continuously fails. If we could figure out what the error is, or how it's failing we might be able to catch it on client side and prevent the re-initialize cycle.. assuming that's the issue.
@snjeza , any insight / a way to reproduce this would be great here.
Checking...
@Nightenom , @starball5 , are there any other errors in your logs before the NullPointerException
regarding JavaLanguageServerPlugin.getPreferencesManager()
? Would you be able to attach the client/server logs of this occuring ?
@Nightenom What version of Java are you using?
Sorry i missed these.
Yes I often use prerelease version but not sure if/when.
Yes first Saw This using cursor but same behavior seen when using vscode.
So many pings.. :D
Logs https://gist.github.com/Nightenom/fb2f16f068375683cd3904739c983635
Java OpenJDK Runtime Environment Temurin-17.0.8.1+1 (build 17.0.8.1+1)
Repro steps (rate 100%):
Those logs are extremely helpful. There is a failure in the Gradle build (from the server logs, .log
) that would be nice to investigate but I don't think that's the root of the problem. The client logs clearly show the failure happens when we attempt to get a reference to the bundle context for jdt.ls.core
. After the failure, we seem to get stuck in some initialize
loop, because the startup was not correctly finished.
Beacuse we're dealing with 2 sets of logs that both give useful info I've tried to reconstruct the failure based on the timestamps :
At some point the language server detects that the parent process (the client with PID 18392) stopped running. After that it begins shutting down while initialization is still occuring. This causes failures on the client side, which ultimately causes the client to re-attempt to initialize.
The good news is, we have code in vscode-java that can detect this and should be able to prevent the initialization loop that causes the massive size in storage. I don't know what is causing the parent process watcher to think the client is gone.
@Nightenom, you could try adding the following to the java.jdt.ls.vmargs
settings : -DwatchParentProcess=false
. It would look something like -XX:+UseParallelGC -XX:GCTimeRatio=4 -XX:AdaptiveSizePolicyWeight=90 -Dsun.zip.disableMemoryMapping=true -Xmx1G -Xms100m -Xlog:disable -DwatchParentProcess=false
if you're just using default options. That should disable parent process watching, so if the problem goes away, at least we'd know it's definitely something to do with that part of the code.
From the linked Stack Overflow question, the asker found that the issue went away when they added Java version info to their Maven config:
<plugin> <groupId>org.apache.maven.plugins</groupId> <artifactId>maven-compiler-plugin</artifactId> <configuration> <source>${maven.compiler.source}</source> <target>${maven.compiler.target}</target> </configuration> </plugin>
@Nightenom, you could try adding the following to the
java.jdt.ls.vmargs
settings :-DwatchParentProcess=false
It still spams, but less and stops for few secs after decent wall of text, then repeats
@Nightenom , The PR merged for this should reduce the errors being logged, but I'm still curious about the root cause. The client.log.2023-11-03
you submitted already truncates very large requests/responses. Unfortunately I think it leaves out a particular interesting portion (making sure the logging displays everything could be a separate issue to improve). You'll see the log has something like :
{
message: "[Trace - 11:54:46 AM] Sending request 'initialize - (0)'.",
level: 'info',
timestamp: '2023-11-03 11:54:46.358'
}
{
message: 'Params: {\n' +
...
...
...
' "typeDefinition": {\n' +
' "dynamicRegistration": true,\n' +
' "linkSupport": true\n' +
' },\n' +
' "implemen'... 23292 more characters,
level: 'info',
timestamp: '2023-11-03 11:54:46.358'
}
Would you be able to access the logs through the UI element below :
and specifically list all the paths in bundles
?
using same repro steps as earlier, without -DwatchParentProcess=false
, vscode 1.83.1, java ext v1.24.0 (after quick investigation of code in mentioned PR i assumed i dont have to update):
https://gist.github.com/Nightenom/8e39699f46929eb53c8f1286a3ede329
had to cut it, hopefully the repetative part is whole, still it's 5mb log
using same repro steps as earlier, without
-DwatchParentProcess=false
, vscode 1.83.1, java ext v1.24.0 (after quick investigation of code in mentioned PR i assumed i dont have to update): https://gist.github.com/Nightenom/8e39699f46929eb53c8f1286a3ede329 had to cut it, hopefully the repetative part is whole, still it's 5mb log
You shouldn't need the -DwatchParentProcess=false
anymore. You will need to update though. The fix is in the 1.25.2023110903
pre-release which went out a few hours ago. If you switch to the pre-release stream you should get it automatically. Also available from the "Version History" page of https://marketplace.visualstudio.com/items?itemName=redhat.java .
Cannot repro with pre-release version v1.25.2023110903
, successfully setups using the previously working repro steps, and there is no bundles
in log anywhere
When switching repos i've got the bundles:
"bundles": [
"p:\\apps\\windows64\\vscode\\data\\extensions\\visualstudioexptteam.vscodeintellicode-1.2.30\\dist\\com.microsoft.jdtls.intellicode.core-0.7.0.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-debug-0.55.0\\server\\com.microsoft.java.debug.plugin-0.50.0.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-dependency-0.23.2\\server\\com.microsoft.jdtls.ext.core-0.23.2.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-jupiter-api_5.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-jupiter-engine_5.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-jupiter-migrationsupport_5.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-jupiter-params_5.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-platform-commons_1.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-platform-engine_1.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-platform-launcher_1.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-platform-runner_1.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-platform-suite-api_1.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-platform-suite-commons_1.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-platform-suite-engine_1.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\junit-vintage-engine_5.9.3.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\org.apiguardian.api_1.1.2.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\org.eclipse.jdt.junit4.runtime_1.3.0.v20220609-1843.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\org.eclipse.jdt.junit5.runtime_1.1.100.v20220907-0450.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\org.opentest4j_1.2.0.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-java-test-0.40.1\\server\\com.microsoft.java.test.plugin-0.40.1.jar",
"p:\\apps\\windows64\\vscode\\data\\extensions\\vscjava.vscode-maven-0.43.0\\jdtls.ext\\com.microsoft.java.maven.plugin\\target\\com.microsoft.java.maven.plugin-0.39.0.jar"
],
Awesome!
1.25.2023110903
was meant to avoid the excessive logging, but wouldn't have prevented the language server from stopping/misbehaving. v1.25.2023111103
(newest pre-release) should now contain a fix that avoids having the language server shut down entirely when this particular issues occurs.
@Nightenom , could you try this new pre-release and report back what the server logs (.log
) show (client logs not necessary). I ask because, although I was able to confirm the problem should go away with the method we used to reproduce, it's likely not the exact same issue you were running into and I'm curious exactly what was causing it on your system.
You should see some additional error message in the logs like :
"Cannot refresh bundle [someBundle] because its dependency closure includes the org.eclipse.jdt.ls.core bundle."
It would be good to know what [someBundle] is.
You should see some additional error message in the logs like :
"Cannot refresh bundle [someBundle] because its dependency closure includes the org.eclipse.jdt.ls.core bundle."
It would be good to know what [someBundle] is.
Given the same repro steps as before none of "bundle" or "org.eclipse.jdt.ls.core" keywords show in both logs or anything similar you've asked for, I have "java.trace.server": "verbose"
but .log seems to be quite empty (unlike client.log.
Btw, I've side question: since my setups takes a long time (due to nature of custom gradle plugin) would it be possible to show the progress message in the notification popup, instead of/along with "check details" button? (see image)
Could you retry the above steps (looking into the logs for that error message), but just before doing so, close VS Code, find your globalStorage
folder (should be a sibling of workspaceStorage
), and remove (or back up) everything under globalStorage/redhat.java/1.24.0
(assuming you were using 1.24.0). Those files should be re-generated after starting up. In my testing I noticed it was the initial startup, where the issue happened for me.
Regarding the progress, we may have done that at a certain point. I think we opted to show less information unless the user performed some action indicating they wanted more details (ie. the details link). We could always add more options to java.showBuildStatusOnStart.enabled
.
As a workaround, is "java.showBuildStatusOnStart.enabled": "terminal"
enough ?
Nope, nothing, cant anyhow reproduce even with stable channel, super weird..
buildStatus in terminal is good enough i guess
I was running out of diskspace and found that my /Users/manderse/Library/Application Support/Cursor/User/workspaceStorage contained 29.6 GB.
19.4 GB of that was redhat.java folder with 18442 client.log. files of about 1.1 mb
whats weird is that its all from about the same sday 2023-09-26 and 2023-09-27.
as if something "bad" happend that day and no cleanup :)