Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

New project initialization times out on "get host name" in vcs/init request #6447

Closed
mwu-tow opened this issue Apr 27, 2023 · 8 comments · Fixed by #6463
Closed

New project initialization times out on "get host name" in vcs/init request #6447

mwu-tow opened this issue Apr 27, 2023 · 8 comments · Fixed by #6463
Assignees

Comments

@mwu-tow
Copy link
Contributor

mwu-tow commented Apr 27, 2023

When I open IDE and create a new project this appears:

obraz

The log from the Language Server JSON WebSocket:

{"jsonrpc":"2.0","id":0,"method":"session/initProtocolConnection","params":{"clientId":"8b598370-a688-4cde-ab1f-fc1a04f878cb"}}	127	
03:40:15.906
{"jsonrpc":"2.0","id":0,"result":{"contentRoots":[{"type":"Project","id":"f1d0764b-3461-4aa3-a930-a2a00c18c8b9"},{"type":"FileSystemRoot","id":"cf2a61c4-bde7-4da5-8dd8-531b50ffad49","path":"C:\\"},{"type":"FileSystemRoot","id":"ccb98ff8-9601-4346-856e-05ac0c046fba","path":"G:\\"},{"type":"FileSystemRoot","id":"4f30d730-08d5-4da2-884e-38570f63e00b","path":"H:\\"},{"type":"FileSystemRoot","id":"e2e7cccc-a7e5-47f7-b86c-b4b4ccb11c10","path":"R:\\"},{"type":"FileSystemRoot","id":"987897e6-7ea0-43c4-8cdc-8e55bfb0da98","path":"E:\\"},{"type":"Home","id":"ac25947f-5ab1-492f-a071-260818aedb0d"},{"type":"FileSystemRoot","id":"a05bd352-db53-4c46-b40d-5a45ac007301","path":"D:\\"},{"type":"FileSystemRoot","id":"b666283a-7b49-4f44-a433-86c1451f2c37","path":"F:\\"}]}}	763	
03:40:18.558
{"jsonrpc":"2.0","id":1,"method":"search/getSuggestionsDatabase","params":{}}	77	
03:40:18.577
{"jsonrpc":"2.0","id":1,"result":{"entries":[],"currentVersion":0}}	67	
03:40:18.632
{"jsonrpc":"2.0","id":2,"method":"vcs/init","params":{"root":{"rootId":"f1d0764b-3461-4aa3-a930-a2a00c18c8b9","segments":[]}}}	126	
03:40:18.635
{"jsonrpc":"2.0","id":2,"error":{"code":1,"message":"Service error"}}	69	
03:40:23.716

The log from the Project Manager:

