Message IDs and Why You Should Log Them

In any environment where there are lots of messages flying around, there are three critical things you need to know about any particular message:

1. Did it arrive as intended?

   An integration team *constantly* gets the ask, “Did you get my Message?” “Did you send my Message?” There must be traceability to messages and whether they arrived or not, with business information attached in the log, like the Order Number of the message, along with the generated MessageID, so you can search on either.

2. Why did that error occur?

   Messages fail. The question is why? In 99.x% of environments, you can’t log a full message payload to any logger (except at the TRACE or DEBUG level), so you have to have a way of knowing what the payload of the message was that caused the error. (See upcoming post about message auditing) And you also need to know which message caused the error. If you are logging message IDs, then you can easily filter for log lines that contain the message ID and get the entire history of the flow and transformations.

3. Where did the message go next?

   Many systems both upstream and downstream of messaging busses have the capability to take in an ID of some sort and correlate it with logs. So send the Message ID as an Outbound Property and have it in the next system’s logs too.

Message ID Logging

Generating a MessageID and logging it. You do this first thing in a flow after the inbound endpoint.

<set-session-variable variableName="messageID" 
value="#[java.util.UUID.randomUUID().toString()]" />
<logger level="INFO" 
message="Received message with messageID=#[messageID] from queue my_queue"
  category="com.company.myapp.flowname" doc:name="INFO" />

From this point forward, *EVERY LOGGER* has the #[messageID] variable in it. Thus you get traceability, and logging is awesome. Other ideas:

1. Set an outbound property of messageID when you send the message somewhere. This works over most transports like JMS and HTTP. Thus the receiving system can get your messageID.
2. See if whatever system is sending the message can also generate and send you a messageID and use that one instead for traceability backwards. Instead of generating the messageID, you’re using an inboundProperty.
3. Correlate messageID with payloads in a database, so that you can lookup the message payload in a persisted way that’s more secure than a log file. (Upcoming blog post).
4. If you can’t log a message to a database, consider using a separate log file (configured with log4j2.xml) that stores message payloads and messageIDs only. Consider also having it somewhere with better security than the log directory.

Here’s an example where it’s super useful to have messageIDs, first the version without MessageIDs. Notice that there is an error here. Also notice there are two requests, the second request comes in on line 12.

  1  [12-02 11:26:08] INFO  flow1: Got Records 4
  2  [12-02 11:26:08] INFO  Transformer: 
  3  Update Case  to be mapped requestAction=UpdateJIRA, jiraId=STAR-10491 
  4  [12-02 11:26:08] INFO  sfdc-flow: Outbound to SFDC recordId:303487
  5  [12-02 11:26:08] INFO  sfdc-flow: SFDC call success recordId:303487 
  6  [12-02 11:26:08] INFO  update-record: After Update 303487
  7  [12-02 11:26:08] INFO  Transformer: Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=STAR-10496
  8  [12-02 11:26:08] INFO  sfdc-flow: Outbound to SFDC recordId:303488
  9  [12-02 11:26:08] INFO  sfdc-flow: SFDC call success recordId:303488 
 10  [12-02 11:26:08] INFO  update-record: After Update 303488
 11  [12-02 11:26:08] INFO  Transformer: Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=STAR-10491 
 12  [12-02 11:26:08] INFO  sfdc-flow: Outbound to SFDC recordId:303489
 13  [12-02 11:26:08] INFO  flow1: Got Records 2
 14  [12-02 11:26:08] INFO  Transformer: Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=HRCOMP-23681
 15  [12-02 11:26:08] INFO  sfdc-flow: Outbound to SFDC recordId:303491
 16  [12-02 11:26:08] INFO  sfdc-flow: SFDC call success recordId:303489 
 17  [12-02 11:26:08] INFO  update-record: After Update 303489
 18  [12-02 11:26:08] ERROR  Transformer: Update Case ERROR INVALID requestAction. Not mapped
 19  [12-02 11:26:08] INFO  sfdc-flow: SFDC call success recordId:303491 
 20  [12-02 11:26:08] INFO  update-record: After Update 303491
 21  [12-02 11:26:08] INFO  Transformer: Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=PERFCUST-298 
 22  [12-02 11:26:08] INFO  sfdc-flow: Outbound to SFDC recordId:303492
 23  [12-02 11:26:08] INFO  sfdc-flow: SFDC call success recordId:303492 
 24  [12-02 11:26:08] INFO  update-record: After Update 303492

