Tracing messages using end-to-end logging in Mule 3

When you need to analyze an issue in Mule, it can be very useful to have an identifier to correlate the log entries. In this blog post, I will describe how we achieved this in Mule.

An important note is that we are using Mule 3. In Mule 4 various things have changes. For example, it’s easier to add target variables to Connectors, without having to wrap them inside a Message Enricher. So if you are using Mule 4, you probably want to consider using this feature.

The default message.correlationId

By default, Mule has a correlationId property available within the Mule message. At the start of the search of solutions, this (obviously) looked like a pretty good solution for storing correlation data. However, during the research we found some issues with this property.

One of the biggest benefits of this property, is that it is available by default within the Mule message variable. Also, when another Mule flow is called via an outbound HTTP Transport Barrier, the correlationId will be preserved.

When the Mule flow reaches an outbound HTTP Transport Barrier, the correlationId will be passed via the MULE_CORRELATION_ID HTTP header. On the other side, the inbound HTTP Transport Barrier will also automatically put the MULE_CORRELATION_ID (back) in the correlationId of the message. Sounds perfect for what we want to achieve, doesn’t it? Well, that was also what we thought. Until we reached the first outbound HTTP Transport Barrier that directed to an external webservice instead of another Mule flow. This external webservice obviously doesn’t return the MULE_CORRELATION_ID header in the response, which unfortunately causes the behavior that the message.correlationId is set to null.

To test the above, I have created 2 simple Mule flows. The example flow is the entry point. This flow contains 2 outbound HTTP Transport Barriers. The first one points to another Mule flow. The second one points to an external webservice. In this case, this is the Google search page.

The Init correlation ID steps both contain the following Groovy script to set the correlationId to the message unique ID if it’s not set before. The reason why we also include the return payload, is that the payload is overwritten by the outcome of the Groovy script. So without the return statement, the message payload would be overwritten with the correlationId.

message.correlationId = (message.correlationId != null ? message.correlationId : message.id);
return payload;

The reason we do this in a Groovy script instead of an Expression, is that the message variable within an Expression is represented by an org.mule.el.context.MessageContext object. This class unfortunately only contains a getter for the correlationId. Within a Groovy script, the message variable is represented by an  org.mule.api.MuleMessage object, which contains both a getter and a setter for the correlationId property.

Executing the example flow, will result in the following log messages:

INFO  2018-10-15 18:20:13,081 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 1:
messageId=4fadcef0-d097-11e8-88cf-34f39ac37765, 
correlationId=4fadcef0-d097-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:20:13,097 [[mule-trace-
example].HTTP_Listener_Configuration.worker.02] 
org.mule.api.processor.LoggerMessageProcessor: OtherFlow - 1: 
messageId=4fb6f6b0-d097-11e8-88cf-34f39ac37765, 
correlationId=4fadcef0-d097-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:20:13,106 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 2: 
messageId=4fadcef0-d097-11e8-88cf-34f39ac37765, 
correlationId=4fadcef0-d097-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:20:13,276 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 3: 
messageId=4fadcef0-d097-11e8-88cf-34f39ac37765, correlationId=null

As you can see, the correlationId is lost right after the HTTP to Google step. A solution for this, which is mentioned on multiple blog or forum posts, is to wrap the outbound Transport Barriers in a Message Enricher or Async component. Both result to the following log messages:

INFO  2018-10-15 18:21:48,770 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 1:
 messageId=6a6fbe20-d096-11e8-88cf-34f39ac37765, 
correlationId=6a6fbe20-d096-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:21:48,858 [[mule-trace-
example].HTTP_Listener_Configuration.worker.02] 
org.mule.api.processor.LoggerMessageProcessor: OtherFlow - 1: 
messageId=6ab070a0-d096-11e8-88cf-34f39ac37765, 
correlationId=6a6fbe20-d096-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:21:48,881 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 2: 
messageId=6a6fbe20-d096-11e8-88cf-34f39ac37765, 
correlationId=6a6fbe20-d096-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:21:49,088 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 3: 
messageId=6a6fbe20-d096-11e8-88cf-34f39ac37765, 
correlationId=6a6fbe20-d096-11e8-88cf-34f39ac37765

Even though using an Async or Message Enricher is a solution for preserving the correlationId, this would mean that in our case we had to refactor a lot of existing flows, which was also not very desirable.

What about using a sessionVar?

The next idea we had, was to use a sessionVar to track the correlation ID. However, when testing this in a flow, we noticed that the sessionVar was not propagated when crossing an HTTP Transport Barrier to another Mule flow.

When we have a look at the MuleSoft documentation, we can read that this is as designed: “Session variables can be easily propagated from one flow to another through the VM transport, or a flow reference, but not through the HTTP Connector.”

Also, sessionVars are removed in Mule 4, so this is probably not the way to go.

Using a custom flowVar

