enso/docs/infrastructure/logging.md

layout	title	category	tags	order
developer-doc	Logging Service	infrastructure	infrastructure logging debug	6

Logging

The Enso project features a centralised logging service to allow for the aggregation of logs from multiple components. This service can be started with one of the main components, allowing other components to connect to it. The service aggregates all logs in one place for easier analysis of the interaction between components. Components can also log to console or files directly without involving the centralized logging service.

• Configuration
  • Custom Log Levels
  • Appenders
    • Format
    • File
    • Network
    • Sentry.io
• JVM Architecture
  • SLF4J Interface
  • Setting Up Logging
  • Log Masking
  • Logging in Tests
  • Logging to file

Configuration

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. Individual values accepted in the config are inspired by SLF4J's properties, formatting and implementations. Currently 3 components define logging configuration:

• project-manager
• launcher
• CLI

The configuration has two main sections:

• custom log levels
• applications' appenders (also known as configuration of log events output target)

During component's setup, its application.conf config file is parsed. The config's keys and values are validated and, if correct, the parsed representation is available as an instance of org.enso.logging.config.LoggingServiceConfig class. The class encapsulates the logging-service section of application.conf file and is used to programmatically initialize loggers.

As per configuration schema any key can be defined with a default value that can be overridden by an environment variable. For example

  {
    host = localhost
    host = $ENSO_HOST
  }

defines a host key once, except that ENSO_HOST values takes a precedence if it is defined during loading of the config file.

Custom Log Levels

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 {
  akka.actor = info
  akka.event = error
  akka.io = error
  slick {
    jdbc.JdbcBackend.statement = debug
    "*" = error
  }
}

For example, the config above limits all akka.actor.* loggers to the info level logging, and akka.event.* loggers can emit only the error level messages.

Config supports globs (*). For example, the config above sets jdbc.JdbcBackend.statement SQL statements logging to debug level, and the rest of the slick loggers to error level.

Additionally, custom log events can be provided during runtime via system properties, without re-packaging the updated config file. For example

akka.actor = info;

is equivalent to

  -Dakka.actor.Logger.level=info

Any custom log level is therefore defined with -Dx.y.Z.Logger.level where x, y and Z refer to the package elements and class name, respectively. System properties always have a higher priority over those defined in the application.conf file.

Appenders

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.

Currently supported are

• console appender - the most basic appender that prints log events to stdout
• file appender - appender that writes log events to a file, with optional rolling file policy
• socket appender - appender that forwards log events to some logging server
• sentry.io appender - appender that forwards log events to a sentry.io service

The appenders are defined by the logging-service.appenders. Currently only a single appender can be selected at a time, although additional 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) and the logs output can be overwritten by ENSO_LOGSERVER_APPENDER env variable
• ensoup or enso - the default log output can be overwritten by defining the ENSO_APPENDER_DEFAULT env variable

For example, for the project manager to output to console one simply executes

ENSO_LOGSERVER_APPENDER=console ./project-manager

Format

The pattern follows the classic's PatternLayout format.

Appenders that store/display log events can specify the format of the log message via pattern field e.g.

  appenders = [
    {
      name = "console"
      pattern = "[%level{lowercase=true}] [%d{yyyy-MM-dd'T'HH:mm:ssXXX}] [%logger] %msg%n%nopex"
    }
    ...
  ]

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.

File Appender

Enabled with ENSO_APPENDER_DEFAULT=file environment variable.

File appender directs all log events to a log file:

  {
    name = "file"
    append = <boolean, optional>
    immediate-flush = <boolean, optional>
    pattern = <string, optional>
    rolling-policy {
      max-file-size = <string, optional>
      max-history = <int, optional>
      max-total-size = <string, optional>
    }
  }

Rolling policy is a fully optional property of File Appender that would trigger automatic log rotation. All properties are optional with some reasonable defaults if missing (defined in org.enso.logging.config.FileAppender config class).

Socket Appender

Enabled with ENSO_APPENDER_DEFAULT=socket environment variable.

Configuration

  {
    name = "socket"
    hostname = <string, required>
    port = <string, required>
  }

The two fields can be overridden via environment variables:

