Fix Java LS logging

[snjeza]

Fixes #2830

[snjeza]

test this please

[rgrunber]

@snjeza was the language server broken before this change ? I tried a recent pre-release of vscode-java and it worked, but launching a child instance was broken without this change. Can you explain exactly what was fixed ? Was it functionality activated through jdt.ls.debug=true ?

[snjeza]

was the language server broken before this change ?

Yes, it was.

Can you explain exactly what was fixed ? Was it functionality activated through jdt.ls.debug=true ?

Yes, It was.

[Frederick888]

This PR somehow broke my setup (Neovim + coc.nvim)

Server:

org.gradle.tooling.BuildException: Could not run phased build action using connection to Gradle distribution 'https://services.gradle.org/distributions/gradle-7.5-bin.zip'.
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:51)
	at org.gradle.tooling.internal.consumer.ExceptionTransformer.transform(ExceptionTransformer.java:29)
	at org.gradle.tooling.internal.consumer.ResultHandlerAdapter.onFailure(ResultHandlerAdapter.java:43)
	at org.gradle.tooling.internal.consumer.async.DefaultAsyncConsumerActionExecutor$1$1.run(DefaultAsyncConsumerActionExecutor.java:69)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
	at org.gradle.tooling.internal.consumer.BlockingResultHandler.getResult(BlockingResultHandler.java:46)
	at org.gradle.tooling.internal.consumer.DefaultPhasedBuildActionExecuter.run(DefaultPhasedBuildActionExecuter.java:63)
	at org.gradle.tooling.internal.consumer.DefaultPhasedBuildActionExecuter.run(DefaultPhasedBuildActionExecuter.java:31)
	at org.eclipse.buildship.core.internal.workspace.EclipseModelUtils.runPhasedModelQuery(EclipseModelUtils.java:111)
	at org.eclipse.buildship.core.internal.workspace.EclipseModelUtils.runTasksAndQueryCompositeModelWithRuntimInfo(EclipseModelUtils.java:86)
	at org.eclipse.buildship.core.internal.workspace.EclipseModelUtils.runTasksAndQueryModels(EclipseModelUtils.java:60)
	at org.eclipse.buildship.core.internal.workspace.DefaultModelProvider.lambda$fetchEclipseProjectAndRunSyncTasks$4(DefaultModelProvider.java:75)
	at org.eclipse.buildship.core.internal.DefaultGradleBuild$GradleConnectionOperation.runInToolingApi(DefaultGradleBuild.java:331)
	at org.eclipse.buildship.core.internal.operation.DefaultToolingApiOperationManager$WorkspaceRunnableAdapter.run(DefaultToolingApiOperationManager.java:58)
	at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2453)
	at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2478)
	at org.eclipse.buildship.core.internal.operation.DefaultToolingApiOperationManager.run(DefaultToolingApiOperationManager.java:39)
	at org.eclipse.buildship.core.internal.DefaultGradleBuild.withConnection(DefaultGradleBuild.java:124)
	at org.eclipse.buildship.core.internal.workspace.DefaultModelProvider.lambda$fetchEclipseProjectAndRunSyncTasks$5(DefaultModelProvider.java:75)
	at com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:4853)
	at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529)
	at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155)
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045)
	at com.google.common.cache.LocalCache.get(LocalCache.java:3951)
	at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4848)
	at org.eclipse.buildship.core.internal.workspace.DefaultModelProvider.getFromCache(DefaultModelProvider.java:98)
	at org.eclipse.buildship.core.internal.workspace.DefaultModelProvider.executeOperation(DefaultModelProvider.java:90)
	at org.eclipse.buildship.core.internal.workspace.DefaultModelProvider.fetchEclipseProjectAndRunSyncTasks(DefaultModelProvider.java:72)
	at org.eclipse.buildship.core.internal.DefaultGradleBuild$SynchronizeOperation.runInToolingApi(DefaultGradleBuild.java:228)
	at org.eclipse.buildship.core.internal.operation.DefaultToolingApiOperationManager$WorkspaceRunnableAdapter.run(DefaultToolingApiOperationManager.java:58)
	at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2453)
	at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2478)
	at org.eclipse.buildship.core.internal.operation.DefaultToolingApiOperationManager.run(DefaultToolingApiOperationManager.java:39)
	at org.eclipse.buildship.core.internal.DefaultGradleBuild$SynchronizeOperation.run(DefaultGradleBuild.java:194)
	at org.eclipse.buildship.core.internal.DefaultGradleBuild.synchronize(DefaultGradleBuild.java:102)
	at org.eclipse.buildship.core.internal.workspace.SynchronizationJob.runInToolingApi(SynchronizationJob.java:64)
	at org.eclipse.buildship.core.internal.workspace.SynchronizationJob.runInToolingApi(SynchronizationJob.java:30)
	at org.eclipse.buildship.core.internal.operation.ToolingApiJob$1.runInToolingApi(ToolingApiJob.java:54)
	at org.eclipse.buildship.core.internal.operation.DefaultToolingApiOperationManager$WorkspaceRunnableAdapter.run(DefaultToolingApiOperationManager.java:58)
	at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2453)
	at org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2478)
	at org.eclipse.buildship.core.internal.operation.DefaultToolingApiOperationManager.run(DefaultToolingApiOperationManager.java:39)
	at org.eclipse.buildship.core.internal.operation.ToolingApiJob.run(ToolingApiJob.java:65)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Caused by: org.gradle.internal.exceptions.LocationAwareException: The specified initialization script '/Users/frederick/Programming/Java/eclipse.jdt.ls/org.eclipse.jdt.ls.product/target/repository/config_mac/org.eclipse.osgi/53/0/.cp/gradle/init/init.gradle' does not exist.
	at org.gradle.initialization.exception.DefaultExceptionAnalyser.transform(DefaultExceptionAnalyser.java:103)
	at org.gradle.initialization.exception.DefaultExceptionAnalyser.collectFailures(DefaultExceptionAnalyser.java:67)
	at org.gradle.initialization.exception.MultipleBuildFailuresExceptionAnalyser.transform(MultipleBuildFailuresExceptionAnalyser.java:55)
	at org.gradle.initialization.exception.MultipleBuildFailuresExceptionAnalyser.transform(MultipleBuildFailuresExceptionAnalyser.java:38)
	at org.gradle.initialization.exception.StackTraceSanitizingExceptionAnalyser.transform(StackTraceSanitizingExceptionAnalyser.java:33)
	at org.gradle.tooling.internal.provider.SessionFailureReportingActionExecuter.execute(SessionFailureReportingActionExecuter.java:61)
	at org.gradle.tooling.internal.provider.SessionFailureReportingActionExecuter.execute(SessionFailureReportingActionExecuter.java:40)
	at org.gradle.tooling.internal.provider.SetupLoggingActionExecuter.execute(SetupLoggingActionExecuter.java:47)
	at org.gradle.tooling.internal.provider.SetupLoggingActionExecuter.execute(SetupLoggingActionExecuter.java:31)
	at org.gradle.launcher.daemon.server.exec.ExecuteBuild.doBuild(ExecuteBuild.java:65)
	at org.gradle.launcher.daemon.server.exec.BuildCommandOnly.execute(BuildCommandOnly.java:37)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.WatchForDisconnection.execute(WatchForDisconnection.java:39)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.ResetDeprecationLogger.execute(ResetDeprecationLogger.java:29)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.RequestStopIfSingleUsedDaemon.execute(RequestStopIfSingleUsedDaemon.java:35)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.ForwardClientInput$2.create(ForwardClientInput.java:78)
	at org.gradle.launcher.daemon.server.exec.ForwardClientInput$2.create(ForwardClientInput.java:75)
	at org.gradle.util.internal.Swapper.swap(Swapper.java:38)
	at org.gradle.launcher.daemon.server.exec.ForwardClientInput.execute(ForwardClientInput.java:75)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.LogAndCheckHealth.execute(LogAndCheckHealth.java:55)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.LogToClient.doBuild(LogToClient.java:63)
	at org.gradle.launcher.daemon.server.exec.BuildCommandOnly.execute(BuildCommandOnly.java:37)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.EstablishBuildEnvironment.doBuild(EstablishBuildEnvironment.java:84)
	at org.gradle.launcher.daemon.server.exec.BuildCommandOnly.execute(BuildCommandOnly.java:37)
	at org.gradle.launcher.daemon.server.api.DaemonCommandExecution.proceed(DaemonCommandExecution.java:104)
	at org.gradle.launcher.daemon.server.exec.StartBuildOrRespondWithBusy$1.run(StartBuildOrRespondWithBusy.java:52)
	at org.gradle.launcher.daemon.server.DaemonStateCoordinator$1.run(DaemonStateCoordinator.java:297)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
