| Author |
Message
|
| Mirage |
 Posted: Thu Dec 01, 2005 6:18 am Post subject: Adapters and MessageFlow with wait time: Puzzling behaviour |
 |
|
Apprentice
Joined: 30 Nov 2004
Posts: 44
Location: IL
|
We've a strange problem happening in our message flows. Most of the message flows use WBI Adapters and to work with the Adapters synchronously we are using the request-reply method.
We've built a custom node called as MQGET using the Java API for MQ. This node is placed after the MQOutput Node(Input queue for the Adapter). When our flow is invoked, it puts a message on to the Adapters input queue and passes the MessageID to the MQGET node. MQGET node waits for a certain interval of time for a message to be put in ResponseQueue with CorrellationID=MessageID(Adapter does this after it finishes its work)
Now, our message flow knows that the adapter was able to process the request and it can continue its process. If for some reason the adapter does not put a message on the Response Queue within that time interval then the MQGET node in our message flow gets a 2033(MessageNot Found) MQ exception and exits the flow towards error handling.
Now, the problem is, this whole process runs very fine without any problem in many message flows we have. But,sometimes the message flows get a timeout exception(2033). When we reveiwed the logs of the adapter, we found that the adapter did not get the message from its request queue untill the message flow finished its processing(i.e, waiting for the message on Response queue and then exiting). The adapter processes the message that was put on the queue as soon as the message flow exited with a timeout error.
Our MQ Output Node's transaction is set to 'NO' and this process works sometimes and does not work sometimes.
Can you suggest us some pointers to look at ?
Is the MQOutput Node not commiting the message till the message flow finished its processing ?. Then how this message flow is working at sometimes ?
Thanks - Raghu. |
|
| Back to top |
|
 |
