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

Usage of fully qualified names causes the engine to crash. #5037

Closed
wdanilo opened this issue Feb 5, 2023 · 5 comments · Fixed by #5600
Closed

Usage of fully qualified names causes the engine to crash. #5037

wdanilo opened this issue Feb 5, 2023 · 5 comments · Fixed by #5600
Assignees
Labels
--bug Type: bug -compiler p-high Should be completed in the next sprint
Milestone

Comments

@wdanilo
Copy link
Member

wdanilo commented Feb 5, 2023

This task is automatically imported from the old Task Issue Board and it was originally created by Paweł Grabarz.
Original issue is here.


When a node is added or modified to contain a fully qualified name, the engine crashes and a project needs to be restarted. If the file was saved with the fully qualified name in script, the project immediately crashes on startup as well.

Minimal code example :

main = 
    Standard.Base.Data.Boolean.True

Engine logs after fresh startup:

[info] [2023-02-03T14:20:03.797Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.0-java11].
[info] [2023-02-03T14:20:03.8Z] [org.enso.projectmanager.service.versionmanagement.ControllerInterface] Installed Enso Engine 2023.1.1-nightly.2023.2.3.
[info] [2023-02-03T14:20:03.836Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine 2023.1.1-nightly.2023.2.3 has already been installed by a different process.
[info] [2023-02-03T14:20:03.837Z] [org.enso.projectmanager.service.versionmanagement.ControllerInterface] The engine 2023.1.1-nightly.2023.2.3 has already been installed by a different process.
[info] [2023-02-03T14:20:03.891Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.0-java11].
[info] [2023-02-03T14:20:03.891Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Booting a language server [LanguageServerDescriptor(language-server-83952581-b1bc-4e4f-889c-116286530bb3,0cd25208-695e-41a6-a19e-5417b3225d74,C:\Users\Frizi\enso\projects\ReproProject,NetworkConfig(127.0.0.1,49152,65535),org.enso.projectmanager.versionmanagement.DefaultDistributionConfiguration$@24ddb377,2023.1.1-nightly.2023.2.3,JVMSettings(None,List()),false,None,None,None,Future(Success(Some(ws://localhost:60274/))))].
[info] [2023-02-03T14:20:03.892Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Found sockets for the language server [json:127.0.0.1:63199, binary:127.0.0.1:50301].
[info] [2023-02-03T14:20:03.894Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] The engine [2023.1.1-nightly.2023.2.3] found.
[info] [2023-02-03T14:20:03.895Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.0-java11].
[info] [2023-02-03T14:20:03.95Z] [org.enso.runtimeversionmanager.components.RuntimeVersionManager] Found GraalVM runtime [GraalVM 22.3.0-java11].
[info] [2023-02-03T14:20:04.686Z] [org.enso.languageserver.boot.LanguageServerComponent] Starting Language Server...
[info] [2023-02-03T14:20:04.693Z] [org.enso.languageserver.boot.MainModule] Initializing main module of the Language Server from [LanguageServerConfig(127.0.0.1,63199,50301,0cd25208-695e-41a6-a19e-5417b3225d74,C:\Users\Frizi\enso\projects\ReproProject,ProfilingConfig(None,None,None),language-server,scala.concurrent.impl.ExecutionContextImpl$$anon$3@4b3ed2f0[Running, parallelism = 24, size = 2, active = 1, running = 1, steals = 0, tasks = 0, submissions = 0]), info]
[info] [2023-02-03T14:20:05.775Z] [org.enso.languageserver.runtime.RuntimeConnector] Starting the runtime connector.
[info] [2023-02-03T14:20:05.775Z] [org.enso.languageserver.runtime.RuntimeConnector] Runtime connector established connection with the message endpoint [com.oracle.truffle.api.instrumentation.TruffleInstrument$Env$MessageTransportProxy$MessageEndpointProxy@791d12].
[info] [2023-02-03T14:20:05.896Z] [org.enso.languageserver.text.BufferRegistry] Starting initialization.
[info] [2023-02-03T14:20:05.903Z] [org.enso.languageserver.search.SuggestionsHandler] Starting suggestions handler from [Config(projectContentRoot=***\ReproProject, fileManager=FileManagerConfig(3 seconds,24), vcsManager=VcsManagerConfig(5 seconds,3 seconds), pathWatcher=PathWatcherConfig(5 seconds,5 seconds,10), executionContext=ExecutionContextConfig(5 seconds), directories=DirectoriesConfig(***\ReproProject)), org.enso.searcher.sql.SqlSuggestionsRepo@5a4eebac, org.enso.searcher.sql.SqlVersionsRepo@2b331c8].
[info] [2023-02-03T14:20:06.347Z] [org.enso.languageserver.boot.MainModule] Main module of the Language Server initialized with config [Config(projectContentRoot=***\ReproProject, fileManager=FileManagerConfig(3 seconds,24), vcsManager=VcsManagerConfig(5 seconds,3 seconds), pathWatcher=PathWatcherConfig(5 seconds,5 seconds,10), executionContext=ExecutionContextConfig(5 seconds), directories=DirectoriesConfig(***\ReproProject))].
[info] [2023-02-03T14:20:06.403Z] [org.enso.languageserver.boot.LanguageServerComponent] Started server at json:127.0.0.1:63199, binary:127.0.0.1:50301
[info] [2023-02-03T14:20:06.628Z] [org.enso.projectmanager.infrastructure.languageserver.LanguageServerBootLoader] Language server booted [LanguageServerConnectionInfo(127.0.0.1,63199,50301)].
[info] [2023-02-03T14:20:06.689Z] [org.enso.languageserver.protocol.json.JsonConnectionController] Initializing resources.
[info] [2023-02-03T14:20:06.69Z] [org.enso.languageserver.boot.resource.DirectoriesInitialization] Initializing directories...
[info] [2023-02-03T14:20:06.691Z] [org.enso.languageserver.boot.resource.DirectoriesInitialization] Initialized directories.
[info] [2023-02-03T14:20:06.693Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initializing suggestions repo [***\suggestions.db]...
[info] [2023-02-03T14:20:06.898Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initialized Suggestions repo [***\suggestions.db].
[info] [2023-02-03T14:20:06.899Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initializing versions repo [***\suggestions.db]...
[info] [2023-02-03T14:20:06.9Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: suggestions repo initialized.
[info] [2023-02-03T14:20:06.907Z] [org.enso.languageserver.boot.resource.RepoInitialization] Initialized Versions repo [***\suggestions.db].
[info] [2023-02-03T14:20:06.908Z] [org.enso.languageserver.text.BufferRegistry] Initiaized.
[info] [2023-02-03T14:20:06.908Z] [org.enso.languageserver.boot.resource.TruffleContextInitialization] Initializing Runtime context...
[info] [2023-02-03T14:20:08.011Z] [org.enso.languageserver.boot.resource.TruffleContextInitialization] Initialized Runtime context.
[info] [2023-02-03T14:20:08.011Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: Truffle context initialized.
[info] [2023-02-03T14:20:08.011Z] [org.enso.languageserver.protocol.json.JsonConnectionController] RPC session initialized for client [a2233080-5534-4504-9852-16748fc88bfd].
[info] [2023-02-03T14:20:08.042Z] [org.enso.languageserver.protocol.binary.BinaryConnectionController] Data session initialized for client: a2233080-5534-4504-9852-16748fc88bfd [127.0.0.1:60393].
[info] [2023-02-03T14:20:08.066Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: project name is updated to [ReproProject].
[info] [2023-02-03T14:20:08.175Z] [org.enso.languageserver.search.SuggestionsHandler] Initializing: got type graph response.
[info] [2023-02-03T14:20:08.218Z] [org.enso.languageserver.search.SuggestionsHandler] Verifying: got verification response.
[info] [2023-02-03T14:20:08.24Z] [org.enso.languageserver.search.SuggestionsHandler] Verified.
[info] [2023-02-03T14:20:08.607Z] [org.enso.languageserver.text.CollaborativeBuffer] Buffer opened for [path:Path(0cd25208-695e-41a6-a19e-5417b3225d74,Vector(src, Main.enso)), client:a2233080-5534-4504-9852-16748fc88bfd].
[info] [2023-02-03T14:20:09.178Z] [enso.org.enso.compiler.PackageRepository$Default] Found library Standard.Visualization @ 2023.1.1-nightly.2023.2.3 at [***\2023.1.1-nightly.2023.2.3].
[info] [2023-02-03T14:20:09.247Z] [enso.org.enso.compiler.PackageRepository$Default] Found library Standard.Base @ 2023.1.1-nightly.2023.2.3 at [***\2023.1.1-nightly.2023.2.3].
[info] [2023-02-03T14:20:09.393Z] [enso.org.enso.compiler.PackageRepository$Default] Found library Standard.Table @ 2023.1.1-nightly.2023.2.3 at [***\2023.1.1-nightly.2023.2.3].
Exception in thread "Thread-9" java.lang.IllegalStateException: There is no current context available.
      at org.graalvm.truffle/com.oracle.truffle.polyglot.PolyglotEngineException.illegalState(PolyglotEngineException.java:135)
      at org.graalvm.truffle/com.oracle.truffle.polyglot.PolyglotContextImpl.requireContext(PolyglotContextImpl.java:720)
      at org.graalvm.truffle/com.oracle.truffle.polyglot.EngineAccessor$EngineImpl.createLanguageSystemThread(EngineAccessor.java:1940)
      at org.graalvm.truffle/com.oracle.truffle.api.TruffleLanguage$Env.createSystemThread(TruffleLanguage.java:1847)
      at org.graalvm.truffle/com.oracle.truffle.api.TruffleLanguage$Env.createSystemThread(TruffleLanguage.java:1813)
      at org.enso.compiler.SerializationManager.$anonfun$pool$1(SerializationManager.scala:54)
      at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.<init>(ThreadPoolExecutor.java:623)
      at java.base/java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:912)
      at java.base/java.util.concurrent.ThreadPoolExecutor.processWorkerExit(ThreadPoolExecutor.java:1005)
      at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
      at java.base/java.lang.Thread.run(Thread.java:829)
      at org.graalvm.truffle/com.oracle.truffle.polyglot.SystemThread.run(SystemThread.java:65)
[error] [2023-02-03T14:20:17.836Z] [org.enso.languageserver.requesthandler.vcs.StatusVcsHandler] Status project request [Number(9)] for [a2233080-5534-4504-9852-16748fc88bfd] failed with: null.

Comments:

(Paweł Grabarz - Feb 3, 2023)


Maybe a duplicate of #184389924 (Hubert Plociniczak - Feb 3, 2023)
@wdanilo wdanilo moved this to 🏗 In progress in Issues Board Feb 6, 2023
@jdunkerley jdunkerley added this to the Beta Release milestone Feb 6, 2023
@hubertp hubertp added p-high Should be completed in the next sprint and removed p-low Low priority labels Feb 6, 2023
@hubertp
Copy link
Collaborator

hubertp commented Feb 6, 2023

Reproducible. Caused by #3663 which changed from env.createThread to env.createSystemThread. Reverting back fixes the problem but breaks native image generation.

@hubertp
Copy link
Collaborator

hubertp commented Feb 7, 2023

And here is a follow up culprit - serializer was silently crashing because we weren't catching the exception:

org.enso.compiler.exception.CompilerError: Compiler Internal Error: Attempting to serialize a concrete module reference to `Standard.Base.Main`.
	at org.enso.compiler.data.BindingsMap$ModuleReference$Concrete.writeObject(BindingsMap.scala:1057)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at java.base/java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1016)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1487)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:345)
	at scala.collection.generic.DefaultSerializationProxy.$anonfun$writeObject$1(DefaultSerializationProxy.scala:38)
	at scala.collection.generic.DefaultSerializationProxy.$anonfun$writeObject$1$adapted(DefaultSerializationProxy.scala:37)
	at scala.collection.immutable.HashMap.foreach(HashMap.scala:1076)
	at scala.collection.generic.DefaultSerializationProxy.writeObject(DefaultSerializationProxy.scala:37)
	at jdk.internal.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at java.base/java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1016)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1487)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:345)
	at scala.collection.generic.DefaultSerializationProxy.$anonfun$writeObject$1(DefaultSerializationProxy.scala:38)
	at scala.collection.generic.DefaultSerializationProxy.$anonfun$writeObject$1$adapted(DefaultSerializationProxy.scala:37)
	at scala.collection.immutable.List.foreach(List.scala:333)
	at scala.collection.generic.DefaultSerializationProxy.writeObject(DefaultSerializationProxy.scala:37)
	at jdk.internal.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at java.base/java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1016)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1487)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:345)
	at scala.collection.generic.DefaultSerializationProxy.$anonfun$writeObject$1(DefaultSerializationProxy.scala:38)
	at scala.collection.generic.DefaultSerializationProxy.$anonfun$writeObject$1$adapted(DefaultSerializationProxy.scala:37)
	at scala.collection.immutable.List.foreach(List.scala:333)
	at scala.collection.generic.DefaultSerializationProxy.writeObject(DefaultSerializationProxy.scala:37)
	at jdk.internal.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at java.base/java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1016)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1487)
	at java.base/java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1423)
	at java.base/java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
	at java.base/java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1543)
	at java.base/java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1500)

