Skip to content

Race-condition between OpenFileCmd and EnsureCompiledJob leads to spurious Main.main source not found errors #13324

@hubertp

Description

@hubertp

On startup EnsureCompiledJob and OpenFileCmd, both compete for compilation lock.
If the former wins first, it reports (initially) a spurious error that quickly disappears:

Image

There is no rule to how often the situation happens. It seems a bit more frequent when trying out a new nightly with no cache (yet) available for the Main.enso module.

See the transcript of a broken run:

[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Waited [EnsureCompiledJob] 0ms for the file
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Waited [EnsureCompiledJob] 0ms for the pending edit
[TRACE] [org.enso.interpreter.instrument.job.EnsureCompiledJob] Applying pending file [/home/hubert/Documents/enso-projects/NewProject43/src/Main.enso] edits [0] idMap [None]
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Kept pending edits lock [EnsureCompiledJob] for 1ms
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Kept file lock [EnsureCompiledJob] for 1ms
[TRACE] [org.enso.interpreter.instrument.job.AnalyzeModuleJob$] Analyzing not-indexed module local.NewProject43.Main
[DEBUG] [org.enso.languageserver.search.SuggestionsHandler] Got module update [local.NewProject43.Main].
[DEBUG] [org.enso.languageserver.search.SuggestionsHandler] Complete module update [local.NewProject43.Main]
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Kept write compilation lock [EnsureCompiledJob] for 3288ms
[TRACE] [org.enso.interpreter.instrument.execution.JobExecutionEngine] Job org.enso.interpreter.instrument.job.EnsureCompiledJob@64e0a95 finished in 3288 ms.
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Waited [ExecuteJob] 3288ms for the read compilation
[TRACE] [org.enso.interpreter.instrument.execution.JobExecutionEngine] Number of remaining pending jobs: 1
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Waited [OpenFileCmd] 3270ms for the read compilation
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Waited [OpenFileCmd] 0ms for the file
[TRACE] [org.enso.interpreter.instrument.job.ProgramExecutionSupport$] Run program 7cd136bf-8dbb-47e9-9a36-ce954723ee7f
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Kept file lock [OpenFileCmd] for 0ms
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Kept read compilation lock [OpenFileCmd] for 0ms
[TRACE] [org.enso.interpreter.instrument.command.Command] Command OpenFileCmd finished.
[TRACE] [org.enso.interpreter.instrument.job.ProgramExecutionSupport$] Execution finished: Left(Some(Failure(The Main.main source not found.,None)))
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Kept read compilation lock [ExecuteJob] for 5ms
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Kept context lock [ExecuteJob] for 3293ms
[TRACE] [org.enso.interpreter.instrument.job.ExecuteJob] Finished ExecuteJob[555050dd-9cc0-4e9e-942d-2cdf75176b9e]
[TRACE] [org.enso.interpreter.instrument.execution.JobExecutionEngine] Job ExecuteJob(contextId=7cd136bf-8dbb-47e9-9a36-ce954723ee7f, jobId=555050dd-9cc0-4e9e-942d-2cdf75176b9e) finished in 3293 ms.
[TRACE] [org.enso.interpreter.instrument.execution.JobExecutionEngine] Number of remaining pending jobs: 0
[TRACE] [org.enso.languageserver.runtime.ContextRegistry] receive handled ExecutionFailed(7cd136bf-8dbb-47e9-9a36-ce954723ee7f,Failure(The Main.main source not found.,None)) from Actor[akka://language-server/deadLetters]
[DEBUG] [org.enso.interpreter.instrument.command.Command] Command PushContextCmd finished.
[DEBUG] [org.enso.interpreter.instrument.command.Command] Executing command synchronously: EditFileCmd...
[TRACE] [org.enso.interpreter.instrument.execution.ReentrantLocking] Waited [EditFileCmd] 0ms for the file

Most importantly Waited [OpenFileCmd] 3270ms for the read compilation. To fix, we have to ensure that EnsureCompiledJob is only run after OpenFileCmd.

Metadata

Metadata

Assignees

Labels

--bugType: bug-compilerp-highShould be completed in the next sprint

Type

No type

Projects

Status

🟢 Accepted

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions