MQSeries.net :: View topic

srailkar · Posted: Thu Feb 14, 2008 7:48 pm Post subject: MsgFlow Strange Behavior

I have a messageflow which is behaving very strangly. When same message is passed thru in debug mode it works perfectly. Without Debug it has a problem processing the following command, complaing that the XML is not well formed:

DECLARE MYSTRINGA CHARACTER CAST(ASBITSTREAM(InputRoot.XMLNS OPTIONS RootBitStream) AS CHARACTER CCSID InputRoot.MQMD.CodedCharSetId ENCODING InputRoot.MQMD.Encoding);

Environment:
WINDOWS 2000 Server
MQ 6.0.1
WBIMB 6.0.2

Trace log - without debug
7I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''BEGIN ... END;'' at ('.PROCESS2OCL.CopyEntireMessage', '1.39').
2008-02-14 22:24:00.678053 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''SET OutputRoot.MQMD = InputRoot.MQMD;'' at ('.PROCESS2OCL.CopyEntireMessage', '3.3').
2008-02-14 22:24:00.678129 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''InputRoot.MQMD'' at ('.PROCESS2OCL.CopyEntireMessage', '3.25'). This resolved to ''InputRoot.MQMD''. The result was ''ROW... Root Element Type=16777216 NameSpace='' Name='MQMD' Value=NULL''.
2008-02-14 22:24:00.678173 9096 UserTrace BIP2568I: Node 'I3_OCL_OUT.PROCESS2OCL': Copying sub-tree from ''InputRoot.MQMD'' to ''OutputRoot.MQMD''.
2008-02-14 22:24:00.678233 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''DECLARE myString CHARACTER CAST(ASBITSTREAM(InputRoot.XMLNS OPTIONS RootBitStream) AS CHARACTER CCSID InputRoot.MQMD.CodedCharSetId ENCODING InputRoot.MQMD.Encoding);'' at ('.PROCESS2OCL.CopyEntireMessage', '4.3').
2008-02-14 22:24:00.678276 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''RootBitStream'' at ('.PROCESS2OCL.CopyEntireMessage', '4.71'). This resolved to ''RootBitStream''. The result was ''0''.
2008-02-14 22:24:00.679471 9096 UserTrace BIP2231E: Error detected whilst processing a message in node 'I3_OCL_OUT.PROCESS2OCL'.
The message broker detected an error whilst processing a message in node 'I3_OCL_OUT.PROCESS2OCL'. The message has been augmented with an exception list and has been propagated to the node's failure terminal for further processing.
See the following messages for details of the error.
2008-02-14 22:24:00.679517 9096 RecoverableException BIP2488E: ('.PROCESS2OCL.Main', '4.3') Error detected whilst executing the SQL statement ''CopyEntireMessage();''.
The message broker detected an error whilst executing the given statement. An exception has been thrown to cut short the SQL program.
See the following messages for details of the error.
2008-02-14 22:24:00.679553 9096 RecoverableException BIP2934E: Error detected whilst executing the function or procedure ''CopyEntireMessage''.
The message broker detected an error whilst executing the function or procedure ''CopyEntireMessage''. An exception has been thrown to cut short the processing of the message.
See the following messages for details of the error.
2008-02-14 22:24:00.679589 9096 RecoverableException BIP2488E: ('.PROCESS2OCL.CopyEntireMessage', '4.3') Error detected whilst executing the SQL statement ''DECLARE myString CHARACTER CAST(ASBITSTREAM(InputRoot.XMLNS OPTIONS RootBitStream) AS CHARACTER CCSID InputRoot.MQMD.CodedCharSetId ENCODING InputRoot.MQMD.Encoding);''.
The message broker detected an error whilst executing the given statement. An exception has been thrown to cut short the SQL program.
See the following messages for details of the error.
2008-02-14 22:24:00.679629 9096 ParserException BIP5010E: XML Writing Errors have occurred.
Errors have occurred during writing of XML.
Review further error messages for an indication to the cause of the errors.
2008-02-14 22:24:00.679661 9096 ParserException BIP5009E: XML Parsing Errors have occurred.
Errors have occurred during parsing of XML.
Review further error messages for an indication to the cause of the errors.
2008-02-14 22:24:00.679696 9096 ParserException BIP5004E: XML parsing error ('Unterminated end tag, 'Request' ') encountered on line 1 column 1963 while parsing element 'Request'.
The above error was reported by the generic XML parser.
This message is usually caused by a badly-formed XML message. Check that the XML message being passed in is a well-formed XML message that adheres to the XML specification. Note that the line number and column number quoted above give the position where the parser discovered the problem. The actual error may be earlier in the message. Internal error codes : (200), ('').
2008-02-14 22:24:00.679787 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCFAIL': Executing statement ''BEGIN ... END;'' at ('.PROCFAIL.Main', '2.2').

