Configuring System Logging

Overview

System logs are used to assist developers analyse and resolve the issue if something inadvertently goes wrong with CCLAS 6.

Debugger Logger (java logging)

CCLAS 6 now uses the logging capabilities of Java to collect, standardise and consolidate log data from different sources into a centralised platform, allowing for streamlined log analysis and correlation.

Trace Logger (legacy logging)

The original logging of system activities in CCLAS 6 shows a log of all activities on the system, not just for the current user. This type of logging is still available.

Process

In Java, logging is managed through various components, each playing a crucial role in the logging process. The key logging components are Loggers, Handlers, Log Levels, Formatters, and Logging methods.

Java logging is based on various standard libraries, particularly:

  • slf4j (Simple Logging Facade for Java) that provides the interface for all libraries to implement when logging in java

  • Assorted implementations of slf4j include logback, log4j, java.util.logging. CCLAS 6 uses logback.

CCLAS 6 logging leverages a few features that come from Logback, combined with some customised java servlets that provide a download capability for some grouped log files from the server. There is also a customised folder backed by EFS, however there is a small limitation on this as the folder needs to be mounted directly into the server so that the log append operation can be done properly.

There are several configurations that separate the loggings depending on their usage. The configuration dictates which format is being used and the output destination, whether it is the system default console or file-based logging complete with file rolling and retention policy.

Configuring the Debugger Logger Framework

The logging framework provides some uniform patterns to define: log levels, logging code, appenders, markers, MDC, patterns, layouts and customisable java.

CCLAS 6 employs various of these constructs to provide rich logging to the server manager.

Log Levels

Log levels define the level of verbosity, from least to noisiest: ERROR, WARN, INFO, DEBUG, TRACE - Level (SLF4J 2.0.1 API)

These levels are cumulative, for example, if the logging level in the logback-xml is set to:

  • INFO—Includes any java lines that are log.error(), log.warn() and log.info()

  • DEBUG—Includes everything but TRACE, that is, any java lines that are log.error(), log.warn(), log.info() and log.debug().

A good explanation of these levels is here: Logging levels - Logback - rule-of-thumb to assign log levels - Stack Overflow

Note: ALL, FATAL and OFF are log4j levels (not standard slf4j), so they should not be used with Logback: Level (SLF4J 2.0.1 API)

Logging Code

Logging code is a simple code mechanism to include logging lines in java:

private static Logger logger = LoggerFactory.getLogger(MyClass.class);
...
        logger.debug("Debug log message");
        logger.info("Info log message");
        logger.error("Error log message");

Having included those lines in java code, the server operator can filter how noisy they want the logs to be by setting the log level for the logs in configuration parameters.

This can be very fine-grained, by setting how noisy or quiet specific java packages are, via setting individual Log levels per package or class.

Appenders

Assorted output pathways are configurable via Appenders, for example, file appenders, console output, and message systems. These are configurable on specific subsets of logging, by package or other markers.

Markers

Markers allow a label to be added at runtime that server-configured filters can use to send logs to different destinations or take other actions, for example:

MDC

MDC is a map of variables that can be used to convey arbitrary information from inside the java runtime across to other java running in the same user session context, and out to the logging context, for example:

Patterns

Each appender can have individually configured log text formatting, including various available variables definable from the runtime and system.

This can include either simple per-line messages, or structured JSON maps of data.

Data included in the messages can come from the server context, Logging code, Markers, or MDC data, for example:

log4j.appender.consoleAppender.layout.ConversionPattern=
 %-4r [%t] %5p %c{1} %x - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n
 
638 [pool-1-thread-2] INFO Log4JBusinessService
 - Has transfer of 1104$ completed successfully ? true. - tx.id=2 tx.owner=Marc
logging.pattern.console=%d{"yyyy/MM/dd HH:mm:ss,SSS"} [%p] [%t] %M\\(%F:%L\\) - %msg%n

There are many ways to configure these patterns depending on the logger in use, so tutorials often provide different advice.

Logback’s Pattern parameters are described here: Chapter 6: Layouts (qos.ch) - ClassicPatternLayout.

Layouts

A deeper level of formatting can be customised with Layouts: Chapter 6: Layouts (qos.ch) (CCLAS does not use custom Layouts)

Customisable Java

All of the above is largely also extensible by using java code to extend the standard classes and add functionality. CCLAS 6 has some examples of this, as described below in CCLAS 6 Custom Appenders.

Debug Logger Definition File

The functionality above is assembled together using an XML definition file, depending on the logging library used. In logback, this definition file is logback.xml, for whatever format is output and whatever reader is used.

A feature of the logback.xml file is the ability to define filtration at the class orpackage level, so that if individual java classes or packages are either too noisy or more detail is wanted, the logging levels can be adjusted to be different to the overall system’s level just by setting a level per package/class. For example, the following setting restricts messages from Crystal Reports to only ERROR and WARN levels:

<logger name="com.crystaldecisions" level="WARN" />

Each server instance can have its own entirely customised logging verbosity, format and destination setup, via its own logback.xml file, directing log output in verbosity, formats and to destinations unique to that server.

The only element of logging that is fixed in the CCLAS 6 software (regardless of server instance) is the Logging Code, for example:

log.info("message to user"))

where the messages are originated at specific verbosity levels, with specific MDC data and markers. If these messages are incorrectly verbose, they can be altered either by changing the java code from log.info() to log.debug() etc, or by setting the log level per-package or per-class in the servers' logback.xml file to hide or expose that log level per java class/package.

Default logback.xml Configuration File

For future reference, the following logback.xml file comes from logback.xml coming from our ellipse-logging module (as at 01 Nov 2023).

logback.xml (from the ellipse-logging module)

