THIS IS CVP 7.0 VXML Server with ICM 7.5(9) I've just deployed a new ordering application and saw an odd behavior using the "Error Element->Yes".   I set a single element at the end of the app as the Error Element to catch any uncaught errors in my app and normally this works perfectly. With my new app I've implemented an "On Call End" class to capture a bunch of data and store it in a SQL database for custom reporting and CDR purposes.  This particular application performs SAP lookups using the sapjco library, we've been using it for years and are used to it's nuances. Here's what happened: 1) My application performed a SAP RFC via a custom element to get customer info. 2) The SAP RFC custom element resulted in a error,error.badfetch probably from a network issue, no biggie, customer routes to rep. 3) The "Error Element" catches the error just fine, the call goes back to ICM and CVP starts the Call End class. 4) What happens next is odd, the Call End class gets executed completely out of order, or at least it logs to the activity log out of order: a.  The activity log normally has AddToLog of all the stuff I'm collecting, then it shows it writing the CDR text file, then it shows writing to the SQL database.  b.  For this call it shows it writes the CDR file, then writes the SQL database (and the data is correct) and THEN it shows it collecting all the data it needs.  c. Then it shows the custom SAP RFC element exiting about 66 seconds after it entered it. d. Lastly it does the CDR write and SQL update again and the SQL update fails because it tries to write the record using the Session ID which is my primary key for the row. What it "seems" like is the On Call End" class executed twice but it's strange all the debug's I use didn't show up on the first instance.  I guess I'll add a catch for the badfetch in my Hot Links tab but just wanted to ask if anyone has observed this. Here is my debug trace (all the "X's" are to mask private data, there is valid data there) to my Activity Log, you'll see at 14:45.54.779 the RFC is excuted, the bad fetch comes at 14:46.26.810, the CDR and SQL gets written, then the call posts the usualy "end, result, duration" info.  35 seconds after that come the debug statements for collecting the info I need then it writes the CDR and SQL info again right after the SAP RFC element exits at 14:47:01.998.  XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:45:54.779,CL SAPGetCustLookup,custom,INFO,Executing SAPGetCustLookup(XXXXXXXXXX) XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:45:54.779,CL SAPGetCustLookup,interaction,audio_group,initial_audio_group XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.810,CL SAPGetCustLookup,element,error,error.badfetch XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.810,ERROR GlobalErrorCatch,enter, XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.888,ERROR GlobalErrorCatch,exit, XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.888,,custom,INFO,Writing CDR to XXXXXXX.txt XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.888,,custom,INFO,WriteCDR result: success XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.904,,custom,CALLEND,sSQL to write->XXXX) XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.904,,end,how,app_session_complete XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.904,,end,result,normal XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:46:26.904,,end,duration,33 XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,rc=X XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,CreditHold=N XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,CustomerID=XXXX XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,DOB=XXXXXXXX XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,OrderNum= XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,OrderStatus= XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,ShippingDate= XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,ZipCode=XXXXX XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,CustomerFlag=X XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,PayerType=X XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,MRN ID->XXXXX XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,geOrderStatus->X XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,PatientFlag=XX XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,CL SAPGetCustLookup,exit, XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,Writing CDR to XXXXX.txt XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:01.998,,custom,INFO,WriteCDR result: success XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:02.014,,custom,CALLEND,sSQL to write->XXXXX) XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:02.123,,custom,CALLEND,Caught SQL Exception->Violation of PRIMARY KEY constraint 'XXXXX'. XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:02.342,,end,how,app_session_complete XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:02.342,,end,result,normal XX.XX.XX.XX.1351626354247.1162.IVR_Order_System,10/30/2012 14:47:02.342,,end,duration,68  Thanks, Bill Westby

This forum used to hold formatting. Now it’s just so ugly.

Posters take trouble to compose a well-structured question or response, and the forum software turns it into garbage. I’d like to replay, since I also have used the SAP Co for years – but the question is dense.