Caused by: java.lang.IllegalArgumentException: The specified initialization script '/Users/frederick/Programming/Java/eclipse.jdt.ls/org.eclipse.jdt.ls.product/target/repository/config_mac/org.eclipse.osgi/53/0/.cp/gradle/init/init.gradle' does not exist.
	at org.gradle.tooling.internal.provider.StartParamsValidatingActionExecuter.validateIsFileAndExists(StartParamsValidatingActionExecuter.java:69)
	at org.gradle.tooling.internal.provider.StartParamsValidatingActionExecuter.execute(StartParamsValidatingActionExecuter.java:60)
	at org.gradle.tooling.internal.provider.StartParamsValidatingActionExecuter.execute(StartParamsValidatingActionExecuter.java:31)
	at org.gradle.tooling.internal.provider.SessionFailureReportingActionExecuter.execute(SessionFailureReportingActionExecuter.java:52)
	... 29 more

Client:

WARNING: Using incubator modules: jdk.incubator.vector, jdk.incubator.foreign
Sept 06, 2023 10:37:15 AM org.apache.aries.spifly.BaseActivator log
INFO: Registered provider ch.qos.logback.classic.servlet.LogbackServletContainerInitializer of service jakarta.servlet.ServletContainerInitializer in bundle ch.qos.logback.classic
Sept 06, 2023 10:37:15 AM org.apache.aries.spifly.BaseActivator log
INFO: Registered provider ch.qos.logback.classic.spi.LogbackServiceProvider of service org.slf4j.spi.SLF4JServiceProvider in bundle ch.qos.logback.classic
[Error - 10:37:20.027] Connection to server Language Support for Java is erroring, Header must provide a Content-Length property.. Shutting down server.
Error: Header must provide a Content-Length property.
    at Jw.onData (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:41668)
    at Socket.<anonymous> (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:41386)
    at Socket.emit (node:events:514:28)
    at addChunk (node:internal/streams/readable:343:12)
    at readableAddChunk (node:internal/streams/readable:316:9)
    at Readable.push (node:internal/streams/readable:253:10)
    at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)
