`ProtocolNotBoundException` exception when importing libraries in IDEA

[alisevych]

Description

The following exception has fallen into IDEA when Generate tests action had been initiated before import libraries and indexing in IDEA process finished:
com.jetbrains.rd.framework.base.ProtocolNotBoundException: Server.EngineProcessModel.obtainClassId::<<unbound>> is not bound to a protocol

To Reproduce

1. The following settings.properties was used:

logConcreteExecutionErrors=true instrumentedProcessLogLevel=Debug

2. Run the 'UTBotJava' project in IntelliJ Idea
3. Install one of the latest plugins built from main
4. Checkout main version from 3 days ago (to initiate import and indexing process lasting long)
5. Start test generation for 1-2 samples (static mocking was selected)

Expected behavior

No exception is supposed to fall down to IDE.

Actual behavior

ProtocolNotBoundException: Server.EngineProcessModel.obtainClassId::<> is not bound to a protocol

com.jetbrains.rd.framework.base.ProtocolNotBoundException: Server.EngineProcessModel.obtainClassId::<> is not bound to a protocol at com.jetbrains.rd.framework.base.RdBindableBase.nb(RdBindableBase.kt:52) at com.jetbrains.rd.framework.base.RdBindableBase.getProtocol(RdBindableBase.kt:36) at com.jetbrains.rd.framework.impl.RdCall.createResponseScheduler(RdTask.kt:264) at com.jetbrains.rd.framework.impl.RdCall.startSuspending(RdTask.kt:258) at com.jetbrains.rd.framework.IRdCall$DefaultImpls.startSuspending(TaskInterfaces.kt:167) at com.jetbrains.rd.framework.impl.RdCall.startSuspending(RdTask.kt:186) at com.jetbrains.rd.framework.IRdCall$DefaultImpls.startSuspending$default(TaskInterfaces.kt:167) at org.utbot.rd.UtRdUtilKt$startBlocking$1.invokeSuspend(UtRdUtil.kt:30) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:284) at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85) at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59) at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source) at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38) at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source) at org.utbot.rd.UtRdUtilKt.startBlocking(UtRdUtil.kt:30) at org.utbot.intellij.plugin.process.EngineProcess.obtainClassId(EngineProcess.kt:200) at org.utbot.intellij.plugin.generator.UtTestsDialogProcessor$createTests$1$1$run$1$2.compute(UtTestsDialogProcessor.kt:173) at org.utbot.intellij.plugin.generator.UtTestsDialogProcessor$createTests$1$1$run$1$2.compute(UtTestsDialogProcessor.kt:171) at com.intellij.openapi.project.DumbService.lambda$runReadActionInSmartMode$0(DumbService.java:113) at com.intellij.openapi.project.DumbService.lambda$runReadActionInSmartMode$1(DumbService.java:157) at com.intellij.openapi.application.impl.ApplicationImpl.runReadAction(ApplicationImpl.java:941) at com.intellij.openapi.application.ReadAction.compute(ReadAction.java:68) at com.intellij.openapi.project.DumbService.runReadActionInSmartMode(DumbService.java:150) at com.intellij.openapi.project.DumbService.runReadActionInSmartMode(DumbService.java:113) at org.utbot.intellij.plugin.generator.UtTestsDialogProcessor$createTests$1$1.run(UtTestsDialogProcessor.kt:171) at com.intellij.openapi.progress.impl.CoreProgressManager.startTask(CoreProgressManager.java:442) at com.intellij.openapi.progress.impl.ProgressManagerImpl.startTask(ProgressManagerImpl.java:114) at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$runProcessWithProgressAsynchronously$5(CoreProgressManager.java:493) at com.intellij.openapi.progress.impl.ProgressRunner.lambda$submit$3(ProgressRunner.java:252) at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$runProcess$2(CoreProgressManager.java:188) at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$executeProcessUnderProgress$12(CoreProgressManager.java:608) at com.intellij.openapi.progress.impl.CoreProgressManager.registerIndicatorAndRun(CoreProgressManager.java:683) at com.intellij.openapi.progress.impl.CoreProgressManager.computeUnderProgress(CoreProgressManager.java:639) at com.intellij.openapi.progress.impl.CoreProgressManager.executeProcessUnderProgress(CoreProgressManager.java:607) at com.intellij.openapi.progress.impl.ProgressManagerImpl.executeProcessUnderProgress(ProgressManagerImpl.java:60) at com.intellij.openapi.progress.impl.CoreProgressManager.runProcess(CoreProgressManager.java:175) at com.intellij.openapi.progress.impl.ProgressRunner.lambda$submit$4(ProgressRunner.java:252) at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) 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.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:702) at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:699) at java.base/java.security.AccessController.doPrivileged(AccessController.java:399) at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(Executors.java:699) at java.base/java.lang.Thread.run(Thread.java:833)

