Logging Service

The Logging Service library provides an advanced logging facility for CSW components and services.

Note

This page explains local logging only. To understand centralized logging facility, refer to this page.

Dependencies

To use the Logging Service without using the framework, add this to your build.sbt file:

sbt
libraryDependencies += "com.github.tmtsoftware.csw" %% "csw-logging-client" % "5.0.1"

Configuration

These are the relevant default configuration values for logging

logging.conf
sourcecsw-logging {

  # Default appender and is recommended only for dev setup.
  # To use multiple appenders give comma separated list of appenders.
  appenders = ["csw.logging.client.appenders.StdOutAppender$"]

  # Recommended for production setup - Uncomment below line and comment above to enable FileAppender
  #appenders = ["csw.logging.client.appenders.FileAppender$"]

  component-log-levels {
    # By default each compoent will use log level specified by `csw-logging.logLevel`. If required, this block allows
    # overriding log level configuration for one/more components.
    # -- Example --
    # tcs.filter = debug
    # nfiraos {
    #      tromboneassembly = error
    #      trombonehcd = info
    #  }
    #
  }

  appender-config {
    file {
      # Include standard headers
      fullHeaders = true
      # Sort the fields in Json objects
      sorted = true
      # Base path directory to hold log files from tmt apps. The value is picked from env var `TMT_LOG_HOME`. It is necessary
      # to have `TMT_LOG_HOME` set as env var otherwise an exception will be thrown when FileAppender gets initialized.
      baseLogPath = ${?TMT_LOG_HOME}
      # Directory to hold log files under base path $TMT_LOG_HOME i.e. basePath/logPath
      logPath = ""
      # Common log messages below this level are removed, none removed when set to trace
      logLevelLimit = trace
      # Flag to turn file rotation ON or OFF. Currently log file is rotated daily at 12:00 pm UTC time. By turning this flag off
      # file rotation will not happen.
      rotate = true
    }
    stdout {
      # Include standard headers
      fullHeaders = false
      # Use colors for log levels
      color = true
      # The maximum number of character that should be on a line
      # This is only a goal; in practice some may contain more characters.
      width = 80
      # Print summary counts when logger is closed
      summary = true
      # pretty output - multiple line json
      pretty = false
      # Messages below this level are removed, none removed when set to trace
      logLevelLimit = trace
      # false Json output; true simple one line text output
      oneLine = false
    }
  }
  # If component does not specify their log level in component-log-levels block,
  # Then this will be considered as default log level for that component.
  logLevel = info
  # Log level for slf4j messages
  slf4jLogLevel = info
  # Log level for Akka messages
  akkaLogLevel = warn
  # Enable timing logging
  time = false
  # Enable garbage collection logging
  gc = false
}
IMPORTANT !!!

It is required to include logging.conf that is shipped with this library in application.conf as follows: Including logging.conf as required will make sure that logging.conf is on classpath.

include required("logging.conf")

Default configuration values can be then overridden in application.conf.

Note
  • Logs generated by components will be by default stored at $TMT_LOG_HOME/tmt/logs. In case $TMT_LOG_HOME is not set as environment variable, then they will be stored at /tmp/tmt/logs. When logs are stored in the /tmp folder, they will not be persisted in case of machine reboot. Hence, for production, it is recommended to have $TMT_LOG_HOME set as environment variable.

  • csw-logging.appender-config.file.logPath from logging.conf will treated as subdirectory under the base directory ($TMT_LOG_HOME/tmt/logs or /tmp/tmt/logs) to store the logs. It can be also overridden in application.conf for each component.

Also logLevel for each component can be set in application.conf as follows:

component-log-levels {
    tcs {
        trombonehcd = debug
        tromboneassembly = error
    }
  }
  
Note

Here trombonehcd and tromboneassembly is the name of component that will be registered with LocationService, which is the name field in the ComponentInfo file (see DeployingComponents). By default, all components will log at level specified by csw-logging.logLevel.

The library provides StdOutAppender as the default logging appender. To use FileAppender or some custom appender along with StdOutAppender, override the appenders property to include multiple appenders in CSV format as follows:


appenders = ["csw.logging.client.appenders.FileAppender$", "csw.logging.client.appenders.StdOutAppender$"]
Note

