-
Notifications
You must be signed in to change notification settings - Fork 683
[3.6 M2] Asynchronous Logging
- Jira: https://www.mulesoft.org/jira/browse/MULE-7769
- Forum discussion: http://forum.mulesoft.org/mulesoft/topics/_3_6_m2_asynchronous_logging
"Logs are like car insurance. Nobody wants to pay for it, but when something goes wrong everyone wants the best available" - Pablo Kraan
The phrase above fully explains why logs are important and why we need to be able to log as much information as possible but without impacting performance. Because logging implies writing to disk, it's a naturally slow operation.
Because Mule is an application container, logging also has additional requirements:
- Log separation: each application/domain needs to keep its own log file
- Each application/domain needs to be able to specify its own logging config.
- If an app/domain doesn't provide a config, a default one needs to be applied
- The performance cost of logging should be minimum
To meet all of these requirements we're going to be migrating our log infrastructure to log4j 2.0 since this framework provides:
- Fastest asynchronous logging capabilities we could find. Because it uses the LMAX Disruptor library, it greatly outperforms other traditional asynchronous loggers such as the ones provided by Logback.
- Ability to specify synchronous loggers
- Extensibility to implement Mule's logging logic
- Highly active development effort
- Responsive community
- As a developer, I want to use mule OOTB with a fast logging setup
- As a developer, I want to be able to configure synchronous loggers for the cases in which logs have a business value
- As a developer, I want to be able to specify a logging configuration at an application or domain level
- As a developer, I want log files and context for different applications/domain to be separated
Mule won't be a user of Log4j2, it will be an implementation of it. It will provide its own implementation of:
- The LoggerContextFactory
- The ContextSelector
- The LoggerContext
That means that some of the log4j2 default behaviour is kept but some is slightly changed
Log4j2 supports configuration through XML, Json and YAML files. We're only going to be supporting XML files. This is because Json and YAML support are built using a version of the Jackson library which is not compatible with the one that is already bundled into Mule. Since upgrading would represent a backwards compatibility issue, for now we're only sticking to the XML version of it which is by far the most popular as far as our user base tells us.
When an application is deployed, Mule will look for a config following a child first pattern like this:
- Look for a file called log4j2-test.xml in the application directory
- Look for a file called log4j2.xml in the application directory
- Look for a file called log4j2-test.xml in the domain directory
- Look for a file called log4j2.xml in the domain directory
- Look for a file called log4j2-test.xml in MULE_HOME/conf
- Look for a file called log4j2.xml in MULE_HOME/conf
- Apply default configuration.
The default config resides at MULE_HOME/conf/log4j2.xml. That default config defines the standard loggers in exactly the same way as Mule has until the 3.6 release. Only difference is that according to this config, all loggers (including the root one) are asynchronous. You can override this config at a domain or application.
The default configuration is one with just one single RollingFileAppender and a root logger at INFO level. They will not log to console
The disadvantage of asynchronous logging is error handling. There're two situations to account for:
- In a synchronous logging schema, if the logger fails to write to disk, the exception would raise on the same thread that's currently processing the mule event. If logging is critical for you, then you can rollback the transaction. In asynchronous logging, the thread doing the processing won't be aware of any issues writing to the disk, so you won't be able to rollback anything.
- Because the actual writing of the log gets differed, there's a chance that log messages might never make it to disk if mule were to crash before the buffers are flushed.
To mitigate this issues, we're providing the following mechanisms.
- ExceptionHandler. By default, mule will register an LMAX ExceptionHandler that will log to the console and to logs/mule_ee.log any issues dumping log events to disk. This is the simplest approach possible that would at least let you know that something is wrong. You can provide your own exception handler by setting the system property 'AsyncLoggerConfig.ExceptionHandler' to the canonical name of a class implementing the interface.
- Unfortunately this is simply part of the performance-reliability trade-off. If this is an issue for you, then you have no choice but to configure your loggers to be synchronous. Notice that you're not forced to choose between all synchronous or all asynchronous. You can have a mix.
By default, Mule will poll modified config files every 60 seconds to check for changes. If any of those files indeed changed, the logger config will be modified on the fly. You can customize this interval by setting the monitorInterval attribute in the root element (check log4j2 manual for further reference)
For testing purposes, sometimes it's useful to disable log separation and send all the output to only one logging context. If that's your case, you can do it by setting the system property 'mule.simpleLog' to 'true'
Because of its limited resources, the edge distribution ships with a different default configuration in which all loggers are synchronous
For a complete reference on Log4j2 configuration please visit http://logging.apache.org/log4j/2.x/manual/configuration.html
Just as an example, here's how the default mule configuration looks like:
<?xml version="1.0" encoding="UTF-8"?>
<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>This configuration not only sets the default loggers as asynchronous, it also provides an asynchronous root logger to guarantee that any additional logger requested from the code is also asynchronous.
You can replace the with simply to have a synchronous root logger and/or replace with for synchronous loggers. Any combination is valid.
Log4j 1.2 allowed configuration through properties files and XML. The XML schema is changed now and the properties format is no longer supported.
Applications with a XML configuration will need to update it. Luckily the schema is pretty similar. For applications using a log4j.properties file, they will need to migrate to XML format. We talked to the log4j2 team asking if they were planning to add support for it and they said that although they don't discard it, they tried and it's very difficult since configuration is now hierarchical and the properties DTD doesn't really support that.
We are also considering adding that support ourselves in Mule, but given the experience from the log4j2 team we're not leaning towards that right now.
The mule project has standarized on the use of slf4j 1.7.7 as a logging mechanism for every new feature. However, we still have a lot of legacy code using a mix of jul, apache commons logging and log4j1.2. Additionally, applications might be using cloud connectors or custom made components which also show this mixture.
Although we highly encourage any user to migrate to slf4j as a the facto logging mechanism for mule applications, we're still going to support that case. Slf4j bridges are included in the mule distribution to make sure that regardless of the framework of your choice, log4j2 ends up handling every log event with a centralised configuration.
However, we do leave it up to the user to make sure not to package any logging library on their applications/extensions to avoid classpath issues between such libraries and our bridges.
Log messages loss due to bad configuration
No impact
No impact
No impact
CloudHub will need to rework its log appender. Additionally, CH also allows to specify logging categories through the console admin. The backend for that will probably also need upgrading and to consider the possibility of also specifying if the added category is sync or async
No impact
Existing applications with custom logging config will need to upgrade their config files.
- Update docs reflecting this new feature
- Update training documents