The next option was using a custom flowVar. This can be set using the same logic as we were using earlier (so by initializing it via the message unique ID. The main disadvantage of this approach, is that when crossing Transport Barriers, this flowVar is not automatically preserved, which requires extra steps to manually add (and use) these headers:

In the above example, the Init trace ID steps set a flowVar named traceId using the below expression. As you can see, additional to the logic we used earlier for the correlationId, we also check for the a value of the TRACE_ID_HEADER header. The same header will be set in the Copy trace ID to HTTP headers step prior to calling the otherFlow.

#[message.inboundProperties['trace_id_header'] != null ? 
message.inboundProperties['trace_id_header'] : message.id]

The above example will lead to the following log entries.

INFO  2018-10-15 18:21:55,162 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 1: 
messageId=6e7010b0-d096-11e8-88cf-34f39ac37765, traceId=6e7010b0-
d096-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:21:55,170 [[mule-trace-
example].HTTP_Listener_Configuration.worker.02] 
org.mule.api.processor.LoggerMessageProcessor: OtherFlow - 1:
messageId=6e75b600-d096-11e8-88cf-34f39ac37765, traceId=6e7010b0-
d096-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:21:55,178 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 2: 
messageId=6e7010b0-d096-11e8-88cf-34f39ac37765, traceId=6e7010b0-
d096-11e8-88cf-34f39ac37765

INFO  2018-10-15 18:21:55,297 [[mule-trace-
example].HTTP_Listener_Configuration.worker.01] 
org.mule.api.processor.LoggerMessageProcessor: Example - 3: 
messageId=6e7010b0-d096-11e8-88cf-34f39ac37765, traceId=6e7010b0-
d096-11e8-88cf-34f39ac37765

As you can see, the traceId is available from the start to the end of the flow now.

Wrapping it up in a custom connector

To prevent that a lot of flows should contain duplicate code and increase maintainability in case we want to add extra trace data later, we decided to write a custom Mule connector, which can be used for these steps. The source of this custom connector is available via Bitbucket.

If you clone the source from Bitbucket and open the project in Anypoint Studio via File > Import… >  Anypoint Connector Project from External Location (this requires the Anypoint DevKit Plugin to be installed), you should be able to build it by right clicking the project > Anypoint Connector > Install or update.

Now, if you search for Trace in the Mule Palette, you should be able to drag the custom connector to the flow. This Trace component contains 3 operations:

• Initialize trace ID
  This operation replaces the Init trace ID steps from the custom flowVar setup. It is possible to force a default trace ID via the optional Default Trace Id parameter.

• Initialize trace outbound properties
  This operation replaces the Copy trace ID to HTTP headers step from the custom flowVar setup.

• Log message with trace data
  This operation “replaces” the Log steps from the previous setups. This method will automatically print the message unique ID and the trace ID with the actual message. Besides the log message, you can optionally specify the severity level, log phase and meta data.

Now, the result will look a little bit different, but it still contains the same information:

INFO  2018-10-15 18:22:02,874 [[mule-trace-example].HTTP_Listener_Configuration.worker.01] nl.whitehorses.mule.trace.TraceConnector: {
        "messageId": "73013190-d096-11e8-88cf-34f39ac37765",
        "traceId": "73013190-d096-11e8-88cf-34f39ac37765",
        "flow": "mule-connector-example",
        "phase": "START",
        "metaData": {
                "serial": "dummy1234"
        },
        "message": "Example - 1"
}

INFO  2018-10-15 18:22:02,884 [[mule-trace-example].HTTP_Listener_Configuration.worker.02] nl.whitehorses.mule.trace.TraceConnector: {
        "messageId": "730e9f10-d096-11e8-88cf-34f39ac37765",
        "traceId": "73013190-d096-11e8-88cf-34f39ac37765",
        "flow": "mule-connector-otherFlow",
        "phase": "START",
        "message": "OtherFlow - 1"
}

INFO  2018-10-15 18:22:02,887 [[mule-trace-example].HTTP_Listener_Configuration.worker.01] nl.whitehorses.mule.trace.TraceConnector: {
        "messageId": "73013190-d096-11e8-88cf-34f39ac37765",
        "traceId": "73013190-d096-11e8-88cf-34f39ac37765",
        "flow": "mule-connector-example",
        "phase": "AFTER_TRANSPORT",
        "message": "Example - 2"
}

INFO  2018-10-15 18:22:03,010 [[mule-trace-example].HTTP_Listener_Configuration.worker.01] nl.whitehorses.mule.trace.TraceConnector: {
        "messageId": "73013190-d096-11e8-88cf-34f39ac37765",
        "traceId": "73013190-d096-11e8-88cf-34f39ac37765",
        "flow": "mule-connector-example",
        "phase": "END",
        "message": "Example - 3"
}

Conclusion

Even though Mule has a correlationId variable wrapped in the Mule message, this might not be a sufficient solution in every case. Using a sessionVar won’t work as well, because sessionVars will not be propagated when crossing HTTP Transport Barriers.

Another solution is to create your own flowVar for tracing purposes. The biggest disadvantage of this approach is that you’ll need to implement a mechanism to pass the trace data over Transport Barriers as well.

We have chosen to implement the flowVar solution, but implemented the required logic in a custom Mule connector to prevent unnecessary duplicate code and for better maintainability.

In case you want to try the examples from this blog yourself, you can download the example flows here.