Language server sending improper data leading to connection failure

[rgrunber]

As discussed on #2831 (comment) and demonstrated on #2831 (comment), there seems to be a regression introduced by m2e logging dependencies that cause improper messaging in the client/server communication. I can confirm some of the failures I've seen while running child instances can also reproduce it.

{
  message: 'Result: {\n    "data": []\n}\n\n',
  level: 'info',
  timestamp: '2023-09-06 11:20:24.689'
}
{
  message: 'Language Support for Java server encountered error and will shut down: undefined, Error: Header must provide a Content-Length property.',
  level: 'error',
  timestamp: '2023-09-06 11:20:24.750'
}
{
  message: '[Error - 11:20:24] Client Language Support for Java: connection to server is erroring. Shutting down server.',
  level: 'info',
  timestamp: '2023-09-06 11:20:24.752'
}
{
  message: '[Error - 11:20:24] Stopping server failed',
  level: 'info',
  timestamp: '2023-09-06 11:20:24.753'
}
{
  message: "Error: Client is not running and can't be stopped. It's current state is: starting\n" +
    '\tat TracingLanguageClient.shutdown (/home/rgrunber/git/vscode-java/dist/extension.js:109297:19)\n' +
    '\tat TracingLanguageClient.stop (/home/rgrunber/git/vscode-java/dist/extension.js:109268:21)\n' +
    '\tat TracingLanguageClient.stop (/home/rgrunber/git/vscode-java/dist/extension.js:118397:22)\n' +
    '\tat TracingLanguageClient.stop (/home/rgrunber/git/vscode-java/dist/extension.js:95333:22)\n' +
    '\tat TracingLanguageClient.handleConnectionError (/home/rgrunber/git/vscode-java/dist/extension.js:109529:18)\n' +
    '\tat process.processTicksAndRejections (node:internal/process/task_queues:96:5)',
  level: 'info',
  timestamp: '2023-09-06 11:20:24.753'
}

Sometimes like this :

[Trace - 11:28:31] Sending request 'initialize - (0)'.
Params: {
...
...
}

Sep. 06, 2023 11:28:32 A.M. 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
Sep. 06, 2023 11:28:32 A.M. 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 - 11:28:34] Client Language Support for Java: connection to server is erroring. Shutting down server.
[Error - 11:28:34] Stopping server failed
Error: Client is not running and can't be stopped. It's current state is: starting
	at TracingLanguageClient.shutdown (/home/rgrunber/git/vscode-java/dist/extension.js:109297:19)
	at TracingLanguageClient.stop (/home/rgrunber/git/vscode-java/dist/extension.js:109268:21)
	at TracingLanguageClient.stop (/home/rgrunber/git/vscode-java/dist/extension.js:118397:22)
	at TracingLanguageClient.stop (/home/rgrunber/git/vscode-java/dist/extension.js:95333:22)
	at TracingLanguageClient.handleConnectionError (/home/rgrunber/git/vscode-java/dist/extension.js:109529:18)
	at process.processTicksAndRejections (node:internal/process/task_queues:96:5)
[Error - 11:28:34] Client Language Support for Java: connection to server is erroring. Shutting down server.

[rgrunber]

The following patch seems to fix the crashes for me, but not the error logs when I run the server via cli. It would certainly make sense. Maybe some configurators are attempting to log onto the stream we're using for client/server interaction ?

diff --git a/org.eclipse.jdt.ls.logback.appender/src/org/eclipse/jdt/ls/logback/appender/JavaLsConfigurator.java b/org.eclipse.jdt.ls.logback.appender/src/org/eclipse/jdt/ls/logback/appender/JavaLsConfigurator.java
index 2def9c8a..73b761fa 100644
--- a/org.eclipse.jdt.ls.logback.appender/src/org/eclipse/jdt/ls/logback/appender/JavaLsConfigurator.java
+++ b/org.eclipse.jdt.ls.logback.appender/src/org/eclipse/jdt/ls/logback/appender/JavaLsConfigurator.java
@@ -55,6 +55,6 @@ public class JavaLsConfigurator extends ContextAwareBase implements Configurator
                        defMavenFilter.setLevel(Level.INFO);
                        defMavenFilter.setAdditive(false);
                }
-               return ExecutionStatus.INVOKE_NEXT_IF_ANY;
+               return ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY;
        }
 }

[snjeza]

@rgrunber Java LS logging works with your patch. Could you create a PR?

[rgrunber]

I can confirm it works, but I don't think it's the whole solution.

Even with my patch I still see the following being spit out :

[Trace - 15:26:39] Sending request 'initialize - (0)'.
Params: {
...
...
}

Sep. 06, 2023 3:26:41 P.M. 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
Sep. 06, 2023 3:26:41 P.M. 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
[Trace - 15:26:43] Received notification 'window/logMessage'.
Params: {
    "type": 3,
    "message": "Sep. 6, 2023, 3:26:43 p.m. Main thread is waiting"
}


[Info  - 15:26:43] Sep. 6, 2023, 3:26:43 p.m. Main thread is waiting
[Trace - 15:26:43] Received notification 'window/logMessage'.
Params: {
    "type": 3,
    "message": "Sep. 6, 2023, 3:26:43 p.m. >> initialize"
}

Those log messages don't seem to affect anything, but I also noticed that the error I produced via cli at #2831 (comment) still occurs. I guess it's better than the current situation though so I'll create a PR.

[rgrunber]

Nevemind. The error I was seeing when interacting via CLI :

Sep. 06, 2023 4:17:50 P.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)

has always been there! It's just that we never reported it because the logging facility wasn't working correctly. I guess my PR should fix things.

[testforstephen]

@rgrunber Thanks for the fix.

Language Support for Java server encountered error and will shut down: undefined, Error: Header must provide a Content-Length property. is one of the top crash error we observed from vscode-java client. Let's see how this error goes on after new version is released.

[rgrunber]

Just to close the loop on #2837 (comment) . The error I was seeing was entirely a misunderstanding on my part regarding the protocol. I was hitting Enter (\r\n) at the end of the content part of the lsp message when sending messages via interactive input. This was correctly interpreting the message once the read() call activated, but introducing an extra \r\n which rightly caused an error. This error was always there, but only started being surfaced after the m2e 2.4.0 update.

The solution is to use ^@ (ctrl+@) prior to hitting enter, which will be interpreted as a null character.