<configuration>
    <!-- no longer supporting JBOSS port -->
    <!-- <define name="port.alloc" class="com.mincom.ellipse.logback.PortPropertyDefiner">
    </define> -->
    <appender name="WRAPPED" class="com.mincom.ellipse.logback.WrappedAppender">
        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%-5level %logger{5} - %msg%n</pattern>
            </encoder>
            <filter class="com.mincom.ellipse.logback.filters.SystemFlagFilter">
                <flagName>ellipse.stdout</flagName>
                <value>false</value>
                <OnMatch>DENY</OnMatch>
            </filter>
            <!-- Leave out AUDIT/SECURITY/SLOW_QUERY logging from default console appender for extra log marking later -->
            <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
                <markerName>AUDIT</markerName>
                <OnMatch>DENY</OnMatch>
            </filter>
            <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
                <markerName>SECURITY</markerName>
                <OnMatch>DENY</OnMatch>
            </filter>
            <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
                <markerName>SLOW_QUERY</markerName>
                <OnMatch>DENY</OnMatch>
            </filter>
        </appender>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.MDCValueFilter">
            <keyName>parent.uuid</keyName>
            <matchValue>null</matchValue>
            <matchOnNoMDC>true</matchOnNoMDC>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
    </appender>
    <!-- this appender will probably not required but we'll just keep it here for backup -->
    <!-- <appender name="ScreenDefMergerAppender" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator>
            <Key>traceKey</Key>
            <DefaultValue>unknown</DefaultValue>
        </discriminator>
        <sift>
            <appender name="TRACE-ScreenDef-${user}" class="com.mincom.ellipse.logback.DeletedRollingFileAppender">
                <File>/${traceKey}/ScreenDef-${traceKey}.log</File>
                <Append>false</Append>
                <encoder>
                    <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>
                </encoder>
                <rollingPolicy class="com.mincom.ellipse.logback.ServerFixedWindowRollingPolicy">
                    <fileNamePattern>/${traceKey}/ScreenDef-${traceKey}.%i.log.zip</fileNamePattern>
                    <minIndex>1</minIndex>
                    <maxIndex>10</maxIndex>
                </rollingPolicy>
                <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
                    <maxFileSize>200MB</maxFileSize>
                </triggeringPolicy>
            </appender>
        </sift>
        <filter class="com.mincom.ellipse.logback.filters.LoggerNameFilter">
            <startsWith>com.abb.enterprise.diff</startsWith>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.TraceInActiveFilter">
            <uiTraceValue>false</uiTraceValue>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender> -->
    <!-- both TRACE and UI_TRACE is needed for the UI trace capture/download feature to work so just leave it here -->
    <appender name="TRACE" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator>
            <Key>traceKey</Key>
            <DefaultValue>unknown</DefaultValue>
        </discriminator>
        <sift>
            <appender name="TRACE-${user}" class="com.mincom.ellipse.logback.DeletedRollingFileAppender">
                <File>/${traceKey}.log</File>
                <Append>false</Append>
                <encoder>
                    <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>
                </encoder>
                <rollingPolicy class="com.mincom.ellipse.logback.Role">
                    <fileNamePattern>/${traceKey}/${traceKey}.%i.log.zip</fileNamePattern>
                    <minIndex>1</minIndex>
                    <maxIndex>10</maxIndex>
                </rollingPolicy>
                <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
                    <maxFileSize>200MB</maxFileSize>
                </triggeringPolicy>
            </appender>
        </sift>
        <filter class="com.mincom.ellipse.logback.filters.TraceInActiveFilter">
            <uiTraceValue>false</uiTraceValue>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender>
    <appender name="UI_TRACE" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator>
            <Key>traceKey</Key>
            <DefaultValue>unknown</DefaultValue>
        </discriminator>
        <sift>
            <appender name="TRACE-ui-${user}" class="com.mincom.ellipse.logback.DeletedRollingFileAppender">
                <File>/${traceKey}ui.log</File>
                <Append>false</Append>
                <encoder>
                    <Pattern>%date{yyyy-MM-dd} %msg%n</Pattern>
                </encoder>
                <rollingPolicy class="com.mincom.ellipse.logback.ServerFixedWindowRollingPolicy">
                    <fileNamePattern>/${traceKey}/${traceKey}ui.%i.log.zip</fileNamePattern>
                    <minIndex>1</minIndex>
                    <maxIndex>10</maxIndex>
                </rollingPolicy>
                <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
                    <maxFileSize>200MB</maxFileSize>
                </triggeringPolicy>
            </appender>
        </sift>
        <filter class="com.mincom.ellipse.logback.filters.TraceInActiveFilter">
            <uiTraceValue>true</uiTraceValue>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender>
    <appender name="BATCH" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d %-5level %-32.32logger{0} - %msg%n</Pattern>
        </encoder>
        <filter class="com.mincom.ellipse.logback.EhCacheExpiredFilter"/>
        <filter class="com.mincom.ellipse.logback.filters.MDCValueFilter">
            <keyName>parent.uuid</keyName>
            <matchValue>null</matchValue>
            <matchOnNoMDC>true</matchOnNoMDC>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>
    <appender name="BATCH_TRACE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d [app=%X{app}, eibline=%X{eibline}] [%t] %-5level %logger{35} - %msg%n</Pattern>
        </encoder>
        <filter class="com.mincom.ellipse.logback.filters.BatchTraceInactiveFilter">
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender>
    <!-- This log is used to log BEC/BATCH related messages -->
    <appender name="BEC" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.LoggerNameFilter">
            <startsWith>com.mincom.batch</startsWith>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.LevelHigherThanFilter">
            <levelName>INFO</levelName>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>ACCEPT</OnMatch>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.MDCValueFilter">
            <keyName>bectrace</keyName>
            <matchValue>true</matchValue>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>ACCEPT</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- Otherwise isTraceEnabled() will always return true -->
    <turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
        <Key>trace</Key>
        <DefaultThreshold>INFO</DefaultThreshold> <!-- So return INFO as the DEFAULT threshould level -->
        <MDCValueLevelPair>
            <value>true</value>
            <level>TRACE</level> <!-- So if MDC trace=true then log for TRACE and higher. Else default -->
        </MDCValueLevelPair>
    </turboFilter>
    <!-- Ignore the VFS logging as is can cause deadlocks between SiftingAppender and LocalFileSystem locks -->
    <turboFilter class="com.mincom.ellipse.logback.filters.turbo.TurboLoggerNameFilter">
        <StartsWith>org.apache.commons.vfs</StartsWith>
        <OnMatch>DENY</OnMatch>
    </turboFilter>
    <!-- This log is used to log transaction messages -->
    <appender name="TX" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.TxFilter">
            <markerName>TX</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- Handle secure logs tagging including security/audit/slow_query logs -->
    <!-- <appender name="SECURITY" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
            <markerName>SECURITY</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [securelog=%marker] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender> -->
    <appender name="AUDIT" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
            <markerName>AUDIT</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [securelog=%marker] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="SLOW_QUERY" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
            <markerName>SLOW_QUERY</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [securelog=%marker] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- This is to stop an informational message created by hibernate when lazy loading is enabled -->
    <logger name="org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog" level="ERROR"/>
    <!-- Reduce this level to see more information about cache clustering and replication status -->
    <logger name="net.sf.ehcache.distribution.RMIAsynchronousCacheReplicator" level="ERROR"/>
    <!-- This is to stop a stack trace which is only INFO when an object is loaded but does not exist, which is done a bit in our code -->
    <logger name="org.hibernate.event.def.DefaultLoadEventListener" level="WARN"/>
    <logger name="com.mincom.ellipse.lsi.implementation.ConnectionManagerImpl" level="ERROR"/>
    <!-- Hide some of the more verbose tracing from Hibernate -->
    <logger name="org.hibernate.hql.ast" level="INFO"/>
    <!-- prevent ClassCastExceptions on foreign key to non primary key columns when level is trace -->
    <logger name="org.hibernate.engine.loading.LoadContexts" level="INFO"/>
    <logger name="org.hibernate.event.def.EvictVisitor" level="INFO"/>
    <logger name="org.hibernate.engine.Collections" level="INFO"/>
    <logger name="org.hibernate.util.JDBCExceptionReporter" level="OFF"/>
    <!-- Hide some of the more verbose tracing from DB Unit -->
    <logger name="org.dbunit" level="OFF"/>
    <logger name="o.d.dataset" level="OFF"/>
    <!-- <logger name="com.abb.enterprise.diff" additivity="false">
        <appender-ref ref="ScreenDefMergerAppender"/>
    </logger> -->
    <root level="${ROOT_LOG_LEVEL:-TRACE}">
        <appender-ref ref="WRAPPED"/>
        <appender-ref ref="TRACE"/>
        <appender-ref ref="UI_TRACE"/>
        <appender-ref ref="BATCH"/>
        <appender-ref ref="BATCH_TRACE"/>
        <appender-ref ref="BEC"/>
        <appender-ref ref="AUDIT"/>
        <appender-ref ref="SLOW_QUERY"/>
        <!-- <appender-ref ref="SECURITY"/> -->
        <appender-ref ref="TX"/>
    </root>