Visual proofs (screenshots, logs, images)

idea.log

2022-11-28 16:10:10,487 [1609496] INFO - STDOUT - Locked 2022-11-28 16:10:10,567 [1609576] INFO - STDOUT - Engine process started with PID = 16012 2022-11-28 16:10:10,569 [1609578] INFO - STDOUT - Engine process log file - C:\Users\lWX1182794\AppData\Local\Temp\UTBot\rdEngineProcessLogs\28-11-2022_16-10-10.log 2022-11-28 16:10:10,573 [1609582] INFO - STDOUT - RdCoroutineHost overridden 2022-11-28 16:10:15,660 [1614669] INFO - #c.j.p.intellij-plugin - [3, source=INIT] ProjectDataProvider#fetchInfoFor() - Failed obtaining data for 8 dependencies 2022-11-28 16:11:17,728 [1676737] WARN - #c.i.u.x.Binding - no accessors for org.jetbrains.idea.perforce.perforce.ConnectionId 2022-11-28 16:11:17,759 [1676768] INFO - #c.i.c.ComponentStoreImpl - Saving Project(name=utbot, containerState=COMPONENT_CREATED, componentStore=C:\Users\lWX1182794\UTBotJava)GradleLocalSettings took 11 ms 2022-11-28 16:12:17,919 [1736928] INFO - STDOUT - ServerSocket: start terminating lifetime 2022-11-28 16:12:18,434 [1737443] INFO - STDOUT - ServerSocket: termination finished

2022-11-28 16:12:56,772 [1775781] INFO - STDOUT - Unlocked
2022-11-28 16:12:56,875 [1775884] SEVERE - #c.i.o.p.Task - Server.EngineProcessModel.obtainClassId::<> is not bound to a protocol
com.jetbrains.rd.framework.base.ProtocolNotBoundException: Server.EngineProcessModel.obtainClassId::<> is not bound to a protocol
at com.jetbrains.rd.framework.base.RdBindableBase.nb(RdBindableBase.kt:52)
at com.jetbrains.rd.framework.base.RdBindableBase.getProtocol(RdBindableBase.kt:36)
at com.jetbrains.rd.framework.impl.RdCall.createResponseScheduler(RdTask.kt:264)
at com.jetbrains.rd.framework.impl.RdCall.startSuspending(RdTask.kt:258)
at com.jetbrains.rd.framework.IRdCall$DefaultImpls.startSuspending(TaskInterfaces.kt:167)
at com.jetbrains.rd.framework.impl.RdCall.startSuspending(RdTask.kt:186)
at com.jetbrains.rd.framework.IRdCall$DefaultImpls.startSuspending$default(TaskInterfaces.kt:167)
at org.utbot.rd.UtRdUtilKt$startBlocking$1.invokeSuspend(UtRdUtil.kt:30)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:284)
at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
at org.utbot.rd.UtRdUtilKt.startBlocking(UtRdUtil.kt:30)
at org.utbot.intellij.plugin.process.EngineProcess.obtainClassId(EngineProcess.kt:200)
at org.utbot.intellij.plugin.generator.UtTestsDialogProcessor$createTests$1$1$run$1$2.compute(UtTestsDialogProcessor.kt:173)
at org.utbot.intellij.plugin.generator.UtTestsDialogProcessor$createTests$1$1$run$1$2.compute(UtTestsDialogProcessor.kt:171)
at com.intellij.openapi.project.DumbService.lambda$runReadActionInSmartMode$0(DumbService.java:113)
at com.intellij.openapi.project.DumbService.lambda$runReadActionInSmartMode$1(DumbService.java:157)
at com.intellij.openapi.application.impl.ApplicationImpl.runReadAction(ApplicationImpl.java:941)
at com.intellij.openapi.application.ReadAction.compute(ReadAction.java:68)
at com.intellij.openapi.project.DumbService.runReadActionInSmartMode(DumbService.java:150)
at com.intellij.openapi.project.DumbService.runReadActionInSmartMode(DumbService.java:113)
at org.utbot.intellij.plugin.generator.UtTestsDialogProcessor$createTests$1$1.run(UtTestsDialogProcessor.kt:171)
at com.intellij.openapi.progress.impl.CoreProgressManager.startTask(CoreProgressManager.java:442)
at com.intellij.openapi.progress.impl.ProgressManagerImpl.startTask(ProgressManagerImpl.java:114)
at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$runProcessWithProgressAsynchronously$5(CoreProgressManager.java:493)
at com.intellij.openapi.progress.impl.ProgressRunner.lambda$submit$3(ProgressRunner.java:252)
at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$runProcess$2(CoreProgressManager.java:188)
at com.intellij.openapi.progress.impl.CoreProgressManager.lambda$executeProcessUnderProgress$12(CoreProgressManager.java:608)
at com.intellij.openapi.progress.impl.CoreProgressManager.registerIndicatorAndRun(CoreProgressManager.java:683)
at com.intellij.openapi.progress.impl.CoreProgressManager.computeUnderProgress(CoreProgressManager.java:639)
at com.intellij.openapi.progress.impl.CoreProgressManager.executeProcessUnderProgress(CoreProgressManager.java:607)
at com.intellij.openapi.progress.impl.ProgressManagerImpl.executeProcessUnderProgress(ProgressManagerImpl.java:60)
at com.intellij.openapi.progress.impl.CoreProgressManager.runProcess(CoreProgressManager.java:175)
at com.intellij.openapi.progress.impl.ProgressRunner.lambda$submit$4(ProgressRunner.java:252)
at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
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.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:702)
at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(Executors.java:699)
at java.base/java.security.AccessController.doPrivileged(AccessController.java:399)
at java.base/java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(Executors.java:699)
at java.base/java.lang.Thread.run(Thread.java:833)
2022-11-28 16:12:56,876 [1775885] SEVERE - #c.i.o.p.Task - IntelliJ IDEA 2022.2.3 Build #IU-222.4345.14
2022-11-28 16:12:56,876 [1775885] SEVERE - #c.i.o.p.Task - JDK: 17.0.4.1; VM: OpenJDK 64-Bit Server VM; Vendor: JetBrains s.r.o.
2022-11-28 16:12:56,876 [1775885] SEVERE - #c.i.o.p.Task - OS: Windows 10
2022-11-28 16:12:56,877 [1775886] SEVERE - #c.i.o.p.Task - Plugin to blame: UnitTestBot version: 2022.11.563.

