Mac automated UI test failure: SocketTimeoutException while typing in the editor

turkeylurkey commented 7 months ago

The UI robot is trying to type characters into the editor but the editor process is not confirming the characters.

GradleSingleModJakartaLSTest > testJakartaQuickFixInJavaPart() FAILED
    java.net.SocketTimeoutException: Read timed out
        at java.base/sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:288)
        at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:314)
        at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:355)
        at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:808)
        at java.base/java.net.Socket$SocketInputStream.read(Socket.java:966)
        at okio.InputStreamSource.read(JvmOkio.kt:94)
        at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:125)
        at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
        at okhttp3.internal.http1.Http1ExchangeCodec.readHeaderLine(Http1ExchangeCodec.java:242)
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.java:213)
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.java:115)
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:94)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:43)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:94)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:88)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117)
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:229)
        at okhttp3.RealCall.execute(RealCall.java:81)
        at retrofit2.OkHttpCall.execute(OkHttpCall.java:204)
        at com.intellij.remoterobot.client.IdeRobotClient.execute(IdeRobotClient.kt:59)
        at com.intellij.remoterobot.JavaScriptApi$DefaultImpls.runJs(JavaScriptApi.kt:35)
        at com.intellij.remoterobot.RemoteRobot.runJs(RemoteRobot.kt:32)
        at com.intellij.remoterobot.JavaScriptApi$DefaultImpls.runJs(JavaScriptApi.kt:25)
        at com.intellij.remoterobot.RemoteRobot.runJs(RemoteRobot.kt:32)
        at com.intellij.remoterobot.utils.Keyboard$enterText$1.invoke(KeyboardUtils.kt:49)
        at com.intellij.remoterobot.utils.Keyboard$enterText$1.invoke(KeyboardUtils.kt:48)
        at com.intellij.remoterobot.stepsProcessing.StepWorkerKt.step(StepWorker.kt:23)
        at com.intellij.remoterobot.utils.Keyboard.enterText(KeyboardUtils.kt:48)
        at com.intellij.remoterobot.utils.Keyboard.enterText$default(KeyboardUtils.kt:48)
        at com.intellij.remoterobot.utils.Keyboard.enterText(KeyboardUtils.kt)
        at io.openliberty.tools.intellij.it.UIBotTestUtils.selectAndModifyTextInJavaPart(UIBotTestUtils.java:1294)
        at io.openliberty.tools.intellij.it.SingleModJakartaLSTestCommon.testJakartaQuickFixInJavaPart(SingleModJakartaLSTestCommon.java:149)

In https://github.com/OpenLiberty/liberty-tools-intellij/actions/runs/8436692171/job/23104688837

vaisakhkannan commented 7 months ago

I found Intellij extension getting stuck while testing the below test   test --tests "io.openliberty.tools.intellij.it.GradleSingleModJakartaLSTest.testJakartaQuickFixInJavaPart"   
( which is part of the above failure)

   I did force quit the extension first, then, I opened it again and found the below exception.   