Make sure to provide full path of the appender since it will be spawned using Java reflection. In the CSW code base, a working example of a custom appender can be found at: Custom Appender

For StdOutAppender, specify the format of log statements in csw-logging.stdout via csw-logging.stdout.pretty and csw-logging.stdout.oneLine.

Turning pretty on or off will produce log statements in following format:

pretty=true
{"@prefix":"my-subsystem.my-component-name",
 "@subsystem":"my-subsystem",
 "@componentName":"my-component-name",
 "@host":"INsaloni.local",
 "@name":"LocationServiceExampleClient",
 "@severity":"INFO",
 "@version":"0.1",
 "actor":
   "akka://csw-examples-locationServiceClient@10.131.23.195:53618/user/$a",
 "class":"csw.location.LocationServiceExampleClient",
 "file":"LocationServiceExampleClientApp.scala",
 "line":149,
 "message":"Result of the find call: None",
 "timestamp":"2017-11-30T10:58:03.102Z"
 }
pretty=false
{"@prefix":"my-subsystem.my-component-name","@subsystem":"my-subsystem","@componentName":"my-component-name","@host":"INsaloni.local","@name":"LocationServiceExampleClient","@severity":"INFO","@version":"0.1","actor":"akka://csw-examples-locationServiceClient@10.131.23.195:53618/user/$a","class":"csw.location.LocationServiceExampleClient","file":"LocationServiceExampleClientApp.scala","line":149,"message":"Result of the find call: None","timestamp":"2017-11-24T04:16:42.108Z"}

Similarly, turning oneLine on will produce log statements in following format:

oneLine=true
[INFO] Attempting to find connection (LocationServiceExampleClientApp.scala 131)
Note
  • If oneLine is set to true then value of pretty will be ignored

Log Levels

Following Log levels are supported by csw-logging library

  • FATAL
  • ERROR
  • WARN
  • INFO
  • DEBUG
  • TRACE

The library allows separate log levels for the component logging API (logLevel), Akka logging (akkaLogLevel), and Slf4J (slf4jLogLevel). The initial values of these are set in the configuration file as seen above. These can be overridden in the application.conf file.

These values can also be changed dynamically by calling methods on LoggingSystem class.

Log Structure

All messages are logged by default as Json. Logs can contain following fields:

  • @prefix: The combination of @subsystem and @componentName of the component for e.g. tcs.filter.wheel
  • @subsystem: The name of the subsystem, if present
  • @componentName: The name of the component, if present
  • @host: The local host name
  • @name: The name of the application being run
  • @version: The version of the application being run
  • @severity: The message level: trace, debug, info, warn, error or fatal
  • actor: The path for an actor when using ActorLogging
  • class: The class for ClassLogging or ActorLogging
  • file: The file containing the log call
  • kind: Either slf4j or akka. Not present for logger API
  • line: The line where the message was logged
  • message: The log message
  • timestamp: The UTC time when the message was logged
  • trace: Information for any exception specified in the logging call
Note
  • @host, @name and @version will appear in log statements only if fullHeaders is set as true in the configuration
  • file and line will appear only in log statements from Scala classes/actors. This is typical for Java logging tools, and is due to the lack of macro support in Java.

Enable Component Logging

Component developers will have an instance of LoggerFactory available from csw-framework. This instance will already have a prefix set by csw-framework which will appear in log statements in the @prefix,@subsystem and @componentName tags. To get the Logger instance from the LoggerFactory, use one of the following:

Scala Class
sourceclass SampleClass(loggerFactory: LoggerFactory) {

  val log: Logger = loggerFactory.getLogger
}
Java Class
sourcepublic class JSampleClass {

    public JSampleClass(JLoggerFactory loggerFactory) {
        ILogger log = loggerFactory.getLogger(getClass());
    }
}
Scala Actor
sourceclass SampleActor(loggerFactory: LoggerFactory) extends akka.actor.Actor {

  // context is available from akka.actor.Actor
  val log: Logger = loggerFactory.getLogger(context)

  override def receive = ???
}
Java Actor
sourceclass JSampleActor extends akka.actor.AbstractActor {

    public JSampleActor(JLoggerFactory loggerFactory) {

        //context() is available from akka.actor.AbstractActor
        ILogger log = loggerFactory.getLogger(context(), getClass());
    }

    @Override
    public Receive createReceive() {
        return null;
    }
}
Scala Typed Actor
sourceclass SampleTypedActor(loggerFactory: LoggerFactory, ctx: ActorContext[ComponentMessage]) {

  val log: Logger = loggerFactory.getLogger(ctx)
}
Java Typed Actor
sourceclass JSampleTypedActor {

    public JSampleTypedActor(JLoggerFactory loggerFactory, ActorContext<ComponentMessage> ctx) {
        ILogger log = loggerFactory.getLogger(ctx, getClass());
    }
}
Note