28-11-2022_16-10-10.log

16:10:11.627 | INFO | EngineProcessMain | RdCWARNING: Illegal reflective access by com.esotericsoftware.kryo.kryo5.unsafe.UnsafeUtil (file:/C:/Users/lWX1182794/AppData/Roaming/JetBrains/IntelliJIdea2022.2/plugins/utbot-intellij/lib/kryo5-5.3.0.jar) to constructor java.nio.DirectByteBuffer(long,int) WARNING: Illegal reflective access by com.esotericsoftware.kryo.kryo5.unsafe.UnsafeUtil (file:/C:/Users/lWX1182794/AppData/Roaming/JetBrains/IntelliJIdea2022.2/plugins/utbot-intellij/lib/kryo5-5.3.0.jar) to method sun.nio.ch.DirectBuffer.cleaner() ClientSocket : connected 16:10:11.697 | DEBUG | EngineProcessMain | RESUME :: {id = ClientSocket/Sender, state = 'AsyncProcessing'} 16:10:11.795 | INFO | EngineProcessMain | signalled 16:10:12.010 | INFO | AnalyticsConfigureUtil | PathSelectorType: INHERITORS_SELECTOR 16:12:17.802 | INFO | EngineProcessMain | terminating lifetime by timeout 16:12:17.807 | INFO | EngineProcessMain | runBlocking ending 16:12:17.807 | INFO | EngineProcessMain | ClientSocket: start terminating lifetime 16:12:17.807 | DEBUG | EngineProcessMain | ClientSocket: shutting down ack sending executor 16:12:17.807 | INFO | EngineProcessMain | runBlocking ended 16:12:17.808 | DEBUG | EngineProcessMain | ClientSocket: send buffer stopped, success: true 16:12:17.808 | DEBUG | EngineProcessMain | ClientSocket: closing socket 16:12:17.809 | DEBUG | EngineProcessMain | ClientSocket: waiting for receiver thread 16:12:17.809 | DEBUG | EngineProcessMain | Exception in SocketWire.Receive: ClientSocket: java.net.SocketException: Socket closed 16:12:17.811 | DEBUG | EngineProcessMain | ClientSocket: receiverProc finished 16:12:17.811 | DEBUG | EngineProcessMain | ClientSocket: terminated. 16:12:17.811 | INFO | EngineProcessMain | ClientSocket: termination finished

Environment

Windows 10 Pro
IntelliJ IDEA 2022.2.2
Gradle
JDK 11

Additional context

javaw.exe process was terminated (checked in Task Manager)

[Domonion]

The problem is with DumbService.runReadActionInSmartMode:
It postpones read action until indexing finished which might take more than 2 minutes. Process would not receive any signal from parent and will consider itself as orphan thus terminate. We should somehow signal process that it should wait for any signal despite timeout