Is the error above part of the first request or the second? It’s probably something you can figure out, but it adds time to support cases. And we are looking for supportability by someone other than an expensive developer.

Now the version with MessageIDs. You’ll notice the Debugging log got a LOT clearer about which message failed. Notice that the next request that came in got a new messageID, and you can easily see what log messages are associated with one request.

  1  [12-02 11:26:08] INFO  flow1: 18a72d84cb3b : Got Records 4
  2  [12-02 11:26:08] INFO  Transformer: 18a72d84cb3b : Update Case  to be mapped requestAction=UpdateJIRA, jiraId=STAR-10491 
  3  [12-02 11:26:08] INFO  sfdc-flow: 18a72d84cb3b : Outbound to SFDC recordId:303487
  4  [12-02 11:26:08] INFO  sfdc-flow: 18a72d84cb3b : SFDC call success recordId:303487 
  5  [12-02 11:26:08] INFO  update-record: 18a72d84cb3b : After Update 303487
  6  [12-02 11:26:08] INFO  Transformer: 18a72d84cb3b : Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=STAR-10496
  7  [12-02 11:26:08] INFO  sfdc-flow: 18a72d84cb3b : Outbound to SFDC recordId:303488
  8  [12-02 11:26:08] INFO  sfdc-flow: 18a72d84cb3b : SFDC call success recordId:303488 
  9  [12-02 11:26:08] INFO  update-record: 18a72d84cb3b : After Update 303488
 10  [12-02 11:26:08] INFO  Transformer: 18a72d84cb3b : Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=STAR-10491 
 11  [12-02 11:26:08] INFO  sfdc-flow: 18a72d84cb3b : Outbound to SFDC recordId:303489
 12  [12-02 11:26:08] INFO  flow1: 2d98498d1274 : Got Records 2
 13  [12-02 11:26:08] INFO  Transformer: 2d98498d1274 : Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=HRCOMP-23681
 14  [12-02 11:26:08] INFO  sfdc-flow: 2d98498d1274 : Outbound to SFDC recordId:303491
 15  [12-02 11:26:08] INFO  sfdc-flow: 18a72d84cb3b : SFDC call success recordId:303489 
 16  [12-02 11:26:08] INFO  update-record: 18a72d84cb3b : After Update 303489
 17  [12-02 11:26:08] ERROR  Transformer: 18a72d84cb3b : Update Case ERROR INVALID requestAction. Not mapped
 18  [12-02 11:26:08] INFO  sfdc-flow: 2d98498d1274 : SFDC call success recordId:303491 
 19  [12-02 11:26:08] INFO  update-record: 2d98498d1274 : After Update 303491
 20  [12-02 11:26:08] INFO  Transformer: 2d98498d1274 : Update Case Payload to be mapped requestAction=UpdateJIRA, jiraId=PERFCUST-298 
 21  [12-02 11:26:08] INFO  sfdc-flow: 2d98498d1274 : Outbound to SFDC recordId:303492
 22  [12-02 11:26:08] INFO  sfdc-flow: 2d98498d1274 : SFDC call success recordId:303492 
 23  [12-02 11:26:08] INFO  update-record: 2d98498d1274 : After Update 303492

The second piece that makes everyone's apps even more supportable is storing the payload that is received at the “Got Records” log step into a message database, and associating that line with the MessageID generated. Any support person could then look in the DB, do a select on the messageID and immediately get the payload that caused the error.