#6. Mule Logger Component

“Logs are like car insurance. Nobody wants to pay for it, but when something goes wrong everyone wants the best available” Pablo Kraan

Hilarious, but true!

Logging is an essential part of any application development. It includes logging various type of messages such as error messages, status notifications, exceptions, etc. In Mule, a logger can be added anywhere in a flow, and it can be configured to log anything: any string, any Mule expression, or any combination of strings and Mule expressions.

Let’s first create a variable. Open the Anypoint studio(or Eclipse) and then the config xml file. Create a flow and drag a Logger component into it. We’ll take the following setup as an example:

Logger

In the above flow, there is one HTTP connector(a listener), one logger component. Using above flow we’ll learn how to configure the flow in a way that whatever value is given to the logger, will be printed on the console of the IDE.

Double clicking on variable transformer, mule component configuration window will appear:

Loggerconfig1

This is configuration window for the logger component with the following parameters:

Field Value Description XML
Display Name Logger Customize to display a unique name for the logger in your application. doc:name=”Logger”
Message String or Mule expression Specify what Mule should log. By default, messages are logged to the console in Mule Studio.  message=”This is logger Component”
Level Select a level from the listed options:

  • ERROR
  • WARN
  • INFO
  • DEBUG
  • TRACE
Specify the level at which the message should be logged.By default, Mule Studio will not log messages at the DEBUG or TRACE level to the console unless you create and configure a log4j.properties file in classpath likr src/main/resources to lower the log level. level=”ERROR”
Category Optional String Optionally specify a category name and configure it in the log4j.properties file to behave per your use case. For example, you can route log messages based on category or set log levels based on category.

The xml for the component looks like: <logger message="This is logger Component" level="ERROR" doc:name="Logger"/>

After the execution of this flow (i.e. running the server, and hitting the port, on which the http listener is configured, by a web-browser), it will show “This is logger Component” message on the console.
The logger can hold any user defined value like a Boolean, a String, an Integer, or values directly extracted from mule message or payload like #[message.payload] or #[message.inboundProperties.’http.query.params’.configID].

Now, comes the internal working just like we did for the Mule variable transformer.

For Logger Component, it all starts with the method process of LoggerMessageProcessor class. It is used to logs the current element of a value evaluated from it using an expression evaluator.
By default the current messages is logged using the DEBUG level to the ‘org.mule.api.processor.LoggerMessageProcessor’ category. The level and category can both be configured to suit your needs.
LoggerMessageProcessor implements an interface MessageProcessor which is used to Processes Mule Events. Implementations that do not mutate the Mule Event or pass it on to another MessageProcessor should return the Mule Event they receive. Implementation of method is given below:


public MuleEvent process(MuleEvent event) throws MuleException
{
    log(event);
    return event;
}

In this, log(event) gets called. This method fetches log level of the logger and according to that it prints the log. Supported log levels by logger component are:

ERROR
Error is used to log all unhandled exceptions. This is typically logged inside a catch block at the boundary of your application.
WARN
Warning is often used for handled ‘exceptions’ or other important log events. For example, if your application requires a configuration setting but has a default in case the setting is missing, then the warning level could be used to log the missing configuration setting.
INFO
This is default log level of logger component. The Information level is typically used to output information that is useful to the running and management of your system.
DEBUG
Designates fine-grained informational events that are most useful to debug an application.
TRACE
This level gives more detailed information than the DEBUG level and sits on top of the hierarchy.

Implementation of log(event) is given below:


protected void log(MuleEvent event)
{
    if (event == null)
    {
        logWithLevel(null);
    }
    else
    {
        if (StringUtils.isEmpty(message))
        {
            logWithLevel(event.getMessage());
        }
        else
        {
            LogLevel logLevel = LogLevel.valueOf(level); // fetch log level and in above example log level is error
            if (LogLevel.valueOf(level).isEnabled(logger))
            {
                logLevel.log(logger, expressionManager.parse(message, event));// goes to error level logging
            }
        }
    }
}

Implementation for log level is given below:


public enum LogLevel
{
    ERROR
    {
        @Override
        public void log(Log logger, Object object)
        {
            logger.error(object);
        }

        @Override
        public boolean isEnabled(Log logger)
        {
            return logger.isErrorEnabled();
        }
    },
    WARN
    {
        @Override
        public void log(Log logger, Object object)
        {
            logger.warn(object);
        }

        @Override
        public boolean isEnabled(Log logger)
        {
            return logger.isWarnEnabled();
        }
    },
    INFO
    {
        @Override
        public void log(Log logger, Object object)
        {
            logger.info(object);
        }

        @Override
        public boolean isEnabled(Log logger)
        {
            return logger.isInfoEnabled();
        }
    },
    DEBUG
    {
        @Override
        public void log(Log logger, Object object)
        {
            logger.debug(object);
        }

        @Override
        public boolean isEnabled(Log logger)
        {
            return logger.isDebugEnabled();
        }
    },
    TRACE
    {
        @Override
        public void log(Log logger, Object object)
        {
            logger.trace(object);
        }

        @Override
        public boolean isEnabled(Log logger)
        {
            return logger.isTraceEnabled();
        }
    };

In this, error(Object) method gets invoked of  SLF4JLocationAwareLog class. This method Converts the input parameter to String and then delegates to the wrapped org.slf4j.Logger instance. Implementation of the method is given below:


public void error(Object message)
{
    logger.log(null, FQCN, 40, String.valueOf(message), null, null);
}

In this, log method gets invoked. Implementation is given below:


