Progress API (#12163)

Defines _Progress API_ - a way to start long running actions and report their progress:
```ruby
type Progress
advance self amount:Standard.Base.Data.Numbers.Integer= -> Standard.Base.Logging.Progress
log self detail:Standard.Base.Data.Text.Text -> Standard.Base.Logging.Progress
run label:Standard.Base.Data.Text.Text up_to:Standard.Base.Data.Numbers.Integer action:Standard.Base.Any.Any -> Standard.Base.Any.Any
```
The reported information is then collected in language server and delivered to the IDE to display the progress via #12126 & co.

# Important Notes
The _"Enso facing API"_ consists of `type Progress` with its static method to execute a _progress reporting_ operations. The operation is a function that gets `Progress` instance as a callback and can use its methods to report the `advance` as well as `log` details of the actual operation in progress.

This is all very similar to _logging_:
- hence the `Progress` type is placed into logging
- logging is used to report the operation progress
- `LoggedMessage.observe` is used to collect the messages in the language server

Author: JaroslavTulach

CHANGELOG.md

@@ -63,6 +63,7 @@
 - [Added Table.Offset][12071]
 - [Implemented Generic JDBC connections.][12073]
 - [Added Column.Offset][12092]
+- [Progress API][12163]
 - [When reading a Delimited file, if a row with more columns than expected is
   encountered, extra columns can be added to the result.][12231]
   - In `Delimited` format, the `keep_invalid_rows` setting has been renamed to
@@ -82,6 +83,7 @@
 [12071]: https://github.com/enso-org/enso/pull/12071
 [12073]: https://github.com/enso-org/enso/pull/12073
 [12092]: https://github.com/enso-org/enso/pull/12092
+[12163]: https://github.com/enso-org/enso/pull/12163
 [12231]: https://github.com/enso-org/enso/pull/12231
 [12206]: https://github.com/enso-org/enso/pull/12206
 [12251]: https://github.com/enso-org/enso/pull/12251

app/gui/src/project-view/stores/project/computedValueRegistry.ts

@@ -56,6 +56,13 @@ export class ComputedValueRegistry {
   processUpdates(updates: ExpressionUpdate[]) {
     for (const update of updates) {
       const info = this.db.get(update.expressionId)
+      if (update.payload.type == 'Pending' && update.payload.progress == -1.0) {
+        // just update the payload
+        if (info) {
+          info.payload = update.payload
+        }
+        continue
+      }
       if (info) updateInfo(info, update, this.projectNames)
       else this.db.set(update.expressionId, combineInfo(undefined, update, this.projectNames))
     }

build.sbt

@@ -1121,7 +1121,8 @@ lazy val `logging-service-logback` = project
     Compile / shouldCompileModuleInfoManually := true,
     Compile / internalModuleDependencies := Seq(
       (`logging-service` / Compile / exportedModule).value,
-      (`logging-config` / Compile / exportedModule).value
+      (`logging-config` / Compile / exportedModule).value,
+      (`logging-utils` / Compile / exportedModule).value
     ),
     Test / shouldCompileModuleInfoManually := true,
     Test / javaModuleName := "org.enso.logging.service.logback.test.provider",
@@ -3062,6 +3063,7 @@ lazy val `runtime-integration-tests` =
     .dependsOn(`runtime`)
     .dependsOn(`runtime-test-instruments`)
     .dependsOn(`logging-service-logback` % "test->test")
+    .dependsOn(`logging-utils` % Test)
     .dependsOn(testkit % Test)
     .dependsOn(`connected-lock-manager-server`)
     .dependsOn(`test-utils`)
@@ -4557,9 +4559,9 @@ lazy val `library-manager-test` = project
   )
   .dependsOn(`library-manager`)
   .dependsOn(`process-utils`)
-  .dependsOn(`logging-utils` % "test->test")
+  .dependsOn(`logging-utils`)
   .dependsOn(testkit)
-  .dependsOn(`logging-service-logback` % "test->test")
+  .dependsOn(`logging-service-logback` % Test)
 
 lazy val `connected-lock-manager` = project
   .in(file("lib/scala/connected-lock-manager"))

distribution/lib/Standard/Base/0.0.0-dev/docs/api/Logging.md

@@ -6,4 +6,9 @@
     - Info
     - Severe
     - Warning
+- type Progress
+    - advance self amount:Standard.Base.Data.Numbers.Integer= -> Standard.Base.Logging.Progress
+    - log self detail:Standard.Base.Data.Text.Text -> Standard.Base.Logging.Progress
+    - run label:Standard.Base.Data.Text.Text up_to:Standard.Base.Data.Numbers.Integer action:Standard.Base.Any.Any -> Standard.Base.Any.Any
+    - to_text self -> Standard.Base.Any.Any
 - Standard.Base.Any.Any.log_message self ~message:Standard.Base.Data.Text.Text level:Standard.Base.Logging.Log_Level= -> Standard.Base.Any.Any

distribution/lib/Standard/Base/0.0.0-dev/src/Logging.enso

@@ -1,5 +1,7 @@
 import project.Any.Any
 import project.Data.Text.Text
+import project.Data.Vector.Vector
+import project.Data.Numbers.Integer
 import project.Meta
 import project.Nothing.Nothing
 
@@ -13,14 +15,74 @@ Any.log_message : Text -> Log_Level -> Any
 Any.log_message self ~message:Text level:Log_Level=Log_Level.Info =
     type_name = self.to Meta.Type . qualified_name
     logger = LoggerFactory.getLogger type_name
-    case level of
-        Log_Level.Finest -> logger.trace message
-        Log_Level.Fine -> logger.debug message
-        Log_Level.Info -> logger.info message
-        Log_Level.Warning -> logger.warn message
-        Log_Level.Severe -> logger.error message
+    log_impl logger message level []
     self
 
+## Infrastructure for reporting logs and progress of computations.
+
+   Useful for longer running actions (more than a second). A must
+   for long running actions (more than ten seconds). 
+   Start by invoking `Progress.run`, providing your own action
+   to preform and report progress as your action advances. Nest
+   your `Progress.run` invocations freely - the infrastructure is
+   going to take care of combining the overall status of the computations
+   together and will report it as a whole to a
+   [progress displaying facility](https://github.com/enso-org/enso/pull/12126).
+type Progress
+    private Running label:Text max:Integer logger
+
+    ## Performs provided `action` while reporting its progress.
+
+       The `action` is a function that takes a `Progress` handle
+       and uses its methods to report progress of the computation.
+       The value returned from `action` is returned from this
+       method.
+
+       Arguments:
+       - label: Overall description of the action
+       - up_to: how _"long"_ - e.g. how many steps the action is expected to take. 
+           It has to be at least one or higher.
+       - action: function performing the computation while reporting its `Progress`
+
+    run label:Text up_to:Integer action:(Progress->Any) -> Any =
+        logger = LoggerFactory.getLogger (Progress.to Meta.Type . qualified_name)
+        progress = Progress.Running label (up_to.max 1) logger
+        log_impl logger "INIT {}:{}@{}" Log_Level.Finest [progress, progress.label, progress.max]
+        res = action progress
+        progress.advance up_to
+        res
+
+    ## Reports progress of the computation.
+
+       Adds provided `amount` to the already
+       accumulated work towards `up_to` value provided when creating this `Progress`.
+
+       Arguments:
+       - amount: value to add to the progress. Must be >= 0
+
+       Returns:
+       The self value.
+
+    advance self amount:Integer=1 -> Progress =
+        add = if amount>=0 then amount else 0
+        log_impl self.logger "ADVANCE {}+{}" Log_Level.Finest [self, add]
+        self
+
+    ## Provides additional human readable detail of the status of the computation.
+
+       Arguments:
+       - info: textual description of what's going on
+
+       Returns:
+       The self value.
+
+    log self detail:Text -> Progress =
+        log_impl self.logger "LOG {}:{}" Log_Level.Finest [self, detail]
+        self
+
+    ## Simple name of the progress
+    to_text self = "Progress"
+
 ## PRIVATE
 type Log_Level
     ## Finest (Trace) level log message.
@@ -37,3 +99,17 @@ type Log_Level
 
     ## Severe level log message.
     Severe
+
+private log_impl logger ~message level args =
+    builder = case level of
+        Log_Level.Finest -> logger.atTrace
+        Log_Level.Fine -> logger.atDebug
+        Log_Level.Info -> logger.atInfo
+        Log_Level.Warning -> logger.atWarn
+        Log_Level.Severe -> logger.atError
+
+    builder.setMessage message
+    args.each a->
+        builder.addArgument a
+
+    builder.log

engine/common/src/main/java/org/enso/common/RuntimeOptions.java

@@ -92,6 +92,11 @@ private RuntimeOptions() {}
   private static final OptionDescriptor ENABLE_GLOBAL_SUGGESTIONS_DESCRIPTOR =
       OptionDescriptor.newBuilder(ENABLE_GLOBAL_SUGGESTIONS_KEY, ENABLE_GLOBAL_SUGGESTIONS).build();
 
+  public static final String ENABLE_PROGRESS_REPORT = optionName("enableProgressReport");
+  public static final OptionKey<Boolean> ENABLE_PROGRESS_REPORT_KEY = new OptionKey<>(true);
+  private static final OptionDescriptor ENABLE_PROGRESS_REPORT_DESCRIPTOR =
+      OptionDescriptor.newBuilder(ENABLE_PROGRESS_REPORT_KEY, ENABLE_PROGRESS_REPORT).build();
+
   public static final String LANGUAGE_HOME_OVERRIDE = optionName("languageHomeOverride");
   public static final OptionKey<String> LANGUAGE_HOME_OVERRIDE_KEY = new OptionKey<>("");
   private static final OptionDescriptor LANGUAGE_HOME_OVERRIDE_DESCRIPTOR =
@@ -156,6 +161,7 @@ private RuntimeOptions() {}
               ENABLE_AUTO_PARALLELISM_DESCRIPTOR,
               ENABLE_PROJECT_SUGGESTIONS_DESCRIPTOR,
               ENABLE_GLOBAL_SUGGESTIONS_DESCRIPTOR,
+              ENABLE_PROGRESS_REPORT_DESCRIPTOR,
               INTERACTIVE_MODE_DESCRIPTOR,
               DISABLE_LINTING_DESCRIPTOR,
               LANGUAGE_HOME_OVERRIDE_DESCRIPTOR,

engine/launcher/src/test/scala/org/enso/launcher/components/LauncherRunnerSpec.scala

@@ -10,12 +10,13 @@ import org.enso.runtimeversionmanager.config.GlobalRunnerConfigurationManager
 import org.enso.runtimeversionmanager.runner._
 import org.enso.runtimeversionmanager.test.RuntimeVersionManagerTest
 import org.enso.launcher.project.ProjectManager
-import org.enso.logger.TestLogger
+import org.enso.logger.ObservedMessage
 import org.slf4j.event.Level
 
 import org.enso.testkit.FlakySpec
 
 import scala.concurrent.Future
+import org.slf4j.LoggerFactory
 
 /** We test integration of both the underlying [[Runner]] and the
   * [[LauncherRunner]] in a single suite.
@@ -176,28 +177,34 @@ class LauncherRunnerSpec extends RuntimeVersionManagerTest with FlakySpec {
       val runner         = makeFakeRunner()
       val projectPath    = getTestDirectory / "project2"
       val nightlyVersion = SemVer.of(0, 0, 0, "SNAPSHOT.2000-01-01")
-      val (_, logs) = TestLogger.gather[Any, Runner](
-        classOf[Runner], {
-          runner
-            .newProject(
-              path                = projectPath,
-              name                = "ProjectName2",
-              engineVersion       = nightlyVersion,
-              normalizedName      = None,
-              projectTemplate     = None,
-              authorName          = None,
-              authorEmail         = None,
-              additionalArguments = Seq()
-            )
-            .get
-        }
+      val logger         = LoggerFactory.getLogger(classOf[Runner])
+      val action: Runnable = () => {
+        runner
+          .newProject(
+            path                = projectPath,
+            name                = "ProjectName2",
+            engineVersion       = nightlyVersion,
+            normalizedName      = None,
+            projectTemplate     = None,
+            authorName          = None,
+            authorEmail         = None,
+            additionalArguments = Seq()
+          )
+          .get
+      }
+      val logs = ObservedMessage.collect(
+        logger,
+        action
       )
       assert(
-        logs.exists(msg =>
-          msg.level == Level.WARN && msg.msg.contains(
-            "Consider using a stable version."
+        logs.stream
+          .filter(msg =>
+            msg.getLevel == Level.WARN && msg.getMessage.contains(
+              "Consider using a stable version."
+            )
           )
-        )
+          .findAny
+          .isPresent
       )
     }
 

engine/runtime-instrument-common/src/main/java/org/enso/interpreter/service/ExecutionCallbacks.java

@@ -6,6 +6,7 @@
 import java.util.Map;
 import java.util.UUID;
 import java.util.function.Consumer;
+import org.enso.common.CachePreferences;
 import org.enso.interpreter.instrument.ExpressionExecutionState;
 import org.enso.interpreter.instrument.MethodCallsCache;
 import org.enso.interpreter.instrument.OneshotExpression;
@@ -39,6 +40,8 @@ final class ExecutionCallbacks implements IdExecutionService.Callbacks {
   private final Consumer<ExpressionValue> onComputedCallback;
   private final Consumer<ExpressionCall> functionCallCallback;
   private final Consumer<ExecutedVisualization> onExecutedVisualizationCallback;
+  private final Consumer<ExpressionValue> onProgressCallbackOrNull;
+  private ExecutionProgressObserver progressObserver;
 
   /**
    * Creates callbacks instance.
@@ -53,6 +56,7 @@ final class ExecutionCallbacks implements IdExecutionService.Callbacks {
    * @param onCachedCallback the consumer of the cached value events.
    * @param functionCallCallback the consumer of function call events.
    * @param onExecutedVisualizationCallback the consumer of an executed visualization result.
+   * @param onProgressCallbackOrNull the consumer of progress events
    */
   ExecutionCallbacks(
       VisualizationHolder visualizationHolder,
@@ -64,7 +68,8 @@ final class ExecutionCallbacks implements IdExecutionService.Callbacks {
       Consumer<ExpressionValue> onCachedCallback,
       Consumer<ExpressionValue> onComputedCallback,
       Consumer<ExpressionCall> functionCallCallback,
-      Consumer<ExecutedVisualization> onExecutedVisualizationCallback) {
+      Consumer<ExecutedVisualization> onExecutedVisualizationCallback,
+      Consumer<ExpressionValue> onProgressCallbackOrNull) {
     this.visualizationHolder = visualizationHolder;
     this.nextExecutionItem = nextExecutionItem;
     this.cache = cache;
@@ -75,6 +80,7 @@ final class ExecutionCallbacks implements IdExecutionService.Callbacks {
     this.onComputedCallback = onComputedCallback;
     this.functionCallCallback = functionCallCallback;
     this.onExecutedVisualizationCallback = onExecutedVisualizationCallback;
+    this.onProgressCallbackOrNull = onProgressCallbackOrNull;
   }
 
   @Override
@@ -92,24 +98,69 @@ public Object findCachedResult(IdExecutionService.Info info) {
     if (result != null && !nodeId.equals(nextExecutionItem)) {
       callOnCachedCallback(nodeId, result);
       return result;
+    } else {
+      if (onProgressCallbackOrNull != null) {
+        reportEvaluationProgress(nodeId);
+      }
     }
 
     return null;
   }
 
+  @CompilerDirectives.TruffleBoundary
+  private void reportEvaluationProgress(UUID nodeId) {
+    if (cache.getPreferences().get(nodeId) == CachePreferences.Kind.BINDING_EXPRESSION) {
+      var newObserver =
+          ExecutionProgressObserver.startComputation(
+              nodeId,
+              (progress, msg) -> {
+                CompilerDirectives.transferToInterpreter();
+                var expressionValue = ExpressionValue.progress(nodeId, progress, msg);
+                onProgressCallbackOrNull.accept(expressionValue);
+              });
+      refreshObserver(newObserver);
+    }
+  }
+
+  private void refreshObserver(ExecutionProgressObserver newObserverOrNull) {
+    var o = progressObserver;
+    if (o != null) {
+      try {
+        o.close();
+      } catch (Exception ex) {
+        throw ExecutionService.raise(RuntimeException.class, ex);
+      }
+    }
+    this.progressObserver = newObserverOrNull;
+  }
+
   @Override
   public void updateCachedResult(IdExecutionService.Info info) {
     Object result = info.getResult();
     TypeInfo resultType = typeOf(result);
     UUID nodeId = info.getId();
+
+    if (progressObserver instanceof ExecutionProgressObserver o && nodeId.equals(o.nodeId())) {
+      refreshObserver(null);
+    }
+
     TypeInfo cachedType = cache.getType(nodeId);
     FunctionCallInfo call = functionCallInfoById(nodeId);
     FunctionCallInfo cachedCall = cache.getCall(nodeId);
     ProfilingInfo[] profilingInfo = new ProfilingInfo[] {new ExecutionTime(info.getElapsedTime())};
 
     ExpressionValue expressionValue =
         new ExpressionValue(
-            nodeId, result, resultType, cachedType, call, cachedCall, profilingInfo, false);
+            nodeId,
+            result,
+            resultType,
+            cachedType,
+            call,
+            cachedCall,
+            profilingInfo,
+            false,
+            -1.0,
+            null);
     syncState.setExpressionUnsync(nodeId);
     syncState.setVisualizationUnsync(nodeId);
 
@@ -172,7 +223,9 @@ private void callOnCachedCallback(UUID nodeId, Object result) {
             calls.get(nodeId),
             cache.getCall(nodeId),
             new ProfilingInfo[] {ExecutionTime.empty()},
-            true);
+            true,
+            -1.0,
+            null);
 
     onCachedCallback.accept(expressionValue);
   }