Using StreamBase Logging

Logging Overview

For all supported operating systems, StreamBase uses the industry-standard SLF4J logging system with the Logback framework. See Windows Event Logging for additional considerations for Windows.

All subsystems in EventFlow and LiveView fragments use Logback logging. You can configure the level of logging information emitted, and can direct logs to different appenders using standard Logback configuration files in XML format.

To configure a custom Logback configuration files see Custom Configuration and StreamBase Logback Extensions below. The default logs subdirectory location can be overridden as described in StreamBase Logback Extensions.

Logging Configuration Processing Order

The StreamBase Runtime processes log configuration in the following order:

  1. Default logging.

  2. Logging configuration specified in fragment archives generated from fragment projects.

  3. Logging configuration specified in StreamBase Application archives generated from an application project.

Logging configurations do not merge. That is, a later configuration in the processing order sequence overrides an earlier one. For this reason, any custom logging configuration file should specify settings for both RootFileAppender and RootConsoleAppender to avoid error messages.

Logging settings are ultimately specified per engine. If your fragment has more than one engine, each engine can inherit the settings made for the fragment and application as a whole.

The logging level and logging configuration can be changed at runtime per engine using the logging target of the epadmin command, as described in Managing Logging at Runtime.

The Log Output Adapter

In addition to the logging messages emitted by EventFlow and LiveView as a whole, you can add logging instructions to any EventFlow module with the Log Output adapter. The adapter has a sample described in Log Output Adapter Sample that illustrates formatting options you can perform with the Log Output adapter.

Do not confuse the Java logging facility discussed here with the StreamBase error stream feature. Logging is for writing your own logging messages and exception stack traces to one or more log files. By contrast, the error stream feature is like a module-level throw that ascends up the call stack to the containing module, and from there to the top-level EventFlow module instance running the fragment. StreamBase sends an error tuple to the error stream when it encounters an exception during a tuple processing method. See Using Error Ports and Error Streams for further information.

Logging in Custom Code

If you write custom operators or adapters, you can use an import org.slf4j.Logger statement in your code to define a logger for your operator or adapter. The base class, Operator, provides the convenience method getLogger(), which returns an org.slf4j.Logger object that should thereafter be used for logging messages and exceptions in your code. For the full list of methods available on Logger objects, refer to the Logger class in the SLF4J Javadoc.

The StreamBase installation includes a logging sample that illustrates the difference between using a Log Output adapter and using getLogger() methods in your custom code. This sample compares both methods with a third module that does not log.

Logback Log Levels

StreamBase uses the standard log level meanings provided by the Logback framework, as defined in the Logger API.

Method Notes
ERROR A node level error caused by a resource problem (memory, disk, file descriptors, and so on), a corrupted product installation with missing required resources, or host machine failures. The node is terminated and must be reinstalled to restore service.
WARN An operational error that impacts a specific operation, application performance, or availability of certain services. An operational error is caused by invalid parameters, temporary resource unavailability, or authentication and/or authorization failures. No other node services are affected. The node may automatically recover from this error, but in some cases operator intervention is required for full recovery.
INFO A normal status message for node and engine life cycle, resource start-up information, and environment details such as library version numbers, class path contents, or location of configuration files. No action is required.
DEBUG Mid-level diagnostic debug messages. DEBUG messages should only be enabled on production systems at the request of product Support. These messages are only of interest to the product development team.
TRACE Low-level diagnostic trace messages. TRACE messages should only be enabled on production systems at the request of product Support. These messages are only of interest to the product development team.

Legacy Log Levels

The following table maps the log level integer settings used in StreamBase releases before 10.2.0 to Logback message levels.

Level Method Notes
–2 ERROR  
–1 WARN  
0 INFO The default setting. (Legacy StreamBase releases called this level notice.)
1 or 2 DEBUG Levels 1 and 2 are equivalent ways to specify DEBUG level logging, and produce the same number of log messages.
3 TRACE (Legacy StreamBase releases called this level debug2.)

Separate Adapter Log Levels

Most StreamBase adapters allow you to set a log level independently for the adapter than for the hosting EventFlow module:

  • The Wombat MAMA Input adapter has a set of log levels that derive from the Wombat MAMA API.

  • Most other adapters allow you to set the log level for log messages emitted from that adapter. To determine whether an adapter of interest has independent logging, look for a Log Level property in the Adapter Properties section of the documentation page for that adapter in the Adapters Guide.

For example, an adapter might set the log level to WARN or ERROR for messages emitted from the adapter while the hosting fragment is still set to its default INFO level. This allows you to troubleshoot adapter connectivity issues without having to wade through hundreds of verbose node messages from the fragment.

Log Files Generated

Log files are generated at the node and engine levels. Log files are written by default into a subdirectory named logs in a fragment's node directory:

  • For fragments run in StreamBase Studio, the node directory is named for the current node's node name, and is found in the .nodes subdirectory of the Studio workspace. The node directory is removed on Studio exit for all successful fragment launches. If a launch fails, its node directory is preserved so that you can inspect log files.

  • For application launches made from the command line, you specify the location of the application's node directory as part of the epadmin node install command. In this case, the node directory and its logs subdirectory are preserved in the location you specify.

You can change the location and name of the node-directory/logs directory using StreamBase Logback extensions.

The log files generated in the node-directory/logs directory are:

  • engine-name.log — log messages from the StreamBase Runtime for each engine running in the node.

  • audit.log, described below.

  • deadlock.log, described below.

  • System*.log. All log files whose names begin with System are of interest only to StreamBase® engineers as part of deep-level debugging of a snapshot file.

Another set of log files is generated in the node-directory/logs/bootstrap directory. These files are populated during the early node startup timeframe before the Logback system has initialized. All files in logs/bootstrap are of interest only to StreamBase® engineers as part of deep-level debugging of a snapshot file.

Default Logback Configuration

StreamBase's default settings for Logback logging are as follows:

  • Two appenders are configured, the console appender and a file appender that writes to the logs subdirectory of the node directory.

  • Log messages from third-party libraries used in StreamBase are set to minimize their chattiness.

  • The default log level is INFO.

  • The default log message pattern is internally defined as:

    %d{yyyy-MM-dd HH:mm:ss.}%usecs%d{Z} [%process:%thread] %-5level %logger: %msg%n
  • One log file is written per engine in a running fragment, with the log file name enginename.log.

  • Log file rollover is set to a maximum size of 10 MB for ten files unless you explicitly set a root file appender to the default value of the com.tibco.ep.dtm.logging.logDirectory substitution variable.

  • If you have not defined a duplicate message filter, a duplicate message filter that suppresses messages after the ninth repetition is installed. The tenth and subsequent messages are suppressed. The log message generated for the suppressed messages uses the same category and severity as the suppressed message.

The components of the default log message pattern have the meanings shown in the following table.

Message Pattern Component Meaning
%d{yyyy-MM-dd HH:mm:ss} Formatted timestamp.
%usecs%d{Z} Adds the microseconds and time zone values to the timestamp. (%usecs is a StreamBase extension.)
[%process:%thread] The process ID and the name of the thread that generated the logging event. (%process is a StreamBase extension.)
%-5level The log level in five characters, left-justified, with one or more padding spaces added on the right.
%logger The qualified name of the class or component from which the logging event was emitted
%msg%n Everything after the hyphen represents the text of the log message emitted by an instance of the Logger class in code. %n represents the line ending character or characters appropriate for the current operating system.

Consult the Logback documentation for PatternLayout for the available log message pattern components.

You can override any of the default settings with a custom Logback configuration.

The following example shows Default Streaming Logback Configuration in XML format:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<turboFilter class="com.tibco.ep.dtm.logging.SBDuplicateMessageFilter">
<AllowedRepetitions>9</AllowedRepetitions>
</turboFilter>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${com.tibco.ep.dtm.logging.logDirectory}/${com.tibco.ep.dtm.logging.logFileNamePrefix}.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<fileNamePattern>
${com.tibco.ep.dtm.logging.logDirectory}/${com.tibco.ep.dtm.logging.logFileNamePrefix}-%i.log
</fileNamePattern>
<minIndex>1</minIndex>
<maxIndex>10</maxIndex>
</rollingPolicy>
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<maxFileSize>10485760</maxFileSize>
</triggeringPolicy>
<encoder>
<pattern>%-4relative [%thread] %-5level %logger'{'35'}' - %msg%n</pattern>
</encoder>
</appender> 
  <root level="INFO">
    <appender-ref ref="FILE" />
  </root>
 <logger name="org.apache.shiro" level="WARN"/>
  <logger name="org.atmosphere" level="WARN"/>
  <logger name="org.eclipse.jetty" level="WARN"/>
  <logger name="org.hibernate" level="WARN"/>
  <logger name="org.springframework" level="WARN"/>
  <logger name="org.springframework.beans.factory.config.PropertyPlaceholderConfigurer" level="ERROR"/>
</configuration>

Custom Configuration for Logback Logging

To configure Logback logging, specify a Logback configuration file. StreamBase accepts files in either the traditional XML format, often named logback.xml. In either case, place your configuration files in the src/main/resources folder of your Studio project.

You can also use the src/test/resources folder for a logging configuration you only need when running Maven tests. To have one configuration used both for standard fragment launches and tests, use src/test/resources.

The StreamBase logging sample includes an example logback.xml configuration file that illustrates a setup for both a console appender and a rolling file appender.

StreamBase Logback Extensions

In general, StreamBase Logback configuration files use standard Logback patterns as described in the Logback documentation for PatternLayout. StreamBase provides the following extensions to the standard Logback patterns:

%usec

A log appender pattern that specifies the microsecond portion of the current second, when used with a timestamp pattern:

%d{yyyy-MM-dd HH:mm:ss.}%usecs%d{Z}
%process

A log appender pattern that specifies the process ID of the currently running engine.

[%process:%thread]
%transaction

A log appender pattern that specifies the transaction ID for the current transaction. %transaction is replaced by:

  • The current transaction identifier, or

  • The string none is there is no active transaction, or

  • The string unavailable if there is an active transaction but the identifier cannot be determined.

com.tibco.ep.dtm.logging.logDirectory

A Logback substitution variable for the directory in which to store log files, with a default value of node-directory/logs.

This variable makes it possible to move the location of engine log files outside of the default node-directory/logs directory. However, if this is done, engine log messages are sent to both the configured location and to the default engine log in node-directory/logs. This is done to ensure that snapshot files include all node logging for diagnostic purposes.

com.tibco.ep.dtm.logging.logFileNamePrefix

A Logback substitution variable for the basename of the log file, with a default value of the current engine name.

If an engine log file is configured to use a non-default engine log file name, but that log file is left in node-directory/logs, only the configured log file name is used.

The following example shows the use of these extensions in a Logback XML configuration file:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<variable name="com.tibco.ep.dtm.logging.logDirectory" value="/Users/sbuser/logs"/>
<variable name="com.tibco.ep.dtm.logging.logFileNamePrefix" value="testrun"/>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>${com.tibco.ep.dtm.logging.logDirectory}/${com.tibco.ep.dtm.logging.logFileNamePrefix}.log</file>
    <encoder>
      <pattern>d{HH:mm:ss.SSS} %usec %process %thread %transaction %-5level %logger: %msg%n</pattern>
    </encoder>
  </appender>
  <root level="INFO">
    <appender-ref ref="FILE"/>
  </root>
</configuration>

Search for "Variable substitution" on this Logback documentation page to learn more about Logback variables.

Audit Log

StreamBase creates entries in an audit log for every node. The audit log contains audit messages for:

Example:

//
// Audit message for display web command
//
2019-08-12 07:16:46.000-0700: Audit: "epadmin --servicename A.X --username sbuser --password
*** display web" executed by Steve succeeded.
//
// Audit message for Health Check endpoint with trusted user
//
2019-08-12 07:17:18.303-0700: 10.0.0.164 "GET /healthcheck/v1/status HTTP/1.1" 200 by -

The audit log:

  • Is always named audit.log. There is no provision to change this name.

  • Is always created in node-directory/logs, even if configuration specifies an alternate log file location for engine log files.

  • Has a default log severity level of INFO.

  • Has additivity disabled so that command audit messages are saved only in the audit log file, and are not duplicated in engine log files.

  • Has the following Logback message format:

    %d{yyyy-MM-dd HH:mm:ss.SSSZ}: %msg%n

Deadlock Log

A deadlock log is configured for every node, and cannot be disabled.

The deadlock log:

  • Is always named deadlock.log. There is no provision to change this name.

  • Is always created in node-directory/logs, even if configuration specifies an alternate log file location for engine log files.

  • Has a default log severity level of WARN.

  • Has additivity disabled so that deadlock messages are saved only in the deadlock log file, and are not duplicated in engine log files.

See Analyzing Deadlocks in the Tuning Guide for details on the deadlock log message format.

Docker Container Logging

You can enable Docker container logging by configuring a console appender in a Docker-hosted StreamBase application. For example:

<xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} %10.10thread %-5level %20.20logger{5} :
%msg%n</pattern>
    </encoder>
  </appender>
  <root level="INFO">
    <appender-ref ref="Console"/>
  </root>
</configuration>

Note

Enabling a Docker build for an application configures a console log appender by default.

When the container containing the application is started it must have a pseudo-tty allocated for the console appender to work correctly. To do so, use the tty parameter with the run command:

docker run --tty --detach --name A.sb10 --network example.com firstapp
A.sb10

When the container is started all engine logging is sent to the container logs.

Docker Logging from Command Line

Container logging is also available from the Docker command line using the logs command:

docker logs --follow A.sb10