Freeze for 40 seconds
IDE KILLED! Sampled time: 31800ms, sampling rate: 100ms, GC time: 284ms (0%), Class loading: 0%
The stack is from the thread that was blocking EDT
com.intellij.diagnostic.Freeze
    at java.base@17.0.10/jdk.internal.misc.Unsafe.park(Native Method)
    at java.base@17.0.10/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
    at java.base@17.0.10/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1866)
    at java.base@17.0.10/java.util.concurrent.ForkJoinPool.compensatedBlock(ForkJoinPool.java:3451)
    at java.base@17.0.10/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
    at java.base@17.0.10/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1939)
    at java.base@17.0.10/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2095)
    at org.microshed.lsp4ij.CompletableFutures.waitUntilDone(CompletableFutures.java:78)
    at org.microshed.lsp4ij.operations.codeactions.LSPLazyCodeActions.getOrLoadCodeActions(LSPLazyCodeActions.java:131)
    at org.microshed.lsp4ij.operations.codeactions.LSPLazyCodeActions.getCodeActionAt(LSPLazyCodeActions.java:90)
    at org.microshed.lsp4ij.operations.codeactions.LSPLazyCodeActionIntentionAction.loadCodeActionIfNeeded(LSPLazyCodeActionIntentionAction.java:148)
    at org.microshed.lsp4ij.operations.codeactions.LSPLazyCodeActionIntentionAction.isAvailable(LSPLazyCodeActionIntentionAction.java:72)
    at com.intellij.codeInsight.intention.impl.ShowIntentionActionsHandler.availableFor(ShowIntentionActionsHandler.java:218)
    at com.intellij.codeInsight.daemon.impl.ShowIntentionsPass.lambda$addAvailableFixesForGroups$2(ShowIntentionsPass.java:148)
    at com.intellij.codeInsight.daemon.impl.ShowIntentionsPass$$Lambda$5662/0x0000000802537548.apply(Unknown Source)
    at com.intellij.codeInsight.daemon.impl.HighlightInfo.find(HighlightInfo.java:124)
    at com.intellij.codeInsight.daemon.impl.HighlightInfo.findRegisteredQuickFix(HighlightInfo.java:109)
    at com.intellij.codeInsight.daemon.impl.ShowIntentionsPass.addAvailableFixesForGroups(ShowIntentionsPass.java:114)
    at com.intellij.codeInsight.daemon.impl.ShowIntentionsPass.getActionsToShow(ShowIntentionsPass.java:324)
    at com.intellij.codeInsight.daemon.impl.ShowIntentionsPass.doCollectInformation(ShowIntentionsPass.java:255)
    at com.intellij.codeHighlighting.TextEditorHighlightingPass.collectInformation(TextEditorHighlightingPass.java:55)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.lambda$doRun$1(PassExecutorService.java:406)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass$$Lambda$5174/0x0000000802378250.consume(Unknown Source)
    at com.intellij.platform.diagnostic.telemetry.helpers.TraceKt.runWithSpanIgnoreThrows(trace.kt:76)
    at com.intellij.platform.diagnostic.telemetry.helpers.TraceUtil.runWithSpanThrows(TraceUtil.java:34)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.lambda$doRun$2(PassExecutorService.java:401)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass$$Lambda$5167/0x0000000802371b90.run(Unknown Source)
    at com.intellij.openapi.application.impl.ApplicationImpl.tryRunReadAction(ApplicationImpl.java:1075)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.lambda$doRun$3(PassExecutorService.java:392)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass$$Lambda$5163/0x0000000802371250.run(Unknown Source)
    at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$executeProcessUnderProgress$12(CoreProgressManager.java:610)
    at com.intellij.openapi.progress.impl.CoreProgressManager$$Lambda$883/0x0000000800912460.compute(Unknown Source)
    at com.intellij.openapi.progress.impl.CoreProgressManager.registerIndicatorAndRun(CoreProgressManager.java:685)
    at com.intellij.openapi.progress.impl.CoreProgressManager.computeUnderProgress(CoreProgressManager.java:641)
    at com.intellij.openapi.progress.impl.CoreProgressManager.executeProcessUnderProgress(CoreProgressManager.java:609)
    at com.intellij.openapi.progress.impl.ProgressManagerImpl.executeProcessUnderProgress(ProgressManagerImpl.java:78)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.doRun(PassExecutorService.java:391)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.lambda$run$0(PassExecutorService.java:367)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass$$Lambda$5160/0x000000080236fab0.run(Unknown Source)
    at com.intellij.openapi.application.impl.ReadMostlyRWLock.executeByImpatientReader(ReadMostlyRWLock.java:200)
    at com.intellij.openapi.application.impl.ApplicationImpl.executeByImpatientReader(ApplicationImpl.java:184)
    at com.intellij.codeInsight.daemon.impl.PassExecutorService$ScheduledPass.run(PassExecutorService.java:365)
    at com.intellij.concurrency.JobLauncherImpl$VoidForkJoinTask$1.exec(JobLauncherImpl.java:187)
    at java.base@17.0.10/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base@17.0.10/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
    at java.base@17.0.10/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
    at java.base@17.0.10/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
    at java.base@17.0.10/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)

  Did you see this issue @turkeylurkey before?     I can see that the exception is coming from org.microshed.lsp4ij. 

turkeylurkey commented 7 months ago

This is interesting but it might be expected for lsp4ij to be waiting for a response. We could investigate whether the language server crashed for some reason and hence did not respond. Or maybe the language server is just slow. Also I wonder if we are requesting code actions when it looks like a Java error, it does not look like one of our language servers has detected a diagnostic.

vaisakhkannan commented 7 months ago

The reason our language servers have not detected diagnostics is because IntelliJ got stuck before writing "{", as shown in the screenshot above. @mrglavas Have you seen this issue before?

mrglavas commented 7 months ago

@vaisakhkannan No, I've never encountered this before. If this is exclusively happening on MacOS that might explain why I haven't seen it. I run Windows on my workstation.

Regarding the stack trace you posted, I thought the CompletableFutures.waitUntilDone() method was written such that the thread periodically wakes up and checks if the action has been cancelled. I've never seen this working in action but I assumed there was some way to cancel and break out of the otherwise infinite wait without force quitting IntelliJ.

angelozerr commented 7 months ago

I found Intellij extension getting stuck while testing the below test  

@vaisakhkannan have you the problem with only the JUnit or too while editing the Java file?