Can we get the forum software fixed?

Regards,
Geoff

I agree Bill, that looks really odd for you to get 2
app_session_completes showing up in the log. I'm wondering if your end
of call java is causing another error that's being re-handled by the
same code.

By the way, until you sort this out, you might try logging (include your
own time stamp) to a file or STDOUT to ensure that you can determine the
order of the logged data.

I've seen some odd things with CVP 8 where timing seems suspicious in
the logs. For example, with a Digits element, it's not unusual to see
the Data created logged before the Interaction (since this is all logged
in separate threads), but usually the time stamp indicates that the
interaction occurred before the variables were created (as I'd expect).

What's strange is that if my Digits element has a Done Audio Group,
where I repeat back the caller's entry , the time stamp on the Done
audio group is the same as for the Initial prompt - indicating that it
played before the Data was created.

Obviously this isn't happening. The VG returns the caller entered data
to VXMLServer and VXML Server sends a new VXML page to the gateway
containing the Done audio group. So, it's just odd that the time stamp
of the Done is not correct.

David,

You can see that it mangled your message in producing this email – it used to do a better job. But I could deal with that if I could post properly.

You have headed down the wrong track – this is nothing to do with HTML formatting, and I am sure that most of us who work with forums know BBCode. What we are talking about is a simple ability to support paragraphs.

I am replying through an email client – Outlook. It actually does a decent job. But I will next log into the forum and post exactly the same message, with the same three paragraphs, a greeting, and a signature – and you will see what happens.

Regards,
Geoff

Hi Janine, hope all is fantastic!! I think I'll add the stdout logging,
good idea. I can't see the On Call End class calling itself, its linear
and I'm catching everything and logging exceptions, don't see any except
the SQL exception which is due to the fact it's being called twice.

I'm not going to spend a lot of time on it, Like Mike A suggested, I'm just
going to set a session var before my subdialog returns and if the var isn't
set I'll know it was a global error and I'll just skip over the call end
code. Or I could look at the caller_input return value too, either way.
Or catch the badfetch error too, so many choices LOL.

I don't doubt I've done something wrong somewhere but this I've been using
these same RFC elements for 3 years with no issues and what baffles me is
why the debug code in the Call End class refuses to output for one of the
two instances, freaky for sure. Since we are on 7.0 and moving to 8.5 in
January like I said I'll just handle it in the code and be done with it.

Thanks for the reply!!

Bill.

On Wed, Oct 31, 2012 at 8:23 AM, Cisco Developer Community Forums <
cdicuser@developer.cisco.com> wrote:

> Janine Graves has created a new message in the forum "General Discussion -
> All Versions":
> -------------------------------------------------------------- I agree
> Bill, that looks really odd for you to get 2
> app_session_completes showing up in the log. I'm wondering if your end
> of call java is causing another error that's being re-handled by the
> same code.
>
> By the way, until you sort this out, you might try logging (include your
> own time stamp) to a file or STDOUT to ensure that you can determine the
> order of the logged data.
>
> I've seen some odd things with CVP 8 where timing seems suspicious in
> the logs. For example, with a Digits element, it's not unusual to see
> the Data created logged before the Interaction (since this is all logged
> in separate threads), but usually the time stamp indicates that the
> interaction occurred before the variables were created (as I'd expect).
>
> What's strange is that if my Digits element has a Done Audio Group,
> where I repeat back the caller's entry , the time stamp on the Done
> audio group is the same as for the Initial prompt - indicating that it
> played before the Data was created.
>
> Obviously this isn't happening. The VG returns the caller entered data
> to VXMLServer and VXML Server sends a new VXML page to the gateway
> containing the Done audio group. So, it's just odd that the time stamp
> of the Done is not correct.
> --
> To respond to this post, please click the following link:
> http://developer.cisco.com/web/cvp/forums/-/message_boards/view_message/8180541or simply reply to this email.