Logging

Blueriq Runtime is a Java Spring Boot application which uses Logback (https://logback.qos.ch/) as a framework for logging. Out of the box, the Runtime logs to STDOUT on INFO level. Reason being is that STDOUT is used by all major cloud providers to inspect container logs.

It is possible to configure logging to a file by setting a JVM parameter logging.file.name. By default, Blueriq uses a size and time based policy so each 10MB and each day the log file will rotate. There are lots of ways to tweak and tune the logging, either by setting some additional properties or overriding the Logback configuration. For more info, please refer to the myBlueriq source.

Log details

The following items are logged by default:

1. Date (yyyy-MM-dd HH:mm:ss.SSS)
2. Log level (e.q. DEBUG, INFO, WARN, ERROR)
3. Log class
4. httpSessionId
5. runtimeSessionId (a single HTTP session holds a map of Runtime sessions)
6. userId (logged in Blueriq user, mapped to system.user.id)
7. projectName (Blueriq project name)
8. projectVersion (Blueriq project version)
9. currentPageName (Blueriq page name)
10. trace (X-B3-TraceId, to provide log correlation across multiple nodes, see Log Correlation)
11. span (X-B3-SpanId, to provide log correlation across multiple nodes, see Log Correlation)
12. Message

The following items are NOT logged by default:

1. tenantName (name of the tenant that is used, see Multi-tenancy). If you use multi-tenancy and if you want to log the tenant name with each log line, you can add tenantName="%X{tenantName}" to the LOG_PATTERN property in your custom logback-spring.xml file.

Example output

2019-04-23 02:45:34.595 INFO    c.a.i.portal.model.session.FlowHandler httpSessionId="FAA05342917D2C3E6775FE3346E83F12" runtimeSessionId="4c2fff20-26c9-4a3e-88c0-8bba58504de9" userId="anonymousUser" projectName="export-AQ_12267_SoapServiceClient_Project2" projectVersion="Trunk" currentPageName="Home" [trace=93e68ee796b28b16,span=93e68ee796b28b16] - [onFlowStart] Starting flow: HandleEvent

Default Logback configuration for Java

By default the following logback-spring.xml file is packaged in the Runtime WAR:

<configuration>

   <!-- Bind Spring environment property to local LogBack property -->
   <springProperty name="logFile" source="logging.file.name"/>

   <!-- Possible log keys: httpSessionId, runtimeSessionId, userName, userId, projectName, projectVersion, currentPageName, tenantName -->
   <property name="LOG_PATTERN"
           value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %40.40logger{40} httpSessionId=&quot;%X{httpSessionId}&quot; runtimeSessionId=&quot;%X{runtimeSessionId}&quot; userId=&quot;%X{userId}&quot; projectName=&quot;%X{projectName}&quot; projectVersion=&quot;%X{projectVersion}&quot; currentPageName=&quot;%X{currentPageName}&quot; [trace=%X{X-B3-TraceId:-},span=%X{X-B3-SpanId:-}] - %msg%n"/>

   <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      <!-- encoders are assigned the type
          ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
      <encoder>
         <pattern>${LOG_PATTERN}</pattern>
      </encoder>
   </appender>

   <if condition='isDefined("logFile")'>
      <then>
         <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <encoder>
               <pattern>${LOG_PATTERN}</pattern>
            </encoder>
            <file>${logFile}</file>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
               <!-- rollover daily -->
               <fileNamePattern>${logFile}-%d.%i.log</fileNamePattern>
               <!-- or whenever the file size reaches 10MB -->
               <maxFileSize>10MB</maxFileSize>
            </rollingPolicy>
         </appender>
      </then>
   </if>

   <!-- Limit the org.springframework category to WARN as its DEBUG is verbose -->
   <logger name="org.springframework" level="WARN"/>

   <!-- Limit the org.apache category to INFO as its DEBUG is verbose -->
   <logger name="org.apache" level="INFO"/>

   <!-- Limit the org.quartz category to INFO as its DEBUG is verbose -->
   <logger name="org.quartz" level="INFO"/>

   <!-- Limit the org.mortbay category to INFO as its DEBUG is verbose -->
   <logger name="org.mortbay" level="INFO"/>

   <!-- Limit the org.hibernate category to INFO as its DEBUG is verbose -->
   <logger name="org.hibernate" level="INFO"/>

   <!-- Limit the tomcat http client communication to INFO as its DEBUG is verbose -->
   <logger name="httpclient.wire" level="INFO"/>

   <root level="INFO">
      <appender-ref ref="STDOUT"/>
      <if condition='isDefined("logFile")'>
         <then>
            <appender-ref ref="FILE"/>
         </then>
      </if>
   </root>
</configuration>


logback-spring.xml can be loaded from a different place by setting a different file name in the logging.config property in application.properties.

# Set this to (let Spring Boot) use a logback-spring.xml that does NOT come from the classpath
logging.config=D:/spring/config/location/logback-spring.xml

Enabling logging to a file

The Runtime by default only logs to the console. To enable logging to a file, you can either add a property to application.properties or set the logging.file.name property as a JVM parameter. Note that an absolute path to the logfile is required.

logging.file.name=D:/temp/runtime.log

-Dlogging.file.name=D:/temp/runtime.log

Preventing Log Injection

To prevent Log Injection attacks, since Blueriq 12.10, you can configure the following in logback-spring.xml:

<configuration>
  <conversionRule conversionWord="crlf" converterClass="org.owasp.security.logging.mask.CRLFConverter" />
  [...]
</configuration>

Additionally, you need to replace the %msg%n part of the LOG_PATTERN with %crlf(%msg) %n. Mind the space between the closing parenthesis and %n. This way, newlines  in log messages are replaced with underscores.

To prevent a second effect of Log Injection, it's prudent to limit the log line length. To do this, replace %msg with %.-500msg. The 500 indicates log lines are limited to 500 characters. You should set this to the length that is appropriate for your use case.

Blueriq recommends to use Log Injection Protection on production environments. By default, Log Injection protection is not enabled.

See here for an example configuration.

If you want to use Log Injection Protection in versions prior to 12.9, you can add a runtime dependency in your pom.xml.

<!-- OWASP Security Logging Logback -->
<dependency>
    <groupId>org.owasp</groupId>
    <artifactId>security-logging-logback</artifactId>
    <version>LATEST</version>
    <scope>runtime</scope>
</dependency>

Limiting the logfile archive

If you want to limit the number of logfiles to be archived, you can do this by setting the <maxHistory> property in the logback-spring.xml that is being used. You can also limit the archive by setting the max capacity of the total archive with the <totalSizeCap>. Both properties should be configured inside the rollingPolicy tag, see https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy for more information.

Log level overrides

If you want to change the log level for the entire application or for certain portions of the application, you can do so in the logback-spring.xml file.

Override the log level for the entire application

In the <root> tag, you can change the level to ERROR, WARN, INFO, DEBUG or TRACE. INFO is the default. For more logging, choose DEBUG or TRACE. For less logging, choose ERROR or WARN.

Override the log level for certain portions

You can change the log level for a portion of the application. First you should identify the package prefix of the portion. You can find it in the log messages. In most use cases, the prefixes com.aquima and com.blueriq will be overridden.

To override a portion, add a line like <logger name="com.blueriq" level="INFO"/> to the logback-spring.xml, as can be seen in the example above. You should configure the log level to suit your needs.

Alternative way of setting log level overrides

Log level overrides can also be set in application.properties:

# Set the root log level to WARN
logging.level.root = WARN


# Set the log level of com.aquima and com.blueriq classes to DEBUG
logging.level.com.blueriq = DEBUG
logging.level.com.aquima = DEBUG

Typically, the log level will be set to DEBUG for development environments and to WARN on production and acceptance environments.

Up to Blueriq 11.8, logging for com.blueriq and com.aquima was set to DEBUG by default. However, this prevented the root logger level to be able to control the level of log verbosity for these portions, which make up a great deal of the Blueriq application. So from Blueriq 11.8 and onward, you should manually enable debug logging. If Blueriq was installed using the installer, however, logging is set to DEBUG for these portions by default.