Regarding the stack trace you posted, I thought the CompletableFutures.waitUntilDone() method was written such that the thread periodically wakes up and checks if the action has been cancelled. I've never seen this working in action but I assumed there was some way to cancel and break out of the otherwise infinite wait without force quitting IntelliJ.

Indeed the main idea is to check unitl 25 ms:

if current progress manager has been cancelled https://github.com/redhat-developer/lsp4ij/blob/6913946576da78a75131ef19e8af0efb37221526/src/main/java/com/redhat/devtools/lsp4ij/internal/CompletableFutures.java#L109
if PsiFile has changed https://github.com/redhat-developer/lsp4ij/blob/6913946576da78a75131ef19e8af0efb37221526/src/main/java/com/redhat/devtools/lsp4ij/internal/CompletableFutures.java#L113

This code avoid using timeout but if those two conditions are not matched, they will an infinite loop. I would like to really avoid using a timeout which breaks the LSP requests, but @vaisakhkannan if you have a problem while editing a file,it is a very very annoying problem.

angelozerr commented 7 months ago

@vaisakhkannan could you tell me please if you have encountered the problem of freeze by editing a file or it is just a matter with test.

I need to improve this wait until to prévent from infinite loop

TrevCraw commented 7 months ago

Hi @vaisakhkannan , @mrglavas and I were discussing this issue and we had a few thoughts:

It is possible there is nothing wrong with the code (language servers, clients, lsp4ij or the tests), and the GHA Mac machines are just super slow, which leads to IntelliJ thinking that it has a frozen/blocking thread and then killing it while it is waiting for the language server response. We were wondering if there is a mechanism in IntelliJ to configure it to not kill “frozen”/"blocking" threads or at least to increase the amount of time it is waiting before killing threads (if that is indeed what is going on).
There is still the possibility that there is something wrong with the language server(s). You mentioned in Slack that you “haven't observed the language server crashing in the logs”, but we are not so sure that language servers crashing would be observable in the IntelliJ logs. A good experiment would be to kill the language server process manually while LT IntelliJ is running and observe if anything shows up in the logs and/or the LSP Console.

angelozerr commented 7 months ago

You need to follow those rules:

computing code action list should be very fast, it means that you need to support resolve code action. The call of codeAction should return the list od code action without TextEdit which can be very slow. Do you support resolve code action?
code action should be cancelled as soon as possible (ex: when the PsiFile changed). For this usecase, I noticed (with our MP LS) that even LSP client cancel the code action request, it never cancel the future called on IJ / JDT side. I created the issue at https://github.com/eclipse/lsp4mp/issues/442

I have tried to emulate the slow computing of code action with a Thread.sleep(10000) and I type a character in the editor, I have noticed that:

when I set this sleep BEFORE the ReadAction.nonBloclinkReadAction, the IJ editor doesn't freeze.
when I set this sleep INSIDE the ReadAction.nonBloclinkReadAction, the IJ editor freeze and I have noticed that the DocumentListener at https://github.com/redhat-developer/lsp4ij/blob/6913946576da78a75131ef19e8af0efb37221526/src/main/java/com/redhat/devtools/lsp4ij/DocumentContentSynchronizer.java#L166 is called only after 10 seconds (after the Thread.sleep). It is a very annoying problem, I dn't know how to fix that, but in short answer code action list should be computed with very fast speed.

angelozerr commented 7 months ago

As LSP4IJ uses ReadAction.nonBlocking to compute anything on IJ side (to collect information from PsiJavaFile), I suggest that you read https://plugins.jetbrains.com/docs/intellij/general-threading-rules.html#read-action-cancellability

But I need to implement https://github.com/eclipse/lsp4mp/issues/442 to have better cancellability

vaisakhkannan commented 7 months ago

@angelozerr, I have encountered the issue of freezing only during UI testing and have not found any problems when editing a file.

angelozerr commented 7 months ago

@angelozerr, I have encountered the issue of freezing only during UI testing and have not found any problems when editing a file.

It is a great news!

mrglavas commented 7 months ago

You need to follow those rules:

* computing code action list should be very fast, it means that you need to support resolve code action. The call of codeAction should return the list od code action without TextEdit which can be very slow. Do you support resolve code action?

Our LSP4Jakarta client has everything in place to support resolving code actions. The client API even now has the resolveCodeAction() method to align with LSP4MP but I understand that the language server itself hasn't yet enabled this path and so it's still eagerly computing the text edits. Both MicroProfile and Jakarta share the same component: https://github.com/OpenLiberty/liberty-tools-intellij/blob/main/src/main/java/io/openliberty/tools/intellij/lsp4mp4ij/psi/internal/core/java/codeaction/CodeActionHandler.java. The code paths executed should be identical once the Jakarta language server supports resolve code action.

angelozerr commented 7 months ago