| basha |
| Posted: Thu Dec 01, 2005 11:03 am Post subject: |
|
|
Apprentice
Joined: 25 Apr 2004
Posts: 31
|
Mirage,
What is the Transaction Mode property on your input node? |
|
| Back to top |
|
|
| Mirage |
| Posted: Thu Dec 01, 2005 12:13 pm Post subject: |
|
|
Apprentice
Joined: 30 Nov 2004
Posts: 44
Location: IL
|
The Transaction Mode is set to 'Yes' in the MQInput Node. Should this be set to 'No' ?. If thats the case, how are some of the transaction working end to end and how some are not working. We are not sure whether its a problem with our Message Flow or Adapter or any MQ Queue Managers Settings
Are there any other settings to check for ?
Thanks - Raghu |
|
| Back to top |
|
|
| wschutz |
| Posted: Thu Dec 01, 2005 12:30 pm Post subject: |
|
|
Jedi Knight
Joined: 02 Jun 2005
Posts: 3316
Location: IBM (retired)
|
Interesting problem. If the MQOutput node is set to "NO" for Transaction Mode, then the message should ALWAYS be outside of syncpoint.
How often does this happen? Is this a production system? Is any type of tracing possible given your message volumes?
_________________
-wayne |
|
| Back to top |
|
|
| wschutz |
| Posted: Thu Dec 01, 2005 12:34 pm Post subject: |
|
|
Jedi Knight
Joined: 02 Jun 2005
Posts: 3316
Location: IBM (retired)
|
Interesting problem. If the MQOutput node is set to "NO" for Transaction Mode, then the message should ALWAYS be outside of syncpoint.
How often does this happen? Is this a production system? Is any type of tracing possible given your message volumes?
_________________
-wayne |
|
| Back to top |
|
|
| Mirage |
| Posted: Thu Dec 01, 2005 1:02 pm Post subject: |
|
|
Apprentice
Joined: 30 Nov 2004
Posts: 44
Location: IL
|
This happens very randomly. We could not recreate it and yes its happening on our Production system.
What type of trace settings you are asking for ?. We can set up tracing for a low volume transaction. Please suggest.
We do have tracing for the MQGET node with a start time and wait time. When this problem occurs the MQGET node traces the wait time and the 2033 error, the adapter picks its message after the MQGET's timeout.
In Adapter's log, the message's JMS Timestamp is almost equal to the MQGET's start time stamp.
Thanks - Raghu. |
|
| Back to top |
|
|
| Mirage |
| Posted: Thu Dec 01, 2005 1:12 pm Post subject: |
|
|
Apprentice
Joined: 30 Nov 2004
Posts: 44
Location: IL
|
Below is the trace we have gathered, First is the MQGET node's trace and second is the Adapters trace.
MQGET Node's Trace: Which is right after the MQOutput node
| Quote: |
************************************************************
Instantiating MQ connection at Mon Nov 21 15:31:54 CST 2005
Hexa decimal representation of message ID from flow 414D512050524442524F4B4552202020436A847B20016522
Creating a connection to PRDBROKER
Opening connection to response queue EAI.EACCS.JTEXTRES
Waiting for Response Message ..
In MQ Exception block
The wait was 87377 milli seconds
Throwing the exception MQJE001: Completion Code 2, Reason 2033
In Exception block
<com.ibm.broker.plugin.MbRecoverableException class: method: source: key:MQJE001: Completion Code 2, Reason 2033 >
Unable to resolve message: Source: Key: MQJE001: Completion Code 2, Reason 2033
Disconnecting from the Queue manager
Disconnected from the Queue Manager successfully
|
Adapters trace:
| Quote: |
[Time: 2005/11/21 15:34:02.821] [System: ConnectorAgent] [SS: EACCS_JTextConnector] [Thread: EAI.EACCS.JTEXTREQJmsThreadPool.thread1 (#20914447)] [Type: Trace] [Mesg: :Receiver.processMsg(msg) received message:
JMS Message class: jms_text
JMSType: mcd://mrm/MOO6AL4002001/EACCSUPLOAD_FileContent?format=CwXML
JMSDeliveryMode: 2
JMSExpiration: 0
JMSPriority: 4
JMSMessageID: ID:414d512050524442524f4b4552202020436a847b20016522
JMSTimestamp: 1132608628640
JMSCorrelationID:null
JMSDestination: null
JMSReplyTo: queue://PRDBROKER/EAI.EACCS.JTEXTRES
JMSRedelivered: false
JMS_IBM_PutDate:20051121
JMSXAppID:
JMS_IBM_Format:MQSTR
JMS_IBM_PutApplType:28
JMS_IBM_MsgType:8
JMSXUserID:eepwbi0
JMS_IBM_PutTime:21302864
JMSXDeliveryCount:1
<?xml version="1.0"?><NS1:EACCSUPLOAD_FileContent xmlns:NS1="http://www.ibm.com/websphere/crossworld
Another 5,180,920 character(s) omitted]
|
JMS Timestamp listed in the Message Header 1132608628640 is equal to a Timestamp of Mon Nov 21 15:30:28 CST 2005 which is sometime before MQGET nodes processing started. Adapter received the message at 15:34:02.821 which is after MQGET Node's processing is over. |
|
| Back to top |
|
|
| fjb_saper |
| Posted: Thu Dec 01, 2005 7:32 pm Post subject: |
|
|
Grand High Poobah
Joined: 18 Nov 2003
Posts: 20756
Location: LI,NY
|
Sorry but from memory, isn't RC 2033 equivalent to NO MORE MSGS ON QUEUE?
So if you happen to see some queue depth it would mean that the message you see is not yet committed (still under syncpoint) and not in a gettable state.
Working as designed... what are you complaining about ?
Enjoy  |
|
| Back to top |
|
|
| jefflowrey |
| Posted: Fri Dec 02, 2005 4:15 am Post subject: |
|
|
Grand Poobah
Joined: 16 Oct 2002
Posts: 19981
|
| fjb_saper wrote: |
| Working as designed... what are you complaining about ? |
Mirage is complaining that the message isn't committed, apparently, even though the message flow was specifically configured to commit it.
A transaction mode of NO on an MQOutput node should always immediately commit the message that's outputed. Should.
I think it's time to enable broker user level tracing, and see what the flow says it's doing.
_________________
I am *not* the model of the modern major general. |
|
| Back to top |
|
|
| Mirage |
| Posted: Fri Dec 02, 2005 6:57 am Post subject: |
|
|
Apprentice
Joined: 30 Nov 2004
Posts: 44
Location: IL
|
We have setup the user level trace to debug now and will be monitoring the message flow for any of these timeout errors.
Can there be any other factors that you can think of for this to happen ?
Thanks - Raghu. |
|
| Back to top |
|
|
| Mirage |
| Posted: Mon Dec 12, 2005 8:07 am Post subject: |
|
|
Apprentice
Joined: 30 Nov 2004
Posts: 44
Location: IL
|
We've setup the debug trace for our message flow and captured the trace when this weird problem occured again. Below is the message from the trace.
MQPut was issued at 2005-12-09 21:03:01 and MQGET node responded with an error at 2005-12-09 21:07:30, the difference is like 4:30 minutes. Our MQGET node was configured to wait for 3 minutes for a response message.
Trace file is around 4MB and I've copied the messages that I think are relevant.
Please let me know what might be the reason for this problem.
| Code: |
- <UserTrace timestamp="2005-12-09 21:03:01.972130" thread="7454" function="SqlReturnStatement::execute" type="ComIbmComputeNode" name="RDT_EACCS_COPYINGTOEA_UPLOAD#FCMComposite_1_12" label="RDT_EACCS_COPYINGTOEA_UPLOAD.Construct_BO_Message" text="Executing statement at (&1, &2)" catalog="BIPv500" number="2537" file="/build/S500_P/src/DataFlowEngine/ImbRdl/ImbRdlReturnStmt.cpp" line="72">
 <Insert type="string">.RDT_EACCS_COPYINGTOEA_UPLOAD_Construct_BO_Message.Main</Insert>
 <Insert type="string">53.2</Insert>
 <Insert type="string">RETURN TRUE;</Insert>
 <Insert type="string">RDT_EACCS_COPYINGTOEA_UPLOAD.Construct_BO_Message</Insert>
 </UserTrace>
- <UserTrace timestamp="2005-12-09 21:03:01.972281" thread="7454" function="ImbComputeNode::propagate" type="ComIbmComputeNode" name="RDT_EACCS_COPYINGTOEA_UPLOAD#FCMComposite_1_12" label="RDT_EACCS_COPYINGTOEA_UPLOAD.Construct_BO_Message" text="Propagating to output terminal" catalog="BIPv500" number="4124" file="/build/S500_P/src/DataFlowEngine/ImbComputeNode.cpp" line="516">
 <Insert type="string">RDT_EACCS_COPYINGTOEA_UPLOAD.Construct_BO_Message</Insert>
 </UserTrace>
- <UserTrace timestamp="2005-12-09 21:03:01.979582" thread="7454" function="ImbMqOutputNode::putMessage" type="ComIbmMQOutputNode" name="RDT_EACCS_COPYINGTOEA_UPLOAD#FCMComposite_1_13" label="RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_RequestQ" text="MQPUT issued to put message to the specified output queue" catalog="BIPv500" number="2638" file="/build/S500_P/src/DataFlowEngine/ImbMqOutputNode.cpp" line="2020">
 <Insert type="string" />
 <Insert type="string">EAI.EACCS.FILEREADREQ</Insert>
 <Insert type="integer">0</Insert>
 <Insert type="integer">0</Insert>
 <Insert type="string">RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_RequestQ</Insert>
 </UserTrace>
- <UserTrace timestamp="2005-12-09 21:03:01.979599" thread="7454" function="ImbMqOutputNode::putMessage" type="ComIbmMQOutputNode" name="RDT_EACCS_COPYINGTOEA_UPLOAD#FCMComposite_1_13" label="RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_RequestQ" text="Message received and queued successfully" catalog="BIPv500" number="2622" file="/build/S500_P/src/DataFlowEngine/ImbMqOutputNode.cpp" line="2136">
 <Insert type="string" />
 <Insert type="string">EAI.EACCS.FILEREADREQ</Insert>
 <Insert type="string">RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_RequestQ</Insert>
 </UserTrace>
- <UserTrace timestamp="2005-12-09 21:07:30.396867" thread="7454" function="ImbTryCatchNode::evaluate" type="ComIbmTryCatchNode" name="RDT_EACCS_COPYINGTOEA_UPLOAD#FCMComposite_1_10" label="RDT_EACCS_COPYINGTOEA_UPLOAD.TryCatch" text="Caught exception and propagating to catch terminal" catalog="BIPv500" number="4081" file="/build/S500_P/src/DataFlowEngine/BasicNodes/ImbTryCatchNode.cpp" line="161">
 <Insert type="string">RDT_EACCS_COPYINGTOEA_UPLOAD.TryCatch</Insert>
 </UserTrace>
- <RecoverableException timestamp="2005-12-09 21:07:30.409805" thread="7454" function="ImbMqOutputNode::evaluate" type="ComIbmMQOutputNode" name="RDT_EACCS_COPYINGTOEA_UPLOAD#FCMComposite_1_13" label="RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_RequestQ" text="Caught exception and rethrowing" catalog="BIPv500" number="2230" file="/build/S500_P/src/DataFlowEngine/ImbMqOutputNode.cpp" line="847">
 <Insert type="string">RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_RequestQ</Insert>
 </RecoverableException>
- <RecoverableException timestamp="2005-12-09 21:07:30.409814" thread="7454" function="ImbJniNode::evaluate" type="ComIbmJniNode" name="RDT_EACCS_COPYINGTOEA_UPLOAD#FCMComposite_1_14" label="RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_MQGET" text="Caught exception and rethrowing" catalog="BIPv500" number="2230" file="/build/S500_P/src/DataFlowEngine/PluginInterface/ImbJniNode.cpp" line="898">
 <Insert type="string">RDT_EACCS_COPYINGTOEA_UPLOAD.FILEREAD_MQGET</Insert>
 </RecoverableException>
- <RecoverableException timestamp="2005-12-09 21:07:30.409822" thread="7454" function="ImbJavaExceptionUtils::throwableToNativeException" text="Unhandled exception in plugin method." catalog="BIPv500" number="4367" file="/build/S500_P/src/DataFlowEngine/PluginInterface/com_ibm_broker_plugin_CMbService.cpp" line="1588">
 <Insert type="string">evaluate</Insert>
 <Insert type="string">FILEREAD_MQGET</Insert>
 <Insert type="string">java.lang.OutOfMemoryError</Insert>
 </RecoverableException>
- <RecoverableException timestamp="2005-12-09 21:07:30.409828" thread="7454" function="ImbJavaExceptionUtils::throwableToNativeException" text="" catalog="BIPv500" number="4395" file="/build/S500_P/src/DataFlowEngine/PluginInterface/com_ibm_broker_plugin_CMbService.cpp" line="1606">
 <Insert type="string">java.lang.OutOfMemoryError</Insert>
 <Insert type="string">Unknown</Insert>
 <Insert type="string">Unknown</Insert>
 <Insert type="string">Unknown</Insert>
 <Insert type="integer">-1</Insert>
|
|
|
| Back to top |
|
|
|
|
