Audit Logging using Log4j in IIB

skadhir

Every project has its own way to capture the logs and they are mostly falls under one of these categories

  • Subflows
  • Monitoring Profiles

And these logs are stored either as files or in database tables. So, here I’m going to explain how to use Log4j to capture the logs from monitoring profiles. Note, we’re not going to use Log4j node but instead we use a simple log4j configuration file and some java code to capture all the elements available from the monitoring profiles.

Let us take a simple flow to understand.

And the monitoring configurations for MQInput Node are

So, the monitoring profile is ready and I’m going to use MQTT instead of MQ to get the monitoring event messages.

To test MQTT is enabled to accept Monitoring Events
To get MQTT port number

MQTT is enabled and the port number is 11884. Let us test the monitoring profile configured and see how the event message looks like.

MQ client to trigger message
MQTT client to view subscribed message

The event monitoring messages are published in topic IBM/IntegrationBus/IB10NODE/Monitoring/default/# and the message looks like 

<wmb:event xmlns:wmb="http://www.ibm.com/xmlns/prod/websphere/messagebroker/6.1.0/monitoring/event">
   <wmb:eventPointData>
      <wmb:eventData wmb:productVersion="100011" wmb:eventSchemaVersion="6.1.0.3" wmb:eventSourceAddress="MQ Input.transaction.Start">
         <wmb:eventIdentity wmb:eventName="OrderReceived"/>
         <wmb:eventSequence wmb:creationTime="2020-06-01T02:02:32.402892Z" wmb:counter="1"/>
         <wmb:eventCorrelation wmb:localTransactionId="f8a1af6d-013b-4420-9c1b-baf23d5e10a4-5" wmb:parentTransactionId="" wmb:globalTransactionId=""/>
      </wmb:eventData>
      <wmb:messageFlowData>
         <wmb:broker wmb:name="IB10NODE" wmb:UUID="b7d2e6dd-0b36-4728-9015-818133dbeb14"/>
         <wmb:executionGroup wmb:name="default" wmb:UUID="61704de3-b47c-4b23-b95f-0ffd934fdcb1"/>
         <wmb:messageFlow wmb:uniqueFlowName="IB10NODE.default.TestMon.TestMon" wmb:name="TestMon" wmb:UUID="429ff9ef-1c8d-48c1-bf42-99ac3bd247fb" wmb:threadId="21980"/>
         <wmb:node wmb:nodeLabel="MQ Input" wmb:nodeType="ComIbmMQInputNode" wmb:detail="IN.Q"/>
      </wmb:messageFlowData>
   </wmb:eventPointData>
   <wmb:applicationData xmlns="">
      <wmb:complexContent wmb:elementName="MQMD">
         <MQMD>
            <SourceQueue>IN.Q</SourceQueue>
            <Transactional>true</Transactional>
            <Encoding>273</Encoding>
            <CodedCharSetId>1208</CodedCharSetId>
            <Format>MQSTR   </Format>
            <Version>2</Version>
            <Report>0</Report>
            <MsgType>8</MsgType>
            <Expiry>-1</Expiry>
            <Feedback>0</Feedback>
            <Priority>0</Priority>
            <Persistence>0</Persistence>
            <MsgId>414d5120494942763130514d475220204064d15e10000105</MsgId>
            <CorrelId>000000000000000000000000000000000000000000000000</CorrelId>
            <BackoutCount>0</BackoutCount>
            <ReplyToQ>                                                </ReplyToQ>
            <ReplyToQMgr>IIBv10QMGR                                      </ReplyToQMgr>
            <UserIdentifier>vaithu      </UserIdentifier>
            <AccountingToken>160105150000002d74cc5dfa721e73431607412b32030000000000000000000b</AccountingToken>
            <ApplIdentityData>                                </ApplIdentityData>
            <PutApplType>28</PutApplType>
            <PutApplName>vaithu</PutApplName>
            <PutDate>2020-06-01</PutDate>
            <PutTime>02:02:32.480</PutTime>
            <ApplOriginData>    </ApplOriginData>
            <GroupId>000000000000000000000000000000000000000000000000</GroupId>
            <MsgSeqNumber>1</MsgSeqNumber>
            <Offset>0</Offset>
            <MsgFlags>0</MsgFlags>
            <OriginalLength>-1</OriginalLength>
         </MQMD>
      </wmb:complexContent>
   </wmb:applicationData>
   <wmb:bitstreamData>
      <wmb:bitstream wmb:encoding="base64Binary">TUQgIAIAAAAAAAAACAAAAP////8AAAAAEQEAALgEAABNUVNUUiAgIAAAAAAAAAAAQU1RIElJQnYxMFFNR1IgIEBk0V4QAAEFAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAACAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIElJQnYxMFFNR1IgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgIHN4cDI2NyAgICAgIBYBBRUAAAAtdMxd+nIec0MWB0ErMgMAAAAAAAAAAAALICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAcAAAAZ21haWwuc3Jpbml2YXNhLkFwcGxpY2F0aW9uIDIwMjAwNjAxMDIwMjMyNDggICAgAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAQAAAAAAAAAAAAAA/////zxPcmRlcnM+CiAgIDxPcmRlcj4KICAgICAgPEN1c3RvbWVySUQ+R1JFQUw8L0N1c3RvbWVySUQ+CiAgICAgIDxFbXBsb3llZUlEPjY8L0VtcGxveWVlSUQ+CiAgICAgIDxPcmRlckRhdGU+MTk5Ny0wNS0wNlQwMDowMDowMDwvT3JkZXJEYXRlPgogICAgICA8UmVxdWlyZWREYXRlPjE5OTctMDUtMjBUMDA6MDA6MDA8L1JlcXVpcmVkRGF0ZT4KICAgICAgPFNoaXBJbmZvIFNoaXBwZWREYXRlPSIxOTk3LTA1LTA5VDAwOjAwOjAwIj4KICAgICAgICAgPFNoaXBWaWE+MjwvU2hpcFZpYT4KICAgICAgICAgPEZyZWlnaHQ+My4zNTwvRnJlaWdodD4KICAgICAgICAgPFNoaXBOYW1lPkdyZWF0IExha2VzIEZvb2QgTWFya2V0PC9TaGlwTmFtZT4KICAgICAgICAgPFNoaXBBZGRyZXNzPjI3MzIgQmFrZXIgQmx2ZC48L1NoaXBBZGRyZXNzPgogICAgICAgICA8U2hpcENpdHk+RXVnZW5lPC9TaGlwQ2l0eT4KICAgICAgICAgPFNoaXBSZWdpb24+T1I8L1NoaXBSZWdpb24+CiAgICAgICAgIDxTaGlwUG9zdGFsQ29kZT45NzQwMzwvU2hpcFBvc3RhbENvZGU+CiAgICAgICAgIDxTaGlwQ291bnRyeT5VU0E8L1NoaXBDb3VudHJ5PgogICAgICA8L1NoaXBJbmZvPgogICA8L09yZGVyPgo8L09yZGVycz4=</wmb:bitstream>
   </wmb:bitstreamData>
