Logging Service

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

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

copysourcecsw-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
}

include required("logging.conf")

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

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

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$"]

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)

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

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

copysourceclass SampleClass(loggerFactory: LoggerFactory) {

  val log: Logger = loggerFactory.getLogger
}

Java Class

copysourcepublic class JSampleClass {

    public JSampleClass(JLoggerFactory loggerFactory) {
        ILogger log = loggerFactory.getLogger(getClass());
    }
}

Scala Actor

copysourceclass 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

copysourceclass 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

copysourceclass SampleTypedActor(loggerFactory: LoggerFactory, ctx: ActorContext[ComponentMessage]) {

  val log: Logger = loggerFactory.getLogger(ctx)
}

Java Typed Actor

copysourceclass JSampleTypedActor {

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

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

copysourceclass GenericClass {

  val log: Logger = GenericLoggerFactory.getLogger
}

Java Class

copysourcepublic class JGenericClass {

    ILogger log = JGenericLoggerFactory.getLogger(getClass());
}

Scala Actor

copysourceobject 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

copysourceclass 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

copysourceclass GenericTypedActor(ctx: ActorContext[ComponentMessage]) {

  val log: Logger = GenericLoggerFactory.getLogger(ctx)
}

Java Typed Actor

copysourceclass 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

copysourcelog.info(s"Result of the find call: $findResult")

Java

copysourcelog.info("Find result: " + connectionInfo(findResult.orElseThrow().connection()));

Java (Supplier)

copysourcelog.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

copysourcelog.info(
  s"Attempting to find $exampleConnection",
  Map(Keys.OBS_ID -> "foo_obs_id", "exampleConnection" -> exampleConnection.name)
)

Java

copysourcelog.info("Attempting to find " + exampleConnection,
        Map.of(
                JKeys.OBS_ID, "foo_obs_id",
                "exampleConnection", exampleConnection.name()
        ));

Java (Supplier)

copysourcelog.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

copysourceval runtimeException = new RuntimeException(s"Received unexpected message $x")
log.error(runtimeException.getMessage, ex = runtimeException)

Java

copysource} catch (InterruptedException | ExecutionException ex) {
    log.info(ex.getMessage(), ex);
    throw ex;
}

Java (Supplier)

copysourceRuntimeException runtimeException = new RuntimeException("Received unexpected message " + x);
log.info(runtimeException::getMessage, runtimeException);

Create LoggerFactory

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

Scala

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

// convert a scala LoggerFactory to java JLoggerFactory
val jLoggerFactory: JLoggerFactory = loggerFactory.asJava

Java

copysourceJLoggerFactory jLoggerFactory = new JLoggerFactory(Prefix.apply("csw.my-component-name"));

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

Create LoggingSystem

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

copysourceprivate val host = InetAddress.getLocalHost.getHostName
// Only call this once per application
val loggingSystem: LoggingSystem = LoggingSystemFactory.start("LocationServiceExampleClient", "0.1", host, typedSystem)

Java

copysourceString host = InetAddress.getLocalHost().getHostName();
loggingSystem = JLoggingSystemFactory.start("JLocationServiceExampleClient", "0.1", host, typedSystem);

Stop LoggingSystem

Please ensure the LoggingSystem is stopped before the application exits.

Scala

copysource// Only call this once per application
await(loggingSystem.stop)

Java

copysource// Only call this once per application
loggingSystem.javaStop().get();

Source code for examples

• Scala Example
• Java Example

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

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.

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.

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

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.