</configuration>

High-level System Properties in the logback.xml Configuration File

In this logback.xml configuration file, there are several high-level system properties that are used to determine which configuration is applied, depending on the value or presence of these properties in system properties. At the moment there are three system properties that determine the configuration: LOG_FILE, LOG_MODE and ROOT_LOG_LEVEL.

LOG_FILE

When this is provided with an appropriate value for log level (TRACE, DEBUG, INFO, WARN, ERROR), the following two (and only) appenders are enabled:

  • ServerLogRollingFileAppender—Print logs to a file in <baseDir>/log/server.log and apply a rolling policy which rolls the server.log into an alternate naming format (in this case, it is of the pattern: /log/${HOSTNAME}${port.alloc}/server.log.appliance.${efs.appliance.id:-SELF}.%d{yyyy-MM-dd}.gz)

  • SentryAppender—Send logging to Sentry (at WARN level and above).

This LOG_FILE system parameter also sets the root log level (overriding the ROOT_LOG_LEVEL parameter, if used). If the system property is defined but has no value, then DEBUG is assigned as the root level.

Setting this variable overrides and disables the functionality of LOG_MODE, ROOT_LOG_LEVEL and overrides the Default Logging Configuration described below.

LOG_MODE

When this property is provided, and the LOG_FILE property is not present), the following two (and only) appenders are enabled:

  • ConsoleAppender—Simple console logging

  • SentryAppender—The same as for the LOG_FILE setting, send logging to Sentry (at WARN level and above).

When the LOG_MODE property is defined but has no value, the root level log is set to DEBUG, thereby turning on debug level log for literally EVERYTHING, which could be very dangerous to system performance, and therefore not advised in a production environment. This is due to the fact that the default extended logging configuration (following) is set to lessen some of the logging verbosity, that is, by restricting some noisy java packages to ERROR level to minimise excess logging. But, if the LOG_MODE is set and has a proper value for the logging level (such as TRACE, DEBUG, INFO, WARN, ERROR), then that logging level filter is applied to all logging occurring in the system This also applies to direct and transitive libraries which may have inappropriately verbose logging included.

Setting this variable overrides and disables the functionality of ROOT_LOG_LEVEL and overrides the Default Logging Configuration described below.

ROOT_LOG_LEVEL

Additionally, there is a variable called ROOT_LOG_LEVEL that should be overwritten via system properties, otherwise it defaults to TRACE which is the most verbose. This property sets the root log level for any java packages that are not otherwise defined in logback.xml to have specific logging levels applied.

Note: This is only effective in the absence of LOG_MODE and LOG_FILE properties.

Default Logging Configuration

In this logback.xml configuration file, the extended configuration section, which is enabled when neither LOG_FILE nor LOG_MODE is provided, contains the default behaviour of a CCLAS 6 production environment.

Extended configuration section

<root level="${ROOT_LOG_LEVEL:-TRACE}">
    <appender-ref ref="WRAPPED" />
    <appender-ref ref="TRACE" />
    <appender-ref ref="UI_TRACE" />
    <appender-ref ref="LOG_DEBUGGER_TRACE" />
    <appender-ref ref="BATCH" />
    <appender-ref ref="BATCH_TRACE" />
    <appender-ref ref="BEC" />
    <appender-ref ref="AUDIT" />
    <appender-ref ref="SECURITY" />
    <appender-ref ref="TX" />
    <appender-ref ref="QUERY" />
</root>

Description of appenders in the extended configuration section:

WRAPPED

This is the standard logging appender that is used throughout the application. It appends log output in two places, which are:

  • the standard console output, and

  • the server.log file,

excluding anything with the following markers:

  • AUDIT

  • SECURITY

  • SLOW_QUERY

(These logs are excluded from the WRAPPED logs due to security reasons and are logged instead under different formats inside the EFS area as described in their sections below.)

The WRAPPED log only appends log output on non-batch processes (indicated by the presence of parent.uuid key on the MDC, which is set inside core java code). It also sets the logging level at INFO level.

This WRAPPED appender will be disabled from outputting to standard console if the ellipse.output system properties is present with a value of false.

TRACE

This log is using a SiftingAppender in its configuration, which creates separate logs based on the value of traceKey present in the MDC. The traceKey is typically set with user information or a combination between user and session, to create an exclusive log for that user or user-session.

The system takes the correlation ID from the presented screen and logs activity to a Log Aggregator on a specified CCLAS 6 server. The list of logs in the Log Aggregator equates to the activity undertaken in the session capture.

One of the access points which can trigger this log is by use of the Trace > Capture menu option from the CCLAS 6 user interface. In combination with LogServlet, it enables each user to capture their own log during the time period where the Capture checkbox is selected, after which the user can utilise the Trace > Download menu option which accesses LogServlet to download the trace log captured in the previous step.

