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

Using TruffleLogger outside of engine leads to crashes #8147

Closed
hubertp opened this issue Oct 24, 2023 · 10 comments · Fixed by #8169
Closed

Using TruffleLogger outside of engine leads to crashes #8147

hubertp opened this issue Oct 24, 2023 · 10 comments · Fixed by #8169
Assignees
Labels
-compiler p-medium Should be completed in the next few sprints

Comments

@hubertp
Copy link
Collaborator

hubertp commented Oct 24, 2023

As pointed out in #8014 (comment):

enso$ git diff
diff --git engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/execution/ReentrantLocking.scala engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/execution/ReentrantLocking.scala
index 8cb4b0b5c4..0b84019fd0 100644
--- engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/execution/ReentrantLocking.scala
+++ engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/execution/ReentrantLocking.scala
@@ -153,6 +153,8 @@ class ReentrantLocking(logger: TruffleLogger) extends Locking {
 
   /** @inheritdoc */
   override def acquireFileLock(file: File): Long = {
+    assertNotLocked(compilationLock, false, "wrong")
+    assertNotLocked(compilationLock, true, "wrong")
     // cannot have pendings lock as of EnsureCompiledJob.applyEdits
     assertNotLocked(
       pendingEditsLock,
$ sbt  runtime-with-instruments/test

and one gets:

java.lang.IllegalStateException: Thread using TruffleLogger has to have a current context or the TruffleLogger has to be bound to an engine., took 0.025 sec
[error]     at com.oracle.truffle.api.TruffleLogger$LoggerCache.noContext(TruffleLogger.java:1011)
[error]     at com.oracle.truffle.api.TruffleLogger$LoggerCache.isLoggable(TruffleLogger.java:993)
[error]     at com.oracle.truffle.api.TruffleLogger.isLoggableSlowPath(TruffleLogger.java:727)
[error]     at com.oracle.truffle.api.TruffleLogger.isLoggable(TruffleLogger.java:722)
[error]     at com.oracle.truffle.api.TruffleLogger.log(TruffleLogger.java:544)
[error]     at org.enso.interpreter.instrument.command.SynchronousCommand.execute(SynchronousCommand.scala:30)
[error]     at org.enso.interpreter.instrument.command.SynchronousCommand.execute(SynchronousCommand.scala:11)
[error]     at org.enso.interpreter.instrument.execution.CommandExecutionEngine.invoke(CommandExecutionEngine.scala:63)
[error]     at org.enso.interpreter.instrument.Handler.onMessage(Handler.scala:128)
[error]     at org.enso.interpreter.instrument.Endpoint.$anonfun$sendBinary$1(Handler.scala:66)
[error]     at org.enso.interpreter.instrument.Endpoint.$anonfun$sendBinary$1$adapted(Handler.scala:64)
[error]     at scala.Option.foreach(Option.scala:437)
[error]     at org.enso.interpreter.instrument.Endpoint.sendBinary(Handler.scala:64)
[error]     at com.oracle.truffle.api.instrumentation.TruffleInstrument$Env$MessageTransportProxy$MessageEndpointProxy.sendBinary(TruffleInstrument.java:1090)
[error]     at org.enso.interpreter.test.instrument.RuntimeServerEmulator.sendToRuntime(RuntimeServerEmulator.scala:53)
[error]     at org.enso.interpreter.test.instrument.RuntimeServerTest$TestContext.send(RuntimeServerTest.scala:94)
[error]     at org.enso.interpreter.test.instrument.IncrementalUpdatesTest.sendUpdatesWhenFunctionBodyIsChanged(IncrementalUpdatesTest.java:202)
[error]     at org.enso.interpreter.test.instrument.IncrementalUpdatesTest.sendUpdatesWhenFunctionBodyIsChangedBySettingValue(IncrementalUpdatesTest.java:150)
[error]     at org.enso.interpreter.test.instrument.IncrementalUpdatesTest.sendUpdatesWhenTextIsChangedBySettingValue(IncrementalUpdatesTest.java:105)

Also noted similar problems when logging things in serializer. Can be simulated when problems occur in verbose mode.

@hubertp hubertp added p-medium Should be completed in the next few sprints -compiler labels Oct 24, 2023
@hubertp hubertp self-assigned this Oct 24, 2023
@hubertp
Copy link
Collaborator Author

hubertp commented Oct 25, 2023

This is weird - I'm no longer to reproduce this one. And I know I used to be able to.

@hubertp
Copy link
Collaborator Author

hubertp commented Oct 25, 2023

So it looks like my change in #7985 has accidentally fixed it.

@enso-bot
Copy link

enso-bot bot commented Oct 25, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-10-24):

Progress: Continued working on translating IR to Java (PR ready). Filed a ticket for forgotten logging problem (so far unable to reproduce using the old setup). It should be finished by 2023-10-26.

Next Day: Next day I will be working on the #8147 task. Address feedback on IR translation pick up next item on the list.

@JaroslavTulach
Copy link
Member

I am able to reproduce the problem even on recent bits: Enough to set private val debugLogLevel = Level.INFO in SerializationManager.scala and then:

sbt:runtime> testOnly *SerdeCompilerTest

with that I get:

[error] Caused by: java.lang.IllegalStateException: Thread using TruffleLogger has to have a current context or the TruffleLogger has to be bound to an engine.
[error]     at com.oracle.truffle.api.TruffleLogger$LoggerCache.noContext(TruffleLogger.java:1011)
[error]     at com.oracle.truffle.api.TruffleLogger$LoggerCache.isLoggable(TruffleLogger.java:993)
[error]     at com.oracle.truffle.api.TruffleLogger.isLoggableSlowPath(TruffleLogger.java:727)
[error]     at com.oracle.truffle.api.TruffleLogger.isLoggable(TruffleLogger.java:722)
[error]     at com.oracle.truffle.api.TruffleLogger.log(TruffleLogger.java:526)
[error]     at org.enso.interpreter.runtime.TruffleCompilerContext.logSerializationManager(TruffleCompilerContext.java:91)
[error]     at org.enso.compiler.SerializationManager.$anonfun$doSerializeModule$1(SerializationManager.scala:591)
[error]     at org.enso.compiler.SerializationManager.$anonfun$doSerializeModule$1$adapted(SerializationManager.scala:583)

I am at 5e468f0

@jdunkerley jdunkerley moved this from ❓New to 📤 Backlog in Issues Board Oct 26, 2023
@jdunkerley jdunkerley moved this from 📤 Backlog to 🔧 Implementation in Issues Board Oct 26, 2023
@enso-bot
Copy link

enso-bot bot commented Oct 26, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-10-25):

Progress: Addressing feedback to IR translation. Found out a potential race-condition leading to random CI failures (#8151). It should be finished by 2023-10-26.

Next Day: Next day I will be working on the #8147 task. Address race-condition and switch to Truffle logger.

@enso-bot
Copy link

enso-bot bot commented Oct 27, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-10-26):

Progress: Fixed a race-condition in CI (#8151). Worked on a Truffle logger-related task about inability to use custom logs (PR created). Tinkering with the solution for logger crash. It should be finished by 2023-10-26.

Next Day: Next day I will be working on the #8147 task. Continue working on the task (delayed by other ones that happened in between).

@hubertp
Copy link
Collaborator Author

hubertp commented Oct 27, 2023

This is really odd. So #8169 provides somewhat a workaround for a case when we test the individual test. But when we run the full suite (e.g. sbt> runtime/testOnly org.enso.compiler.*) it still crashes. I narrowed it down to useThreadPool argument when serializing module. If false, everything will pass but I doubt this is what we want, so something is fishy when performing serialization asynchronously.

@enso-bot
Copy link

enso-bot bot commented Oct 30, 2023

Hubert Plociniczak reports a new 🔴 DELAY for the provided date (2023-10-27):

Summary: There is 4 days delay in implementation of the Using TruffleLogger outside of engine leads to crashes (#8147) task.
It will cause 0 days delay for the delivery of this weekly plan.

Delay Cause: Worked on other tickets inbetween.

@enso-bot
Copy link

enso-bot bot commented Oct 30, 2023

Hubert Plociniczak reports a new STANDUP for the provided date (2023-10-27):

Progress: Kept tinkering with the (sometimes) failling example. Turns out the likely culprit is the kind of logger that gets created - we use TruffleLogger bound to the context rather than to the engine. That's bound to ocassionally fail with threadpools. It should be finished by 2023-10-30.

Next Day: Next day I will be working on the #8147 task. Make sure that the hypothesis is correct, address PR comments

@mergify mergify bot closed this as completed in #8169 Oct 31, 2023
mergify bot pushed a commit that referenced this issue Oct 31, 2023
Using a `TruffleLogger` in `SerializationManager` that is bound to the engine rather than the context prevents reaching an illegal state when using thread pools.

Also cleaned up some tests for consistency.

To verify the fix
```diff
--- a/engine/runtime/src/main/scala/org/enso/compiler/SerializationManager.scala
+++ b/engine/runtime/src/main/scala/org/enso/compiler/SerializationManager.scala
@@ -31,7 +31,7 @@ final class SerializationManager(compiler: Compiler) {
import SerializationManager._

/** The debug logging level. */
-  private val debugLogLevel = Level.FINE
+  private val debugLogLevel = Level.INFO
```
and run
`sbt:enso> runtime/test`

Closes #8147.
@github-project-automation github-project-automation bot moved this from 🔧 Implementation to 🟢 Accepted in Issues Board Oct 31, 2023
@enso-bot
Copy link

enso-bot bot commented Oct 31, 2023

Hubert Plociniczak reports a new STANDUP for the provided date (2023-10-30):

Progress: Updated PR with a proper solution. Addressing comments. Investigating random apply edit failures. Planning next tasks. It should be finished by 2023-10-30.

Next Day: Next day I will be working on the #8147 task. Address remaining comments for a related #8162. Continue with failures

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
-compiler p-medium Should be completed in the next few sprints
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

2 participants