INTEGRATION USING MULE

Fish Tagging – Message Tracking

Fish Tagging is the process of adding a tag(containing unique number) to a fish inorder to identify the fish. These tags on the fish can provide valuable information about the fish like when/where it was caught, tracking the movement/migration of the fish.

Similar to this, each message received by Mule application can be tagged with a unique num

 

ber which can be used to identify message and analyze the path the message took in different flows of the application.

Why should you tag incoming messages?

 

In integration applications, two most common scenarios are to either pick a message from different system or accept incoming message. Once the message is received, it will then go through transformation/enrichment and is sent to other system(s) and/or service(s). Now imagine this with a multi user / multi threaded environment. While reading application logs, how do you keep track of what path the incoming message took from the time it was received until it was completely processed? From the mule application logs, how do you identify message1 received a response of 500-Server Error while sending to external system while message2 was successful when both were sent at the same exact time?

Tagging a message received at mule application helps a lot in debugging and will give you greater ability to uniquely identify each message processed while looking at the logs. If you are using Log analyzing systems like Splunk, tagging will be useful information while building dashboards.

How do you create a tag?

Tag should be unique identifier of the incoming message. There are lot of ways to generate unique identifier, the easiest would be to just use #[message.id]. Although this uniquely identifies a message, my personal approach would be to use something which is meaningful to the user who is sending the message. For example, if user is requesting customer information via API built on Mule application, meaningful tag would contain the customer number in it along with the unique number. This gives you ability to search in the logs what happened based on customer number. Testers doing user testing involving the Front End application calling Mule API will say – “this is the customer number used when application failed” they may not be able say this is the transaction id used while calling mule API or this is the unique id API returned in response.

Why should you still generate unique number and append to the customer number and why not just use customer number? Using just the customer number will void the ability to identify uniqueness of message received. What if client sends you the same customer number twice at the same second, you will not be able to uniquely identify what happened to both the messages with same customer number.

What information should not be in the tag?

Any data which can be qualified as PII(Personally Identifiable Information) should not be used while building the tag as this will put you out of compliance. In the above example, if customer number will be considered as PII, you shouldn’t be using it. If all you have is PII data coming in, you can add mandatory transaction id header to the API which needs to be sent by the client. It is always better to have this information in the header rather than in body as there may be times where the message body can be in a zip format or encrypted. If you have the information in header, you don’t have to open the message body.

Where should you store the tag information?

Tag information can be stored in a flow variable in the beginning of the flow or you can also set the tag information inside correlation id by setting MULE_CORRELATION_ID property.

Once you have set this, the correlation id can be simply referenced using #[message.correlationId]. One of the down side of using mule correlation id is if you are calling different flows within mule application asynchronously, correlation id is not maintained.

How to log tag information?

To my knowledge two approaches of doing this are –

Approach 1: Manually using the tag while writing any log statements.

In the below screen shot, I am using #[message.id] as unique identifier and prefixing log statements with it

With this approach, every time you use a logger, you have to remember to use #[message.id] in the log message. This may not work all the times as people tend to forget and if a new person is modifying something in your code, they may not add the message.id to the log statements

Approach 2 – Leveraging ThreadContext and PatternLayout in log4j2

In this approach, you will need to insert the tag information into the thread context and specify pattern layout in log4j2 file to use the information inserted in thread context.

Information can be inserted in the thread context by calling a Java component and using below code:

[java] import org.apache.logging.log4j.ThreadContext;
import org.mule.api.MuleEventContext;
import org.mule.api.lifecycle.Callable;

/**
* @Created By: Ruman Khan
*
*/
public class FishTagging implements Callable {

@Override
public Object onCall(MuleEventContext eventContext) throws Exception {
Object transactionId = eventContext.getMessage().getInboundProperty(“transactionid”);
String messageId = eventContext.getMessage().getMessageRootId();
if(ThreadContext.get(“tag”) == null){
//If transactionid is not included in the header use messageId
ThreadContext.put(“tag”, transactionId != null ? transactionId.toString() : messageId );
}
return eventContext.getMessage();
}

}
[/java]

The inserted transaction id can be used in log4j2 file by using %X{tag} in the PatternLayout.

Once this is configured, you no longer have to specify anything while writing log statements and the tag information will be displayed from the threadcontext

When the log statement is written tag is auto added by the log4j2. Sample log statement:

2018-02-17 03:30:06,701 [[messagetracker].HTTP_Listener_Configuration.worker.01] INFO org.mule.api.processor.LoggerMessageProcessor tag=[23eb5330-13c5-11e8-ace8-0a0027000002]– Message Received at Inbound

Caveats for ThreadContext: As the name suggests we are using application’s “current” thread context and adding tag information in it. This means anytime you are using logger in a different thread context, the tag information added in the beginning of the flow will not be available. This can happen while using scatter-gather or calling any flow asynchronously. Also, any statements written by mule inbuilt components (either by enabling DEBUG or exception stacktrace) will not have the tag information as they are written in different thread context. In order to overcome this, you can re-insert the tag information inside the thread being used by the components by configuring and using mule server notifications.

Note on Log4j2 and CloudHub(AnypointPlatform): Approach 2 described above works well if you are deploying the application On-Premises. If you deploy the same application on Mule’s CloudHub, you will no longer see the tag information in the log statements. This is because Mule ignores the log4j2 file in the application and uses its own log4j2 file on CloudHub. Speaking to one of the Mule reps about this, the reasoning I got was, anypoint platform needs the log statements to be in a particular format and it may have issues processing log statements if log4j2 of the application is considered as the log formats can change. However, if you still want anypoint platform to consider the application’s log4j2 file, raise a ticket with Mule to consider log4j2 file in the application. The detailed steps on this can be found at CloudHub Custom Log Appender

References:

FishTagging: http://www.fishtagger.com/faq.php

Log4j2 Thread Context: https://logging.apache.org/log4j/2.x/manual/thread-context.html

Mule Server Notifications: https://docs.mulesoft.com/mule-user-guide/v/3.9/mule-server-notifications

CloudHub Custom Log Appender: https://docs.mulesoft.com/runtime-manager/custom-log-appender