Skip to main content

Logging

The Flowable products and custom projects using the Flowable Spring Boot starters are all based on Spring Boot. Thus, when it comes to logging, all online documentation for Spring Boot related to logging applies.

For example, to log to a file instead of terminal output, assuming an application.properties configuration file (or equivalent):

logging.file=flowable-work.log

Or, in case you are interested to get DEBUG logging for specific packages:

logging.level.com.flowable=DEBUG
logging.level.org.springframework.boot.web.servlet.filter=INFO

See the Spring Boot documentation for advanced configuration options.

Log current tenant and current user​

v3.15.0+

Flowable provides custom logging mechanism for Logback and Log4J 2 for logging the current tenant and / or the current authenticated user in the log message. This is done by using a Logback custom conversion specifier or a Log4J 2 custom pattern converter. Depending on which logging framework you are using the configuration varies.

note

This is available only for Flowable Work

Logback​

This is the default logging framework from Spring Boot and the default one for the Flowable out-of-the-box applications. In order for you to be able to use this you'll have to write a custom logback.xml and register the Flowable converters.

An example logback.xml looks like:

<?xml version="1.0" encoding="UTF-8"?>

<included>
    <conversionRule conversionWord="tenant" converterClass="com.flowable.platform.common.logging.logback.TenantConverter" />
    <conversionRule conversionWord="authenticatedUser" converterClass="com.flowable.platform.common.logging.logback.AuthenticatedUserConverter" />
    <property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15tenant - %15.15authenticatedUser]){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
    <property name="FILE_LOG_PATTERN" value="${FILE_LOG_PATTERN:-%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSSXXX}} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%tenant] [%authenticatedUser] [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/spring.log}"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    <!-- Add the file appender if you want to use file logging as well -->
    <include resource="org/springframework/boot/logging/logback/file-appender.xml" />
    <root level="INFO">
        <appender-ref ref="CONSOLE" />
        <!-- Add the file appender if you want to use file logging as well -->
        <appender-ref ref="FILE" />
    </root>
</included>

The CONSOLE_LOG_PATTERN and FILE_LOG_PATTERN are the ones provided by Spring Boot from their defaults.xml file with the difference being adding the %clr([%15.15tenant]){faint} %clr([%15.15authenticatedUser]){faint} for the console and [%tenant] [%authenticatedUser] for the file log patterns

When there is no tenant or user then <missing> will be outputted in the logs. When the user is in the empty tenant then <empty> will be outputted in the logs.

Log4J 2​

In order to configure Log4J 2 the only thing you need to do is to configure the logging.pattern.console and logging.pattern.file properties appropriately. The tenant and authenticatedUser converters are automatically registered when using Log4J 2. The properties are the ones provided by Spring Boot with the difference being adding the %clr{[%15.15tenant]}{faint} %clr{[%15.15authenticatedUser]}{faint} for the console and [%tenant] [%authenticatedUser] for the file log pattern.

The properties look like:

logging.pattern.console=%clr{%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}{faint} %clr{%p} %clr{%pid}{magenta} %clr{---}{faint} %clr{[%15.15tenant]}{faint} %clr{[%15.15authenticatedUser]}{faint} %clr{[%15.15t]}{faint} %clr{%-40.40c{1.}}{cyan} %clr{:}{faint} %m%n%wEx
logging.pattern.file=%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %5p %pid --- [%tenant] [%authenticatedUser] [%t] %-40.40logger{39} : %m%n%wEx

When there is no tenant or user then <missing> will be outputted in the logs. When the user is in the empty tenant then <empty> will be outputted in the logs.

FlowableOptimisticLockingException​

In the logs there sometimes will be lines mentioning that Flowable encountered an 'optimistic locking exception'. This sounds scary on a first glimpse, but is actually a signal of a normal functioning system.

Flowable uses optimistic locking to avoid that two or more competing updates in different transactions would change the same data. A transaction could for example be caused by two or more users clicking simulatenously on a user task form, or it could be caused by two or more events from an external system coming in, etc.

As processing the transaction in the database takes time, there's a window of overlap. To avoid data corruption, Flowable will use a 'revision' field when the data is fetched, which is then included in update and delete statements, if applicable. This revision value is automatically incremented for each update or delete statement and used in the SQL where clause. When the transaction then commits, this will either go through (= no concurrent collision) or it won't (= another transaction was faster).

Let's assume that in the example below, transaction TX 1 and TX 2 are concurrent and they also concurrently commit.

TX 1: select * from entity; --> [rev = 1, ...]
TX 2: select * from entity; --> [rev = 1, ...]

// Work happens

TX 1 commits: update entity set rev = 2, ... where rev = 1;
TX 2 commits: update entity set rev = 2, ... where rev = 1;

Due to the nature of ACID database transactions, only one update statement will go through. If one of them returns with 0 results, it means that two or more transactions tried to change the same data. One transaction 'loses' and Flowable automatically throws an exception, causing the transaction to roll back and the data not getting corrupted.

This also means a FlowableOptimisticLockingException is not a bad thing. In fact, it's a sign of the engine making sure there's no collision on your data.

Some examples where this can happen:

  • Two or more users change the same variable in different forms.
  • Two or more events come in, changing the same data.
  • A timer fires, but a user changes a value at the same time.

In these scenarios, without optimistic locking exceptions, the last transaction related to for example the form completion would win and overwrite the value of the other transaction. Both variable values from concurrent transaction are correct and equally valuable - Flowable has no way of knowing which one should be the one that 'wins'. With an optimistic locking exception, the Flowable engines makes sure that at least the first change isn't overwritten automatically in this situation.

In case you are absolutely sure that this is fine, the optimistic locking exception can be caught in a java try-catch and the operation can be retried.