Don't cancel pending visualization's upserts (#8853)

Uniqueness check of `UpsertVisualizationJob` only involved expressionId. Apparently now GUI sends mutliple visualizations for the same expressions and expects all of them to exist. Since previously we would cancel duplicate jobs, this was problematic.

This change makes sure that uniqueness also takes into account visualization id. Fixed a few logs that were not passing arguments properly.

Closes #8801

# Important Notes
I have not noticed any more problems with loading visualizations so the issue appears to be resolved with this change.
Added a unit test case that would previously fail due to cancellation of a job that upserts visualization.

build.sbt

@@ -1747,9 +1747,10 @@ lazy val runtime = (project in file("engine/runtime"))
       "ENSO_TEST_DISABLE_IR_CACHE" -> "false",
       "ENSO_EDITION_PATH"          -> file("distribution/editions").getCanonicalPath
     ),
-    Test / compile := (Test / compile)
-      .dependsOn(`runtime-fat-jar` / Compile / compileModuleInfo)
-      .value
+    Test / compile := {
+      (LocalProject("runtime-instrument-common") / Test / compile).value
+      (Test / compile).value
+    }
   )
   .settings(
     (Compile / javacOptions) ++= Seq(
@@ -1898,13 +1899,18 @@ lazy val `runtime-instrument-common` =
       Test / fork := true,
       Test / envVars ++= distributionEnvironmentOverrides ++ Map(
         "ENSO_TEST_DISABLE_IR_CACHE" -> "false"
+      ),
+      libraryDependencies ++= Seq(
+        "junit"          % "junit"           % junitVersion     % Test,
+        "com.github.sbt" % "junit-interface" % junitIfVersion   % Test,
+        "org.scalatest" %% "scalatest"       % scalatestVersion % Test
       )
     )
     .dependsOn(`refactoring-utils`)
     .dependsOn(
       LocalProject(
         "runtime"
-      ) % "compile->compile;test->test;runtime->runtime;bench->bench"
+      ) % "compile->compile;runtime->runtime;bench->bench"
     )
 
 lazy val `runtime-instrument-id-execution` =

engine/language-server/src/test/scala/org/enso/languageserver/websocket/json/LibrariesTest.scala