This appender has a filter called TraceInActiveFilter which has a condition that only triggers the onMatch result when the MDC map is empty, MDC map traceKey is blank, or when the MDC map trace is not true or blank. Otherwise it triggers the onMismatch result.

Note: The onMatch result in this appender is set to the DENY value, which means that, if it finds that Trace is Inactive, it will not display results in the log, but when it finds that Trace is active, it returns NEUTRAL (which is the onMismatch value), which means that the filter does not take effect, and results are displayed in the log.

UI_TRACE

The exact same rule as TRACE but with uiTraceValue set to true, which causes the evaluation of the TraceInActiveFilter to be matched only when the MDC map is empty, MDC map traceKey is blank, or when the MDC map trace is not true, or when the MDC map uitrace is not true.

This seems to be unused at the moment since there is no explicit reference to this uitrace MDC map key.

BATCH

This appender records all the log lines that have the parent.uuid MDC map key set, at INFO level. It does it in a grouping based on the parent.uuid and records them under a hashed folder under EFS storage in a file called log.log.

BATCH_TRACE

This is exactly the same as BATCH appender but it captures the log at trace level, and produces a file called trace.log inside the hashed EFS folder.

BEC

This is configured to include the logging from classes with a java package of com.mincom.batch, with log level equal to INFO or higher, when the MDC map key bectrace is set to true. But there is no assignment to MDC with a key of bectrace which may indicate that this appender is no longer used.

AUDIT

This is a Marker-based filtering appender using the AUDIT marker. There are numerous code points that utilise this marker and its matching logs are stored under EFS storage with a configured rollingPolicy.

SECURITY This is a Security-specific appender (marker based) and is intended to capture log lines marked by the SECURITY marker, but in CCLAS 6 context, there is no explicit use of it and it is subject to future removal.
TX

This appender captures logs coming from a few frameworks that perform transactions. It is captured based on the log messages originating from java package names that match any of the followings:

  • org.springframework.transaction
  • com.arjuna
  • com.mincom.ews.service.transaction
  • com.abb.ji.transaction

The transaction logs are stored under EFS on /log/${HOSTNAME}${port.alloc}/transactions/tx.log. The port.alloc section can be ignored in a Spring Boot release since the JBOSS port is not used.

QUERY

This marker-based appender captures log messages marked with the SLOW_QUERY marker. This is automatically detected once the query threshold is passed, as defined by the edoi.slow.query.threshold system property (default two minutes).

LOG_DEBUGGER_TRACE

This logging appender is used for Log Debugger by utilising ConsoleAppender, which outputs logs to the standard console. It appends logs only when the user-trace-id is present in the MDC. The user-trace-id serves as the correlation ID for the current session when log debugging is initiated, generating exclusive logs for that user session.

Logging is triggered via the Log Debugger > Start Capture menu option from the CCLAS 6 user interface and stopped with the Log Debugger > Stop Capture menu option. The user-trace-id is used for filtering logs in a log aggregator.

This appender includes a filter called LogDebuggerInActiveFilter with the following conditions:

  • onMatch—Triggered when the MDC map is empty, user-trace-id is blank, or the trace flag is either missing or not set to true.

  • onMismatch—Triggered when none of the above conditions are met.

When onMatch is triggered, indicating the Log Debugger is inactive, the appender is set to DENY, preventing logs from being appended to the console. Conversely, when onMismatch is triggered, indicating the Log Debugger is active, the appender is set to NEUTRAL, allowing logs to be appended to the console.

  <appender name="LOG_DEBUGGER_TRACE" class="ch.qos.logback.core.ConsoleAppender">
      <encoder>
          <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>
      </encoder>
      <filter class="com.mincom.ellipse.logback.filters.LogDebuggerInActiveFilter">
          <OnMismatch>NEUTRAL</OnMismatch>
          <OnMatch>DENY</OnMatch>
      </filter>
  </appender>
LOG_DEBUGGER_ROLLING

This appender logs to a file using the ServerLogRollingFileAppender, as shown in the following example:

<appender name="LOG_DEBUGGER_ROLLING" class="com.mincom.ellipse.logback.ServerLogRollingFileAppender">
    <file>/log/debuglogger.log</file>
    <encoder>
        <pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</pattern>
    </encoder>
    <rollingPolicy class="com.mincom.ellipse.logback.ServerTimeBasedRollingPolicy">
        <fileNamePattern>/log/${HOSTNAME}${port.alloc}/debuglogger.log.appliance.${efs.appliance.id:-SELF}.%d{yyyy-MM-dd}.gz</fileNamePattern>
        <maxHistory>35</maxHistory>
    </rollingPolicy>
    <filter class="com.mincom.ellipse.logback.filters.LogDebuggerInActiveFilter">
        <OnMismatch>NEUTRAL</OnMismatch>
        <OnMatch>DENY</OnMatch>
    </filter>  
</appender>

In either case of LOG_DEBUGGER_TRACE or LOG_DEBUGGER_ROLLING, whether logging to the console or a file, the log aggregator must capture the logs from the console or log file for further filtering.

Alternatively, to reuse an existing appender to consistently capture log debugger events, add the following filter configuration and place it as the first filter in the appender:

<filter class="com.mincom.ellipse.logback.filters.LogDebuggerInActiveFilter">
    <OnMismatch>ACCEPT</OnMismatch>
    <OnMatch>NEUTRAL</OnMatch>
</filter>
<!-- other filter goes here e.g. -->
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
    <level>INFO</level>
</filter>

In Logback, the filters are evaluated in the order they are defined. If a filter returns ACCEPT or DENY, then the evaluation stops and the decision is made. If a filter returns NEUTRAL, then the next filter in the chain is evaluated.

In above case, if the LogDebuggerInActiveFilter is active, that is, it is set to OnMismatch, then it returns ACCEPT and the logging event is accepted immediately without consulting the remaining filters.

However, if the LogDebuggerInActiveFilter filter is inactive, that is, it is set to OnMatch, then it returns NEUTRAL and the next filter, for example, ThresholdFilter is evaluated. If the logging event's level is INFO or higher, then the ThresholdFilter accepts the event. If the logging event's level is lower than INFO, then the ThresholdFilter denies the event.

CCLAS 6 Custom Appenders

WrappedAppender

This appender groups a lists of appenders as a single appender, to share common filters that applies to the group. For example:

<appender name="WRAPPED" class="com.mincom.ellipse.logback.WrappedAppender">
    <appender name="STDOUT" class="...">
        <filter class="com.mincom.ellipse.logback.filters.SystemFlagFilter">  
            ...
        </filter>
    </appender>
    <appender name="ROLLING" class="...">...</appender>  
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">  
        <level>INFO</level>  
    </filter>
