Logging in Mule

I don't like wrapping well stablished frameworks to add little to no functionality. It does not sound right.

Creating wrappers around log4j is the most common example of this awful practice. It is just a dragging thing that we should all avoid. My point is: if it is simple and it works, just live it alone. After all, the best code you can ever write is the code you did not write!

So, most of my Mule applications rely solely on bare Log4j for logging.

The below is a collection of some of the best log4j practices I have been using for awhile in my Mulesoft applications.

One log file per application

Each application logs to its own log files.
That is, only the errors thrown by a application are allowed to be written on the main mule console or default log files. Everything else is on the application log file.

Therefore, each application have its own appender and logger:

...
    <Appenders>
        <RollingFile name="file" fileName="${sys:mule.home}${sys:file.separator}logs${sys:file.separator}${app_name}.log"
            filePattern="${sys:mule.home}${sys:file.separator}logs${sys:file.separator}${app_name}-%i.log">
            <PatternLayout pattern="%d %-5p - %m%X{eaiRecordDescriptor}%n"/>
            <SizeBasedTriggeringPolicy size="20 MB"/>
            <DefaultRolloverStrategy max="10"/>
        </RollingFile>
    </Appenders>
...
    <AsyncLogger name="${app_name}" level="TRACE" additivity="${sys:additivity:-true}">
        <AppenderRef ref="file"/>
     </AsyncLogger>
...

Log Additivity

In Test, QA and PROD (really, any non local developer machine) we start mule with -Dadditivity=false to prevent application specific logging into the general/default mule log. As you can see below, we want to writes logs to your anypoint studio console, so we keep the default additivity = true here:

   <Properties>
        ....
        <Property name="additivity">true</Property>
   </Properties>
    ...
   <AsyncLogger name="${app_name}" level="TRACE" additivity="${sys:additivity:-true}" />

Log Category

The log category is the full name of the application.

<logger category="myMuleApplication" level="INFO" message="#['Starting batch process']" doc:name="Logs start batch"/>

If extra categories are necessary, then they should be children of the full application category:

<logger category="myMuleAppName.javaSerializer" level="TRACE"
message="#['serialized byte '+thisByte]" doc:name="Logs each byte serialized"/>

Log Levels

I use DEBUG to print stuff that makes sense for developers.

INFO for messages that QA and Support can understand themselves without asking to developers. Usually things like  logging the boundaries of the system (Starting Batch, sending message to queue, receiving request from client, etc...") are good examples of using INFO level.

I use TRACE for those really annoying verbose messages. Payloads printouts must be in TRACE. If the Payload is too big, you might consider to substring it before logging, but keep in mind that almost every time the payload is very important and should not be cropped. Therefore, substring a payload must be discussed with the team before you go forward and substring it.

WARNING is to log alerts usually for Business rules violations or system wide issues. Examples: "Records was skipped because did not have ID", "Going to retry this batch after 30 seconds", "Out Of Space". etc...

I use ERROR  level for exceptions only.

The patternLayout

 <PatternLayout pattern="%d %-5p - %m%X{eaiRecordDescriptor}%n"/>

2 Important things there:

• I do not print the thread name (%t) in the application specific log file.

• I populate the log4j MDC Map for eaiRecordDescriptor with some value that helps to understand what is the current record that is been dealt with. e.g. "Batch # 1/2", "Order Id 123223"

In order to print the record descriptor on the logs of the application, the developer must set the eaiRecordDescriptor entry into the Log4j context. This can be done using a script:

<scripting:component doc:name="sets eai Record Descriptor">
    <scripting:script engine="Groovy"><![CDATA[
      org.apache.log4j.MDC.put('eaiRecordDescriptor','Order Id '+123);]]>
    </scripting:script>
</scripting:component>

Logging the payload

I log the payload in TRACE level before and after each external endpoint call.
I know, it is too much! But necessary.

<logger category="myMuleApplication" level="TRACE"
message="#['Payload before '+eaiAction+':'+payload]" doc:name="Logs payload before endpoint call"/>

I do not transform the payload from  to a string just for the sake of getting a better view/understanding of the payload, unless there is a requirement or some discussion that approves it.

So if you do not need to know what is inside but want to see that your endpoint call worked, it is ok to print:

Payload after CMS Add account endpoint:org.glassfish.grizzly.utils.BufferInputStream@1872d578

You really do not want to bring the whole object to memory JUST to get a pretty log message. Must be more than that.

This is a complete log4j.xml for your reference. Just change the app_name and enjoy it:
And you, how do you use Log4j in Mule?