The LoggerFactory can be changed to JLoggerFactory by using asJava method and JLoggerFactory can be changed to LoggerFactory by using asScala method

Enable Generic Logging

In case there is a need to log statements without having a @prefix, @subsystem and @componentName tags, which can be due to unavailability of componentName in some utility code, then use the GenericLoggerFactory as follows:

Scala Class
sourceclass GenericClass {

  val log: Logger = GenericLoggerFactory.getLogger
}
Java Class
sourcepublic class JGenericClass {

    ILogger log = JGenericLoggerFactory.getLogger(getClass());
}
Scala Actor
sourceobject GenericActor {

  def behavior[T]: Behavior[T] =
    Behaviors.setup[T] { context =>
      val log: Logger = GenericLoggerFactory.getLogger(context)
      // actor setup

      Behaviors.receiveMessage { case _ => // handle messages and return new behavior
        Behaviors.same
      }
    }
}
Java Actor
sourceclass JGenericActor extends akka.actor.AbstractActor {

    //context() is available from akka.actor.AbstractActor
    ILogger log = JGenericLoggerFactory.getLogger(context(), getClass());

    @Override
    public Receive createReceive() {
        return null;
    }
}
Scala Typed Actor
sourceclass GenericTypedActor(ctx: ActorContext[ComponentMessage]) {

  val log: Logger = GenericLoggerFactory.getLogger(ctx)
}
Java Typed Actor
sourceclass JGenericTypedActor {

    public JGenericTypedActor(ActorContext<ComponentMessage> ctx) {
        ILogger log = JGenericLoggerFactory.getLogger(ctx, getClass());
    }
}

The Logger log is now available in Scala and Java classes to write log statements as explained in next section.

Log Statements

Logging statements are used very much like existing logging services such as log4j. For Java, there is an additional way of writing log messages using Supplier methods (lambdas). The use of lambdas is more efficient since the computations in a message (e.g. string concatenation) are not performed unless the message is actually being logged. Therefore, these supplier methods should be used in cases where high performance is required (see performance results below).

A basic info statement can be written as follows:

Scala
sourcelog.info(s"Result of the find call: $findResult")
Java
sourcelog.info("Find result: " + connectionInfo(findResult.orElseThrow().connection()));
Java (Supplier)
sourcelog.info(() -> "Resolve result: " + connectionInfo(resolveResult.orElseThrow().connection()));

The output of log statement will be:

Scala
{"@prefix":"my-subsystem.my-component-name",
 "@subsystem":"my-subsystem",
 "@componentName":"my-component-name",
 "@host":"INsaloni.local",
 "@name":"LocationServiceExampleClient",
 "@severity":"INFO",
 "@version":"0.1",
 "actor":
   "akka://csw-examples-locationServiceClient@10.131.23.195:53618/user/$a",
 "class":"csw.location.LocationServiceExampleClient",
 "file":"LocationServiceExampleClientApp.scala",
 "line":149,
 "message":"Result of the find call: None",
 "timestamp":"2017-11-30T10:58:03.102Z"
 }
Java
{"@prefix":"my-subsystem.my-component-name",
 "@subsystem":"my-subsystem",
 "@componentName":"my-component-name",
 "@host":"INsaloni.local",
 "@name":"JLocationServiceExampleClient",
 "@severity":"INFO",
 "@version":"0.1",
 "actor":
   "akka://csw-examples-locationServiceClient@10.131.23.195:53625/user/LocationServiceExampleClient",
 "class":"csw.location.JLocationServiceExampleClient",
 "message":"Result of the find call : None",
 "timestamp":"2017-11-30T11:02:54.691Z"
}
Java (Supplier)
{"@prefix":"my-subsystem.my-component-name",
 "@subsystem":"my-subsystem",
 "@componentName":"my-component-name",
 "@host":"INsaloni.local",
 "@name":"JLocationServiceExampleClient",
 "@severity":"INFO",
 "actor":
   "akka://csw-examples-locationServiceClient@10.131.23.195:53625/user/LocationServiceExampleClient",
 "class":"csw.location.JLocationServiceExampleClient",
 "message":
   "Resolve result: LocationServiceExampleComponent-assembly-akka, component type=Assembly, connection type=AkkaType",
 "timestamp":"2017-07-26T19:44:58.636Z"
}