[Error - 10:37:20.029] Stopping server failed
Error: Client is not running and can't be stopped. It's current state is: 1
    at Md.shutdown (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:13434)
    at Md.stop (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:13229)
    at Md.stop (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:244:3009)
    at Md.handleConnectionError (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:16424)
    at e (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:15079)
    at /Users/frederick/.vim/plugged/coc.nvim/build/index.js:237:5619
    at vP.invoke (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:34722)
    at ih.fire (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:35491)
    at Ne (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:22:7095)
    at vP.invoke (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:34722)
[Error - 10:37:20.029] Connection to server Language Support for Java is erroring, Header must provide a Content-Length property.. Shutting down server.
Error: Header must provide a Content-Length property.
    at Jw.onData (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:41668)
    at Socket.<anonymous> (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:41386)
    at Socket.emit (node:events:514:28)
    at addChunk (node:internal/streams/readable:343:12)
    at readableAddChunk (node:internal/streams/readable:316:9)
    at Readable.push (node:internal/streams/readable:253:10)
    at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)
[Error - 10:37:20.029] Stopping server failed
Error: Client is not running and can't be stopped. It's current state is: 1
    at Md.shutdown (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:13434)
    at Md.stop (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:13229)
    at Md.stop (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:244:3009)
    at Md.handleConnectionError (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:16424)
    at e (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:240:15079)
    at /Users/frederick/.vim/plugged/coc.nvim/build/index.js:237:5619
    at vP.invoke (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:34722)
    at ih.fire (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:35491)
    at Ne (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:22:7095)
    at vP.invoke (/Users/frederick/.vim/plugged/coc.nvim/build/index.js:20:34722)

$ ls -lah /Users/frederick/Programming/Java/eclipse.jdt.ls/org.eclipse.jdt.ls.product/target/repository/config_mac
total 16
drwxr-xr-x@  3 frederick  staff    96B  6 Sep 10:44 .
drwxr-xr-x@ 21 frederick  staff   672B  6 Sep 10:44 ..
-rw-r--r--@  1 frederick  staff   6.4K  6 Sep 10:44 config.ini

[snjeza]

@Frederick888 Could you, please, create a new issue?

[rgrunber]

@snjeza this is exactly what I was going to mention.

Error: Header must provide a Content-Length property.

I've seen the same thing.

1. Start the language server and have it listening for connections in one shell.

CLIENT_HOST=127.0.0.1 CLIENT_PORT=5036 ./org.eclipse.jdt.ls.product/target/repository/bin/jdtls --jvm-arg=-Dsocket.stream.debug=true --jvm-arg=-Dosgi.dev

2. Use socat (on Linux) to connect as a client in another shell.

socat - tcp:localhost:5036

3. In the client shell from (2), send something like :

Content-Length: 254\r\n
\r\n
{"jsonrpc":"2.0","id":1,"method":"initialize","params":{"initializationOptions":{"workspaceFolders":["file:///home/rgrunber/git/lemminx"],"settings":{"java":{"home":"/usr/lib/jvm/java-17-openjdk-17.0.7.0.7-5.fc37.x86_64","autobuild":{"enabled":true}}}}}}\r\n

You may need to replace java.home (and the Content-Length value) with your own location for it. Replace \r\n with carriage return (enter key).

The server will respond by initializing but you'll see the following in the server shell :

Sep. 06, 2023 8:43:21 A.M. org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer fireError
SEVERE: Missing header Content-Length in input "
"
java.lang.IllegalStateException: Missing header Content-Length in input "
"
	at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:91)
	at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)

If you remove either the aries bundle or logback classic from the autostart configuration, it works as expected. When I debugged into StreamMessageProducer, what seemed off was that normally, after the server responds, it appears to receive an additional newline whereas before this change, it didn't. Not sure where its coming from.

[Frederick888]

I can confirm #2838 fixed my setup too 👍