Report failures when upserting visualizations (#8306)

Attaching or modifying a visualizations returns early on, to avoid a situation when a background job is stalled (by other jobs) and eventually the request timeouts. This has an unfortunate consequence that any error reported in the `UpsertVisualizationJob` cannot be reported as a directly reply to a request because the sender has already been removed from the list. Added more logs to discover why we get errors in the first place. Modified the API a bit so that we carry `VisualizationContext` instead of three parameters all over the place. Bonus: Modified `JsonRpcServerTestKit` to implicitly require a position so that we get better error reporting on failures.
2024-09-11 13:15:52 +03:00 · 2023-11-20 12:38:51 +01:00 · 2023-11-20 12:38:51 +01:00 · b8ebed69c3
commit b8ebed69c3
parent 9edc94afa0
17 changed files with 121 additions and 59 deletions
--- a/engine/language-server/src/main/scala/org/enso/languageserver/protocol/json/JsonConnectionController.scala
+++ b/engine/language-server/src/main/scala/org/enso/languageserver/protocol/json/JsonConnectionController.scala
@ -397,18 +397,16 @@ class JsonConnectionController(
      )

    case ContextRegistryProtocol.VisualizationEvaluationFailed(
-          contextId,
-          visualizationId,
-          expressionId,
+          ctx,
          message,
          diagnostic
        ) =>
      webActor ! Notification(
        VisualizationEvaluationFailed,
        VisualizationEvaluationFailed.Params(
-          contextId,
-          visualizationId,
-          expressionId,
+          ctx.contextId,
+          ctx.visualizationId,
+          ctx.expressionId,
          message,
          diagnostic
        )
--- a/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ContextEventsListener.scala
+++ b/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ContextEventsListener.scala
@ -145,9 +145,7 @@ final class ContextEventsListener(
      message.pipeTo(sessionRouter)

    case Api.VisualizationEvaluationFailed(
-          `contextId`,
-          visualizationId,
-          expressionId,
+          Api.VisualizationContext(visualizationId, contextId, expressionId),
          message,
          diagnostic
        ) =>
@ -157,9 +155,7 @@ final class ContextEventsListener(
          .sequence
        payload =
          ContextRegistryProtocol.VisualizationEvaluationFailed(
-            contextId,
-            visualizationId,
-            expressionId,
+            VisualizationContext(visualizationId, contextId, expressionId),
            message,
            diagnostic
          )
--- a/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ContextRegistry.scala
+++ b/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ContextRegistry.scala
@ -112,8 +112,11 @@ final class ContextRegistry(
      case update: Api.ExecutionUpdate =>
        store.getListener(update.contextId).foreach(_ ! update)

+      case update: Api.VisualizationExpressionFailed =>
+        store.getListener(update.ctx.contextId).foreach(_ ! update)
+
      case update: Api.VisualizationEvaluationFailed =>
-        store.getListener(update.contextId).foreach(_ ! update)
+        store.getListener(update.ctx.contextId).foreach(_ ! update)

      case CreateContextRequest(client, contextIdOpt) =>
        val contextId = contextIdOpt.getOrElse(UUID.randomUUID())
--- a/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ContextRegistryProtocol.scala
+++ b/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ContextRegistryProtocol.scala
@ -568,6 +568,7 @@ object ContextRegistryProtocol {
    * @param diagnostic the detailed information about the failure
    */
  case class VisualizationExpressionFailed(
+    ctx: VisualizationContext,
    message: String,
    diagnostic: Option[ExecutionDiagnostic]
  ) extends Failure
@ -582,9 +583,7 @@ object ContextRegistryProtocol {
    * @param diagnostic the detailed information about the error
    */
  case class VisualizationEvaluationFailed(
-    contextId: UUID,
-    visualizationId: UUID,
-    expressionId: UUID,
+    ctx: VisualizationContext,
    message: String,
    diagnostic: Option[ExecutionDiagnostic]
  )
--- a/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ExecutionApi.scala
+++ b/engine/language-server/src/main/scala/org/enso/languageserver/runtime/ExecutionApi.scala
@ -6,7 +6,10 @@ import org.enso.jsonrpc.{Error, HasParams, HasResult, Method, Unused}
 import org.enso.languageserver.data.CapabilityRegistration
 import org.enso.languageserver.filemanager.Path
 import org.enso.languageserver.libraries.LibraryComponentGroup
-import org.enso.languageserver.runtime.ContextRegistryProtocol.ExecutionDiagnostic
+import org.enso.languageserver.runtime.ContextRegistryProtocol.{
+  ExecutionDiagnostic,
+  VisualizationContext
+}

 import java.util.UUID

@ -265,6 +268,7 @@ object ExecutionApi {
      extends Error(2006, s"Visualization not found")

  case class VisualizationExpressionError(
+    ctx: VisualizationContext,
    msg: String,
    diagnostic: Option[ContextRegistryProtocol.ExecutionDiagnostic]
  ) extends Error(
--- a/engine/language-server/src/main/scala/org/enso/languageserver/runtime/RuntimeConnector.scala
+++ b/engine/language-server/src/main/scala/org/enso/languageserver/runtime/RuntimeConnector.scala
@ -9,6 +9,7 @@ import org.enso.languageserver.runtime.RuntimeConnector.{
 import org.enso.languageserver.util.UnhandledLogging
 import org.enso.lockmanager.server.LockManagerService
 import org.enso.logger.akka.ActorMessageLogging
+import org.enso.logger.masking.ToLogString
 import org.enso.polyglot.runtime.Runtime
 import org.enso.polyglot.runtime.Runtime.{Api, ApiEnvelope}
 import org.enso.profiling.events.EventsMonitor
@ -137,6 +138,11 @@ final class RuntimeConnector(
            correlationId,
            payload.getClass.getCanonicalName
          )
+          payload match {
+            case msg: ToLogString =>
+              logger.warn("Dropped response: {}", msg.toLogString(false))
+            case _ =>
+          }
      }
      context.become(
        initialized(engine, eventsMonitor, senders - correlationId)
--- a/engine/language-server/src/main/scala/org/enso/languageserver/runtime/RuntimeFailureMapper.scala
+++ b/engine/language-server/src/main/scala/org/enso/languageserver/runtime/RuntimeFailureMapper.scala
@ -39,9 +39,14 @@ final class RuntimeFailureMapper(contentRootManager: ContentRootManager) {
        ContextRegistryProtocol.InvalidStackItemError(contextId)
      case Api.ModuleNotFound(moduleName) =>
        ContextRegistryProtocol.ModuleNotFound(moduleName)
-      case Api.VisualizationExpressionFailed(message, result) =>
+      case Api.VisualizationExpressionFailed(ctx, message, result) =>
        for (diagnostic <- result.map(toProtocolDiagnostic).sequence)
          yield ContextRegistryProtocol.VisualizationExpressionFailed(
+            ContextRegistryProtocol.VisualizationContext(
+              ctx.visualizationId,
+              ctx.contextId,
+              ctx.expressionId
+            ),
            message,
            diagnostic
          )
@ -188,7 +193,11 @@ object RuntimeFailureMapper {
        VisualizationNotFoundError
      case ContextRegistryProtocol.ModuleNotFound(name) =>
        ModuleNotFoundError(name)
-      case ContextRegistryProtocol.VisualizationExpressionFailed(msg, result) =>
-        VisualizationExpressionError(msg, result)
+      case ContextRegistryProtocol.VisualizationExpressionFailed(
+            ctx,
+            msg,
+            result
+          ) =>
+        VisualizationExpressionError(ctx, msg, result)
    }
 }
--- a/engine/language-server/src/test/scala/org/enso/languageserver/runtime/ContextEventsListenerSpec.scala
+++ b/engine/language-server/src/test/scala/org/enso/languageserver/runtime/ContextEventsListenerSpec.scala
@ -415,9 +415,11 @@ class ContextEventsListenerSpec
        val visualizationId = UUID.randomUUID()
        val expressionId    = UUID.randomUUID()
        listener ! Api.VisualizationEvaluationFailed(
-          contextId,
-          visualizationId,
-          expressionId,
+          Api.VisualizationContext(
+            visualizationId,
+            contextId,
+            expressionId
+          ),
          message,
          None
        )
@ -426,9 +428,11 @@ class ContextEventsListenerSpec
          DeliverToJsonController(
            clientId,
            VisualizationEvaluationFailed(
-              contextId,
-              visualizationId,
-              expressionId,
+              VisualizationContext(
+                visualizationId,
+                contextId,
+                expressionId
+              ),
              message,
              None
            )
--- a/engine/language-server/src/test/scala/org/enso/languageserver/websocket/json/ContextRegistryTest.scala
+++ b/engine/language-server/src/test/scala/org/enso/languageserver/websocket/json/ContextRegistryTest.scala
@ -819,7 +819,11 @@ class ContextRegistryTest extends BaseServerTest {
        }
      runtimeConnectorProbe.lastSender ! Api.Response(
        requestId2,
-        Api.VisualizationExpressionFailed(expressionFailureMessage, None)
+        Api.VisualizationExpressionFailed(
+          Api.VisualizationContext(visualizationId, contextId, expressionId),
+          expressionFailureMessage,
+          None
+        )
      )
      client.expectJson(
        json.executionContextVisualizationExpressionFailed(
--- a/engine/language-server/src/test/scala/org/enso/languageserver/websocket/json/VisualizationOperationsTest.scala
+++ b/engine/language-server/src/test/scala/org/enso/languageserver/websocket/json/VisualizationOperationsTest.scala
@ -279,6 +279,7 @@ class VisualizationOperationsTest extends BaseServerTest {
      runtimeConnectorProbe.lastSender ! Api.Response(
        requestId,
        Api.VisualizationExpressionFailed(
+          Api.VisualizationContext(visualizationId, contextId, expressionId),
          expressionFailureMessage,
          Some(
            Api.ExecutionResult.Diagnostic.error(
--- a/engine/polyglot-api/src/main/scala/org/enso/polyglot/runtime/Runtime.scala
+++ b/engine/polyglot-api/src/main/scala/org/enso/polyglot/runtime/Runtime.scala
@ -1417,6 +1417,7 @@ object Runtime {
      * @param failure the detailed information about the failure
      */
    final case class VisualizationExpressionFailed(
+      ctx: VisualizationContext,
      message: String,
      failure: Option[ExecutionResult.Diagnostic]
    ) extends Error
@ -1425,6 +1426,9 @@ object Runtime {
      /** @inheritdoc */
      override def toLogString(shouldMask: Boolean): String =
        "VisualizationExpressionFailed(" +
+        s"contextId=${ctx.contextId}," +
+        s"visualizationId=${ctx.visualizationId}," +
+        s"expressionId=${ctx.expressionId}," +
        s"message=${MaskedString(message).toLogString(shouldMask)}," +
        s"failure=${failure.map(_.toLogString(shouldMask))}" +
        ")"
@ -1440,9 +1444,7 @@ object Runtime {
      * @param diagnostic the detailed information about the failure
      */
    final case class VisualizationEvaluationFailed(
-      contextId: ContextId,
-      visualizationId: VisualizationId,
-      expressionId: ExpressionId,
+      ctx: VisualizationContext,
      message: String,
      diagnostic: Option[ExecutionResult.Diagnostic]
    ) extends ApiNotification
@ -1451,9 +1453,9 @@ object Runtime {
      /** @inheritdoc */
      override def toLogString(shouldMask: Boolean): String =
        "VisualizationEvaluationFailed(" +
-        s"contextId=$contextId," +
-        s"visualizationId=$visualizationId," +
-        s"expressionId=$expressionId," +
+        s"contextId=${ctx.contextId}," +
+        s"visualizationId=${ctx.visualizationId}," +
+        s"expressionId=${ctx.expressionId}," +
        s"message=${MaskedString(message).toLogString(shouldMask)}," +
        s"diagnostic=${diagnostic.map(_.toLogString(shouldMask))}" +
        ")"
--- a/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/command/AttachVisualizationCmd.scala
+++ b/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/command/AttachVisualizationCmd.scala
@ -3,6 +3,8 @@ package org.enso.interpreter.instrument.command
 import org.enso.interpreter.instrument.execution.RuntimeContext
 import org.enso.interpreter.instrument.job.{ExecuteJob, UpsertVisualizationJob}
 import org.enso.polyglot.runtime.Runtime.Api
+
+import java.util.logging.Level
 import scala.concurrent.{ExecutionContext, Future}

 /** A command that attaches a visualization to an expression.
@ -22,6 +24,11 @@ class AttachVisualizationCmd(
    ctx: RuntimeContext,
    ec: ExecutionContext
  ): Future[Unit] = {
+    ctx.executionService.getLogger.log(
+      Level.FINE,
+      "Attach visualization cmd for request id [{}] and visualization id [{}]",
+      Array(maybeRequestId, request.visualizationId)
+    )
    ctx.endpoint.sendToClient(
      Api.Response(maybeRequestId, Api.VisualizationAttached())
    )
--- a/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/command/ModifyVisualizationCmd.scala
+++ b/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/command/ModifyVisualizationCmd.scala
@ -10,6 +10,7 @@ import org.enso.interpreter.instrument.job.{
 import org.enso.polyglot.runtime.Runtime.Api
 import org.enso.polyglot.runtime.Runtime.Api.ExpressionId

+import java.util.logging.Level
 import scala.concurrent.{ExecutionContext, Future}

 /** A command that modifies a visualization.
@ -29,6 +30,11 @@ class ModifyVisualizationCmd(
    ctx: RuntimeContext,
    ec: ExecutionContext
  ): Future[Unit] = {
+    ctx.executionService.getLogger.log(
+      Level.FINE,
+      "Modify visualization cmd for request id [{}] and visualization id [{}]",
+      Array(maybeRequestId, request.visualizationId)
+    )
    val existingVisualization = ctx.contextManager.getVisualizationById(
      request.visualizationConfig.executionContextId,
      request.visualizationId
--- a/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/job/ProgramExecutionSupport.scala
+++ b/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/job/ProgramExecutionSupport.scala
@ -551,9 +551,8 @@ object ProgramExecutionSupport {
        ctx.endpoint.sendToClient(
          Api.Response(
            Api.VisualizationEvaluationFailed(
-              contextId,
-              visualizationId,
-              expressionId,
+              Api
+                .VisualizationContext(visualizationId, contextId, expressionId),
              message,
              getDiagnosticOutcome.lift(error)
            )
--- a/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/job/UpsertVisualizationJob.scala
+++ b/engine/runtime-instrument-common/src/main/scala/org/enso/interpreter/instrument/job/UpsertVisualizationJob.scala
@ -28,6 +28,7 @@ import org.enso.pkg.QualifiedName
 import org.enso.polyglot.runtime.Runtime.Api

 import java.util.logging.Level
+import scala.annotation.unused

 /** A job that upserts a visualization.
  *
@ -37,7 +38,7 @@ import java.util.logging.Level
  * @param config a visualization config
  */
 class UpsertVisualizationJob(
-  requestId: Option[Api.RequestId],
+  @unused requestId: Option[Api.RequestId],
  val visualizationId: Api.VisualizationId,
  val expressionId: Api.ExpressionId,
  config: Api.VisualizationConfiguration
@ -70,11 +71,19 @@ class UpsertVisualizationJob(

      maybeCallable match {
        case Left(ModuleNotFound(moduleName)) =>
-          replyWithError(Api.ModuleNotFound(moduleName))
+          ctx.endpoint.sendToClient(
+            Api.Response(Api.ModuleNotFound(moduleName))
+          )
          None

        case Left(EvaluationFailed(message, result)) =>
-          replyWithExpressionFailedError(message, result)
+          replyWithExpressionFailedError(
+            config.executionContextId,
+            visualizationId,
+            expressionId,
+            message,
+            result
+          )
          None

        case Right(EvaluationResult(module, callable, arguments)) =>
@ -122,22 +131,28 @@ class UpsertVisualizationJob(
  }

  private def replyWithExpressionFailedError(
+    contextId: Api.ContextId,
+    visualizationId: Api.VisualizationId,
+    expressionId: Api.ExpressionId,
    message: String,
    executionResult: Option[Api.ExecutionResult.Diagnostic]
  )(implicit ctx: RuntimeContext): Unit = {
+    ctx.executionService.getLogger.log(
+      Level.SEVERE,
+      "Visualization for expression {0} failed: {1} (evaluation result: {2}",
+      Array(expressionId, message, executionResult)
+    )
    ctx.endpoint.sendToClient(
      Api.Response(
-        requestId,
-        Api.VisualizationExpressionFailed(message, executionResult)
+        Api.VisualizationExpressionFailed(
+          Api.VisualizationContext(visualizationId, contextId, expressionId),
+          message,
+          executionResult
+        )
      )
    )
  }

-  private def replyWithError(error: Api.Error)(implicit
-    ctx: RuntimeContext
-  ): Unit = {
-    ctx.endpoint.sendToClient(Api.Response(requestId, error))
-  }
 }

 object UpsertVisualizationJob {
--- a/engine/runtime-with-polyglot/src/test/scala/org/enso/interpreter/test/instrument/RuntimeVisualizationsTest.scala
+++ b/engine/runtime-with-polyglot/src/test/scala/org/enso/interpreter/test/instrument/RuntimeVisualizationsTest.scala
@ -1703,7 +1703,7 @@ class RuntimeVisualizationsTest
    )
    context.receiveN(2) should contain theSameElementsAs Seq(
      Api.Response(requestId, Api.VisualizationAttached()),
-      Api.Response(requestId, Api.ModuleNotFound("Test.Undefined"))
+      Api.Response(Api.ModuleNotFound("Test.Undefined"))
    )
  }

@ -1870,8 +1870,8 @@ class RuntimeVisualizationsTest
    context.receiveN(2) should contain theSameElementsAs Seq(
      Api.Response(requestId, Api.VisualizationAttached()),
      Api.Response(
-        requestId,
        Api.VisualizationExpressionFailed(
+          Api.VisualizationContext(visualizationId, contextId, idMain),
          "Method `does_not_exist` of type Main could not be found.",
          Some(
            Api.ExecutionResult.Diagnostic.error(
@ -1956,9 +1956,11 @@ class RuntimeVisualizationsTest
      Api.Response(requestId, Api.VisualizationAttached()),
      Api.Response(
        Api.VisualizationEvaluationFailed(
-          contextId,
-          visualizationId,
-          idMain,
+          Api.VisualizationContext(
+            visualizationId,
+            contextId,
+            idMain
+          ),
          "Method `visualise_me` of type Integer could not be found.",
          Some(
            Api.ExecutionResult.Diagnostic.error(
@ -2074,9 +2076,11 @@ class RuntimeVisualizationsTest
      Api.Response(requestId, Api.VisualizationAttached()),
      Api.Response(
        Api.VisualizationEvaluationFailed(
-          contextId,
-          visualizationId,
-          idMain,
+          Api.VisualizationContext(
+            visualizationId,
+            contextId,
+            idMain
+          ),
          "Method `visualise_me` of type Integer could not be found.",
          Some(
            Api.ExecutionResult.Diagnostic.error(
@ -2306,9 +2310,11 @@ class RuntimeVisualizationsTest
      ),
      Api.Response(
        Api.VisualizationEvaluationFailed(
-          contextId,
-          visualizationId,
-          idMain,
+          Api.VisualizationContext(
+            visualizationId,
+            contextId,
+            idMain
+          ),
          "42",
          Some(
            Api.ExecutionResult.Diagnostic.error(
--- a/lib/scala/json-rpc-server-test/src/main/scala/org/enso/jsonrpc/test/JsonRpcServerTestKit.scala
+++ b/lib/scala/json-rpc-server-test/src/main/scala/org/enso/jsonrpc/test/JsonRpcServerTestKit.scala
@ -14,6 +14,7 @@ import org.enso.jsonrpc.{
  JsonRpcServer,
  ProtocolFactory
 }
+import org.scalactic.source.Position
 import org.scalatest.matchers.{MatchResult, Matcher}
 import org.scalatest.matchers.should.Matchers
 import org.scalatest.wordspec.AnyWordSpecLike
@ -122,12 +123,14 @@ abstract class JsonRpcServerTestKit
    def expectJson(
      json: Json,
      timeout: FiniteDuration = 5.seconds.dilated
-    ): Assertion = {
+    )(implicit pos: Position): Assertion = {
      val parsed = parse(expectMessage(timeout))
      parsed shouldEqual Right(json)
    }

-    def expectSomeJson(timeout: FiniteDuration = 5.seconds.dilated): Json = {
+    def expectSomeJson(
+      timeout: FiniteDuration = 5.seconds.dilated
+    )(implicit pos: Position): Json = {
      val parsed = parse(expectMessage(timeout))
      inside(parsed) { case Right(json) => json }
    }