Logging in Mule
Mule Runtime Engine versions 3.5, 3.6, and 3.7 reached End of Life on or before January 25, 2020. For more information, contact your Customer Success Manager to determine how you can migrate to the latest Mule version. |
You can configure what gets logged, where it gets logged, and how by editing a configuration file that sits in your project.
Mule logs multiple messages and specific elements in your applications' flows, in order to help you debug and keep track of events. You can also include the <logger>
Element anywhere in a flow and set it up to output any message you want. By creating a configuration file, you can define what kinds of messages are logged, in what way (asynchronously or synchronously), and where they get logged (e.g. to the console, to disk, to an endpoint or to a database).
For logging, Mule ESB uses slf4j, which is a logging facade that discovers and uses a logging strategy from the classpath, such as log4j2 or the JDK Logger. By default, Mule includes log4j2, which is configured with a file called log4j2.xml
.
The Mule server has a log4j2.xml
in its conf
directory, which you can customize when running the server in standalone mode. Additionally, all the examples included with Mule have log4j2.xml
files in their conf
directories.
Synchronous vs Asynchronous Logging
By default, Mule logs messages asynchronously as from version 3.6.0. |
When logging synchronously, the execution of the thread that is processing your message is interrupted to wait for the log message to be fully handled before it can continue:
When logging asynchronously, the logging operation occurs in a separate thread, so the actual processing of your message won’t be delayed to wait for the logging to complete:
For most cases, it’s recommended that you use asynchronous logging, as it brings a substantial improvement in throughput and latency of message processing.
On the negative side of using asynchronous logging, you may find that after a system crash, some actions were performed but not logged, since log writing is performed on a separate thread that runs independently of other actions. You may also find that on occasion, you can’t avoid the action of logging something in case you need to roll back a transaction. Check the Exception Handling With Asynchronous Logging section below to see how to mitigate these problems.
Application logs may sometimes be required to be used as audit trails. In such cases, you can’t afford to loose any log message and thus you should configure your application to always use synchronous logging.
To appreciate the impact in performance between synchronous and asynchronous logging, consider the test results shown below. We ran performance tests with an application that logs about one million messages, using an increasingly higher amount of threads on each run (these threads were responsible for generating messages; the more threads, the more concurrent messages).
The above chart shows how much latency increased as we added more concurrent messages. Notice that the results of logging asynchronously are significantly closer to those of not logging anything at all. Note that each transaction implied logging 1000 messages.
Configuring Custom Logging Settings
By default, the logging in Mule is done asynchronously and at a level greater than or equal to INFO, and thus discards log messages at the DEBUG or TRACE level.
If you need to use synchronized logging, adjust the logging level or define custom categories, you can configure these properties via the file $MULE_HOME/conf/log4j2.xml
. This file specifies how the logger behaves. Not editing this XML file implies that you use the default properties.
The default config defines the standard loggers exactly as Mule did before the introduction of asynchronous logging. The only difference is that the new config defines all loggers (including the root one) as asynchronous.
You can override this config at the domain or application level. When an application is deployed, Mule looks for a config file following a child-first pattern, as listed below:
-
Look for a file called
log4j2-test.xml
in the application classpath -
Look for a file called
log4j2.xml
in the application classpath -
Look for a file called
log4j2-test.xml
in the domain classpath -
Look for a file called
log4j2.xml
in the domain classpath -
Look for a file called
log4j2-test.xml
inMULE_HOME/conf
-
Look for a file called
log4j2.xml
inMULE_HOME/conf
-
Apply default configuration.
Here’s the default configuration for the log4j2.xml file:
Example log4j2.xml file
<Configuration>
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%-5p %d [%t] %c: %m%n"/>
</Console>
</Appenders>
<Loggers>
<!-- CXF is used heavily by Mule for web services -->
<AsyncLogger name="org.apache.cxf" level="WARN"/>
<!-- Apache Commons tend to make a lot of noise which can clutter the log-->
<AsyncLogger name="org.apache" level="WARN"/>
<!-- Reduce startup noise -->
<AsyncLogger name="org.springframework.beans.factory" level="WARN"/>
<!-- Mule classes -->
<AsyncLogger name="org.mule" level="INFO"/>
<AsyncLogger name="com.mulesoft" level="INFO"/>
<AsyncRoot level="INFO">
<AppenderRef ref="Console"/>
</AsyncRoot>
</Loggers>
</Configuration>
For more information on how to build this configuration file, refer to the log4j 2 configuration guide |
Exception Handling With Asynchronous Logging
If you’re using asynchronous logging and experience a system crash that could have caused incomplete logs, there is an exception handler designed to help you in this situation. By default Mule registers an LMAX ExceptionHandler
that logs any issues dumping log events to disk, to the console and to logs/mule_ee.log
. Alternatively, you can provide your own exception handler by setting the system property AsyncLoggerConfig.ExceptionHandler
to the canonical name of a class implementing the interface.
This is what the default exception handler class looks like:
/*
* Copyright (c) MuleSoft, Inc. All rights reserved. http://www.mulesoft.com
* The software in this package is published under the terms of the CPAL v1.0
* license, a copy of which has been included with this distribution in the
* LICENSE.txt file.
*/
package org.mule.module.launcher.log4j2;
import com.lmax.disruptor.ExceptionHandler;
import org.apache.logging.log4j.status.StatusLogger;
/**
* Implementation of {@link com.lmax.disruptor.ExceptionHandler} to be used
* when async loggers fail to log their messages. It logs this event
* using the {@link org.apache.logging.log4j.status.StatusLogger}
*
* @since 3.6.0
*/
public class AsyncLoggerExceptionHandler implements ExceptionHandler
{
private static final StatusLogger logger = StatusLogger.getLogger();
@Override
public void handleEventException(Throwable ex, long sequence, Object event)
{
logger.error("Failed to asynchronously log message: " + event, ex);
}
@Override
public void handleOnStartException(Throwable ex)
{
logger.error("Failed to start asynchronous logger", ex);
}
@Override
public void handleOnShutdownException(Throwable ex)
{
logger.error("Failed to stop asynchronous logger", ex);
}
}
Unfortunately, this is not a full solution, as ultimately there is a performance-reliability trade-off between asynchronous and synchronous logging. If the risk of loosing these log messages is a serious issue, then you have no choice but to configure your loggers to be synchronous. Notice that you’re not forced to choose between making all logging synchronous or all asynchronous, you can have a mix of both.
log4j to log4j2 Migration
As of Mule runtime 3.6.0, log4j was replaced by log4j2 as the backend tool for managing logging. This implies some backwards compatibility issues as the necessary configuration files in this new framework are different. Log4j2 allows for asynchronous logging, which wasn’t previously available; Mule now implements asynchronous logging by default, as it implies a very substantial improvement in performance. Although Mule has a policy of not breaking backwards compatibility on minor releases, the extent of the improvement in performance brought by this change outweighed any inconveniences by far, and made it worthwhile to implement the change.
Migrated applications from versions of Mule that are older than 3.6.0 but use the default logging settings won’t experience any issues and keeps working as normal (except that logging is asynchronous). For applications that are older than 3.6.0 and do include a custom logging configuration file – both with .xml and .properties extensions – this file won’t be recognized anymore; in these cases, logging is managed according to the default settings.
If you have issues updating your configuration files, please find more information on the log4j 2 configuration guide or contact our support. |
It’s highly encouraged that you implement slf4j as your logging mechanism, as the Mule project is standardized on the use of slf4j 1.7.7 . Nevertheless, other APIs are also supported, and slf4j bridges are included in the Mule distribution to make sure that regardless of the framework you choose, log4j2 ends up handling every log event with a centralized configuration. In such a case, you must make sure not to package any logging library on your applications/extensions to avoid classpath issues between such libraries and the bridge that link to slf4j.
Configuration Reloading
By default, Mule polls modified config files every 60 seconds to check for changes. If any of those files have changed, the logger config are modified on the fly. You can customize this interval by setting the monitorInterval
attribute in the root element (check log4j2 manual for further reference).
Making the HTTP Connector More Verbose
To debug projects that use the new HTTP Connector you may find it useful to make the logging more verbose than usual and track all of the behavior of both the http-listener
and http-request
connectors on your project. To activate this mode, you must make the following addition to your log4j2 configuration file:
<AsyncLogger name="org.glassfish.grizzly" level="DEBUG"/>
<AsyncLogger name="org.asynchttpclient" level="DEBUG"/>
Controlling Logging from JMX
You can expose a manager’s logging configuration over JMX by configuring a log4j2 JMX agent in your Mule configuration file. See JMX Management for more information.
Troubleshooting Logging
I don’t see any logging output
Ensure that the log4j2.xml
file is at the root of your classpath. For more information about configuring log4j2, see Apache’s website.
I reconfigured log4j2, but nothing happened
This happens because there is another log4j2.xml
file on your classpath that is getting picked up before your modified one. To find out which configuration file log4j2 is using, add the following switch when starting Mule (or container startup script if you are embedding Mule):
-M-Dlog4j.debug=true
This parameter writes the log4j2 startup information, including the location of the configuration file being used, to stdout
. You must remove that configuration file before your modified configuration can work.