[info] [2023-04-27T01:34:53.756Z] [org.enso.projectmanager.boot.ProjectManager$] Starting Project Manager...
[info] [2023-04-27T01:34:54.939Z] [org.enso.projectmanager.boot.ProjectManager$] Started server at 127.0.0.1:30535, press enter to kill server
[info] [2023-04-27T01:34:55.949Z] [org.enso.projectmanager.protocol.ClientController] Client connected to Project Manager [8bc6ef14-5bc5-4c38-8afa-d1830cdb4c8c]
[warn] [2023-04-27T01:34:56.774Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.3.3),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:34:56.782Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.2.22),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:34:56.783Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.4.19),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:35:00.397Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.3.3),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:35:00.411Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.2.22),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:35:00.412Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.4.19),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[info] [2023-04-27T01:35:00.626Z] [org.enso.projectmanager.infrastructure.log.Slf4jLogging] Created project with actual name [Unnamed_14].
[info] [2023-04-27T01:35:00.637Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine [2023.1.1-nightly.2023.4.26] found.
[info] [2023-04-27T01:35:00.716Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.1-java11].
[info] [2023-04-27T01:35:01.651Z] [org.enso.projectmanager.infrastructure.log.Slf4jLogging] Project created [Project(0d359122-d78d-4ccf-9436-b8f23eb18c4f,Unnamed_14,local,UserProject,2023-04-27T01:35:00.637527Z,None,None,None,None)].
[info] [2023-04-27T01:35:01.891Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine [2023.1.1-nightly.2023.4.26] found.
[info] [2023-04-27T01:35:01.972Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.1-java11].
[info] [2023-04-27T01:35:01.973Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Booting a language server [LanguageServerDescriptor(language-server-0d359122-d78d-4ccf-9436-b8f23eb18c4f,0ee0da2d-c41c-44ea-81f9-f5eb751e3deb,C:\Users\mwurb\enso\projects\Unnamed_14,NetworkConfig(127.0.0.1,49152,65535),org.enso.projectmanager.versionmanagement.DefaultDistributionConfiguration$@7883f392,2023.1.1-nightly.2023.4.26,JVMSettings(None,List()),false,None,None,None,Future(Success(Some(ws://localhost:49505/))),false)].
[info] [2023-04-27T01:35:01.974Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Found sockets for the language server [json:127.0.0.1:58606, binary:127.0.0.1:60593].
[info] [2023-04-27T01:35:02.012Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine [2023.1.1-nightly.2023.4.26] found.
[info] [2023-04-27T01:35:02.221Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.1-java11].
[info] [2023-04-27T01:35:03.472Z] [org.enso.languageserver.boot.LanguageServerComponent] Starting Language Server...
[info] [2023-04-27T01:35:03.481Z] [org.enso.languageserver.boot.MainModule] Initializing main module of the Language Server from [2023.1.1-nightly.2023.4.26, LanguageServerConfig(127.0.0.1,58606,60593,0ee0da2d-c41c-44ea-81f9-f5eb751e3deb,C:\Users\mwurb\enso\projects\Unnamed_14,ProfilingConfig(None,None,None),StartupConfig(false),language-server,scala.concurrent.impl.ExecutionContextImpl$$anon$3@3a12c404[Running, parallelism = 16, size = 2, active = 1, running = 1, steals = 0, tasks = 0, submissions = 0]), info]
[info] [2023-04-27T01:35:04.141Z] [org.enso.languageserver.runtime.RuntimeConnector] Starting the runtime connector.
[info] [2023-04-27T01:35:04.141Z] [org.enso.languageserver.runtime.RuntimeConnector] Runtime connector established connection with the message endpoint [com.oracle.truffle.api.instrumentation.TruffleInstrument$Env$MessageTransportProxy$MessageEndpointProxy@6adf7e07].
[info] [2023-04-27T01:35:04.295Z] [org.enso.languageserver.search.SuggestionsHandler] Starting suggestions handler from [Config(projectContentRoot=ContentRootWithFile(contentRoot=Project(0ee0da2d-c41c-44ea-81f9-f5eb751e3deb),file=***\Unnamed_14), fileManager=FileManagerConfig(3 seconds,16), vcsManager=VcsManagerConfig(5 seconds,3 seconds,true), pathWatcher=PathWatcherConfig(5 seconds,5 seconds,10), executionContext=ExecutionContextConfig(5 seconds), directories=DirectoriesConfig(***\Unnamed_14)), org.enso.searcher.sql.SqlSuggestionsRepo@23e00cce].
[info] [2023-04-27T01:35:04.831Z] [org.enso.languageserver.boot.MainModule] Main module of the Language Server initialized with config [Config(projectContentRoot=ContentRootWithFile(contentRoot=Project(0ee0da2d-c41c-44ea-81f9-f5eb751e3deb),file=***\Unnamed_14), fileManager=FileManagerConfig(3 seconds,16), vcsManager=VcsManagerConfig(5 seconds,3 seconds,true), pathWatcher=PathWatcherConfig(5 seconds,5 seconds,10), executionContext=ExecutionContextConfig(5 seconds), directories=DirectoriesConfig(***\Unnamed_14))].
[info] [2023-04-27T01:35:04.98Z] [org.enso.languageserver.boot.LanguageServerComponent] Started server at json:127.0.0.1:58606, binary:127.0.0.1:60593
[info] [2023-04-27T01:35:05.9Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Language server booted [LanguageServerConnectionInfo(127.0.0.1,58606,60593)].
[info] [2023-04-27T01:35:05.992Z] [org.enso.languageserver.protocol.json.JsonConnectionController] Initializing resources.
[info] [2023-04-27T01:35:05.994Z] [org.enso.languageserver.boot.resource.DirectoriesInitialization] Initializing directories...
[info] [2023-04-27T01:35:05.994Z] [org.enso.languageserver.boot.resource.DirectoriesInitialization] Initialized directories.
[info] [2023-04-27T01:35:05.998Z] [org.enso.languageserver.boot.resource.JsonRpcInitializationComponent] Initializing JSON-RPC protocol.
[info] [2023-04-27T01:35:05.998Z] [org.enso.languageserver.boot.resource.JsonRpcInitializationComponent] JSON-RPC protocol initialized.
[info] [2023-04-27T01:35:05.998Z] [org.enso.languageserver.boot.resource.ZioRuntimeInitialization] Initializing ZIO runtime...
[info] [2023-04-27T01:35:06.254Z] [org.enso.languageserver.boot.resource.ZioRuntimeInitialization] ZIO runtime initialized [org.enso.languageserver.effect.ExecutionContextRuntime@19e20f7e].
[info] [2023-04-27T01:35:06.254Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initializing sql database [org.enso.searcher.sql.SqlDatabase@46660e1]...
[info] [2023-04-27T01:35:06.352Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initialized sql database [org.enso.searcher.sql.SqlDatabase@46660e1].
[info] [2023-04-27T01:35:06.352Z] [org.enso.languageserver.boot.resource.TruffleContextInitialization] Initializing Runtime context...
[info] [2023-04-27T01:35:08.257Z] [org.enso.languageserver.boot.resource.TruffleContextInitialization] Initialized Runtime context.
[info] [2023-04-27T01:35:08.257Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: Truffle context initialized.
[info] [2023-04-27T01:35:08.258Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initializing suggestions repo [***\suggestions.db]...
[info] [2023-04-27T01:35:08.325Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: project name is updated to [Unnamed_14].
[info] [2023-04-27T01:35:08.498Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: got type graph response.
[info] [2023-04-27T01:35:08.699Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initialized Suggestions repo [***\suggestions.db].
[info] [2023-04-27T01:35:08.699Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: suggestions repo initialized.
[info] [2023-04-27T01:35:08.699Z] [org.enso.languageserver.protocol.json.JsonConnectionController] RPC session initialized for client [65b3f82b-b23e-476a-b086-8791d339cde6].
[info] [2023-04-27T01:35:08.735Z] [org.enso.languageserver.protocol.binary.BinaryConnectionController] Data session initialized for client: 65b3f82b-b23e-476a-b086-8791d339cde6 [127.0.0.1:49543].
[info] [2023-04-27T01:35:12.763Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/2#1756797557] was not delivered. [1] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/2#1756797557] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[info] [2023-04-27T01:35:13.384Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/3#-2036585870] was not delivered. [2] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/3#-2036585870] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[error] [2023-04-27T01:35:13.901Z] [org.enso.languageserver.requesthandler.vcs.InitVcsHandler] Initialize project request [Number(2)] for [65b3f82b-b23e-476a-b086-8791d339cde6] failed with: null.
java.util.concurrent.TimeoutException: None
  at org.enso.languageserver.effect.ZioExec$.<clinit>(Exec.scala:134)
  at org.enso.languageserver.effect.ZioExec.$anonfun$execTimed$5(Exec.scala:85)
  at scala.Option.fold(Option.scala:263)
  at org.enso.languageserver.effect.ZioExec.$anonfun$execTimed$4(Exec.scala:85)
  at org.enso.languageserver.effect.ZioExec.$anonfun$execTimed$4$adapted(Exec.scala:85)
  at zio.ZIO.$anonfun$foldCause$4(ZIO.scala:683)
  at zio.internal.FiberRuntime.runLoop(FiberRuntime.scala:958)
  at zio.internal.FiberRuntime.evaluateEffect(FiberRuntime.scala:391)
  at zio.internal.FiberRuntime.evaluateMessageWhileSuspended(FiberRuntime.scala:514)
  at zio.internal.FiberRuntime.drainQueueOnCurrentThread(FiberRuntime.scala:230)
  at zio.internal.FiberRuntime.run(FiberRuntime.scala:139)
  at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:49)
  at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1426)
  at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
  at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
  at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
  at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
  at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
[info] [2023-04-27T01:35:13.919Z] [org.enso.languageserver.protocol.binary.BinaryConnectionController] Connection closed [127.0.0.1:49543].
[info] [2023-04-27T01:35:14.004Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/4#-308611560] was not delivered. [3] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/4#-308611560] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[info] [2023-04-27T01:35:14.624Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/5#1868720252] was not delivered. [4] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/5#1868720252] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[info] [2023-04-27T01:40:05.177Z] [org.enso.projectmanager.protocol.ClientController] Client disconnected from the Project Manager [8bc6ef14-5bc5-4c38-8afa-d1830cdb4c8c]
[info] [2023-04-27T01:40:05.184Z] [org.enso.languageserver.runtime.RuntimeKiller] Shutting down the runtime server [Actor[akka://language-server/user/runtime-connector#-2075484827]].
[info] [2023-04-27T01:40:05.192Z] [org.enso.languageserver.runtime.RuntimeKiller] Shutting down the Truffle context [org.graalvm.polyglot.Context@775ad65c]. Attempt #1.
[info] [2023-04-27T01:40:05.298Z] [org.enso.languageserver.boot.LanguageServerComponent] Terminated truffle context.
[info] [2023-04-27T01:40:05.306Z] [org.enso.languageserver.boot.LanguageServerComponent] Terminated json connections.
[info] [2023-04-27T01:40:05.308Z] [org.enso.languageserver.boot.LanguageServerComponent] Terminated binary connections.
[info] [2023-04-27T01:40:05.325Z] [akka.actor.CoordinatedShutdown] Running CoordinatedShutdown with reason [ActorSystemTerminateReason]
[info] [2023-04-27T01:40:05.395Z] [org.enso.languageserver.boot.LanguageServerComponent] Terminated actor system.
[info] [2023-04-27T01:40:05.396Z] [org.enso.languageserver.boot.MainModule] Closed Language Server main module.
[info] [2023-04-27T01:40:05.397Z] [org.enso.languageserver.boot.LanguageServerComponent] Terminated main module.
[info] [2023-04-27T01:40:05.501Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerController] Language server shut down successfully [Project(0d359122-d78d-4ccf-9436-b8f23eb18c4f,Unnamed_14,local,UserProject,2023-04-27T01:35:00.637527Z,Some(Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())),Some(2023-04-27T01:35:01.889703300Z),Some(C:\Users\mwurb\enso\projects\Unnamed_14),Some(2023-04-27T01:35:01.433749Z))].
[info] [2023-04-27T01:40:06.729Z] [org.enso.projectmanager.protocol.ClientController] Client connected to Project Manager [67abe176-d884-4137-9440-56712854c3c7]
[warn] [2023-04-27T01:40:06.852Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.3.3),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:40:06.86Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.2.22),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:40:06.86Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.4.19),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:40:09.12Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.3.3),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:40:09.13Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.2.22),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[warn] [2023-04-27T01:40:09.131Z] [org.enso.projectmanager.service.ProjectService] Could not resolve engine version for Edition(Some(2023.1.1-nightly.2023.4.19),None,Map(),Map()). Falling back to Edition(Some(2023.1.1-nightly.2023.4.26),None,Map(),Map())
[info] [2023-04-27T01:40:09.328Z] [org.enso.projectmanager.infrastructure.log.Slf4jLogging] Created project with actual name [Unnamed_15].
[info] [2023-04-27T01:40:09.339Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine [2023.1.1-nightly.2023.4.26] found.
[info] [2023-04-27T01:40:09.411Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.1-java11].
[info] [2023-04-27T01:40:10.253Z] [org.enso.projectmanager.infrastructure.log.Slf4jLogging] Project created [Project(cf0215e6-cb93-407c-b032-5fe8b4152e63,Unnamed_15,local,UserProject,2023-04-27T01:40:09.338760200Z,None,None,None,None)].
[info] [2023-04-27T01:40:10.5Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine [2023.1.1-nightly.2023.4.26] found.
[info] [2023-04-27T01:40:10.567Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.1-java11].
[info] [2023-04-27T01:40:10.567Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Booting a language server [LanguageServerDescriptor(language-server-cf0215e6-cb93-407c-b032-5fe8b4152e63,f1d0764b-3461-4aa3-a930-a2a00c18c8b9,C:\Users\mwurb\enso\projects\Unnamed_15,NetworkConfig(127.0.0.1,49152,65535),org.enso.projectmanager.versionmanagement.DefaultDistributionConfiguration$@7883f392,2023.1.1-nightly.2023.4.26,JVMSettings(None,List()),false,None,None,None,Future(Success(Some(ws://localhost:49505/))),false)].
[info] [2023-04-27T01:40:10.568Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Found sockets for the language server [json:127.0.0.1:55213, binary:127.0.0.1:59369].
[info] [2023-04-27T01:40:10.569Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine [2023.1.1-nightly.2023.4.26] found.
[info] [2023-04-27T01:40:10.653Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.1-java11].
[info] [2023-04-27T01:40:11.811Z] [org.enso.languageserver.boot.LanguageServerComponent] Starting Language Server...
[info] [2023-04-27T01:40:11.82Z] [org.enso.languageserver.boot.MainModule] Initializing main module of the Language Server from [2023.1.1-nightly.2023.4.26, LanguageServerConfig(127.0.0.1,55213,59369,f1d0764b-3461-4aa3-a930-a2a00c18c8b9,C:\Users\mwurb\enso\projects\Unnamed_15,ProfilingConfig(None,None,None),StartupConfig(false),language-server,scala.concurrent.impl.ExecutionContextImpl$$anon$3@3a12c404[Running, parallelism = 16, size = 2, active = 1, running = 1, steals = 0, tasks = 0, submissions = 0]), info]
[info] [2023-04-27T01:40:12.451Z] [org.enso.languageserver.runtime.RuntimeConnector] Starting the runtime connector.
[info] [2023-04-27T01:40:12.451Z] [org.enso.languageserver.runtime.RuntimeConnector] Runtime connector established connection with the message endpoint [com.oracle.truffle.api.instrumentation.TruffleInstrument$Env$MessageTransportProxy$MessageEndpointProxy@2f033a65].
[info] [2023-04-27T01:40:12.599Z] [org.enso.languageserver.search.SuggestionsHandler] Starting suggestions handler from [Config(projectContentRoot=ContentRootWithFile(contentRoot=Project(f1d0764b-3461-4aa3-a930-a2a00c18c8b9),file=***\Unnamed_15), fileManager=FileManagerConfig(3 seconds,16), vcsManager=VcsManagerConfig(5 seconds,3 seconds,true), pathWatcher=PathWatcherConfig(5 seconds,5 seconds,10), executionContext=ExecutionContextConfig(5 seconds), directories=DirectoriesConfig(***\Unnamed_15)), org.enso.searcher.sql.SqlSuggestionsRepo@39d7d147].
[info] [2023-04-27T01:40:13.115Z] [org.enso.languageserver.boot.MainModule] Main module of the Language Server initialized with config [Config(projectContentRoot=ContentRootWithFile(contentRoot=Project(f1d0764b-3461-4aa3-a930-a2a00c18c8b9),file=***\Unnamed_15), fileManager=FileManagerConfig(3 seconds,16), vcsManager=VcsManagerConfig(5 seconds,3 seconds,true), pathWatcher=PathWatcherConfig(5 seconds,5 seconds,10), executionContext=ExecutionContextConfig(5 seconds), directories=DirectoriesConfig(***\Unnamed_15))].
[info] [2023-04-27T01:40:13.258Z] [org.enso.languageserver.boot.LanguageServerComponent] Started server at json:127.0.0.1:55213, binary:127.0.0.1:59369
[info] [2023-04-27T01:40:14.29Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Language server booted [LanguageServerConnectionInfo(127.0.0.1,55213,59369)].
[info] [2023-04-27T01:40:15.919Z] [org.enso.languageserver.protocol.json.JsonConnectionController] Initializing resources.
[info] [2023-04-27T01:40:15.921Z] [org.enso.languageserver.boot.resource.DirectoriesInitialization] Initializing directories...
[info] [2023-04-27T01:40:15.922Z] [org.enso.languageserver.boot.resource.DirectoriesInitialization] Initialized directories.
[info] [2023-04-27T01:40:15.925Z] [org.enso.languageserver.boot.resource.JsonRpcInitializationComponent] Initializing JSON-RPC protocol.
[info] [2023-04-27T01:40:15.925Z] [org.enso.languageserver.boot.resource.JsonRpcInitializationComponent] JSON-RPC protocol initialized.
[info] [2023-04-27T01:40:15.926Z] [org.enso.languageserver.boot.resource.ZioRuntimeInitialization] Initializing ZIO runtime...
[info] [2023-04-27T01:40:16.216Z] [org.enso.languageserver.boot.resource.ZioRuntimeInitialization] ZIO runtime initialized [org.enso.languageserver.effect.ExecutionContextRuntime@5518e332].
[info] [2023-04-27T01:40:16.216Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initializing sql database [org.enso.searcher.sql.SqlDatabase@37d21d8d]...
[info] [2023-04-27T01:40:16.324Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initialized sql database [org.enso.searcher.sql.SqlDatabase@37d21d8d].
[info] [2023-04-27T01:40:16.325Z] [org.enso.languageserver.boot.resource.TruffleContextInitialization] Initializing Runtime context...
[info] [2023-04-27T01:40:18.167Z] [org.enso.languageserver.boot.resource.TruffleContextInitialization] Initialized Runtime context.
[info] [2023-04-27T01:40:18.168Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: Truffle context initialized.
[info] [2023-04-27T01:40:18.17Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initializing suggestions repo [***\suggestions.db]...
[info] [2023-04-27T01:40:18.231Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: project name is updated to [Unnamed_15].
[info] [2023-04-27T01:40:18.373Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: got type graph response.
[info] [2023-04-27T01:40:18.549Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initialized Suggestions repo [***\suggestions.db].
[info] [2023-04-27T01:40:18.55Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: suggestions repo initialized.
[info] [2023-04-27T01:40:18.55Z] [org.enso.languageserver.protocol.json.JsonConnectionController] RPC session initialized for client [8b598370-a688-4cde-ab1f-fc1a04f878cb].
[info] [2023-04-27T01:40:18.57Z] [org.enso.languageserver.protocol.binary.BinaryConnectionController] Data session initialized for client: 8b598370-a688-4cde-ab1f-fc1a04f878cb [127.0.0.1:50959].
[info] [2023-04-27T01:40:21.182Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/28#514565792] was not delivered. [5] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/28#514565792] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[info] [2023-04-27T01:40:21.803Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/29#-1688584594] was not delivered. [6] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/29#-1688584594] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[info] [2023-04-27T01:40:22.425Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/30#886229349] was not delivered. [7] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/30#886229349] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[info] [2023-04-27T01:40:23.064Z] [akka.actor.LocalActorRef] Message [akka.actor.ReceiveTimeout$] to Actor[akka://project-manager/system/IO-TCP/selectors/$a/31#-1948095722] was not delivered. [8] dead letters encountered. If this is not an expected behavior then Actor[akka://project-manager/system/IO-TCP/selectors/$a/31#-1948095722] may have terminated unexpectedly. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
[error] [2023-04-27T01:40:23.715Z] [org.enso.languageserver.requesthandler.vcs.InitVcsHandler] Initialize project request [Number(2)] for [8b598370-a688-4cde-ab1f-fc1a04f878cb] failed with: null.
java.util.concurrent.TimeoutException: None
  at org.enso.languageserver.effect.ZioExec$.<clinit>(Exec.scala:134)
  at org.enso.languageserver.effect.ZioExec.$anonfun$execTimed$5(Exec.scala:85)
  at scala.Option.fold(Option.scala:263)
  at org.enso.languageserver.effect.ZioExec.$anonfun$execTimed$4(Exec.scala:85)
  at org.enso.languageserver.effect.ZioExec.$anonfun$execTimed$4$adapted(Exec.scala:85)
  at zio.ZIO.$anonfun$foldCause$4(ZIO.scala:683)
  at zio.internal.FiberRuntime.runLoop(FiberRuntime.scala:958)
  at zio.internal.FiberRuntime.evaluateEffect(FiberRuntime.scala:391)
  at zio.internal.FiberRuntime.evaluateMessageWhileSuspended(FiberRuntime.scala:514)
  at zio.internal.FiberRuntime.drainQueueOnCurrentThread(FiberRuntime.scala:230)
  at zio.internal.FiberRuntime.run(FiberRuntime.scala:139)
  at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:49)
  at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1426)
  at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
  at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
  at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
  at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
  at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
[info] [2023-04-27T01:40:23.721Z] [org.enso.languageserver.protocol.binary.BinaryConnectionController] Connection closed [127.0.0.1:50959].

I suspect that this has something to do with my local environment, as I've tested quite a number of nightlies from the last month and they display the same behavior, while previously they were working correctly. But now this happens every single time and I don't know what is the reason.
I've tried running IDE on a relatively fresh VM Windows environment and the same thing happens there. I don't see this on Linux though.

Logs come from 2023.1.1-nightly.2023.4.26 build.

@vitvakatu
Copy link
Contributor

It seems like a return of #4960

Also related: #5058

@hubertp hubertp removed the -tooling Category: tooling label Apr 27, 2023
@hubertp
Copy link
Contributor

hubertp commented Apr 27, 2023

Yes, could in theory happen if the FS is reaaaaaaly slow. That's why #5058 would be the best way to fix it.

@mwu-tow
Copy link
Contributor Author

mwu-tow commented Apr 27, 2023

@hubertp

Yes, could in theory happen if the FS is reaaaaaaly slow. That's why #5058 would be the best way to fix it.

I don't think my system is that slow. I can still build the GUI! I suspect some other change in the environment might have happened, but I'd need some pointers on how to debug this.

@JaroslavTulach
Copy link
Member

JaroslavTulach commented Apr 27, 2023

Michal says that he can reproduce the problem every time - that's a great opportunity to analyze it. Remote debugging on his computer? Or we could try "self profiling": launch the project manager with following options:

$ project-manager --profiling-path failure.npss --profiling-events-log-path failure.log --profiling-time 30

connect the IDE to it (with --no-backend option). After 30s there should be two non-empty failure.* files. When you share them we may get a better clue of what's happening and where the engine execution hicks up.

@mwu-tow
Copy link
Contributor Author

mwu-tow commented Apr 27, 2023

@hubertp @JaroslavTulach
I've opened IDE, created a new project, waited for the issue to happen, then closed IDE.
failure.zip

--no-backend

It seems that the option was renamed to --no-engine.

@hubertp hubertp removed the triage label Apr 27, 2023
@hubertp hubertp self-assigned this Apr 27, 2023
@hubertp hubertp moved this from ❓New to 🔧 Implementation in Issues Board Apr 28, 2023
@hubertp hubertp added this to the Design Partners milestone Apr 28, 2023
@JaroslavTulach
Copy link
Member

JaroslavTulach commented Apr 28, 2023

@hubertp @JaroslavTulach I've opened IDE, created a new project, waited for the issue to happen, then closed IDE. failure.zip

Thanks for the log files. I unzipped, renamed failure.nps to failure.npss (sorry for a typo). I can see 3s are spent in:

org.eclipse.jgit.util.FS$FileStoreAttributes.measureMinimalRacyInterval ()	3,005 ms

I can see that following is blocked for 5s on getHostByAddr:

org.eclipse.jgit.lib.UserConfig.<init>()

obrazek

My conclusion: we need to make sure we can use jgit on computers with misconfigured network.

@hubertp
Copy link
Contributor

hubertp commented Apr 28, 2023

Hmm, but this should be run in a separate thread and non-blocking 🤔
edit:

org.eclipse.jgit.util.FS$FileStoreAttributes.measureMinimalRacyInterval ()

is. but config init is not apparently.

@JaroslavTulach JaroslavTulach changed the title New project initialization fails on vcs/init request New project initialization times out on "get host name" in vcs/init request Apr 28, 2023
hubertp added a commit that referenced this issue Apr 28, 2023
During initialization JGit may attempt to resolve hostname. On some
systems this can take more than desired triggering timeouts.
This change does two things:
- sets the default committer for changes, lack of which probably
  triggered the check
- sets the default hostname to `localhost` (we don't care), in case
  something else in JGit still wants to resolve hostname

Closes #6447.
@hubertp hubertp moved this from 🔧 Implementation to 🌟 Q/A review in Issues Board Apr 28, 2023
hubertp added a commit that referenced this issue Apr 28, 2023
During initialization JGit may attempt to resolve hostname. On some
systems this can take more than desired triggering timeouts.
This change does two things:
- sets the default committer for changes, lack of which probably
  triggered the check
- sets the default hostname to `localhost` (we don't care), in case
  something else in JGit still wants to resolve hostname

Closes #6447.
@mergify mergify bot closed this as completed in #6463 Apr 28, 2023
mergify bot pushed a commit that referenced this issue Apr 28, 2023
During initialization JGit may attempt to resolve hostname. On some systems this can take more than desired triggering timeouts. This change does two things:
- sets the default committer for changes, lack of which probably triggered the check
- sets the default hostname to `localhost` (we don't care), in case something else in JGit still wants to resolve hostname

Closes #6447.

# Important Notes
I wasn't able to reproduce this so relying on @mwu-tow since apparently he can repro it reliably.
@github-project-automation github-project-automation bot moved this from 🌟 Q/A review to 🟢 Accepted in Issues Board Apr 28, 2023
@enso-bot
Copy link

enso-bot bot commented May 1, 2023

Hubert Plociniczak reports a new STANDUP for the provided date (2023-04-28):

Progress: Debugging initialization issue encountered for vcs. Thanks to Jaroslav's insight we figured that hostname checking could potentially lead to delays on some odd machines. Added workaround to avoid making such requests by JGIT. Investigating #6395 but couldn't reproduce so far. Also having trouble with building IDE via run which was another reason for making it hard to reproduce. Investigating #6454. It should be finished by 2023-04-28.

Next Day: Next day I will be working on the #6395 task. Try to reproduce and debug the issue with CB creating a node that doesn't show up until restart.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

4 participants