Transaction Logging

Owned by Patrick Lobre (Unlicensed)
Jul 08, 2019

In a multi-threaded environment, logging statements can end up populated in a non-sequential order, making it hard to tell which log statements belong together in the same thread of execution.

Design Approach

CONNECT includes an optional field to the Entity interface to capture a transaction id. Each transaction id will map to one or more message ids. CONNECT maintains a mapping from the transaction id and the message id associated with it. This will include mapping replies and responses to the initiating gateway's provided transaction id. The next part of the puzzle uses the Mapped Diagnostic Context feature of log4j. The context holds the message id and the transaction id (if known). This allows all logged messages to include this information by configuring the appender. In most cases this context is passed to child threads and will be available to them as well.

Transaction logging is implemented by passing a single correlated identifier, transactionId, within the soap header.  

An example of a header with the transactionId element:

<soap:Header>
<MessageID xmlns="http://www.w3.org/2005/08/addressing" mustUnderstand="true">urn:uuid:1234-1234-1234</MessageID>
<txn:TransactionID xmlns:txn="http://connectopensource.org/transaction/">urn:uuid:AAA-BBB-CCC</txn:TransactionID>
</soap:Header>

A transaction handler, which implements the JAX-WS Soap Handler paradigm, is used to intercept the soap messages.  The handler is implemented on all services at the interface endpoints for Entity, and Nhin, including secured and unsecured endpoints and deferred services.  The handler analyzes the header for transaction logging information using the following logic.

  • Checks the soap header for the existence of the transactionID element.  If the transaction log element exists, the message's messageID and transactionID from the header are inserted into the database.  The insertion does require that the messageID and transactionID make a unique pair.  The values are also appended to the server log via the log4j feature Mapped Diagnostic Context (MDC)
  • If no transaction element is discovered, the handler will attempt to correlate a transaction ID based on the header RelatesTo element's value.  The database is queried on the RelatesTo ID and if a transaction ID is found the message's messageID and transactionID are inserted into the database and the the MDC is appended.  This part of the logic also takes into account the possibility of having multiple RelatesTo IDs that correlate to multiple different transaction IDs
  • If neither steps 1 or 2 produce a transactionID correlation, the database is queried on the header messageID to discover if a transactionID already has a correlation.  Upon successful look-up, the messageId and transactionID values are appended to the log via MDC

Database Design

The transaction identifier and the associated message identifiers are stored in a single database table named transactionrepository. This table contains four columns: id, transactionTime, messageId, and transactionId. The id column is just a unique surrogate key. The transactiontime is a timestamp representing when the entry was recorded in the database. The columns messageId and transactionId are VARCHAR(100). There is a uniqueness constraint on messageId and transactionId, and an index is set on messageId to facilitate the quick retrieval-related transactionId.

User Interface Design

CONNECT does not include a user interface for transaction logging.The relationship between the transaction and message is stored in the database and can be viewed by querying the database. Each log4j statement now contains the transaction-id and message-id from the message diagnostic context. The layout of the log4j statements is configurable in the log4j properties.
log4j.appender.C.layout.ConversionPattern=[%d{dd/HH:mm:ss:SSS}] %-5p %-30.30c{1} %m %X{transaction-id} %X{message-id}%n

Example

The following is an example of the output for both the database and the log for a related chain of Patient Discovery, Document Query, and Document Retrieve messages that use the same correlated transaction ID.
Database example (using MySQL, using MySQL Query Browser)

Note that there are two transaction entries logged for each service.  The response Nhin message ID was logged based on its RelatesTo message ID.
Log4j example (from Glassfish 3.1.1 using the default log4j MDC property)
[02/16:19:42:426] DEBUG Printer gov.hhs.fha.nhinc.hibernate.AuditRepositoryRecord{participationIDTypeCode=2, participationTypeCodeRole=1, timeStamp=2012-10-02 16:19:42, eventId=0, communityId=2.2, receiverPatientId=, senderPatientId=null, userId=kskagerb, participationTypeCode=1, messageType=Entity Outbound, id=287, message=org.hibernate.lob.SerializableBlob@30a4473c} urn:uuid:AAA-AAA-AAA urn:uuid:<QD Request ID>
[02/16:19:42:427] TRACE AbstractFlushingEventListener executing flush urn:uuid:AAA-AAA-AAA urn:uuid:<QD Request ID>
[02/16:19:42:427] TRACE ConnectionManager registering flush begin urn:uuid:AAA-AAA-AAA urn:uuid:<QD Request ID>|#]