• hostname has an equivalent $ENSO_LOGSERVER_HOSTNAME variable
• port has an equivalent $ENSO_LOGSERVER_PORT variable

Sentry Appender

Enabled with ENSO_APPENDER_DEFAULT=sentry environment variable.

  {
    name = "sentry"
    dsn = <string, required>
    flush-timeout = <int, optional>
    debug = <boolean, optional>
  }

Sentry's Appender has a single required field, dsn. The dsn value can be provided via an environment variable ENSO_APPENDER_SENTRY_DSN. flush-timeout determines how often logger should send its collected events to sentry.io service. If debug value is true, logging will print to stdout additional trace information of the logging process itself.

JVM Architecture

Enso's logging makes use of two logging APIs - java.util.logging and org.slf4j. The former is being used by the Truffle runtime, which itself relies on jul, while the latter is used everywhere else. The implementation of the logging is using off the shelf Logback implementation with some custom setup methods. The two APIss cooperate by essentially forwarding log messages from the former to the latter.

While typically any SLF4J customization would be performed via custom LoggerFactory and Logger implementation that is returned via a StaticLoggerBinder instance, this is not possible for our use-case:

• file logging requires Enso-specific directory which is only known during runtime
• centralized logging
• modifying log levels without recompilation

SLF4J Interface

The user code must not be calling any of the underlying implementations, such as Log4J or Logback, and should only request loggers via factory methods.

One can use the org.slf4j.LoggerFactory directly to retrieve class-specific logger. For Scala code, it is recommended to use the com.typesafe.scalalogging.Logger instead which wraps the SLF4J logger with macros that compute the log messages only if the given logging level is enabled, and allows much prettier initialisation.

package foo;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Foo {
    private Logger logger = LoggerFactory.getLogger(Foo.class);

    public void bar() {
        logger.info("Hello world!");
    }
}

Setting Up Logging

The org.slf4j.Logger instances have to know where to send log events. This setting is typically performed once, when the service starts, and applies globally during its execution. Currently, it is not possible to dynamically change where log events are being stored. The main (abstract) class used for setting up logging is org.enso.logging.config.LoggerSetup. An instance of that class can be retrieved with the thread-safe org.enso.logging.config.LoggerSetup.get factory method. org.enso.logging.config.LoggerSetup provides a number of setupXYZAppender methods that will direct loggers to send log events to an XYZ appender. Setting a specific hard-coded appender programmatically should however be avoided by the users. Instead, one should invoke one of the overloaded setup variants that initialize loggers based on the provided logging-service configuration.

package foo;
import org.enso.logging.config.LoggerSetup;
import org.slf4j.event.Level;

public class MyService {

  private Logger logger = LoggerFactory.getLogger(Foo.class);
  ...
  public void start(Level logLevel) {
    LoggerSetup.get().setup(logLevel);
    logger.info("My service is starting...");
    ...
  }
  ...
}

org.enso.logging.service.LoggingSetupHelper class was introduced to help with the most common use cases - establishing a file-based logging in the Enso's dedicated directories or connecting to an existing logging server once it starts accepting connections. That is why services don't call LoggerSetup directly but instead provide a service-specific implementation of org.enso.logging.service.LoggingSetupHelper. LoggingSetupHelper and LoggerSetup provide teardown methods to properly dispose of log events.

Log Masking

Logs should not contain personally identifiable information (PII). The following is considered PII:

• User code
• Values of executed expressions
• Values of user environment variables. Although variable names are not considered PII and can be logged.
• File paths inside the user project directory. System and distribution paths and a path to the user project can be logged.

Project logging library implements masking of PII. To utilize it

1. Logged object should implement an interface that defines custom log-string representation of this object
2. The logging should be performed by supplying a template string with {} placeholders, and the arguments

   log.debug("Created {} at [{}].", obj, path)
   

String interpolation in log statements s"Created $obj" should be avoided because it uses default toString implementation and can leak critical information even if the object implements custom interface for masked logging.

Logging in Tests

The Logging Service provides a helper function TestLogger.gatherLogs that will execute the closure and collect all logs reported in the specified class. That 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 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 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 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.

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 for details.