Fix logging in CLI (#11472)

* Fix logging in CLI

Previously, unless `--logger-connect` was used, CLI would always
fallback to console logging. In addition it would be misconfigured if
`application.conf` was provided with logging configuration.

This change makes sure that CLI uses the same logging infrastructure as
the rest of the system.
As a result, CLI will now by default not only log to the console and
respect the provided configuration but also log to the file system.

* Update docs

* c&p error

* More examples

Author: hubertp

build.sbt

@@ -3689,6 +3689,7 @@ lazy val `engine-runner` = project
   .dependsOn(cli)
   .dependsOn(`profiling-utils`)
   .dependsOn(`library-manager`)
+  .dependsOn(`distribution-manager`)
   .dependsOn(`edition-updater`)
   .dependsOn(`runtime-parser`)
   .dependsOn(`logging-service`)

docs/infrastructure/logging.md

@@ -35,13 +35,17 @@ involving the centralized logging service.
 
 ## Configuration
 
-The logging settings should be placed under the `logging-service` key of the
-`application.conf` config. Each of the main components can customize format and
-output target via section in `application.conf` configuration file. The
+All logging settings are configured via the `logging-service` section of the
+`application.conf` config file. Each of the main components can customize format
+and output target via section in `application.conf` configuration file. The
 configuration is using HOCON-style, as defined by
 [lightbend/config](https://github.com/lightbend/config). Individual values
 accepted in the config are inspired by SLF4J's properties, formatting and
-implementations.
+implementations. Currently 3 components define logging configuration:
+
+- [`project-manager`](../../lib/scala/project-manager/src/main/resources/application.conf)
+- [`launcher`](../../engine/launcher/src/main/resources/application.conf)
+- [CLI](../../engine/runner/src/main/resources/application.conf)
 
 The configuration has two main sections:
 
@@ -57,8 +61,8 @@ representation is available as an instance of
 programmatically initialize loggers.
 
 As per [configuration schema](https://github.com/lightbend/config) any key can
-have a default value that can be overridden by an environment variable. For
-example
+be defined with a default value that can be overridden by an environment
+variable. For example
 
 ```
   {
@@ -72,10 +76,18 @@ it is defined during loading of the config file.
 
 ### Custom Log Levels
 
-The `logging-service.logger` configuration provides an ability to override the
-default application log level for particular loggers. In the `logger` subconfig
-the key specifies the logger name (or it's prefix) and the value specifies the
-log level for that logger.
+Possible log level values are (in the order of precedence):
+
+- `error`
+- `warn`
+- `info`
+- `debug`
+- `trace`
+
+The `logging-service.logger` configuration section provides an ability to
+override the default application log level for particular loggers. In the
+`logger` subconfig the key specifies the logger name (or it's prefix) and the
+value specifies the log level for that logger.
 
 ```
 logging-service.logger {
@@ -117,7 +129,7 @@ properties always have a higher priority over those defined in the
 
 ### Appenders
 
-Log output target is also configured in the `application.conf` files in the
+Log output target is configured in the `application.conf` files in the
 "appenders" section ("appender" is equivalent to `java.util.logging.Handler`
 semantics). Each appender section can provide further required and optional
 key/value pairs, to better customize the log target output.
@@ -133,8 +145,10 @@ Currently supported are
   a sentry.io service
 
 The appenders are defined by the `logging-service.appenders`. Currently only a
-single appender can be selected at a time. The selection may also be done via an
-environmental variable but it depends on which component we are executing.
+single appender can be selected at a time, although additional
+[logging to file](#logging-to-file) is supported. The selection may also be done
+via an environmental variable but it depends on which component we are
+executing.
 
 - `project-manager` - project manager by default starts a centralized logging
   server that collects logs (as defined in `logging-service.server` config key)
@@ -169,6 +183,17 @@ message via `pattern` field e.g.
   ]
 ```
 
+In the above example `%logger` format will be substituted with a class name for
+which the logger was created with.
+
+By default, console pattern includes `%nopex` formatter which means that any
+stacktrace attached to the log message will always be ignored. By default other
+appenders do not have such formatting key. This means that if an exception is
+included in the logged messaged, a full stacktrace will be attached, if present.
+
+For a full list of formatting keys please refer to the concrete implementation's
+[manual](https://logback.qos.ch/manual/layouts.html#ClassicPatternLayout).
+
 #### File Appender
 
 Enabled with `ENSO_APPENDER_DEFAULT=file` environment variable.
@@ -352,18 +377,83 @@ way it can verify that all logs are being reported within the provided code.
 ### Logging to file
 
 By default Enso will attempt to persist (verbose) logs into a designated log
-file. This means that even though a user might be shown `WARNING` level logs in
-the console, logs with up to `DEBUG` level will be dumped into the log file. A
-user can disable this parallel logging to a file by setting the environment
-variable:
+file. This means that even though a user might be shown only `WARNING` level
+logs in the console, logs with up to `DEBUG` or `TRACE` level, including full
+stacktraces, can be dumped into the log file. A user can disable this parallel
+logging to a file by setting the environment variable:
 
 ```
 ENSO_LOG_TO_FILE=false project-manager ...
 ```
 
-Users can also modify the default maximal log level, `DEBUG`, used when logging
-to a log file by setting the environment variable:
+Users can fully control the maximal log level used when logging to a log file by
+setting the environment variable:
 
 ```
 ENSO_LOG_TO_FILE_LOG_LEVEL=trace project-manager ...
 ```
+
+For example, in the above example `project-manager` will log events of up-to
+`trace` in the log file.
+
+**Note** Logging to a file requires presence of the `file`
+[appender](#file-appender) in the `logging-service.appenders` section.
+
+# How to use logging
+
+Logging infrastructure uses a popular SLF4J interface which most of developers
+should be familiar with. In this section we include a only small number of
+examples, full user manual is available at SLF4J's
+[website](https://www.slf4j.org/manual.html).
+
+## Log a simple INFO message
+
+```
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class HelloWorld {
+
+  public static void main(String[] args) {
+    Logger logger = LoggerFactory.getLogger(HelloWorld.class);
+    logger.info("Hello World");
+  }
+}
+```
+
+## Log a simple INFO message only if TRACE is enabled
+
+```
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class HelloWorld {
+
+  public static void main(String[] args) {
+    Logger logger = LoggerFactory.getLogger(HelloWorld.class);
+    if (logger.isTraceEnabled()) {
+      logger.info("Hello World");
+    }
+  }
+}
+```
+
+## Log an exception
+
+```
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class HelloWorld {
+
+  public static void main(String[] args) {
+    Logger logger = LoggerFactory.getLogger(HelloWorld.class);
+    Throwable ex = new RuntimeException("foo")
+    logger.error("Hello World", ex);
+  }
+}
+```
+
+Note that in order for the full stacktrace to be printed, pattern in the desired
+appender must not contain `%nopex` formatting key. See [formatting](#format) for
+details.

engine/runner/src/main/java/org/enso/runner/Main.java

@@ -101,6 +101,8 @@ public class Main {
   private static final String WARNINGS_LIMIT = "warnings-limit";
   private static final String SYSTEM_PROPERTY = "vm.D";
 
+  private static final String DEFAULT_MAIN_METHOD_NAME = "main";
+
   private static final org.slf4j.Logger logger = LoggerFactory.getLogger(Main.class);
 
   Main() {}
@@ -854,20 +856,20 @@ private void runPackage(
       java.util.List<String> additionalArgs) {
     var topScope = context.getTopScope();
     var mainModule = topScope.getModule(mainModuleName);
-    runMain(mainModule, projectPath, additionalArgs, "main");
+    runMain(mainModule, projectPath, additionalArgs, DEFAULT_MAIN_METHOD_NAME);
   }
 
   private void runSingleFile(
       PolyglotContext context, File file, java.util.List<String> additionalArgs) {
     var mainModule = context.evalModule(file);
-    runMain(mainModule, file, additionalArgs, "main");
+    runMain(mainModule, file, additionalArgs, DEFAULT_MAIN_METHOD_NAME);
   }
 
   private void runMain(
       Module mainModule,
       File rootPkgPath,
       java.util.List<String> additionalArgs,
-      String mainMethodName // = "main"
+      String mainMethodName // = DEFAULT_MAIN_METHOD_NAME
       ) {
     try {
       var mainType = mainModule.getAssociatedType();
@@ -881,7 +883,7 @@ private void runMain(
         throw exitFail();
       }
       var main = mainFun.get();
-      if (!"main".equals(mainMethodName)) {
+      if (!DEFAULT_MAIN_METHOD_NAME.equals(mainMethodName)) {
         main.execute(join(mainType, nil()));
       } else {
         // Opportunistically parse arguments and convert to ints.

engine/runner/src/main/java/org/enso/runner/RunnerEnvironment.java

@@ -0,0 +1,5 @@
+package org.enso.runner;
+
+import org.enso.distribution.Environment;
+
+public class RunnerEnvironment implements Environment {}

engine/runner/src/main/java/org/enso/runner/RunnerLogging.java

@@ -4,6 +4,7 @@
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
+import org.enso.distribution.DistributionManager;
 import org.enso.logger.masking.Masking;
 import org.enso.logging.config.LoggerSetup;
 import org.slf4j.Logger;
@@ -14,6 +15,8 @@ final class RunnerLogging {
   private RunnerLogging() {}
 
   private static final Logger logger = LoggerFactory.getLogger(RunnerLogging.class);
+  private static final DistributionManager distributionManager =
+      new DistributionManager(new RunnerEnvironment());
 
   /**
    * Sets up the runner's logging service.
@@ -49,17 +52,38 @@ private static void setupImpl(
         var success = future.get();
         if (success) {
           logger.trace("Connected to logging service at [{}]", connectionUri);
-          return;
         } else {
           throw new RuntimeException("Failed to connect to logging service");
         }
       } catch (InterruptedException | ExecutionException e) {
         System.err.println(
             "Failed to connect to the logging service server, " + "falling back to local logging.");
       }
-    }
-    if (!setupConsoleAppender(logLevel, executorService, loggerSetup)) {
-      System.err.println("Failed to initialize logging infrastructure");
+    } else {
+      var future =
+          executorService.submit(
+              () ->
+                  loggerSetup.setup(
+                      logLevel,
+                      distributionManager.detectPaths().logs(),
+                      "enso-cli",
+                      loggerSetup.getConfig()));
+      try {
+        var success = future.get();
+        if (!success) {
+          System.err.println("Failed to initialize logging from the configuration");
+        } else {
+          return;
+        }
+      } catch (InterruptedException | ExecutionException e) {
+        System.err.println(
+            "Failed to initialize logging from the configuration due to internal exception: "
+                + e.getMessage());
+      }
+      System.err.println("Attempting to fallback logging to console only");
+      if (!setupConsoleAppender(logLevel, executorService, loggerSetup)) {
+        System.err.println("Failed to initialize logging infrastructure");
+      }
     }
   }
 

engine/runner/src/main/resources/application.conf

@@ -0,0 +1,28 @@
+# CLI's application.conf
+
+logging-service {
+  logger {
+    akka.actor = info
+    akka.event = error
+    akka.io = error
+    akka.stream = error
+  }
+  appenders = [
+      {
+        name = "file",
+        pattern = "[%level{lowercase=true}] [%d{yyyy-MM-dd'T'HH:mm:ssXXX}] [%logger] %msg%n"
+      },
+      {
+        name = "console"
+        pattern = "[%level{lowercase=true}] [%d{yyyy-MM-dd'T'HH:mm:ssXXX}] [%logger] %msg%n%nopex"
+      }
+  ]
+  default-appender = console
+  default-appender = ${?ENSO_APPENDER_DEFAULT}
+  log-to-file {
+    enable = true
+    enable = ${?ENSO_LOG_TO_FILE}
+    log-level = trace
+    log-level = ${?ENSO_LOG_TO_FILE_LOG_LEVEL}
+  }
+}