The library allows usage of Map in message as follows:

Scala
sourcelog.info(
  s"Attempting to find $exampleConnection",
  Map(Keys.OBS_ID -> "foo_obs_id", "exampleConnection" -> exampleConnection.name)
)
Java
sourcelog.info("Attempting to find " + exampleConnection,
        Map.of(
                JKeys.OBS_ID, "foo_obs_id",
                "exampleConnection", exampleConnection.name()
        ));
Java (Supplier)
sourcelog.info(() -> "Attempting to resolve " + exampleConnection + " with a wait of " + waitForResolveLimit + ".." +
        ".", () -> Map.of(
        JKeys.OBS_ID, "foo_obs_id",
        "exampleConnection", exampleConnection.name()
));

The output of log statement will be:

Scala
{"@prefix":"my-subsystem.my-component-name",
 "@subsystem":"my-subsystem",
 "@componentName":"my-component-name",
 "@host":"INsaloni.local",
 "@name":"LocationServiceExampleClient",
 "@severity":"INFO",
 "@version":"0.1",
 "actor":
   "akka://csw-examples-locationServiceClient@10.131.23.195:53618/user/$a",
 "class":"csw.location.LocationServiceExampleClient",
 "exampleConnection":"LocationServiceExampleComponent-assembly-akka",
 "file":"LocationServiceExampleClientApp.scala",
 "line":143,
 "message":
   "Attempting to find AkkaConnection(ComponentId(LocationServiceExampleComponent,Assembly))",
 "obsId":"foo_obs_id",
 "timestamp":"2017-11-30T10:58:03.097Z"
}
Java
{"@prefix":"my-subsystem.my-component-name",
 "@subsystem":"my-subsystem",
 "@componentName":"my-component-name",
 "@host":"INsaloni.local",
 "@name":"JLocationServiceExampleClient",
 "@severity":"INFO",
 "@version":"0.1",
 "actor":
   "akka://csw-examples-locationServiceClient@10.131.23.195:53625/user/LocationServiceExampleClient",
 "class":"csw.location.JLocationServiceExampleClient",
 "exampleConnection":"LocationServiceExampleComponent-assembly-akka",
 "message":
   "Attempting to find AkkaConnection(ComponentId(LocationServiceExampleComponent,Assembly))",
 "obsId":"foo_obs_id",
 "timestamp":"2017-11-30T11:02:54.686Z"
}
Java (Supplier)
{"@prefix":"my-subsystem.my-component-name",
 "@subsystem":"my-subsystem",
 "@componentName":"my-component-name",
 "@host":"INsaloni.local",
 "@name":"JLocationServiceExampleClient",
 "@severity":"INFO",
 "@version":"0.1",
 "actor":
   "akka://csw-examples-locationServiceClient@10.131.23.195:53625/user/LocationServiceExampleClient",
 "class":"csw.location.JLocationServiceExampleClient",
 "exampleConnection":"LocationServiceExampleComponent-assembly-akka",
 "message":
   "Attempting to resolve AkkaConnection(ComponentId(LocationServiceExampleComponent,Assembly)) with a wait of 30 seconds...",
 "obsId":"foo_obs_id",
 "timestamp":"2017-11-24T04:22:02.589Z"
}

The library allows you to log an error with its full stacktrace as follows:

Scala
sourceval runtimeException = new RuntimeException(s"Received unexpected message $x")
log.error(runtimeException.getMessage, ex = runtimeException)
Java
source} catch (InterruptedException | ExecutionException ex) {
    log.info(ex.getMessage(), ex);
    throw ex;
}
Java (Supplier)
sourceRuntimeException runtimeException = new RuntimeException("Received unexpected message " + x);
log.info(runtimeException::getMessage, runtimeException);

Create LoggerFactory

Note

This functionality is included in the framework code and users should not have to implement it themselves. Documentation is included for testing or further understanding.