@@ -59,7 +59,7 @@ class LibrariesTest
   )
 
   "LocalLibraryManager" should {
-    "create a library project and include it on the list of local projects" taggedAs Flaky in {
+    "create a library project and include it on the list of local projects" taggedAs SkipOnFailure in {
       val client          = getInitialisedWsClient()
       val testLibraryName = LibraryName("user", "My_Local_Lib")
 

engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/command/AttachVisualizationCmd.scala

@@ -34,7 +34,7 @@ class AttachVisualizationCmd(
     )
     val maybeFutureExecutable =
       ctx.jobProcessor.run(
-        new UpsertVisualizationJob(
+        upsertVisualization(
           maybeRequestId,
           request.visualizationId,
           request.expressionId,
@@ -48,6 +48,20 @@ class AttachVisualizationCmd(
     }
   }
 
+  def upsertVisualization(
+    maybeRequestId: Option[Api.RequestId],
+    visualizationId: Api.VisualizationId,
+    expressionId: Api.ExpressionId,
+    config: Api.VisualizationConfiguration
+  ): UpsertVisualizationJob = {
+    new UpsertVisualizationJob(
+      maybeRequestId,
+      visualizationId,
+      expressionId,
+      config
+    )
+  }
+
   override def toString: String = {
     "AttachVisualizationCmd(visualizationId: " + request.visualizationId + ",expressionId=" + request.expressionId + ")"
   }

engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/command/ModifyVisualizationCmd.scala

@@ -33,7 +33,7 @@ class ModifyVisualizationCmd(
     ctx.executionService.getLogger.log(
       Level.FINE,
       "Modify visualization cmd for request id [{}] and visualization id [{}]",
-      Array(maybeRequestId, request.visualizationId)
+      Array[Object](maybeRequestId, request.visualizationId)
     )
     val existingVisualization = ctx.contextManager.getVisualizationById(
       request.visualizationConfig.executionContextId,

engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/job/DeserializeLibrarySuggestionsJob.scala

@@ -30,7 +30,8 @@ final class DeserializeLibrarySuggestionsJob(
   override def run(implicit ctx: RuntimeContext): Unit = {
     ctx.executionService.getLogger.log(
       Level.FINE,
-      s"Deserializing suggestions for library [$libraryName]."
+      "Deserializing suggestions for library [{}].",
+      libraryName
     )
     val serializationManager = SerializationManager(
       ctx.executionService.getContext.getCompiler.context

engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/job/EnsureCompiledJob.scala

@@ -429,7 +429,8 @@ final class EnsureCompiledJob(
     if (invalidatedVisualizations.nonEmpty) {
       ctx.executionService.getLogger.log(
         Level.FINEST,
-        s"Invalidated visualizations [${invalidatedVisualizations.map(_.id)}]"
+        "Invalidated visualizations [{}]",
+        invalidatedVisualizations.map(_.id)
       )
     }
 

engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/job/UpsertVisualizationJob.scala

@@ -53,7 +53,7 @@ class UpsertVisualizationJob(
   override def equalsTo(that: UniqueJob[_]): Boolean =
     that match {
       case that: UpsertVisualizationJob =>
-        this.expressionId == that.expressionId
+        this.expressionId == that.expressionId && this.visualizationId == that.visualizationId
       case _ => false
     }
 
@@ -146,7 +146,7 @@ class UpsertVisualizationJob(
     ctx.executionService.getLogger.log(
       Level.SEVERE,
       "Visualization for expression {0} failed: {1} (evaluation result: {2})",
-      Array(expressionId, message, executionResult)
+      Array[Object](expressionId, message, executionResult)
     )
     ctx.endpoint.sendToClient(
       Api.Response(
@@ -159,6 +159,10 @@ class UpsertVisualizationJob(
     )
   }
 
+  override def toString: String = {
+    s"UpsertVisualizationJob(visualizationId=$visualizationId, expressionId=$expressionId)"
+  }
+
 }
 
 object UpsertVisualizationJob {

engine/runtime-instrument-common/src/test/java/org/enso/interpreter/instrument/MockHandler.java

@@ -1,11 +1,11 @@
 package org.enso.interpreter.instrument;
 
 import org.enso.interpreter.instrument.command.CommandFactory;
-import org.enso.interpreter.instrument.command.MockedCommandFactory$;
+import org.enso.interpreter.instrument.command.MockedCommandFactory;
 
 public class MockHandler extends Handler {
 
-  private CommandFactory _cmdFactory = MockedCommandFactory$.MODULE$;
+  private CommandFactory _cmdFactory = new MockedCommandFactory();
 
   @Override
   public CommandFactory cmdFactory() {

engine/runtime-instrument-common/src/test/java/org/enso/interpreter/instrument/job/JobsTest.java

@@ -0,0 +1,37 @@
+package org.enso.interpreter.instrument.job;
+
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertTrue;
+
+import java.util.UUID;
+import org.enso.polyglot.runtime.Runtime$Api$VisualizationConfiguration;
+import org.enso.polyglot.runtime.Runtime$Api$VisualizationExpression$Text;
+import org.junit.Test;
+import scala.Option;
+
+public class JobsTest {
+  @Test
+  public void upsertJobUniqueness() {
+    var config =
+        new Runtime$Api$VisualizationConfiguration(
+            UUID.randomUUID(), new Runtime$Api$VisualizationExpression$Text("foo", "bar"), "test");
+    var expression1 = UUID.randomUUID();
+    var expression2 = UUID.randomUUID();
+    var visualization1 = UUID.randomUUID();
+    var visualization2 = UUID.randomUUID();
+    var visualization3 = UUID.randomUUID();
+
+    var upsert1 = new UpsertVisualizationJob(Option.empty(), visualization1, expression1, config);
+    var upsert2 = new UpsertVisualizationJob(Option.empty(), visualization2, expression1, config);
+    var upsert3 = new UpsertVisualizationJob(Option.empty(), visualization3, expression2, config);
+    var upsert4 = new UpsertVisualizationJob(Option.empty(), visualization1, expression1, config);
+    var upsert5 = new UpsertVisualizationJob(Option.empty(), visualization1, expression2, config);
+
+    assertFalse(upsert1.equalsTo(upsert2));
+    assertFalse(upsert2.equalsTo(upsert3));
+    assertFalse(upsert1.equalsTo(upsert3));
+    assertTrue(upsert1.equalsTo(upsert4));
+    assertFalse(upsert3.equalsTo(upsert4));
+    assertFalse(upsert5.equalsTo(upsert3));
+  }
+}

engine/runtime-instrument-common/src/test/java/org/enso/interpreter/runtime/ModuleTestUtils.java

@@ -0,0 +1,15 @@
+package org.enso.interpreter.runtime;
+
+import org.enso.polyglot.CompilationStage;
+
+public final class ModuleTestUtils {
+  private ModuleTestUtils() {}
+
+  public static void unsafeSetIr(Module m, org.enso.compiler.core.ir.Module ir) {
+    m.unsafeSetIr(ir);
+  }
+
+  public static void unsafeSetCompilationStage(Module m, CompilationStage s) {
+    m.unsafeSetCompilationStage(s);
+  }
+}

engine/runtime-instrument-common/src/test/scala/org/enso/compiler/test/CompilerTestSetup.scala

@@ -0,0 +1,228 @@
+package org.enso.compiler.test
+
+import org.enso.compiler.context.{FreshNameSupply, InlineContext, ModuleContext}
+import org.enso.compiler.core.EnsoParser
+import org.enso.compiler.core.Implicits.AsMetadata
+import org.enso.compiler.core.ir.{Expression, Module}
+import org.enso.compiler.core.ir.MetadataStorage.MetadataPair
+import org.enso.compiler.data.BindingsMap.ModuleReference
+import org.enso.compiler.data.{BindingsMap, CompilerConfig}
+import org.enso.compiler.pass.analyse.BindingAnalysis
+import org.enso.compiler.pass.{PassConfiguration, PassManager}
+import org.enso.interpreter.runtime
+import org.enso.interpreter.runtime.ModuleTestUtils
+import org.enso.compiler.context.LocalScope
+import org.enso.pkg.QualifiedName
+import org.enso.polyglot.CompilationStage
+
+/** A reduced version of [[org.enso.compiler.test.CompilerRunner]] that avoids introducing a cyclic dependency
+  * to `runtime-instrument-common` subject.
+  */
+trait CompilerTestSetup {
+  // === IR Utilities =========================================================
+
+  /** An extension method to allow converting string source code to IR as a
+    * module.
+    *
+    * @param source the source code to convert
+    */
+  implicit private class ToIrModule(source: String) {
+
+    /** Converts program text to a top-level Enso module.
+      *
+      * @return the [[IR]] representing [[source]]
+      */
+    def toIrModule: Module = {
+      val compiler = new EnsoParser()
+      try compiler.compile(source)
+      finally compiler.close()
+    }
+  }
+
+  /** An extension method to allow converting string source code to IR as an
+    * expression.
+    *
+    * @param source the source code to convert
+    */
+  implicit private class ToIrExpression(source: String) {
+
+    /** Converts the program text to an Enso expression.
+      *
+      * @return the [[IR]] representing [[source]], if it is a valid expression
+      */
+    def toIrExpression: Option[Expression] = {
+      val compiler = new EnsoParser()
+      try compiler.generateIRInline(compiler.parse(source))
+      finally compiler.close()
+    }
+  }
+
+  /** Provides an extension method allowing the running of a specified list of
+    * passes on the provided IR.
+    *
+    * @param ir the IR to run the passes on
+    */
+  implicit private class RunPassesOnModule(ir: Module) {
+
+    /** Executes the passes using `passManager` on the input [[ir]].
+      *
+      * @param passManager the pass configuration
+      * @param moduleContext the module context it is executing in
+      * @return the result of executing the passes in `passManager` on [[ir]]
+      */
+    def runPasses(
+      passManager: PassManager,
+      moduleContext: ModuleContext
+    ): Module = {
+      passManager.runPassesOnModule(ir, moduleContext)
+    }
+  }
+
+  /** Provides an extension method allowing the running of a specified list of
+    * passes on the provided IR.
+    *
+    * @param ir the IR to run the passes on
+    */
+  implicit private class RunPassesOnExpression(ir: Expression) {
+
+    /** Executes the passes using `passManager` on the input [[ir]].
+      *
+      * @param passManager the pass configuration
+      * @param inlineContext the inline context it is executing in
+      * @return the result of executing the passes in `passManager` on [[ir]]
+      */
+    def runPasses(
+      passManager: PassManager,
+      inlineContext: InlineContext
+    ): Expression = {
+      passManager.runPassesInline(ir, inlineContext)
+    }
+  }
+
+  /** Adds an extension method to preprocess the source as IR.
+    *
+    * @param source the source code to preprocess
+    */
+  implicit class Preprocess(source: String)(implicit
+    passManager: PassManager
+  ) {
+
+    /** Translates the source code into appropriate IR for testing this pass.
+      *
+      * @return IR appropriate for testing the alias analysis pass as a module
+      */
+    def preprocessModule(implicit moduleContext: ModuleContext): Module = {
+      source.toIrModule.runPasses(passManager, moduleContext)
+    }
+
+    /** Translates the source code into appropriate IR for testing this pass
+      *
+      * @return IR appropriate for testing the alias analysis pass as an
+      *         expression
+      */
+    def preprocessExpression(implicit
+      inlineContext: InlineContext
+    ): Option[Expression] = {
+      source.toIrExpression.map(_.runPasses(passManager, inlineContext))
+    }
+  }
+
+  // === IR Testing Utils =====================================================
+
+  /** Builds a module context with a mocked module for testing purposes.
+    *
+    * @param moduleName the name of the test module.
+    * @param freshNameSupply the fresh name supply to use in tests.
+    * @param passConfiguration any additional pass configuration.
+    * @return an instance of module context.
+    */
+  def buildModuleContext(
+    moduleName: QualifiedName                    = QualifiedName.simpleName("Test_Module"),
+    freshNameSupply: Option[FreshNameSupply]     = None,
+    passConfiguration: Option[PassConfiguration] = None,
+    compilerConfig: CompilerConfig               = defaultConfig,
+    isGeneratingDocs: Boolean                    = false
+  ): ModuleContext = buildModuleContextModule(
+    moduleName,
+    freshNameSupply,
+    passConfiguration,
+    compilerConfig,
+    isGeneratingDocs
+  )._1
+
+  /** Builds a module context with a mocked module for testing purposes.
+    *
+    * @param moduleName the name of the test module.
+    * @param freshNameSupply the fresh name supply to use in tests.
+    * @param passConfiguration any additional pass configuration.
+    * @return an pair of module context and module.
+    */
+  def buildModuleContextModule(
+    moduleName: QualifiedName                    = QualifiedName.simpleName("Test_Module"),
+    freshNameSupply: Option[FreshNameSupply]     = None,
+    passConfiguration: Option[PassConfiguration] = None,
+    compilerConfig: CompilerConfig               = defaultConfig,
+    isGeneratingDocs: Boolean                    = false
+  ): (ModuleContext, runtime.Module) = {
+    val mod = runtime.Module.empty(moduleName, null)
+    val ctx = ModuleContext(
+      module            = mod.asCompilerModule(),
+      freshNameSupply   = freshNameSupply,
+      passConfiguration = passConfiguration,
+      compilerConfig    = compilerConfig,
+      isGeneratingDocs  = isGeneratingDocs
+    )
+    (ctx, mod)
+  }
+
+  /** Builds an inline context with a mocked module for testing purposes.
+    *
+    * @param localScope the local scope for variable resolution.
+    * @param isInTailPosition whether the expression is being evaluated in
+    *                         a tail position.
+    * @param freshNameSupply the fresh name supply to use for name generation.
+    * @param passConfiguration any additional pass configuration.
+    * @return an instance of inline context.
+    */
+  def buildInlineContext(
+    localScope: Option[LocalScope]               = None,
+    isInTailPosition: Option[Boolean]            = None,
+    freshNameSupply: Option[FreshNameSupply]     = None,
+    passConfiguration: Option[PassConfiguration] = None,
+    compilerConfig: CompilerConfig               = defaultConfig
+  ): InlineContext = {
+    val mod =
+      runtime.Module.empty(QualifiedName.simpleName("Test_Module"), null)
+    ModuleTestUtils.unsafeSetIr(
+      mod,
+      Module(List(), List(), List(), false, None)
+        .updateMetadata(
+          new MetadataPair(
+            BindingAnalysis,
+            BindingsMap(
+              List(),
+              ModuleReference.Concrete(mod.asCompilerModule())
+            )
+          )
+        )
+    )
+    ModuleTestUtils.unsafeSetCompilationStage(
+      mod,
+      CompilationStage.AFTER_CODEGEN
+    )
+    val mc = ModuleContext(
+      module         = mod.asCompilerModule(),
+      compilerConfig = compilerConfig
+    )
+    InlineContext(
+      module            = mc,
+      freshNameSupply   = freshNameSupply,
+      passConfiguration = passConfiguration,
+      localScope        = localScope,
+      isInTailPosition  = isInTailPosition,
+      compilerConfig    = compilerConfig
+    )
+  }
+
+  val defaultConfig: CompilerConfig = CompilerConfig()
+}

engine/runtime-instrument-common/src/test/scala/org/enso/compiler/test/context/ChangesetBuilderTest.scala

@@ -13,15 +13,20 @@ import org.enso.compiler.core.ir.expression.Application
 import org.enso.compiler.core.ir.expression.errors
 import org.enso.compiler.core.ir.module.scope.definition
 import org.enso.compiler.pass.PassManager
-import org.enso.compiler.test.CompilerTest
+import org.enso.compiler.test.CompilerTestSetup
 import org.enso.compiler.context.LocalScope
 import org.enso.text.buffer.Rope
 import org.enso.text.editing.JavaEditorAdapter
 import org.enso.text.editing.model.{Position, Range, TextEdit}
+import org.scalatest.matchers.should.Matchers
+import org.scalatest.wordspec.AnyWordSpecLike
 
 import java.util.UUID
 
-class ChangesetBuilderTest extends CompilerTest {
+class ChangesetBuilderTest
+    extends AnyWordSpecLike
+    with Matchers
+    with CompilerTestSetup {
 
   implicit val passManager: PassManager = new Passes(defaultConfig).passManager
 

engine/runtime-instrument-common/src/test/scala/org/enso/interpreter/instrument/command/MockedCommandFactory.scala

@@ -1,16 +1,25 @@
 package org.enso.interpreter.instrument.command
 import org.enso.polyglot.runtime.Runtime.Api
 
-object MockedCommandFactory extends CommandFactory {
+class MockedCommandFactory extends CommandFactory {
 
-  private var editRequestCounter = 0
+  private var editRequestCounter         = 0
+  private var attachVisualizationCounter = 0
 
   override def createCommand(request: Api.Request): Command = {
     request.payload match {
       case payload: Api.EditFileNotification =>
-        val cmd = new SlowEditFileCmd(payload, editRequestCounter)
+        val cmd = new SlowEditFileCmd(payload, editRequestCounter % 2 == 0)
         editRequestCounter += 1
         cmd
+      case payload: Api.AttachVisualization =>
+        val cmd = new SlowAttachVisualizationCmd(
+          request.requestId,
+          payload,
+          attachVisualizationCounter % 2 == 0
+        )
+        attachVisualizationCounter += 1
+        cmd
       case _ =>
         super.createCommand(request)
     }

engine/runtime-instrument-common/src/test/scala/org/enso/interpreter/instrument/command/SlowAttachVisualizationCmd.scala

@@ -0,0 +1,35 @@
+package org.enso.interpreter.instrument.command
+
+import org.enso.interpreter.instrument.job.{
+  SlowUpsertVisualizationJob,
+  UpsertVisualizationJob
+}
+import org.enso.polyglot.runtime.Runtime.Api
+import org.slf4j.LoggerFactory
+
+class SlowAttachVisualizationCmd(
+  maybeRequestId: Option[Api.RequestId],
+  request: Api.AttachVisualization,
+  delay: Boolean
+) extends AttachVisualizationCmd(maybeRequestId, request) {
+
+  private val logger =
+    LoggerFactory.getLogger(classOf[SlowAttachVisualizationCmd])
+
+  override def upsertVisualization(
+    maybeRequestId: Option[Api.RequestId],
+    visualizationId: Api.VisualizationId,
+    expressionId: Api.ExpressionId,
+    config: Api.VisualizationConfiguration
+  ): UpsertVisualizationJob = {
+
+    logger.info("Delaying upsert for {}: {}", request.visualizationId, delay)
+    new SlowUpsertVisualizationJob(
+      maybeRequestId,
+      visualizationId,
+      expressionId,
+      config,
+      delay
+    )
+  }
+}

engine/runtime-instrument-common/src/test/scala/org/enso/interpreter/instrument/command/SlowEditFileCmd.scala

@@ -5,7 +5,7 @@ import org.enso.polyglot.runtime.Runtime.Api
 
 import scala.concurrent.ExecutionContext
 
-class SlowEditFileCmd(request: Api.EditFileNotification, counter: Int)
+class SlowEditFileCmd(request: Api.EditFileNotification, delay: Boolean)
     extends EditFileCmd(request) {
 
   override def executeSynchronously(implicit
@@ -13,7 +13,7 @@ class SlowEditFileCmd(request: Api.EditFileNotification, counter: Int)
     ec: ExecutionContext
   ): Unit = {
     if (
-      ctx.executionService.getContext.isRandomDelayedCommandExecution && counter % 2 == 0
+      ctx.executionService.getContext.isRandomDelayedCommandExecution && delay
     ) {
       try {
         Thread.sleep(2000)

engine/runtime-instrument-common/src/test/scala/org/enso/interpreter/instrument/job/SlowUpsertVisualizationJob.scala

@@ -0,0 +1,33 @@
+package org.enso.interpreter.instrument.job
+
+import org.enso.interpreter.instrument.execution.{Executable, RuntimeContext}
+import org.enso.polyglot.runtime.Runtime.Api
+
+import scala.annotation.unused
+
+class SlowUpsertVisualizationJob(
+  @unused requestId: Option[Api.RequestId],
+  visualizationId: Api.VisualizationId,
+  expressionId: Api.ExpressionId,
+  config: Api.VisualizationConfiguration,
+  delay: Boolean
+) extends UpsertVisualizationJob(
+      requestId,
+      visualizationId,
+      expressionId,
+      config
+    ) {
+
+  override val isCancellable: Boolean         = true
+  override val mayInterruptIfRunning: Boolean = true
+
+  override def run(implicit ctx: RuntimeContext): Option[Executable] = {
+    if (
+      ctx.executionService.getContext.isRandomDelayedCommandExecution && delay
+    ) {
+      Thread.sleep(1000)
+    }
+
+    super.run(ctx)
+  }
+}

engine/runtime/src/test/resources/application-test.conf

@@ -1 +1,26 @@
 akka.coordinated-shutdown.run-by-actor-system-terminate = off
+logging-service {
+  logger {
+    akka.actor = info
+    akka.event = error
+    akka.routing = error
+    akka.io = error
+    akka.stream = error
+    slick.jdbc.JdbcBackend.statement = error # log SQL queries on debug level
+    slick."*" = error
+    org.eclipse.jgit = error
+    io.methvin.watcher = error
+  }
+  appenders = [
+    {
+      name = "memory"
+      forward-to = console
+    },
+    {
+      name = "console"
+      pattern = "[%level] [%d{yyyy-MM-ddTHH:mm:ssXXX}] [%logger] %msg%n"
+    }
+  ]
+  default-appender = memory
+  log-level = "error"
+}