From a5ebdf4e792b1c3834eea3d5e3215a592dd50182 Mon Sep 17 00:00:00 2001 From: Hubert Plociniczak Date: Thu, 7 Nov 2024 16:03:19 +0100 Subject: [PATCH] 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 --- build.sbt | 1 + docs/infrastructure/logging.md | 128 +++++++++++++++--- .../src/main/java/org/enso/runner/Main.java | 10 +- .../org/enso/runner/RunnerEnvironment.java | 5 + .../java/org/enso/runner/RunnerLogging.java | 32 ++++- .../src/main/resources/application.conf | 28 ++++ 6 files changed, 177 insertions(+), 27 deletions(-) create mode 100644 engine/runner/src/main/java/org/enso/runner/RunnerEnvironment.java create mode 100644 engine/runner/src/main/resources/application.conf diff --git a/build.sbt b/build.sbt index 2a7909868b..3e77bcaca2 100644 --- a/build.sbt +++ b/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`) diff --git a/docs/infrastructure/logging.md b/docs/infrastructure/logging.md index ec993c963b..24509714b5 100644 --- a/docs/infrastructure/logging.md +++ b/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. diff --git a/engine/runner/src/main/java/org/enso/runner/Main.java b/engine/runner/src/main/java/org/enso/runner/Main.java index 46cbcc3958..fd99d8486c 100644 --- a/engine/runner/src/main/java/org/enso/runner/Main.java +++ b/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 @@ public class Main { java.util.List 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 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 additionalArgs, - String mainMethodName // = "main" + String mainMethodName // = DEFAULT_MAIN_METHOD_NAME ) { try { var mainType = mainModule.getAssociatedType(); @@ -881,7 +883,7 @@ public class Main { 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. diff --git a/engine/runner/src/main/java/org/enso/runner/RunnerEnvironment.java b/engine/runner/src/main/java/org/enso/runner/RunnerEnvironment.java new file mode 100644 index 0000000000..8136bd50e4 --- /dev/null +++ b/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 {} diff --git a/engine/runner/src/main/java/org/enso/runner/RunnerLogging.java b/engine/runner/src/main/java/org/enso/runner/RunnerLogging.java index 24b1169f7f..da8f93560e 100644 --- a/engine/runner/src/main/java/org/enso/runner/RunnerLogging.java +++ b/engine/runner/src/main/java/org/enso/runner/RunnerLogging.java @@ -4,6 +4,7 @@ import java.net.URI; 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,7 +52,6 @@ final class RunnerLogging { 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"); } @@ -57,9 +59,31 @@ final class RunnerLogging { 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"); + } } } diff --git a/engine/runner/src/main/resources/application.conf b/engine/runner/src/main/resources/application.conf new file mode 100644 index 0000000000..33d055c6df --- /dev/null +++ b/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} + } +}