</wmb:event>

Let us see what happens when there is an exception. To generate an exception, I’m just going to make the out queue name to a random non-existing queue OUTaa.Q and now the monitoring event with Exception tree looks like

<wmb:event xmlns:wmb="http://www.ibm.com/xmlns/prod/websphere/messagebroker/6.1.0/monitoring/event">
   <wmb:eventPointData>
      <wmb:eventData wmb:productVersion="100011" wmb:eventSchemaVersion="6.1.0.3" wmb:eventSourceAddress="MQ Input.transaction.Rollback">
         <wmb:eventIdentity wmb:eventName="OrderRollback"/>
         <wmb:eventSequence wmb:creationTime="2020-06-01T02:17:30.450741Z" wmb:counter="2"/>
         <wmb:eventCorrelation wmb:localTransactionId="47ab24c4-91c8-48b6-91a2-e0cc0393085b-1" wmb:parentTransactionId="" wmb:globalTransactionId=""/>
      </wmb:eventData>
      <wmb:messageFlowData>
         <wmb:broker wmb:name="IB10NODE" wmb:UUID="b7d2e6dd-0b36-4728-9015-818133dbeb14"/>
         <wmb:executionGroup wmb:name="default" wmb:UUID="61704de3-b47c-4b23-b95f-0ffd934fdcb1"/>
         <wmb:messageFlow wmb:uniqueFlowName="IB10NODE.default.TestMon.TestMon" wmb:name="TestMon" wmb:UUID="429ff9ef-1c8d-48c1-bf42-99ac3bd247fb" wmb:threadId="8076"/>
         <wmb:node wmb:nodeLabel="MQ Input" wmb:nodeType="ComIbmMQInputNode" wmb:detail="IN.Q"/>
      </wmb:messageFlowData>
   </wmb:eventPointData>
   <wmb:applicationData xmlns="">
      <wmb:complexContent wmb:elementName="ExceptionList">
         <ExceptionList>
            <RecoverableException>
               <File>F:\build\S1000_slot1\S1000_P\src\DataFlowEngine\TemplateNodes\ImbOutputTemplateNode.cpp</File>
               <Line>303</Line>
               <Function>ImbOutputTemplateNode::processMessageAssemblyToFailure</Function>
               <Type>ComIbmMQOutputNode</Type>
               <Name>TestMon#FCMComposite_1_2</Name>
               <Label>TestMon.MQ Output</Label>
               <Catalog>BIPmsgs</Catalog>
               <Severity>3</Severity>
               <Number>2230</Number>
               <Text>Caught exception and rethrowing</Text>
               <Insert>
                  <Type>14</Type>
                  <Text>TestMon.MQ Output</Text>
               </Insert>
               <MessageException>
                  <File>F:\build\S1000_slot1\S1000_P\src\DataFlowEngine\Connectors\mqconnector\MQConnection.cpp</File>
                  <Line>1003</Line>
                  <Function>MQConnection::acquireOutputQueueHandle</Function>
                  <Type></Type>
                  <Name></Name>
                  <Label></Label>
                  <Catalog>BIPmsgs</Catalog>
                  <Severity>3</Severity>
                  <Number>2666</Number>
                  <Text>Failed to open queue</Text>
                  <Insert>
                     <Type>2</Type>
                     <Text>-1</Text>
                  </Insert>
                  <Insert>
                     <Type>5</Type>
                     <Text>MQW101</Text>
                  </Insert>
                  <Insert>
                     <Type>2</Type>
                     <Text>2085</Text>
                  </Insert>
                  <Insert>
                     <Type>5</Type>
                     <Text></Text>
                  </Insert>
                  <Insert>
                     <Type>5</Type>
                     <Text>IIBv10QMGR</Text>
                  </Insert>
                  <Insert>
                     <Type>5</Type>
                     <Text>OUTaa.Q</Text>
                  </Insert>
                  <Insert>
                     <Type>2</Type>
                     <Text>2</Text>
                  </Insert>
               </MessageException>
            </RecoverableException>
         </ExceptionList>
      </wmb:complexContent>
   </wmb:applicationData>