</appender>

In the configuration above, STDOUT has a filter. This filter at this scope, however, is not shared among the other appenders listed in the WRAPPER appender.

ServerLogRollingFileAppender

This appender adds some customisation as to which folder the log file goes to, message formats and the naming of rolling archives. It extends a base RollingFileAppender which allows printing of a log to a specified file in the <file> tag. It currently supports two locations based on these system properties: azure.server.log.dir and jboss.server.base.dir. According to the Appender java code, azure.server.log.dir takes precedence if both system properties are present. The usage of this appender is exactly the same as the RollingFileAppender and there are no changes on top of that other than which base folder it uses, depending on the file location system properties mentioned above being present at runtime. For example:

<appender name="ROLLING" class="com.mincom.ellipse.logback.ServerLogRollingFileAppender">  
    <file>/log/server.log</file>  
    <encoder>
        <pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</pattern>  
    </encoder>
    <rollingPolicy class="com.mincom.ellipse.logback.ServerTimeBasedRollingPolicy">
        <fileNamePattern>/log/${HOSTNAME}${port.alloc}/server.log.appliance.${efs.appliance.id:-SELF}.%d{yyyy-MM-dd}.gz</fileNamePattern>
    ...
</appender>

In this example, by specifying a value of /log/server.log, a log folder is created in the specified base folder, and the server.log file is created in that.

In the case where one of the mentioned system properties is provided, then that is used as the base folder for storing the log file. For example, if an azure.server.log.dir=/var property is defined, then the final log destination is /var/log/server.log.

Note: If neither of the mentioned properties are present, then this appender writes the log under the java.io.tmpdir system temporary folder instead.
DeleteRollingFileAppender

This appender is another that is based on RollingFileAppender, with the addition being that, if the log file is found to be absent, it triggers a roll over. Hence, whenever this appender is trying to append a log but the initial file has been removed, the system attempts to trigger the roll over process from RollingFileAppender to create a new iteration of the log file. The following is an example of this appender:

<appender name="TRACE-${user}" class="com.mincom.ellipse.logback.DeletedRollingFileAppender">  
    <File>/${traceKey}.log</File>  
    <Append>false</Append>  
    <encoder>
        <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>  
    </encoder>
    <rollingPolicy class="com.mincom.ellipse.logback.ServerFixedWindowRollingPolicy">  
        <fileNamePattern>/${traceKey}/${traceKey}.%i.log.zip</fileNamePattern>  
        <minIndex>1</minIndex>  
        <maxIndex>10</maxIndex>  
    </rollingPolicy>
    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">  
        <maxFileSize>200MB</maxFileSize>  
    </triggeringPolicy>
</appender>

In this example, the system attempts to write a log to a file named ${traceKey}.log, and if that defined file is not located in the ellipse.logs folder or in the system temporary folder, then the appender rolls over the log set.

Note: Like any other extension of RollingFileAppender, the rollingPolicy and triggeringPolicy are important as the rollingPolicy dictates the roll over file format and maximum number of roll over files and triggeringPolicy is the trigger condition to start the roll over mechanism.

EllipseFileSystemAppender

This is an OutputStreamAppender extension that works on practically any file and collects the logs appended by it, zips them and adds the zip file into an EFS file. An example of the usage of this appender is as follows:

<appender name="BATCH-${parent.uuid}" class="com.mincom.ellipse.logback.EllipseFileSystemAppender">  
    <File>log.log</File>  
    <Group>${parent.uuid}</Group>  
    <encoder>
        <Pattern>%d %-5level %-32.32logger{0} - %msg%n</Pattern>  
    </encoder>
    <maxFileSize>200MB</maxFileSize>  
    <filter class="com.mincom.ellipse.logback.EhCacheExpiredFilter"/>  
</appender>

This appender is usually combined with SiftingAppender to provide a grouping capability based on certain fields described in the <discriminator> section. The discriminator key determines which logs go to which path. The path can be defined as a file name or group, depending on the needs of the user.

EllipseZipFileSystemAppender

This is also an extension of OutputStreamAppender will keeps appending the outputStream to a zip file stored in EFS. The zip file rolls over when the maxFileSize property defined in the appender is reached. The roll over behaviour is manually defined in the implementation based on the maxFileSize, instead of using triggeringPolicy and rollingPolicy like RollingFileAppender. For example:

<appender name="TRACE-${parent.uuid}" class="com.mincom.ellipse.logback.EllipseZipFileSystemAppender">  
    <File>trace.log</File>  
    <Group>${parent.uuid}</Group>  
    <encoder>
        <Pattern>
        %d [app=%X{app}, eibline=%X{eibline}] [%t] %-5level %logger{35} - %msg%n</Pattern>  
    </encoder>
    <maxFileSize>200MB</maxFileSize>  
</appender>

This appender is usually combined with SiftingAppender to provide grouping of logs in separate zip files. It acts with the same behaviour as EllipseFileSystemAppender, but instead of writing to a readable log file, this appender writes the output stream as a compressed zip file.

EFSRollingFileAppender

This appender uses the exact same approach asServerLogRollingFileAppender but defines the base folder using the ellipse.fs.root property, and where the ellipse.fs.root property is not present at runtime, defaults to using the system temporary folder. For example:

<appender name="BEC" class="com.mincom.ellipse.logback.EFSRollingFileAppender">  
    ... 
    <file>/batch/batch.log</file>  
    <encoder>
        <pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</pattern>  
    </encoder>
    <rollingPolicy class="com.mincom.ellipse.logback.ServerTimeBasedRollingPolicy">  
        <fileNamePattern>/batch/batch.log.%d{yyyy-MM-dd}</fileNamePattern>  
        <maxHistory>7</maxHistory>  
    </rollingPolicy>
</appender>

Logging Suggestion for Container-based CCLAS 6

Although the logging.xml shown above is quite elaborate in separating the logs and populating the files nicely in EFS, this does not work quite as well in a container context, especially in combination with a log aggregator. The log aggregator by default expects the log to be populated in the container console, but the default CCLAS 6 configuration directs some of the logs to EFS.

To fulfil a requirement to accommodate container/aggregator logging we could set the LOG_MODE to a valid log level, but that disables the feature of downloading a user trace log from the CCLAS 6 user interface. Alternatively, to keep most of the existing default logging functionality, with the necessary log visible in the console, while also keeping the additional capability to hide some logs with security risks, the following log configuration can be used:

logback-console.xml