Trace log - with debug
UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''InputRoot.MQMD.Encoding'' at ('.PROCESS2OCL.CopyEntireMessage', '4.144'). This resolved to ''InputRoot.MQMD.Encoding''. The result was ''273''.
2008-02-14 22:26:10.419522 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''CAST(ASBITSTREAM(InputRoot.XMLNS OPTIONS RootBitStream) AS CHARACTER CCSID InputRoot.MQMD.CodedCharSetId ENCODING InputRoot.MQMD.Encoding)'' at ('.PROCESS2OCL.CopyEntireMessage', '4.30'). This resolved to ''CAST(X'3c3f786d6c2076657273696f6e3d22312e302220656e636f64696e673d227574662d38223f3e3c736f61703a456e76656c6f706520786d6c6e733a736f61703d'... (data of len 2069 truncated)' AS CHARACTER CCSID 437 ENCODING 273 )''. The result was '''<?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><ProcessNameListMessageResult xmlns="http://www.attuswebsolutions.com/AttusTechSystemNameLookup/SearchService"><ATTUSWATCHDOGRESPONSE tranid="10110533029" trandate="2008-02-14 21:26:54" xmlns=""><BILLINGCODE partnerid="8b881326-bd66-4e1b-8b09-d19f37389328" billingid="8b881326-bd66-4e1b-8b09-d19f37389328" functionid="6PI/upEE0epQR5SObftn+s2fW3M=" servicerequest="6PI/upEE0epQR5SObftn+s2fW3M=" password="3d97a1a7-6ebf-4ace-9dff-23157d949719" macaddress="X03MO1qnZdYdgyfeulLPmQ=="/><LISTS><LIST code="OFAC"/></LISTS><QUERY><ITEM operator="" threshold=".90" surname="" givenname="" othername="" unparsedname="" allentities="Smoke Test4" id="" addr1="" addr2="" state="" postalcode="" country="US" countrycodeISO2="" countrycodeISO3="" countrycodeNum="" blockedcountryname="" blockedcountryISO2="" blockedcountryISO3="" blockedcountryNum=""/></QUERY><SEARCHCRITERIA><NUMRECORDS totalhits="0" totalentityhits="0" totalblockedcountryhits="0"/><SEARCHLISTINFORMATION name="Office of Foreign Assets Control" description="2008-02-12 OFAC Source Data" listcode="OFAC"/></SEARCHCRITERIA><MessageHDR><ReplyToQ>I3.OFAC.OUT</ReplyToQ><STATUS>NO HIT</STATUS><PolicyNumber>TGL6298149-00</PolicyNumber><Message>OFAC NAME SEARCH Request Successful - NO HIT ON NAME SENT FOR VALIDATION. POLICY NUMBER: TGL6298149-00</Message><Request><Request><PolicyId><![CDATA[482550000.440315]]></PolicyId><PolicyNumber><![CDATA[TGL6298149-00]]></PolicyNumber><PartyId><![CDATA[482550000.149454]]></PartyId><Name><CommercialName>Smoke Test4</CommercialName><NameDesignationType>Party</NameDesignationType></Name><CountryName>US</CountryName><RequestDate><![CDATA[2008-02-14]]></RequestDate><RequestTime>10:24:27</RequestTime><RequestSystemId>Insure3</RequestSystemId></Request></Request></MessageHDR></ATTUSWATCHDOGRESPONSE></ProcessNameListMessageResult></soap:Body></soap:Envelope>'''.
2008-02-14 22:26:10.419564 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''DECLARE POS1 INTEGER;'' at ('.PROCESS2OCL.CopyEntireMessage', '7.3').
2008-02-14 22:26:10.419599 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''DECLARE POS2 INTEGER;'' at ('.PROCESS2OCL.CopyEntireMessage', '8.3').
2008-02-14 22:26:10.419631 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''DECLARE POS3 INTEGER LENGTH(myString);'' at ('.PROCESS2OCL.CopyEntireMessage', '9.3').
2008-02-14 22:26:10.419670 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''myString'' at ('.PROCESS2OCL.CopyEntireMessage', '9.27'). This resolved to ''myString''. The result was '''<?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><ProcessNameListMessageResult xmlns="http://www.attuswebsolutions.com/AttusTechSystemNameLookup/SearchService"><ATTUSWATCHDOGRESPONSE tranid="10110533029" trandate="2008-02-14 21:26:54" xmlns=""><BILLINGCODE partnerid="8b881326-bd66-4e1b-8b09-d19f37389328" billingid="8b881326-bd66-4e1b-8b09-d19f37389328" functionid="6PI/upEE0epQR5SObftn+s2fW3M=" servicerequest="6PI/upEE0epQR5SObftn+s2fW3M=" password="3d97a1a7-6ebf-4ace-9dff-23157d949719" macaddress="X03MO1qnZdYdgyfeulLPmQ=="/><LISTS><LIST code="OFAC"/></LISTS><QUERY><ITEM operator="" threshold=".90" surname="" givenname="" othername="" unparsedname="" allentities="Smoke Test4" id="" addr1="" addr2="" state="" postalcode="" country="US" countrycodeISO2="" countrycodeISO3="" countrycodeNum="" blockedcountryname="" blockedcountryISO2="" blockedcountryISO3="" blockedcountryNum=""/></QUERY><SEARCHCRITERIA><NUMRECORDS totalhits="0" totalentityhits="0" totalblockedcountryhits="0"/><SEARCHLISTINFORMATION name="Office of Foreign Assets Control" description="2008-02-12 OFAC Source Data" listcode="OFAC"/></SEARCHCRITERIA><MessageHDR><ReplyToQ>I3.OFAC.OUT</ReplyToQ><STATUS>NO HIT</STATUS><PolicyNumber>TGL6298149-00</PolicyNumber><Message>OFAC NAME SEARCH Request Successful - NO HIT ON NAME SENT FOR VALIDATION. POLICY NUMBER: TGL6298149-00</Message><Request><Request><PolicyId><![CDATA[482550000.440315]]></PolicyId><PolicyNumber><![CDATA[TGL6298149-00]]></PolicyNumber><PartyId><![CDATA[482550000.149454]]></PartyId><Name><CommercialName>Smoke Test4</CommercialName><NameDesignationType>Party</NameDesignationType></Name><CountryName>US</CountryName><RequestDate><![CDATA[2008-02-14]]></RequestDate><RequestTime>10:24:27</RequestTime><RequestSystemId>Insure3</RequestSystemId></Request></Request></MessageHDR></ATTUSWATCHDOGRESPONSE></ProcessNameListMessageResult></soap:Body></soap:Envelope>'''.
2008-02-14 22:26:10.419836 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''LENGTH(myString)'' at ('.PROCESS2OCL.CopyEntireMessage', '9.20'). This resolved to ''LENGTH('<?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><ProcessNameListMessageResult xmlns="http://www.attuswebsolutions.com/AttusTechSystemNameLookup/SearchService"><ATTUSWATCHDOGRESPONSE tranid="10110533029" trandate="2008-02-14 21:26:54" xmlns=""><BILLINGCODE partnerid="8b881326-bd66-4e1b-8b09-d19f37389328" billingid="8b881326-bd66-4e1b-8b09-d19f37389328" functionid="6PI/upEE0epQR5SObftn+s2fW3M=" servicerequest="6PI/upEE0epQR5SObftn+s2fW3M=" password="3d97a1a7-6ebf-4ace-9dff-23157d949719" macaddress="X03MO1qnZdYdgyfeulLPmQ=="/><LISTS><LIST code="OFAC"/></LISTS><QUERY><ITEM operator="" threshold=".90" surname="" givenname="" othername="" unparsedname="" allentities="Smoke Test4" id="" addr1="" addr2="" state="" postalcode="" country="US" countrycodeISO2="" countrycodeISO3="" countrycodeNum="" blockedcountryname="" blockedcountryISO2="" blockedcountryISO3="" blockedcountryNum=""/></QUERY><SEARCHCRITERIA><NUMRECORDS totalhits="0" totalentityhits="0" totalblockedcountryhits="0"/><SEARCHLISTINFORMATION name="Office of Foreign Assets Control" description="2008-02-12 OFAC Source Data" listcode="OFAC"/></SEARCHCRITERIA><MessageHDR><ReplyToQ>I3.OFAC.OUT</ReplyToQ><STATUS>NO HIT</STATUS><PolicyNumber>TGL6298149-00</PolicyNumber><Message>OFAC NAME SEARCH Request Successful - NO HIT ON NAME SENT FOR VALIDATION. POLICY NUMBER: TGL6298149-00</Message><Request><Request><PolicyId><![CDATA[482550000.440315]]></PolicyId><PolicyNumber><![CDATA[TGL6298149-00]]></PolicyNumber><PartyId><![CDATA[482550000.149454]]></PartyId><Name><CommercialName>Smoke Test4</CommercialName><NameDesignationType>Party</NameDesignationType></Name><CountryName>US</CountryName><RequestDate><![CDATA[2008-02-14]]></RequestDate><RequestTime>10:24:27</RequestTime><RequestSystemId>Insure3</RequestSystemId></Request></Request></MessageHDR></ATTUSWATCHDOGRESPONSE></ProcessNameListMessageResult></soap:Body></soap:Envelope>')''. The result was ''2069''.
2008-02-14 22:26:10.419875 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''DECLARE POS4 INTEGER;'' at ('.PROCESS2OCL.CopyEntireMessage', '10.3').
2008-02-14 22:26:10.419908 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''DECLARE POS5 INTEGER;'' at ('.PROCESS2OCL.CopyEntireMessage', '11.3').
2008-02-14 22:26:10.419943 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''SET POS1 = POSITION('<Request><Request>' IN myString) + 9;'' at ('.PROCESS2OCL.CopyEntireMessage', '12.9').
2008-02-14 22:26:10.419982 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''myString'' at ('.PROCESS2OCL.CopyEntireMessage', '12.53'). This resolved to ''myString''. The result was '''<?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><ProcessNameListMessageResult xmlns="http://www.attuswebsolutions.com/AttusTechSystemNameLookup/SearchService"><ATTUSWATCHDOGRESPONSE tranid="10110533029" trandate="2008-02-14 21:26:54" xmlns=""><BILLINGCODE partnerid="8b881326-bd66-4e1b-8b09-d19f37389328" billingid="8b881326-bd66-4e1b-8b09-d19f37389328" functionid="6PI/upEE0epQR5SObftn+s2fW3M=" servicerequest="6PI/upEE0epQR5SObftn+s2fW3M=" password="3d97a1a7-6ebf-4ace-9dff-23157d949719" macaddress="X03MO1qnZdYdgyfeulLPmQ=="/><LISTS><LIST code="OFAC"/></LISTS><QUERY><ITEM operator="" threshold=".90" surname="" givenname="" othername="" unparsedname="" allentities="Smoke Test4" id="" addr1="" addr2="" state="" postalcode="" country="US" countrycodeISO2="" countrycodeISO3="" countrycodeNum="" blockedcountryname="" blockedcountryISO2="" blockedcountryISO3="" blockedcountryNum=""/></QUERY><SEARCHCRITERIA><NUMRECORDS totalhits="0" totalentityhits="0" totalblockedcountryhits="0"/><SEARCHLISTINFORMATION name="Office of Foreign Assets Control" description="2008-02-12 OFAC Source Data" listcode="OFAC"/></SEARCHCRITERIA><MessageHDR><ReplyToQ>I3.OFAC.OUT</ReplyToQ><STATUS>NO HIT</STATUS><PolicyNumber>TGL6298149-00</PolicyNumber><Message>OFAC NAME SEARCH Request Successful - NO HIT ON NAME SENT FOR VALIDATION. POLICY NUMBER: TGL6298149-00</Message><Request><Request><PolicyId><![CDATA[482550000.440315]]></PolicyId><PolicyNumber><![CDATA[TGL6298149-00]]></PolicyNumber><PartyId><![CDATA[482550000.149454]]></PartyId><Name><CommercialName>Smoke Test4</CommercialName><NameDesignationType>Party</NameDesignationType></Name><CountryName>US</CountryName><RequestDate><![CDATA[2008-02-14]]></RequestDate><RequestTime>10:24:27</RequestTime><RequestSystemId>Insure3</RequestSystemId></Request></Request></MessageHDR></ATTUSWATCHDOGRESPONSE></ProcessNameListMessageResult></soap:Body></soap:Envelope>'''.
2008-02-14 22:26:10.420031 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''POSITION('<Request><Request>' IN myString)'' at ('.PROCESS2OCL.CopyEntireMessage', '12.20'). This resolved to ''POSITION('<Request><Request>' IN '<?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><soap:Body><ProcessNameListMessageResult xmlns="http://www.attuswebsolutions.com/AttusTechSystemNameLookup/SearchService"><ATTUSWATCHDOGRESPONSE tranid="10110533029" trandate="2008-02-14 21:26:54" xmlns=""><BILLINGCODE partnerid="8b881326-bd66-4e1b-8b09-d19f37389328" billingid="8b881326-bd66-4e1b-8b09-d19f37389328" functionid="6PI/upEE0epQR5SObftn+s2fW3M=" servicerequest="6PI/upEE0epQR5SObftn+s2fW3M=" password="3d97a1a7-6ebf-4ace-9dff-23157d949719" macaddress="X03MO1qnZdYdgyfeulLPmQ=="/><LISTS><LIST code="OFAC"/></LISTS><QUERY><ITEM operator="" threshold=".90" surname="" givenname="" othername="" unparsedname="" allentities="Smoke Test4" id="" addr1="" addr2="" state="" postalcode="" country="US" countrycodeISO2="" countrycodeISO3="" countrycodeNum="" blockedcountryname="" blockedcountryISO2="" blockedcountryISO3="" blockedcountryNum=""/></QUERY><SEARCHCRITERIA><NUMRECORDS totalhits="0" totalentityhits="0" totalblockedcountryhits="0"/><SEARCHLISTINFORMATION name="Office of Foreign Assets Control" description="2008-02-12 OFAC Source Data" listcode="OFAC"/></SEARCHCRITERIA><MessageHDR><ReplyToQ>I3.OFAC.OUT</ReplyToQ><STATUS>NO HIT</STATUS><PolicyNumber>TGL6298149-00</PolicyNumber><Message>OFAC NAME SEARCH Request Successful - NO HIT ON NAME SENT FOR VALIDATION. POLICY NUMBER: TGL6298149-00</Message><Request><Request><PolicyId><![CDATA[482550000.440315]]></PolicyId><PolicyNumber><![CDATA[TGL6298149-00]]></PolicyNumber><PartyId><![CDATA[482550000.149454]]></PartyId><Name><CommercialName>Smoke Test4</CommercialName><NameDesignationType>Party</NameDesignationType></Name><CountryName>US</CountryName><RequestDate><![CDATA[2008-02-14]]></RequestDate><RequestTime>10:24:27</RequestTime><RequestSystemId>Insure3</RequestSystemId></Request></Request></MessageHDR></ATTUSWATCHDOGRESPONSE></ProcessNameListMessageResult></soap:Body></soap:Envelope>')''. The result was ''1526''.
2008-02-14 22:26:10.420104 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''POSITION('<Request><Request>' IN myString) + 9'' at ('.PROCESS2OCL.CopyEntireMessage', '12.63'). This resolved to ''1526 + 9''. The result was ''1535''.
2008-02-14 22:26:10.420125 9096 UserTrace BIP2537I: Node 'I3_OCL_OUT.PROCESS2OCL': Executing statement ''SET POS2 = POSITION('</Request></Request>' IN myString) + 10;'' at ('.PROCESS2OCL.CopyEntireMessage', '13.3').
2008-02-14 22:26:10.420167 9096 UserTrace BIP2539I: Node 'I3_OCL_OUT.PROCESS2OCL': Evaluating expression ''myString'' at ('.PROCESS2OCL.CopyEntireMessa