@enso-bot
Copy link

enso-bot bot commented Feb 8, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-02-07):

Progress: Continued investigation into the crash. I think I have a better understanding of the crash and why we should revert to Env.createThread call instead of Env.createSystemThread. Having said that, the real source of the problem is somewhere else. It appears that we silently ignored serialization failures. And that one is indeed caused by FQN referencing concrete modules. Why we don't recover from that still remains to be discovered. It should be finished by 2023-02-09.

Next Day: Next day I will be working on the #5037 task. Discover why we don't recover gently from serialization problems, come up with a fix for serializing FQNs

mergify bot pushed a commit that referenced this issue Feb 9, 2023
An exception encountered during serialization prevents engine from continuing because it enters an infinite loop(!).

# Important Notes
The aim of this PR is to make it possible for engine to recover from the serialization failures. Any failure would mean that we enter an infinite loop in deserialization which is in turn waiting for the serialization to finish (which will never happen).
In this particular case FQNs are [referencing concrete modules](#5037). A separate PR will address that.
@enso-bot
Copy link

enso-bot bot commented Feb 9, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-02-08):

Progress: Created PR for an issue when a crash in serializer would render engine unusable - deserialization would enter an infinite loop waiting for serialization to finish; serializer already finished (via a crash) but didn't communicate it.Continued investigation for the actual failure itself - turned out in FQNs we weren't properly preparing metadata for serialization/deserialization (toAbstract and toConcrete conversions were incorrect). It should be finished by 2023-02-09.

