Re: Call Studio scripts stop working

nstankovic · ‎08-18-2020

We have specific problem in our IVR applications that will be used for outbound.
When we deploy the Call Studio application to VXML server, and restart server, it works normally. After some time, when high load comes on the VXML server (this is production VXML server with a lot of inbound calls), our application just stops working. And it doesn’t work until we restart VXML server again.
We are using custom node and library as Acqueon LCM REST API client. LCM server is in local network and responses in milliseconds. You can see in the following log that after LCM API invocation VXML server just stops giving responses to VVB and the badfetch error happens:

10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,newcall,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,ani,00381653537625
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,areacode,NA
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,exchange,NA
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,dnis,6661111000
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,uui,NA
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,iidigits,NA
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,parameter,callid=83363441AFDE11EA8C3F888C5DAE5E5D
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,parameter,_ani=00381653537625
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,parameter,ann_folder=OUTBOUND_OPS_CG
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,parameter,language=bg-bg
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,parameter,_dnis=6661111000
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,,start,parameter,lcm_account_number=16|6|3|0|0|62|-1
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.971,CVP Subdialog Start,enter,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.986,CVP Subdialog Start,exit,done
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.986,__Set Audio Path,enter,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.986,__Set Audio Path,exit,done
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.986,Connect Silence,enter,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.992,Connect Silence,interaction,audio_group,initial_audio_group
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.986,Connect Silence,exit,done
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:46.986,__Set Global Variables,enter,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.002,__Set Global Variables,custom,endpoin_GetContactDetail,Success
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.002,__Set Global Variables,custom,accountNumber,Success
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.002,__Set Global Variables,custom,priority,Success
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.017,__Set Global Variables,custom,ivrEntry,Success
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.017,__Set Global Variables,custom,transfer_reason,Success
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.017,__Set Global Variables,custom,Result,Success
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.017,__Set Global Variables,exit,done
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.017,__WS_GetContactDetail_01,enter,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.064,__WS_GetContactDetail_01,custom,__WS_GetContactDetail_01_result,{
"customerCode" : "1234"
"customerName" : "test"
"baCode" : "9002151425"
"baName" : "test bname"
"routingPointId" : "321"
"cmsTaskLink" : "task link"
"balance" : "321.21"
"invoiceNumber" : "12345"
"invoiceDate" : "двайсет и трети декември две хиляди двайсет и първа година "
"campaignType" : "test type"
"description" : "description"
"listName" : "test collection list"
"callingListName" : "test collection calling list"
}
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.064,__WS_GetContactDetail_01,element,warning,A substitution representing Element data from element "__WS_GetContactDetail_01" and variable named "exception" referred to non-existent information. An empty string was substituted instead.
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.064,__WS_GetContactDetail_01,custom,__WS_GetContactDetail_01_exception,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.064,__WS_GetContactDetail_01,exit,done
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.064,__Check_GetContactDetailRes,enter,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.064,__Check_GetContactDetailRes,exit,default
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.064,__SetContactData,enter,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:34:47.070,__SetContactData,interaction,audio_group,initial_audio_group
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:35:09.050,__SetContactData,element,error,error.badfetch: request (http://ccprodcvp1a.ad.btk.bg:7000/CVP/Server) was timed out after 20000 milliseconds.
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:35:09.050,__SetContactData,exit,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:35:09.050,,element,error,
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:35:10.487,,end,how,disconnect
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:35:10.487,,end,result,error
10.24.70.74.1592404486971.132385.OUTBOUND_OPS_CG,06/17/2020 17:35:10.487,,end,duration,24

And this is not always the same, sometimes it disconnects even before our custom node:

10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,newcall,
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,ani,0877225837
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,areacode,087
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,exchange,722
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,dnis,6661111000
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,uui,NA
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,iidigits,NA
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,parameter,callid=F1A2267CBB7711EA82D49009BA5CBC2C
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,parameter,_ani=0877225837
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,parameter,ann_folder=OUTBOUND_OPS_CG
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,parameter,language=bg-bg
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,parameter,_dnis=6661111000
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,,start,parameter,lcm_account_number=16|6|3|0|0|62|-1
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,CVP Subdialog Start,enter,
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,CVP Subdialog Start,exit,done
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,__Set Audio Path,enter,
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,__Set Audio Path,exit,done
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.121,Connect Silence,enter,
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.131,Connect Silence,interaction,audio_group,initial_audio_group
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.152,Connect Silence,exit,done
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.152,__Set Global Variables,enter,
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.152,__Set Global Variables,custom,endpoin_GetContactDetail,Success
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:50:54.162,__Set Global Variables,interaction,audio_group,initial_audio_group
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:51:56.155,__Set Global Variables,element,error,error.badfetch: request (http://ccprodcvp1a.ad.btk.bg:7000/CVP/Server) was timed out after 60000 milliseconds.
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:51:56.155,__Set Global Variables,exit,
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:51:56.155,,element,error,
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:51:57.609,,end,how,disconnect
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:51:57.609,,end,result,error
10.24.70.74.1593679854121.235437.OUTBOUND_OPS_CG,07/02/2020 11:51:57.609,,end,duration,63

In the examples above, the problem always happens in Set Value node from Math section in Call studio. You would say that we have some problems in calculation in those nodes. But we are sure that this is not the case because there is no calculation in __Set Global Variables node (second example). And also, how is it possible application to start working normally after VXML server restart?

Another important thing is that sample IVR application without custom parts works normally.
Also, we have tried the same application on inbound and it doesn’t work as well. So, we concluded that there is no Cisco dialer issue but more likely VXML server issue.

One more thing that could be symptomatic is heap memory of VXML server.

We did heap dump in both situations – before and after VXML server restart.
In heap dump before restart you can see a lot of objects of type com.audium.server.controller.AudiumServerConfiguration.jsEnginePool that might cause memory leak (heap_before_restart.png).
On the other hand, in heap dump after VXML server restart, number of those objects is a way smaller (heap_after_restart.png).

We don’t know much about those Java classes and why we have so many of them in memory but it can be a problem for sure. We can conclude that these classes have to do something with Java Script and Set Value node is based on JS.

david.macias · ‎08-18-2020

Is every __Set Global Variables its own VXML element? Can you collapse them to one? Sounds like you have a memory leak, finding where might be a bit tricky specially as I assume that you're running multiple apps. Is this the only one that stops working or is this the only one you notice immediately because it's used so much?

I've used this in the past (many years ago) when I was chasing a memory leak problem give it a shot and see if it helps. https://www.cisco.com/c/en/us/support/docs/customer-collaboration/unified-customer-voice-portal/210796-CVP-Memory-Troubleshooting-with-Jconsole.pdf

david

Blog

nstankovic · ‎03-09-2022

Hi guys,

After long story with Cisco support the outcome is that you should not use Set Value node too much. Actually, we really liked to use it because we could do a quick if-else or quick loop without complicating the flow with many nodes.

To make long story short, our suggestion is - do not use Set Value node at all on CVP versions 12+. It has some low level issues on Java 8 which can not be overcome.

Even if you have only few of them, in some of the applications that are not highly loaded, you should consider removing it. This node can cause strange issues which can not be easily tracked. For instance, we observed some of the calls being dropped without any errors or alarms, just disconnected. Other strange issue is already described in my post here. And keep in mind that Set Value node in only one application can affect performances and behavior of all the other applications on the server.

I hope this is going to be helpful to someone, not to end up like us redesigning all the applications.

Best regards,

Nikola

david.macias · ‎03-09-2022

This doesn't make sense, can you push TAC to provide a bug ID?

david

Blog

nstankovic · ‎05-06-2022

Cisco provided a fix - CSCvx14235.

This fix basically replaces Nashorn with Rhino. Rhino prevents a lot of strange behaviors, but still, there are performance issues.

Nikola