<configuration>
    <!-- no longer supporting JBOSS port -->
    <!-- <define name="port.alloc" class="com.mincom.ellipse.logback.PortPropertyDefiner">
    </define> -->
    <appender name="WRAPPED" class="com.mincom.ellipse.logback.WrappedAppender">
        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%-5level %logger{5} - %msg%n</pattern>
            </encoder>
            <filter class="com.mincom.ellipse.logback.filters.SystemFlagFilter">
                <flagName>ellipse.stdout</flagName>
                <value>false</value>
                <OnMatch>DENY</OnMatch>
            </filter>
            <!-- Leave out AUDIT/SECURITY/SLOW_QUERY logging from default console appender for extra log marking later -->
            <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
                <markerName>AUDIT</markerName>
                <OnMatch>DENY</OnMatch>
            </filter>
            <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
                <markerName>SECURITY</markerName>
                <OnMatch>DENY</OnMatch>
            </filter>
            <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
                <markerName>SLOW_QUERY</markerName>
                <OnMatch>DENY</OnMatch>
            </filter>
        </appender>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.MDCValueFilter">
            <keyName>parent.uuid</keyName>
            <matchValue>null</matchValue>
            <matchOnNoMDC>true</matchOnNoMDC>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
    </appender>
    <!-- this appender will probably not required but we'll just keep it here for backup -->
    <!-- <appender name="ScreenDefMergerAppender" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator>
            <Key>traceKey</Key>
            <DefaultValue>unknown</DefaultValue>
        </discriminator>
        <sift>
            <appender name="TRACE-ScreenDef-${user}" class="com.mincom.ellipse.logback.DeletedRollingFileAppender">
                <File>/${traceKey}/ScreenDef-${traceKey}.log</File>
                <Append>false</Append>
                <encoder>
                    <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>
                </encoder>
                <rollingPolicy class="com.mincom.ellipse.logback.ServerFixedWindowRollingPolicy">
                    <fileNamePattern>/${traceKey}/ScreenDef-${traceKey}.%i.log.zip</fileNamePattern>
                    <minIndex>1</minIndex>
                    <maxIndex>10</maxIndex>
                </rollingPolicy>
                <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
                    <maxFileSize>200MB</maxFileSize>
                </triggeringPolicy>
            </appender>
        </sift>
        <filter class="com.mincom.ellipse.logback.filters.LoggerNameFilter">
            <startsWith>com.abb.enterprise.diff</startsWith>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.TraceInActiveFilter">
            <uiTraceValue>false</uiTraceValue>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender> -->
    <!-- both TRACE and UI_TRACE is needed for the UI trace capture/download feature to work so just leave it here -->
    <appender name="TRACE" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator>
            <Key>traceKey</Key>
            <DefaultValue>unknown</DefaultValue>
        </discriminator>
        <sift>
            <appender name="TRACE-${user}" class="com.mincom.ellipse.logback.DeletedRollingFileAppender">
                <File>/${traceKey}.log</File>
                <Append>false</Append>
                <encoder>
                    <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>
                </encoder>
                <rollingPolicy class="com.mincom.ellipse.logback.Role">
                    <fileNamePattern>/${traceKey}/${traceKey}.%i.log.zip</fileNamePattern>
                    <minIndex>1</minIndex>
                    <maxIndex>10</maxIndex>
                </rollingPolicy>
                <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
                    <maxFileSize>200MB</maxFileSize>
                </triggeringPolicy>
            </appender>
        </sift>
        <filter class="com.mincom.ellipse.logback.filters.TraceInActiveFilter">
            <uiTraceValue>false</uiTraceValue>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender>
    <appender name="UI_TRACE" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator>
            <Key>traceKey</Key>
            <DefaultValue>unknown</DefaultValue>
        </discriminator>
        <sift>
            <appender name="TRACE-ui-${user}" class="com.mincom.ellipse.logback.DeletedRollingFileAppender">
                <File>/${traceKey}ui.log</File>
                <Append>false</Append>
                <encoder>
                    <Pattern>%date{yyyy-MM-dd} %msg%n</Pattern>
                </encoder>
                <rollingPolicy class="com.mincom.ellipse.logback.ServerFixedWindowRollingPolicy">
                    <fileNamePattern>/${traceKey}/${traceKey}ui.%i.log.zip</fileNamePattern>
                    <minIndex>1</minIndex>
                    <maxIndex>10</maxIndex>
                </rollingPolicy>
                <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
                    <maxFileSize>200MB</maxFileSize>
                </triggeringPolicy>
            </appender>
        </sift>
        <filter class="com.mincom.ellipse.logback.filters.TraceInActiveFilter">
            <uiTraceValue>true</uiTraceValue>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender>
    <appender name="BATCH" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d %-5level %-32.32logger{0} - %msg%n</Pattern>
        </encoder>
        <filter class="com.mincom.ellipse.logback.EhCacheExpiredFilter"/>
        <filter class="com.mincom.ellipse.logback.filters.MDCValueFilter">
            <keyName>parent.uuid</keyName>
            <matchValue>null</matchValue>
            <matchOnNoMDC>true</matchOnNoMDC>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>
    <appender name="BATCH_TRACE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d [app=%X{app}, eibline=%X{eibline}] [%t] %-5level %logger{35} - %msg%n</Pattern>
        </encoder>
        <filter class="com.mincom.ellipse.logback.filters.BatchTraceInactiveFilter">
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
    </appender>
    <!-- This log is used to log BEC/BATCH related messages -->
    <appender name="BEC" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.LoggerNameFilter">
            <startsWith>com.mincom.batch</startsWith>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.LevelHigherThanFilter">
            <levelName>INFO</levelName>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>ACCEPT</OnMatch>
        </filter>
        <filter class="com.mincom.ellipse.logback.filters.MDCValueFilter">
            <keyName>bectrace</keyName>
            <matchValue>true</matchValue>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>ACCEPT</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- Otherwise isTraceEnabled() will always return true -->
    <turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
        <Key>trace</Key>
        <DefaultThreshold>INFO</DefaultThreshold> <!-- So return INFO as the DEFAULT threshould level -->
        <MDCValueLevelPair>
            <value>true</value>
            <level>TRACE</level> <!-- So if MDC trace=true then log for TRACE and higher. Else default -->
        </MDCValueLevelPair>
    </turboFilter>
    <!-- Ignore the VFS logging as is can cause deadlocks between SiftingAppender and LocalFileSystem locks -->
    <turboFilter class="com.mincom.ellipse.logback.filters.turbo.TurboLoggerNameFilter">
        <StartsWith>org.apache.commons.vfs</StartsWith>
        <OnMatch>DENY</OnMatch>
    </turboFilter>
    <!-- This log is used to log transaction messages -->
    <appender name="TX" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.TxFilter">
            <markerName>TX</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- Handle secure logs tagging including security/audit/slow_query logs -->
    <!-- <appender name="SECURITY" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
            <markerName>SECURITY</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [securelog=%marker] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender> -->
    <appender name="AUDIT" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
            <markerName>AUDIT</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [securelog=%marker] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="SLOW_QUERY" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
            <markerName>SLOW_QUERY</markerName>
            <OnMismatch>DENY</OnMismatch>
            <OnMatch>NEUTRAL</OnMatch>
        </filter>
        <encoder>
            <pattern>%d [%X] [securelog=%marker] [%t] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- This is to stop an informational message created by hibernate when lazy loading is enabled -->
    <logger name="org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog" level="ERROR"/>
    <!-- Reduce this level to see more information about cache clustering and replication status -->
    <logger name="net.sf.ehcache.distribution.RMIAsynchronousCacheReplicator" level="ERROR"/>
    <!-- This is to stop a stack trace which is only INFO when an object is loaded but does not exist, which is done a bit in our code -->
    <logger name="org.hibernate.event.def.DefaultLoadEventListener" level="WARN"/>
    <logger name="com.mincom.ellipse.lsi.implementation.ConnectionManagerImpl" level="ERROR"/>
    <!-- Hide some of the more verbose tracing from Hibernate -->
    <logger name="org.hibernate.hql.ast" level="INFO"/>
    <!-- prevent ClassCastExceptions on foreign key to non primary key columns when level is trace -->
    <logger name="org.hibernate.engine.loading.LoadContexts" level="INFO"/>
    <logger name="org.hibernate.event.def.EvictVisitor" level="INFO"/>
    <logger name="org.hibernate.engine.Collections" level="INFO"/>
    <logger name="org.hibernate.util.JDBCExceptionReporter" level="OFF"/>
    <!-- Hide some of the more verbose tracing from DB Unit -->
    <logger name="org.dbunit" level="OFF"/>
    <logger name="o.d.dataset" level="OFF"/>
    <!-- <logger name="com.abb.enterprise.diff" additivity="false">
        <appender-ref ref="ScreenDefMergerAppender"/>
    </logger> -->
    <root level="${ROOT_LOG_LEVEL:-TRACE}">
        <appender-ref ref="WRAPPED"/>
        <appender-ref ref="TRACE"/>
        <appender-ref ref="UI_TRACE"/>
        <appender-ref ref="BATCH"/>
        <appender-ref ref="BATCH_TRACE"/>
        <appender-ref ref="BEC"/>
        <appender-ref ref="AUDIT"/>
        <appender-ref ref="SLOW_QUERY"/>
        <!-- <appender-ref ref="SECURITY"/> -->
        <appender-ref ref="TX"/>
    </root>