</wmb:event>

Now, we know how the monitoring profile and monitoring events works. Let us develop a solution which will accept these messages and log them as we needed. For this, I’ve another message flow and it looks like

The MQTTSubscribe node is used to get the published event monitoring messages and the Java compute node is used to decipher the event monitoring XML message and log them. A sample log file looks like 

2020-05-31 22:54:29.036 [Thread-49] INFO  - ----------------------------------------Transaction Starts---------------------------------------------------------
2020-05-31 22:54:29.058 [Thread-49] INFO  - Event Number :2
2020-05-31 22:54:30.001 [Thread-49] ERROR - Data Element Name :ExceptionList
2020-05-31 22:54:32.301 [Thread-49] ERROR - Error Message :Failed to open queue;MQW101;2085;IIBv10QMGR;OUTaa.Q;
2020-05-31 22:54:32.301 [Thread-49] INFO  - ----------------------------------------Transaction Ends---------------------------------------------------------
2020-05-31 22:54:36.142 [Thread-49] INFO  - ----------------------------------------Transaction Starts---------------------------------------------------------
2020-05-31 22:54:36.156 [Thread-49] INFO  - Event Number :1
2020-05-31 22:54:37.475 [Thread-49] INFO  - Data Element Name :MQMD
2020-05-31 22:54:37.476 [Thread-49] INFO  - ***********************************************************************
2020-05-31 22:54:37.477 [Thread-49] INFO  - SourceQueue : IN.Q
2020-05-31 22:54:37.478 [Thread-49] INFO  - Transactional : true
2020-05-31 22:54:37.478 [Thread-49] INFO  - Encoding : 273
2020-05-31 22:54:37.480 [Thread-49] INFO  - CodedCharSetId : 1208
2020-05-31 22:54:37.480 [Thread-49] INFO  - Format : MQSTR   
2020-05-31 22:54:37.481 [Thread-49] INFO  - Version : 2
2020-05-31 22:54:37.482 [Thread-49] INFO  - Report : 0
2020-05-31 22:54:37.483 [Thread-49] INFO  - MsgType : 8
2020-05-31 22:54:37.484 [Thread-49] INFO  - Expiry : -1
2020-05-31 22:54:37.484 [Thread-49] INFO  - Feedback : 0
2020-05-31 22:54:37.485 [Thread-49] INFO  - Priority : 0
2020-05-31 22:54:37.485 [Thread-49] INFO  - Persistence : 0
2020-05-31 22:54:37.486 [Thread-49] INFO  - MsgId : 414d5120494942763130514d475220204064d15e1000010d
2020-05-31 22:54:37.486 [Thread-49] INFO  - CorrelId : 000000000000000000000000000000000000000000000000
2020-05-31 22:54:37.487 [Thread-49] INFO  - BackoutCount : 1
2020-05-31 22:54:37.487 [Thread-49] INFO  - ReplyToQ :                                                 
2020-05-31 22:54:37.487 [Thread-49] INFO  - ReplyToQMgr : IIBv10QMGR                                      
2020-05-31 22:54:37.488 [Thread-49] INFO  - UserIdentifier : vaithu      
2020-05-31 22:54:37.488 [Thread-49] INFO  - AccountingToken : 160105150000002d74cc5dfa721e73431607412b32030000000000000000000b
2020-05-31 22:54:37.488 [Thread-49] INFO  - ApplIdentityData :                                 
2020-05-31 22:54:37.490 [Thread-49] INFO  - PutApplType : 28
2020-05-31 22:54:37.490 [Thread-49] INFO  - PutApplName : vaithu
2020-05-31 22:54:37.491 [Thread-49] INFO  - PutDate : 2020-06-01
2020-05-31 22:54:37.492 [Thread-49] INFO  - PutTime : 02:54:15.150
2020-05-31 22:54:37.493 [Thread-49] INFO  - ApplOriginData :     
2020-05-31 22:54:37.493 [Thread-49] INFO  - GroupId : 000000000000000000000000000000000000000000000000
2020-05-31 22:54:37.494 [Thread-49] INFO  - MsgSeqNumber : 1
2020-05-31 22:54:37.494 [Thread-49] INFO  - Offset : 0
2020-05-31 22:54:37.494 [Thread-49] INFO  - MsgFlags : 0
2020-05-31 22:54:37.495 [Thread-49] INFO  - OriginalLength : -1
2020-05-31 22:54:37.495 [Thread-49] INFO  - ***********************************************************************
2020-05-31 22:54:37.495 [Thread-49] INFO  - OrderReceived Payload :
MD            ÿÿÿÿ      ¸  MQSTR           AMQ IIBv10QMGR  @dÑ^ 
                                                                           IIBv10QMGR                                      vaithu         -tÌ]úrsCA+2                                            vaithu 2020060102541515                                       ÿÿÿÿ<Orders>
   <Order>
      <CustomerID>GREAL</CustomerID>
      <EmployeeID>6</EmployeeID>
      <OrderDate>1997-05-06T00:00:00</OrderDate>
      <RequiredDate>1997-05-20T00:00:00</RequiredDate>
      <ShipInfo ShippedDate="1997-05-09T00:00:00">
         <ShipVia>2</ShipVia>
         <Freight>3.35</Freight>
         <ShipName>Great Lakes Food Market</ShipName>
         <ShipAddress>2732 Baker Blvd.</ShipAddress>
         <ShipCity>Eugene</ShipCity>
         <ShipRegion>OR</ShipRegion>
         <ShipPostalCode>97403</ShipPostalCode>
         <ShipCountry>USA</ShipCountry>
      </ShipInfo>
   </Order>