Next Day: Next day I will be working on the #5568 task. Come up with a test case and start looking into performance improvements to import/export

@hubertp hubertp mentioned this issue Feb 9, 2023
4 tasks
@enso-bot
Copy link

enso-bot bot commented Feb 10, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-02-09):

Progress: Coming up with a setup for the test-case took longer than expected but overall quite happy with the state of PR (no further failures so far). During QA took special attention to the logs of project-manager serializer and noticed weird caching problems that led to constant recompilation during startup, for a clean project. Going down the rabbit hole led me to filing #5608 which might improve our performance. Started looking at the state of import/export resolution. It should be finished by 2023-02-09.

Next Day: Next day I will be working on the #5568 task. Main focus is improving/caching import/export resolution.

@mergify mergify bot closed this as completed in #5600 Feb 10, 2023
mergify bot pushed a commit that referenced this issue Feb 10, 2023
Serialization of FQNs' metadata was broken - we attempted to serialiaze concrete modules and that's against the design.

Added a test illustrating the problem which would previously fail during serialization.

Closes #5037

# Important Notes
It is still hard to discover problems like this because SerializationManager creates system threads; when the exception occurs, it is typically not the real cause. Creating regular threads via `createThread` seems to be problematic for `native-image`. There is a simple workaround for the former but will leave it out for another PR to simplify the review.
@github-project-automation github-project-automation bot moved this from 🔧 Implementation to 🟢 Accepted in Issues Board Feb 10, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
--bug Type: bug -compiler p-high Should be completed in the next sprint
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

3 participants