</configuration>

This logback-console.xml has switched most of the FileAppender based appenders into ConsoleAppender which prints logs into the container’s standard output, making it visible from the log aggregator. However, some of the logging still remains in the FileAppender to keep the user trace download log functionality working.

Database Migration Logging

The logging during database migration has a different way of working and does not make use of most of the appenders described in the list above. Most of the logging is simply done on standard output (based on the WRAPPED configuration in the logback.xml and any environment variables associated with it), so the only output from this process is the console output and the server.log. But, there are additional things to consider outside of the default logback.xml settings. This includes that the docker image that wraps around the CCLAS 6 server also has manual logging defined within its built image. Several notable things about the CCLAS 6 docker images around logging are as follows:

  • The docker image exposes an environment variable called EFS_DIR which basically states where the EFS root path is.

  • It also has a LOG_DIR environment variable which takes the EFS_DIR value by default unless otherwise specified. This LOG_DIR eventually becomes the final log path that the docker images uses. There are four kinds of logs coming out from the image internals:

    • pre-conversion-hook.log—At the clean up before performing database migration (mostly does clean up of core data which is pulled in during the coreDataLoad process)

    • conversion.log—At the start of performing the conversion to apply the latest model changes (this stage only detects changes or differences between the current database structure and the latest modelled data object coming from RSA)

    • coreDataLoad.log—At the population of the core data based on sets of specified tables (MSF010, MSF025, MSF081, MSF1ED, MSF1EE, MSF1EB, MENUTABLES, SECURITY)

    • post-conversion-hook.log—At the last step of the database migration task where it applies a few customisation changes on top of the upgraded data.

  • In kubernetes setting, the EFS folder is mounted on the volumes on a path like /mnt/efs/, and LOG_DIR can be set to have a prefix of /mnt/efs/, and logs are automatically written to the EFS. (This follows what the EFS is defined as, depending on which cloud provider is being run. If it is on Azure, then it goes to the storage account file shared folder, and if on AWS, then it goes to the NFS server instead.)

  • In the CCLAS-DM deployment Ansible playbook, there is a step to upload the finished logs during data migration to the s3 bucket. However the Azure environment does not have Ansible involved so the s3 upload behaviour is not present in Azure, which aligns with our intended direction.

Undertow Logging

In prior versions of CCLAS 6 when JBoss WildFly was used as the application server instead of Spring Boot’s Undertow, the EAR file was deployed as an application on top of a running WildFly server. As an application serve,r WildFly does a lot more compared to a lightweight embedded server such as Undertow. This also affects the standard logging being printed out in the log file. By default, a Wildfly implementation has another log file called console.log to distinguish between the application server log and the bespoke application log. (Some people may be more familiar with calling the console.log a server.log while the server.log that currently referenced in the logback.xml might be called an application.log. The distinction can be separated further by differentiating between error log, security log, batch log, etc.)

On moving away from WildFly to Spring Boot, however, this behaviour has changed. The Undertow server that is used in exchange for WildFly does not have the behaviour of creating a separate log file called console.log. Instead, its logs are just processed via Spring Boot’s logging overall mechanism (as described above regarding the logback.xml file configuration). Since Undertow is embedded inside the Spring Boot application itself, it does not need to have extra logging definitions apart from what is configured at the application level. With that knowledge, and looking at the containerised application context, the need for a separate console.log is no longer relevant. When combined with the intention to use log aggregators, all that is necessary is that Undertow logging naturally outputs to the standard output (if defined in logback.xml) so that it is visible, with specified filtering, to the log aggregators.

In summary, due to the changes between the WildFly environment and Spring Boot, especially in the containerised environment, the need for having the console.log is no longer relevant. The application server starts in conjunction with the application under Spring Boot and logging operates according to the application’s logback.xml file definition. With the above configuration suggested for a container-based application, most, if not all, of the logging is expected to go to the console, then captured by the log aggregator implemented on that container.