</Orders>
2020-05-31 22:54:37.497 [Thread-49] INFO  - ----------------------------------------Transaction Ends---------------------------------------------------------
2020-05-31 22:54:41.125 [Thread-49] INFO  - ----------------------------------------Transaction Starts---------------------------------------------------------
2020-05-31 22:54:41.135 [Thread-49] INFO  - Event Number :2
2020-05-31 22:54:42.179 [Thread-49] ERROR - Data Element Name :ExceptionList
2020-05-31 22:54:44.299 [Thread-49] ERROR - Error Message :Failed to open queue;MQW101;2085;IIBv10QMGR;OUTaa.Q;
2020-05-31 22:54:44.299 [Thread-49] INFO  - ----------------------------------------Transaction Ends---------------------------------------------------------

Here each event message is clearly separated and easily readable. The exception handler captures the right error message and ignores all other unnecessary information. So, we know the key elements, input and output payload and the exception message. Since we’re using monitoring profile, there is no need for any custom subflows and this solution is production tested code and works fantastically, thanks to log4j settings. 

2020-05-31 22:54:41.125 [Thread-49] INFO  - ----------------------------------------Transaction Starts---------------------------------------------------------
2020-05-31 22:54:41.135 [Thread-49] INFO  - Event Number :2
2020-05-31 22:54:42.179 [Thread-49] ERROR - Data Element Name :ExceptionList
2020-05-31 22:54:44.299 [Thread-49] ERROR - Error Message :Failed to open queue;MQW101;2085;IIBv10QMGR;OUTaa.Q;
2020-05-31 22:54:44.299 [Thread-49] INFO  - ----------------------------------------Transaction Ends---------------------------------------------------------

All these logs are categorically separated like nodename/servername/flowname so that it is easy to identify the log files. The log files gets rolled up automatically and each log file size is 10MB as these are controlled by the log4j settings.

All you’ve to do is, just enable monitoring and see the logs in the folder configured in the log4j config file.

If you’d like to understand how the log4j file looks like and the Java code used, there is a session on this next week Sunday.

Contact us at support@vaithu.com for more details and to purchase.

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.