 public void log(org.slf4j.Marker marker, String fqcn, int level, String message, Object[] params, Throwable throwable)
{
    Level log4jLevel = getLevel(level);
    org.apache.logging.log4j.Marker log4jMarker = getMarker(marker);
    if (!logger.isEnabled(log4jLevel, log4jMarker, message, params))
        return;
    Message msg;
    Message msg;
    if ((eventLogger) && (marker != null) && (marker.contains(EVENT_MARKER)) && (converter != null)) {
    msg = converter.convertEvent(message, params, throwable); } else { Message msg;
        if (params == null) {
            msg = new SimpleMessage(message);
        } else {
            msg = new ParameterizedMessage(message, params, throwable);
            if (throwable != null)
                throwable = msg.getThrowable();
        } }
        logger.logMessage(fqcn, log4jLevel, log4jMarker, msg, throwable);
    }
}

Now, the logMessage gets invoked of ExtendedLogger interface and implementation class is Logger. The implementation of the method is given below:


public void logMessage(String fqcn, Level level, Marker marker, Message message, Throwable t)
{
    Message msg = message == null ? new SimpleMessage("") : message;
    config.config.getConfigurationMonitor().checkConfiguration();
    config.loggerConfig.log(getName(), fqcn, marker, level, msg, t);
}

It again calls log method of LoggerConfig class.

public void log(String loggerName, String fqcn, Marker marker, Level level, Message data, Throwable t)
{
    List props = null;
    if (properties != null) {
        props = new ArrayList(properties.size());

        for (Map.Entry<Property, Boolean> entry : properties.entrySet()) {
            Property prop = (Property)entry.getKey();
            String value = ((Boolean)entry.getValue()).booleanValue() ? config.getStrSubstitutor().replace(prop.getValue()) : prop.getValue();

            props.add(Property.createProperty(prop.getName(), value));
        }
    }
    LogEvent event = logEventFactory.createEvent(loggerName, marker, fqcn, level, data, props, t);
    log(event);
}

It again calls log(event) of the same class i.e. LoggerConfig Implementation is as below:

public void log(LogEvent event)
{
    counter.incrementAndGet();
    try {
        if (isFiltered(event)) {
            return;
        }

        event.setIncludeLocation(isIncludeLocation());
        callAppenders(event); // call this method to append log into the log file or console according to their level

        if ((additive) && (parent != null)) {
            parent.log(event);
        }
    } finally {
        if (counter.decrementAndGet() == 0) {
            shutdownLock.lock();
            try {
                if (shutdown.get()) {
                    noLogEvents.signalAll();
                }
            } finally {
                shutdownLock.unlock();
            }
        }
    }
}
 

In this, callAppenders(event) method gets invoked of AppenderControl class. Implementation is given below:

protected void callAppenders(LogEvent event) {
    for (AppenderControl control : appenders.values()) {
        control.callAppender(event); // call method of AppenderControl which finally call append method and print the content in the logger.
    }
}

Implementation of callAppender is as below:

public void callAppender(LogEvent event)
{
    if (getFilter() != null) {
        Filter.Result r = getFilter().filter(event);
        if (r == Filter.Result.DENY) {
            return;
        }
    }
    if ((level != null) && (intLevel < event.getLevel().intLevel())) {
        return;
    }
    if (recursive.get() != null) {
        appender.getHandler().error("Recursive call to appender " + appender.getName());
        return;
    }
    try {
        recursive.set(this);

        if (!appender.isStarted()) {
            appender.getHandler().error("Attempted to append to non-started appender " + appender.getName());

            if (!appender.ignoreExceptions()) {
                throw new AppenderLoggingException("Attempted to append to non-started appender " + appender.getName());
            }
        }

        if (((appender instanceof Filterable)) && (((Filterable)appender).isFiltered(event))) {
            return;
        }
        try
        {
            appender.append(event);// call append method of the class org.apache.logging.log4j.core.appender.RandomAccessFileAppender
        } catch (RuntimeException ex) {
            appender.getHandler().error("An exception occurred processing Appender " + appender.getName(), ex);
            if (!appender.ignoreExceptions()) {
                throw ex;
            }
        } catch (Exception ex) {
            appender.getHandler().error("An exception occurred processing Appender " + appender.getName(), ex);
            if (!appender.ignoreExceptions()) {
                throw new AppenderLoggingException(ex);
            }
        }
    } finally {
        recursive.set(null);
    }
}
public void append(LogEvent event)
{
    ((RandomAccessFileManager)getManager()).setEndOfBatch(event.isEndOfBatch());
    super.append(event);
}

In this append(event) method of RandomAccessFileAppender gets invoked which actually is responsible for writing logger content on the console.

 public void append(LogEvent event)
{
    readLock.lock();
    try {
        byte[] bytes = getLayout().toByteArray(event);
        if (bytes.length > 0) {
            manager.write(bytes); // it writes content onto the console.
            if ((immediateFlush) || (event.isEndOfBatch())) {
                manager.flush();
            }
        }
    } catch (AppenderLoggingException ex) {
        error("Unable to write to stream " + manager.getName() + " for appender " + getName());
            throw ex;
    } finally {
        readLock.unlock();
    }
}

After this method, it returns message to the class from where it was invoked and this is all how Mule logging works. Stay tuned for next posts. Tame The Mule

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s