In my application I am calling a WSOP2 inside a Try-Catch with timeout set to 10 seconds. After 10 seconds the WSOP comes back with "Axis Fault message <- Read timed out". I am seeing this in the VXML log. But this error is not caught by the Catch, instead the http session gets removed. Note: I have set the Global Fetch Timeout in the app to 60 seconds.

Here is the log snippet showing the WSOP2 and the actions thereafter:


07/08/2018 13:26:41:600 INFO - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Calling method [{http://tempuri.org/}TranscriptionRequest] on web service [TranscribeRequest] at [http://10.101.253.40/SurveyRecordings/Service1.svc]
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:26:41:631 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:26:41:647 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Web Service Request -> <?xml version='1.0' encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><ns1:TranscriptionRequest xmlns:ns1="http://tempuri.org/"><ns1:Ucid>00001009761533673564</ns1:Ucid><ns1:questionNumber>5</ns1:questionNumber><ns1:customerId>TEST</ns1:customerId></ns1:TranscriptionRequest></soapenv:Body></soapenv:Envelope>
07/08/2018 13:26:51:647 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Axis Fault message <- Read timed out
07/08/2018 13:26:51:647 ERROR - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Got AxisFault during web service call: Read timed out
07/08/2018 13:26:51:647 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Fault action <- null
07/08/2018 13:26:51:647 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Fault node <- null
07/08/2018 13:26:51:647 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Fault role <- null
07/08/2018 13:26:51:647 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Fault type <- 0
07/08/2018 13:26:51:647 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Fault message <- Read timed out
07/08/2018 13:26:51:662 INFO - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : HTTP Session lost removing SCESession 9CA684E11F58E8D6A28513A217B97840
07/08/2018 13:26:51:662 INFO - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : SCESession Removed
07/08/2018 13:26:51:662 DEBUG - 9CA684E11F58E8D6A28513A217B97840:/SurveyRCCL : Removing 1 session stack frames.


The puzzling thing is if logging is enabled for this application in AEP, then the Catch is working. Please see the attached AppLog.snag that shows the logging enabled for "Runtime Traces".

Here is the VXML log for this scenario:


07/08/2018 13:39:33:241 INFO - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Calling method [{http://tempuri.org/}TranscriptionRequest] on web service [TranscribeRequest] at [http://10.101.253.40/SurveyRecordings/Service1.svc]
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
07/08/2018 13:39:33:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
07/08/2018 13:39:43:272 ERROR - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Got AxisFault during web service call: Read timed out
07/08/2018 13:39:43:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Fault action <- null
07/08/2018 13:39:43:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Fault node <- null
07/08/2018 13:39:43:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Fault role <- null
07/08/2018 13:39:43:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Fault type <- 0
07/08/2018 13:39:43:272 DEBUG - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Fault message <- Read timed out
07/08/2018 13:39:43:272 INFO - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Using SCESession ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL servlet : Hang_Up-Set_WS2_Error
07/08/2018 13:39:43:272 INFO - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Assigning [10] to [LogVariables:LogEventCode]
07/08/2018 13:39:43:272 INFO - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Assigning [RowsReturned] to [LogVariables:LogErrorCode]
07/08/2018 13:39:43:272 INFO - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Assigning [Web service call to trancribe request failed] to [LogVariables:LogComments]
07/08/2018 13:39:43:272 INFO - ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL : Using SCESession ED11E7ECBDB817D884055981DDB726E1:/SurveyRCCL servlet : Hang_Up-LogWS_Error


One final note - this issue is happening in one of our customer site too and the customer opened up a ticket with Avaya Services. The ticket number was "Service Request SR 1-13828558543".

Please let me know if you need more log info.

Appreciate your help on this.

Thanks.

Interesting. By looking at the logs for the 1st case, I can't say the catch works or not. The timeout works and the execution comes back print out the AxisFault but the http session ends without any reason. Can you add some logs to the catch to determine if the catch executes or not? Also you can enable the Show Caught Exceptions option to print out the exception stack trace too.

Hi Wilson,

This is getting more weirder.
As per your instruction I added a trace item inside my catch and deployed it without enabling the showcaughtexceptions. And this is what I got: httpsession was lost

15/08/2018 11:20:57:287 INFO - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Calling method [{http://tempuri.org/}TranscriptionRequest] on web service [TranscribeRequest] at [http://10.101.253.40/SurveyRecordings/Service1.svc]
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:20:57:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:21:07:318 ERROR - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Got AxisFault during web service call: Read timed out
15/08/2018 11:21:07:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Fault action <- null
15/08/2018 11:21:07:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Fault node <- null
15/08/2018 11:21:07:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Fault role <- null
15/08/2018 11:21:07:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Fault type <- 0
15/08/2018 11:21:07:318 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Fault message <- Read timed out
15/08/2018 11:21:07:334 INFO - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : HTTP Session lost removing SCESession 4EBEBA17F25989D4EA463FAF021B3DCB
15/08/2018 11:21:07:334 INFO - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : SCESession Removed
15/08/2018 11:21:07:334 DEBUG - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : Removing 1 session stack frames.
15/08/2018 11:21:07:334 INFO - 4EBEBA17F25989D4EA463FAF021B3DCB:/SurveyRCCL : ** Popped Stack Frame [/SurveyRCCL]



But then I added the "showcaughtexceptions" line in my ddrt.properties file, but left it disabled.
Just adding this line made the catch to work, here is the log: please see my trace item(in bold) in the catch.

15/08/2018 11:19:36:115 INFO - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Calling method [{http://tempuri.org/}TranscriptionRequest] on web service [TranscribeRequest] at [http://10.101.253.40/SurveyRecordings/Service1.svc]
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Admin VariableField:getStringValue(): return string value for Survey_Parms:CustomerID
15/08/2018 11:19:36:162 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : get param for app: 0:SurveyRCCL_DEV
15/08/2018 11:19:46:177 ERROR - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Got AxisFault during web service call: Read timed out
15/08/2018 11:19:46:177 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Fault action <- null
15/08/2018 11:19:46:177 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Fault node <- null
15/08/2018 11:19:46:177 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Fault role <- null
15/08/2018 11:19:46:177 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Fault type <- 0
15/08/2018 11:19:46:177 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Fault message <- Read timed out
15/08/2018 11:19:46:177 DEBUG - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : session id:mpp02-san-2018227181902-7 | SurveyRCCL:Hang_Up-TranscribeRequest | web service exception: | ddLastException:message : Read timed out
15/08/2018 11:19:46:177 INFO - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Using SCESession 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL servlet : Hang_Up-Set_WS2_Error
15/08/2018 11:19:46:177 INFO - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Assigning [10] to [LogVariables:LogEventCode]
15/08/2018 11:19:46:177 INFO - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Assigning [RowsReturned] to [LogVariables:LogErrorCode]
15/08/2018 11:19:46:177 INFO - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Assigning [Web service call to trancribe request failed] to [LogVariables:LogComments]
15/08/2018 11:19:46:177 INFO - 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL : Using SCESession 7E7F94CA0F23C026287280A40F5DE63F:/SurveyRCCL servlet : Hang_Up-LogWS_Error


Also attached is the log with "showcaughtexceptions=enabled". Since it is big I have added it as an attachment "showcaughtenable.txt"

This is really odd. I checked the code. The log property has nothing to do with it. I also ran some tests in my environment with OD 7.2.1 (no recent changes between 7.0 and 7.2.1) and was not able to reproduce the problem. I can't really explain what's happening. If you can reproduce it with a simple app and send it to me, I would be happy to take a look.

Sorry, I realize you are actually doing a REST call not the traditional WS. I found the problem. I will post a patch/workaround later.

Give this hot fix a try.

Hi Wilson,

Sorry for my late reply.

We are using axis2 web service not REST.

As you suggested before I created a small test app in OD 7.1.0.1202 where it just calls a AXIS2 webservice to one of our internal endpoints. This endpoint times out and the OD app http session times out when the "showcaughtexceptions" entry does not exist in ddrt file. But if the entry is there, the web service exception is caught and it takes the exception path in the call flow.
Please see attached my test app and its log.
The log file contains scenario of both when the "showcaughtexceptions" entry is present and not present.

Appreciate your help.

Thanks

For some reason, I ran your app in the 7.2.1 environment but don't see any problem with all the properties in ddrt.properties disable and showcaughtexceptions removed.
Anyways, I guess you will be OK even you have to introduce the line no the trace log not needed to be enabled. Right?

I am facing the same issue. Exception not caught, please help.