In order to create a LoggerFactory with a custom prefix, refer to the following code:

Scala
sourceval loggerFactory: LoggerFactory = new LoggerFactory(Prefix("csw.my-component-name"))

// convert a scala LoggerFactory to java JLoggerFactory
val jLoggerFactory: JLoggerFactory = loggerFactory.asJava
Java
sourceJLoggerFactory jLoggerFactory = new JLoggerFactory(Prefix.apply("csw.my-component-name"));

// convert a java JLoggerFactory to scala LoggerFactory
LoggerFactory loggerFactory = jLoggerFactory.asScala();

Create LoggingSystem

Note

This functionality is included in the framework code and users should not have to implement it themselves. Documentation is included for testing or further understanding.

For logging statements to appear in the program, start LoggingSystem at an earliest location in an application. Also note, LoggingSystem should be started only once in an application. The name used while creating LoggingSystem will be used to create the folder that will contain all logging files.

Scala
sourceprivate val host = InetAddress.getLocalHost.getHostName
// Only call this once per application
val loggingSystem: LoggingSystem = LoggingSystemFactory.start("LocationServiceExampleClient", "0.1", host, typedSystem)
Java
sourceString host = InetAddress.getLocalHost().getHostName();
loggingSystem = JLoggingSystemFactory.start("JLocationServiceExampleClient", "0.1", host, typedSystem);
Note
  • The hostname that is provided while creating LoggingSystem will appear in log statements against @host tag

Stop LoggingSystem

Note

This functionality is included in the framework code and users should not have to implement it themselves. Documentation is included for testing or further understanding.

Please ensure the LoggingSystem is stopped before the application exits.

Scala
source// Only call this once per application
await(loggingSystem.stop)
Java
source// Only call this once per application
loggingSystem.javaStop().get();

Source code for examples

Performance

Performance results documented on this page is measured in terms of throughput and obtained with the JMH Java benchmark harness. Sourcecode for all the JMH benchmarks can be found here at CSW Benchmarks

Wikipedia definition of “throughput” is the maximum rate of production or the maximum rate at which something can be processed. In our case, throughput is defined as how many messages can be logged in a certain period of time.

Test Machine Configuration :

  • MacBook Pro (Retina, 15-inch, Mid 2015)
  • Processor Name: Intel Core i7
  • Processor Speed: 2.8 GHz
  • No. of Processors: 1
  • No. of Cores: 4
  • L2 Cache (per Core): 256 KB
  • L3 Cache: 6 MB
  • Memory: 16 GB 1600 MHz DDR3
  • JDK: 1.8.0_121

Scala Logging : Appender’s Throughput

Logging Appenders Throughput

Above graph includes the throughput results for File and StdOut appenders using the Scala logging API. The Java logging API throughput results are included further down this page.
As shown in the above graph, the experiment was carried out for 1, 2, 4, 8 and 16 threads. That means, multiple threads are logging messages concurrently.

Note
  • Numbers indicated in the graph does not mean that those number of messages are actually written to file or console. These are the number of logging messages sent to LogActor asynchronously for the period of one second.
  • It is the responsibility of LogActor to write these messages to file or console.
  • LogActor uses BoundedMailbox with a mailbox-capacity = 262144, messages are dropped if mailbox gets full.

Scala And Java Logging : Throughput Comparision (Log Level Enabled vs Disabled)

Below graph depicts the throughput of the Java logging API (String and Supplier) and the Scala logging API when the log level was enabled and disabled.

Note
  • Log Level Enabled : Results are obtained for log.info when the default log level was set to info, which means the logging messages were sent to LogActor for writing it to file.
  • Log Level Disabled : Results are obtained for log.trace when the default log level was set to info, which means the logging messages were not written to file.

Java Scala Throughput Comparision

This graph is produced based on the result generated by JE2ELoggingBenchmark and E2ELoggingBenchmark

Note
  • As you can see in the above graph, the Supplier version of the Java log API and the “by name” version of Scala API are very efficient and throughput is much higher than the String version. Therefore, it is recommended that Java developers use the Supplier API.

Technical Description

See Logging Service Technical Description.

Acknowledgement

The codebase in csw-logging module is based on persist-logging library. We appreciate efforts put in by authors of the persist-logging library which made our development fast and easy.