Logging - Useful Logback Configurations

Introduction

This document lists useful logging configurations for the Sophora Server and tools. The Sophora Server and most of the tools use the Logback framework for log output. The following snippets are meant to be added to the logback.xml file of the server or the tools.

Writing output to a separate log file

The following example configuration writes log messages by the LoggingProfiler to a separate log file called "profile.log". The attribute additivity in the logger configuration controls whether the log messages are written to the main log file in addition to the profile.log.

<appender name="profile" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <File>${sophora.home}/logs/profile.log</File>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <fileNamePattern>${sophora.home}/logs/profile.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
    <maxHistory>7</maxHistory>
  </rollingPolicy>
  <encoder>
    <pattern>[%d{ISO8601}, %-5p] [%t] [IP: %X{IP}] [UUID: %X{uuid}] [SOPHORA_ID: %X{sophora_id}] [USER: %X{user}] %m%n</pattern>
  </encoder>
</appender>

<logger name="com.subshell.sophora.commons.profile.LoggingProfiler" level="DEBUG" additivity="false">
  <appender-ref ref="profile" />
</logger>

Logging events that require human intervention

Some events on the server require a human response. The Sophora Server logs those scenarios with the special marker EMERGENCY in order to be able to separate them from other messages. The appender configuration should be provided with a new condition, which reacts exclusively to those log messages.

<appender name="emergency" class="ch.qos.logback.core.rolling.RollingFileAppender">
 	<evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
 		<marker>EMERGENCY</marker>
 	</evaluator>
 	<File>${sophora.home}/logs/emergency.log</File>
 	<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
 		<fileNamePattern>${sophora.home}/logs/emergency.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
 		<maxHistory>7</maxHistory>
 	</rollingPolicy>
 	<encoder>
 		<pattern>[%d{ISO8601}, %-5p] [%t] [IP: %X{IP}] [UUID: %X{uuid}] [SOPHORA_ID: %X{sophora_id}] [USER: %X{user}] %m%n</pattern>
 	</encoder>
 </appender>

<root level="INFO"> 
	<appender-ref ref="emergency" />
</root>  

Redirecting some log messages to the mail

In addition to redirecting important events to a separate log file, logback offers a way to receive such messages per mail. Please note that a valid SMTP configuration is requrired.

<appender name="email" class="ch.qos.logback.classic.net.SMTPAppender">
 		<evaluator class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
 			<marker>EMERGENCY</marker>
 		</evaluator>
 		<smtpHost>....</smtpHost>
 		<smtpPort>...</smtpPort>
 		<STARTTLS>true</STARTTLS>
 		<from>...</from>
 		<to>...</to>
 		<username>...</username>
 		<password>...</password>
 		<subject>EMERGENCY at Sophora Server</subject>
 		<layout class="ch.qos.logback.classic.html.HTMLLayout" />
 		<cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTracker">
 			<!-- send just one log entry per email -->
 			<bufferSize>1</bufferSize>
 		</cyclicBufferTracker>
 </appender>

 <root level="INFO">
 	<appender-ref ref="email"/>
 </root>

Using a format pattern variable

A format pattern can be defined in a variable and then be reused in multiple appenders. The format is documented in the logback manual. The following example defines a variable APPENDER_PATTERN, which is then used in an appender.

<property name="APPENDER_PATTERN" value="%d{dd.MM.yyyy HH:mm:ss} %5level [%10.10thread] %-40.40(%logger{0}:%L): %msg%n" />

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <encoder>
    <pattern>${APPENDER_PATTERN}</pattern>
  </encoder>
</appender>

Sophora Server

All calls on the ContentManager API, including execution times. See also Activating the profile log.

<logger name="com.subshell.sophora.commons.profile.LoggingProfiler" level="DEBUG" />

All SOLR queries, including connections made directly to the SOLR server:

<logger name="org.apache.solr.core.SolrCore" level="INFO" />

All JCR / XPath searches:

<logger name="com.subshell.sophora.server.application.manager.search.jcr.XpathSearchManager" level="DEBUG" />

IQuery SOLR searches executed by the server:

<logger name="com.subshell.sophora.server.application.manager.search.solr.SolrSearchStrategy" level="DEBUG" />

Server script executions, including execution times:

<logger name="com.subshell.sophora.server.application.scripting.jmx.ScriptingStatistics" level="DEBUG" />

Logging by document change scripts which use the logger from the IScriptContext:

<logger name="com.subshell.sophora.server.application.scripting.ScriptManager" level="DEBUG" />

Logging by timing scripts which use the logger from the ITimingActionScriptContext:

<logger name="com.subshell.sophora.server.application.timingaction.DocumentTimingActionsJob" level="INFO" />

Tools / Webapps

All calls on the ISophoraClient API, including execution times:

<logger name="com.subshell.sophora.client.profiling.SophoraClientProfiling" level="TRACE" />

All calls from the Sophora Client library to the Sophora server, including execution times:

<logger name="com.subshell.sophora.client.profiling.ContentManagerProfiling" level="TRACE" />

DeskClient

To show debug output of a client script in the DeskClient log, add the following code to the script:

import org.slf4j.LoggerFactory
import ch.qos.logback.classic.Logger
import ch.qos.logback.classic.Level
 
Logger logger = LoggerFactory.getLogger(this.getClass())
logger.setLevel(Level.DEBUG)

JSON Logging / Structured Logging

As logging aggregation solutions like Grafana Loki, Logstash, Datadog, Google Cloud Logging and the like are becoming more popular we gradually start supporting structured JSON logging in our applications.

Our applications which support structured logging (effective November 2021) are:

• Sophora Indexing Service
• Sophora Server (basic support only)

Enabling JSON logging

To enable JSON logging, the logging configuration in the logback.xml needs to be configured. If you're using the provided logback.xml files all you have to do is to set an environment variable according to the following table:

If you use a custom logback.xml file you will have to change it to use the LogstashEncoder similar to the following example.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<appender name="jsonConsoleAppender" class="ch.qos.logback.core.ConsoleAppender">
		<encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
	</appender>

	<root level="DEBUG">
		<appender-ref ref="jsonConsoleAppender"/>
	</root>
</configuration>

Structured Logging support in the Sophora Server

Migrating an application's log statements to structured logging includes adding the required libraries to the application's dependencies and then migrating every single log statement in the code to the new format. The structured format ensures that variables in a log statement, such as a Sophora document's IDs, are available as fields in the structured JSON so they are available for easy filtering.

Migrating every log statement is a significant effort. And while it is required to fully embrace structured logging, there are already benefits in just enabling JSON logs now as some default JSON fields are already populated in the log statements and already improve filtering of messages. Currently the Sophora Server is not fully migrated to structured logging but allows to enable basic JSON logs.