The code paths executed should be identical once the Jakarta language server supports resolve code action.

Once jakarta ls will support resolve code action I think it should fix your problem of this issue.

But as I said, the jakarta ls should support the cancellation of the future java/*/codeAction to improve again the performance when code action is cancelled on lsp client side.

You will have this usecase if you align your lsp4ij with our lsp4ij. I have managed refactor code action where code action appears even if there are not an error. In this case code action is called one each cursor caret changes.

mrglavas commented 7 months ago

The code paths executed should be identical once the Jakarta language server supports resolve code action.

Once jakarta ls will support resolve code action I think it should fix your problem of this issue.

But as I said, the jakarta ls should support the cancellation of the future java/*/codeAction to improve again the performance when code action is cancelled on lsp client side.

I was just about to comment on this. This feels like common code that could be shared between LSP4MP and LSP4Jakarta. I know Andy/Ed have been exploring commonality between the language servers and I think this could fit well in that layer. I guess in the short term they would copy your solution in LSP4MP into LSP4Jakarta.

You will have this usecase if you align your lsp4ij with our lsp4ij. I have managed refactor code action where code action appears even if there are not an error. In this case code action is called one each cursor caret changes.

We're making progress in that direction. It's been challenging for us to find a stable baseline which is why we're still taking snapshots and applying targeted fixes to them to resolve issues with upgrading to the new level. The current one is based on LSP4iJ from April 1st so hopefully not that far off of what's currently there. We do want to get to a point where we can just pull directly from the official project and just use what's being released. I've been meaning to ask about the stability of the API/component. Ideally upgrading to a new version of LSP4iJ (or any dependency for that matter) should be as simple as updating the version number and everything still works without requiring other code changes. In practice, it hasn't been that simple yet.

angelozerr commented 7 months ago

We plan to do a release soon with @fbricon when I will finish the rename symbol support.

I hope API will be stable but I think we need again some refactoring.

Once release will be done I will promote lsp4ij to several community like go rust scala clojure since now it is super easy to integrate any language server which supports stdio without developping an ij plugin https://github.com/redhat-developer/lsp4ij/blob/main/docs%2FUserDefinedLanguageServer.md

yeekangc commented 7 months ago

Thanks, @angelozerr. Do you have an outlook for the refactoring work that may still be needed for the API?

angelozerr commented 7 months ago

@yeekangc we plan to do a release soon and I hope I will do less refactoring, but as I'm not the author of the origin code it is hard to say that I will stop refactoring.

vaisakhkannan commented 7 months ago

I tested it with the latest pull of lsp4ij. Today, I completed the entire testing process and noticed some issues: not getting hover descriptions in bootstrap.properties and server.env files( during UI Testing also), so those tests failed. Additionally, I haven't seen the 'java.net.SocketTimeoutException: Read timed out' failure when I tested it locally. java.net.SocketTimeoutException: Read timed out this was the main reason behind mac os build failure. So I hoping it that , latest pull of lsp4ij will resolve mac os build failure that we are getting now.

mrglavas commented 7 months ago

I tested it with the latest pull of lsp4ij. Today, I completed the entire testing process and noticed some issues: not getting hover descriptions in bootstrap.properties and server.env files( during UI Testing also), so those tests failed. Additionally, I haven't seen the 'java.net.SocketTimeoutException: Read timed out' failure when I tested it locally. java.net.SocketTimeoutException: Read timed out this was the main reason behind mac os build failure. So I hoping it that , latest pull of lsp4ij will resolve mac os build failure that we are getting now.

@vaisakhkannan We are aware of the issues (see https://github.com/OpenLiberty/liberty-tools-intellij/issues/717) with hover text not being displayed (after the LSP4iJ upgrade) for property names in bootstrap.properties and server.env and have been investigating. We are still trying to determine the root cause. Five tests in total are failing on Linux.

vaisakhkannan commented 6 months ago

Once we use the latest LSP4IJ, ensure to check this issue and test whether all the tests are passing on Mac.

turkeylurkey commented 6 months ago

This looks like the IntelliJ UI hanged when it did not display { after it had been typed. I had this problem using a copy of lsp4ij to which I had added logging.

turkeylurkey commented 3 weeks ago

Once this happens we probably cannot recover and reestablish communication so it would be best to let it fail and retry in a new test run.

Perhaps exit JUnit with a code we can check for and then rerun if we detect this code. Alternatively search the log of the test run for this exception and rerun if necessary.

turkeylurkey commented 4 days ago

Searching the log was successful and then the return code of 23 is used:

Process 'Gradle Test Executor 1' finished with non-zero exit value 23

Still need to shutdown IntelliJ under test to allow restart.

OpenLiberty / liberty-tools-intellij

Mac automated UI test failure: SocketTimeoutException while typing in the editor #702