JSON Logging format

The net.logstash.logback.encoder.LogstashEncoder for JSON log format can be used in CCLAS 6.

To switch to JSON format, the encoder in logback.xml must be updated. An external logback.xml can be referenced by application start up options , otherwise CCLAS 6 uses the in-build logback.xml which, by default, logs message in plain text format.

To define an external logback.xml in the application start up properties file:

logging.config=/mnt/efs/cclas68/logback.xml

Similarly, use external logback.xml in a java start-up option:

-Dlogging.config=/mnt/efs/cclas68/logback.xml

LogstashEncoder Configuration in logback.xml

The following example patterns are for switching from a plain text encoder to a JSON encoder:

Example pattern 1: <pattern>%-5level %logger{5} - %msg%n</pattern>

From:

<encoder>
    <pattern>%-5level %logger{5} - %msg%n</pattern>
</encoder>

To:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
    <fieldNames>
        <logger>logger</logger>
        <thread>thread</thread>
    </fieldNames>
    <includeMdc>false</includeMdc>
    <includeContext>false</includeContext>
</encoder>

Example pattern 2: <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>

From:

<encoder>
    <Pattern>%d [%X] [%t] %-5level %logger{35} - %msg%n</Pattern>
</encoder>

To:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
    <fieldNames>
        <logger>logger</logger>
        <thread>thread</thread>
    </fieldNames>
    <timestampPattern>yyyy-MM-dd' 'HH:mm:ss.SSS</timestampPattern>
    <includeContext>false</includeContext>
</encoder>

Example pattern 3: <Pattern>%d [app=%X{app}, eibline=%X{eibline}] [%t] %-5level %logger{35} - %msg%n</Pattern>

From:

<encoder>
    <Pattern>%d [app=%X{app}, eibline=%X{eibline}] [%t] %-5level %logger{35} - %msg%n</Pattern>
</encoder>

To:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
    <fieldNames>
        <logger>logger</logger>
        <thread>thread</thread>
    </fieldNames>
    <timestampPattern>yyyy-MM-dd' 'HH:mm:ss.SSS</timestampPattern>
    <includeMdcKeyName>app</includeMdcKeyName>
    <includeMdcKeyName>eibline</includeMdcKeyName>
    <includeContext>false</includeContext>
</encoder>

JSON log “pretty“ format:

By default, JSON logs are displayed as a single-line message. To format the JSON logs in a more readable, "pretty" format, it is enabled using the following setting:

<jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>

For example:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
    <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/> 
    <fieldNames>
        <logger>logger</logger>
        <thread>thread</thread>
    </fieldNames>
    <includeMdc>false</includeMdc>
    <includeContext>false</includeContext>
</encoder>

Dual Logging in Plain Text and JSON

Both plain text and JSON outputs are configured by defining two appenders, each with a different encoder. This setup allows the same log event to be recorded in both plain text and JSON formats.

Note: This produces duplicate logs for the same event.

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <encoder>
      <pattern>%-5level %logger{5} - %msg%n</pattern>
  </encoder>
  <filter class="com.mincom.ellipse.logback.filters.SystemFlagFilter">
      <flagName>ellipse.stdout</flagName>
      <value>false</value>
      <OnMatch>DENY</OnMatch>
  </filter>
  <!-- Don't Log Audit events to StdOut -->
  <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
      <markerName>AUDIT</markerName>
      <OnMatch>DENY</OnMatch>
  </filter>
  <!-- Don't Log Security events to StdOut -->
  <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
      <markerName>SECURITY</markerName>
      <OnMatch>DENY</OnMatch>
  </filter>
  <!-- Don't Log Security events to StdOut -->
  <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
      <markerName>SLOW_QUERY</markerName>
      <OnMatch>DENY</OnMatch>
  </filter>
</appender>

<appender name="STDOUT_JSON" class="ch.qos.logback.core.ConsoleAppender">
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
      <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>
      <fieldNames>
          <logger>logger</logger>
          <thread>thread</thread>
      </fieldNames>
      <timestampPattern>yyyy-MM-dd' 'HH:mm:ss.SSS</timestampPattern>
      <includeContext>false</includeContext>
      <includeMdc>true</includeMdc>
  </encoder>
  <filter class="com.mincom.ellipse.logback.filters.SystemFlagFilter">
      <flagName>ellipse.stdout</flagName>
      <value>false</value>
      <OnMatch>DENY</OnMatch>
  </filter>
  <!-- Don't Log Audit events to StdOut -->
  <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
      <markerName>AUDIT</markerName>
      <OnMatch>DENY</OnMatch>
  </filter>
  <!-- Don't Log Security events to StdOut -->
  <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
      <markerName>SECURITY</markerName>
      <OnMatch>DENY</OnMatch>
  </filter>
  <!-- Don't Log Security events to StdOut -->
  <filter class="com.mincom.ellipse.logback.filters.MarkerFilter">
      <markerName>SLOW_QUERY</markerName>
      <OnMatch>DENY</OnMatch>
  </filter>
</appender>

Using a Log Aggregator

Datamine recommends using the ELK log aggregator to view logs from the debugger logger, however, this is not mandatory as the flat text log files could be viewed, if required.

ELK is the most popular open-source log aggregation tool on the market.

  • E—Elasticsearch, a NoSQL, Lucene search engine implementation

  • L—Logstash, a log pipeline system that can ingest data, transform it, and load it into a store like Elasticsearch

  • K—Kibana, a visualisation layer on top of Elasticsearch.

Refer to The Complete Guide to the ELK Stack.

Apart form that, CCLAS 6 uses Filebeat to forward and centralise logs captured from the debugger logger. Refer to Filebeat—Lightweight shipper for logs.

The filebeat multiline configuration for the ELK log aggregator can be updated as follows to process JSON format logs.

multiline.pattern: '^(ERROR|WARN|INFO|DEBUG|TRACE|FATAL|^\[\d{2} \w{3} \d{4} \d{2}:\d{2}:\d{2}:\d{3}\]|^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} \[.*\]|^\{)'
multiline.negate: true
multiline.match: after
fields:
  source: cclas-db-migrate-console
fields_under_root: true 
processors:
  - decode_json_fields:
      fields: ["message"]
      target: ""  # This will place parsed JSON fields at the root level
      overwrite_keys: true
      add_error_key: true

The multiline.pattern now has an extra ^\{ which caters for the JSON log format.

The decode_json_fields processor parses JSON message fields.