Logging is handled by Logback. The server automatically loads its logging configuration from any logback.xml file on the classpath. We recommend placing your logback.xml in the configuration directory alongside your sophora.properties file. If needed, you can explicitly specify its location using the JVM option -Dlogback.configurationFile.
Use the following logback.xml as a starting point. In Kubernetes setups, this is pretty much all you need.
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
<jmxConfigurator/>
<property file="${sophora.properties}"/>
<appender name="jsonConsoleAppender" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
</appender>
<logger name="com.subshell.sophora" level="INFO"/>
<logger name="liquibase" level="INFO"/>
<logger name="org.apache.jackrabbit" level="WARN"/>
<logger name="com.subshell.sophora.server.application.manager.impl.LockManager" level="WARN"/>
<logger name="com.subshell.sophora.server.MetricsReporter" level="WARN" />
<logger name="com.subshell.sophora.server.replication.slave.jms.JmsSlave" level="TRACE" />
<logger name="com.subshell.sophora.server.util.Profiler" level="DEBUG" />
<root level="WARN">
<appender-ref ref="jsonConsoleAppender"/>
</root>
</configuration>
Structure Node Logging
To log actions performed on structure nodes, use the following logging configuration. It logs detailed information whenever a structure node is moved or created.
<logger name="com.subshell.sophora.server.application.structure.StructureNodeLogger" level="DEBUG" />
Script Executions
Log Sophora Script executions, including execution times.
<logger name="com.subshell.sophora.server.application.scripting.jmx.ScriptingStatistics" level="DEBUG" />
Document Change Scripts
It uses logger from the IScriptContext.
<logger name="com.subshell.sophora.server.application.scripting.ScriptManager" level="DEBUG" />
Timing Scripts
It uses the logger from the ITimingActionScriptContext.
<logger name="com.subshell.sophora.server.application.timingaction.DocumentTimingActionsJob" level="DEBUG" />
What is the profile log?
The profile log prints every single request to the servers content manager (without payload) including the duration it took to perform the request.
When should I enable the profile log?
Profiling might easily generate a gigabyte of log per day. So you should just activate it if you're about to investigate those log files.
Profile log however helps to track slow requests or figure out which requests are received generally.
How to activate the profile log
The profile log is enabled via the logback.xml file. To generally enable it this single line is sufficient:
<logger name="com.subshell.sophora.server.util.Profiler" level="DEBUG" />
This will make the profile logger append to your root definitions and most likely write to your general log file. If you'd prefer to write your profile log information to a different logfile you might want to write this:
<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</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.server.util.Profiler" 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>
