CVP VXML Services needing to be restarted

Albert Edwards · ‎09-16-2011

Has anyone experience the need to restart the CVP VXML Server services, due to calls failing to Run Ext. Script (routing_VXML).If so what was the problem. License ?

Sent from Cisco Technical Support iPad App

Kris Lambrechts · ‎09-19-2011

That's a really rather vague description. This could have a multitude of causes, you'd really have to provide some more information, some log snippets that you've found etc..

Licensing seems rather unlikely though, if a license has expired or is otherwise invalid, that won't be resolved by a restart.

Cheers,

Kris

Albert Edwards · ‎09-21-2011

Thanks Kris, Here are some of the logs I found, take a look and tell me what you think. Thanks.

4246777: 10.100.2.40: Sep 15 2011 06:51:52.684 -0700: %CVP_4_0_IVR-3-CALL_ERROR: CALLGUID=A814E956-DED811E0-A95C001E-F7EC5070 DNIS=81111111115250 CVP VXML Server encountered a Bad-Fetch Error - URL:

http://vxmlserver:7000/CVP/en-us/../Server?Dial=70307&ANI=2283042381&CallID=A814E956-DED811E0-A95C001E-F7EC5070&application=National_Recruiting

(Client: 10.100.2.15) [id:3023]

4246778: 10.100.2.40: Sep 15 2011 06:51:52.684 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [CVP_BAD_FETCH(45)] CALLGUID: A814E956-DED811E0-A95C001E-F7EC5070 DNIS=81111111115250 {VRUScriptName: 'GS,Server,V,1' ConfigParam: ''} [id:3023]

4247427: 10.100.2.40: Sep 15 2011 08:01:50.106 -0700: %CVP_4_0_IVR-3-CALL_ERROR: CALLGUID=5BFED561-DEE211E0-9B99DB67-C9288B6A DNIS=81111111117105 CVP VXML Server encountered a Bad-Fetch Error - URL:

http://vxmlserver:7000/CVP/en-us/../Server?Dial=70307&ANI=9805212726&CallID=5BFED561-DEE211E0-9B99DB67-C9288B6A&application=National_Recruiting

(Client: 10.100.4.15) [id:3023]

4247428: 10.100.2.40: Sep 15 2011 08:01:50.106 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.4.15 [CVP_BAD_FETCH(45)] CALLGUID: 5BFED561-DEE211E0-9B99DB67-C9288B6A DNIS=81111111117105 {VRUScriptName: 'GS,Server,V,1' ConfigParam: ''} [id:3023]

4247429: 10.100.2.40: Sep 15 2011 08:01:52.824 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [NO_ENTRY(17)] CALLGUID: 52DB3934-DEE211E0-82DCA6BA-BD15AF92 DNIS=81111111117099 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]

4247430: 10.100.2.40: Sep 15 2011 08:01:55.981 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.4.15 [NO_ENTRY(17)] CALLGUID: 302769E5-DEE211E0-BA10001E-F7EC4F50 DNIS=81111111117073 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]

4247431: 10.100.2.40: Sep 15 2011 08:02:07.168 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [NO_ENTRY(17)] CALLGUID: 52DB3934-DEE211E0-82DCA6BA-BD15AF92 DNIS=81111111117099 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]

4247432: 10.100.2.40: Sep 15 2011 08:02:37.668 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [NO_ENTRY(17)] CALLGUID: 0FF7812D-DEE211E0-AB4F001E-F7EC5070 DNIS=81111111117038 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]

4247433: 10.100.2.40: Sep 15 2011 08:02:44.903 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.4.15 [NO_ENTRY(17)] CALLGUID: 302769E5-DEE211E0-BA10001E-F7EC4F50 DNIS=81111111117073 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]

4247434: 10.100.2.40: Sep 15 2011 08:02:49.262 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 209.201.73.6 [NO_ENTRY(17)] CALLGUID: 85F8E4EE-DEE211E0-85490014-6AEC4E38 DNIS=81111111117143 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]

4246777: 10.100.2.40: Sep 15 2011 06:51:52.684 -0700: %CVP_4_0_IVR-3-CALL_ERROR: CALLGUID=A814E956-DED811E0-A95C001E-F7EC5070 DNIS=81111111115250 CVP VXML Server encountered a Bad-Fetch Error - URL: http://vxmlserver:7000/CVP/en-us/../Server?Dial=70307&ANI=2283042381&CallID=A814E956-DED811E0-A95C001E-F7EC5070&application=National_Recruiting

(Client: 10.100.2.15) [id:3023]

4246778: 10.100.2.40: Sep 15 2011 06:51:52.684 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [CVP_BAD_FETCH(45)] CALLGUID: A814E956-DED811E0-A95C001E-F7EC5070 DNIS=81111111115250 {VRUScriptName: 'GS,Server,V,1' ConfigParam: ''} [id:3023]

4247427: 10.100.2.40: Sep 15 2011 08:01:50.106 -0700: %CVP_4_0_IVR-3-CALL_ERROR: CALLGUID=5BFED561-DEE211E0-9B99DB67-C9288B6A DNIS=81111111117105 CVP VXML Server encountered a Bad-Fetch Error - URL: http://vxmlserver:7000/CVP/en-us/../Server?Dial=70307&ANI=9805212726&CallID=5BFED561-DEE211E0-9B99DB67-C9288B6A&application=National_Recruiting (Client: 10.100.4.15) [id:3023]
4247428: 10.100.2.40: Sep 15 2011 08:01:50.106 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.4.15 [CVP_BAD_FETCH(45)] CALLGUID: 5BFED561-DEE211E0-9B99DB67-C9288B6A DNIS=81111111117105 {VRUScriptName: 'GS,Server,V,1' ConfigParam: ''} [id:3023]
4247429: 10.100.2.40: Sep 15 2011 08:01:52.824 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [NO_ENTRY(17)] CALLGUID: 52DB3934-DEE211E0-82DCA6BA-BD15AF92 DNIS=81111111117099 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]
4247430: 10.100.2.40: Sep 15 2011 08:01:55.981 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.4.15 [NO_ENTRY(17)] CALLGUID: 302769E5-DEE211E0-BA10001E-F7EC4F50 DNIS=81111111117073 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]
4247431: 10.100.2.40: Sep 15 2011 08:02:07.168 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [NO_ENTRY(17)] CALLGUID: 52DB3934-DEE211E0-82DCA6BA-BD15AF92 DNIS=81111111117099 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]
4247432: 10.100.2.40: Sep 15 2011 08:02:37.668 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.2.15 [NO_ENTRY(17)] CALLGUID: 0FF7812D-DEE211E0-AB4F001E-F7EC5070 DNIS=81111111117038 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]
4247433: 10.100.2.40: Sep 15 2011 08:02:44.903 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 10.100.4.15 [NO_ENTRY(17)] CALLGUID: 302769E5-DEE211E0-BA10001E-F7EC4F50 DNIS=81111111117073 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]
4247434: 10.100.2.40: Sep 15 2011 08:02:49.262 -0700: %CVP_4_0_IVR-3-CALL_ERROR: RunScript Error from 209.201.73.6 [NO_ENTRY(17)] CALLGUID: 85F8E4EE-DEE211E0-85490014-6AEC4E38 DNIS=81111111117143 {VRUScriptName: 'M,-1' ConfigParam: '1-9/*/#/0,Y,3,1,1,N,N'} [id:3023]

david.macias · ‎09-21-2011

So, you're saying this works just fine then all of a sudden it starts to fail? If so, are you sure nothing else changes? The log you posted shows a lot of fetch errors, are all your promps in the right location and accessible?

david

Blog

Albert Edwards · ‎09-21-2011

Yes, that is what I'm saying. It was working fine, with no changes. However I found some new logs that may suggest there a memory problem.

Sep 15, 2011 10:01:38 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:01:43 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:01:59 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:02:05 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:02:28 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:02:28 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:02:51 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:03:07 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:03:26 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:03:26 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:03:57 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:03:57 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:03:57 AM org.apache.coyote.http11.Http11AprProcessor process
SEVERE: Error processing request
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:04:20 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:05:33 AM org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:09:38 AM org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor processChildren
SEVERE: Exception invoking periodic operation:
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:12:21 AM org.apache.coyote.http11.Http11AprProcessor process
SEVERE: Error processing request
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 10:12:23 AM org.apache.coyote.http11.Http11AprProcessor process
SEVERE: Error processing request
java.lang.OutOfMemoryError: Java heap space
Sep 15, 2011 11:26:47 AM org.apache.coyote.http11.Http11AprProtocol pause
INFO: Pausing Coyote HTTP/1.1 on http-7000
Sep 15, 2011 11:26:47 AM org.apache.coyote.http11.Http11AprProtocol pause
INFO: Pausing Coyote HTTP/1.1 on http-7443
Sep 15, 2011 11:26:47 AM org.apache.coyote.ajp.AjpAprProtocol pause
INFO: Pausing Coyote AJP/1.3 on ajp-7009
Sep 15, 2011 11:26:48 AM org.apache.catalina.core.StandardService stop
INFO: Stopping service Catalina
Sep 15, 2011 11:26:48 AM org.apache.catalina.session.StandardManager stop
SEVERE: Exception unloading sessions to persistent storage
java.lang.OutOfMemoryError: Java heap space

Unloading application 'CorporateCalls'...DatafeedLogger.destroy(): datafeeed logger CorporateCalls_CVPDatafeedLog_com.cisco.cvp.vxml.datafeed.DatafeedLogger@1582a7c is unregistered.
Done
Unloading application 'KNGT_RecordAudio'...DatafeedLogger.destroy(): datafeeed logger KNGT_RecordAudio_CVPDatafeedLog_com.cisco.cvp.vxml.datafeed.DatafeedLogger@130998 is unregistered.
Done
Unloading application 'National_Recruiting'...DatafeedLogger.destroy(): datafeeed logger National_Recruiting_CVPDatafeedLog_com.cisco.cvp.vxml.datafeed.DatafeedLogger@1728ebb is unregistered.
Done
Unloading application 'PriorityCode_Lookup'...DatafeedLogger.destroy(): datafeeed logger PriorityCode_Lookup_CVPDatafeedLog_com.cisco.cvp.vxml.datafeed.DatafeedLogger@17a7706 is unregistered.
Done
Unloading application 'National_Shop'...DatafeedLogger.destroy(): datafeeed logger National_Shop_CVPDatafeedLog_com.cisco.cvp.vxml.datafeed.DatafeedLogger@1f2edd2 is unregistered.
Done
Exception in thread "Cisco Unified CVP VoiceXML Server: Logger Manager" java.lang.NullPointerException
at com.audium.server.globalLogging.a.for(SourceFile:52)
at com.audium.server.globalLogging.d.(SourceFile:14)
at com.audium.server.globalLogging.GlobalLoggerFactory.if(SourceFile:181)
at com.audium.server.globalLogging.GlobalLoggerFactory.if(SourceFile:69)
at com.audium.server.globalLogging.e.a(SourceFile:56)
at com.audium.server.globalLogging.e.a(SourceFile:42)
at com.audium.server.logger.b.run(SourceFile:183)
at java.lang.Thread.run(Unknown Source)
Sep 15, 2011 11:27:21 AM org.apache.coyote.http11.Http11AprProtocol destroy
INFO: Stopping Coyote HTTP/1.1 on http-7000
Sep 15, 2011 11:27:21 AM org.apache.coyote.http11.Http11AprProtocol destroy
INFO: Stopping Coyote HTTP/1.1 on http-7443
Sep 15, 2011 11:27:21 AM org.apache.coyote.ajp.AjpAprProtocol destroy
INFO: Stopping Coyote AJP/1.3 on ajp-7009

geoff · ‎09-21-2011

You should examine what parameters you are giving to the JVM. Look in

HKEY_LOCAL_MACHINE\SOFTWARE\Apache Software Foundation\Procrun 2.0\VXMLServer\Parameters\Java

and Options (some irrelevant stuff omitted)

-Djre.home=C:\Cisco\CVP\jre

...

-XX:NewSize=512m

-XX:MaxNewSize=512m

-Xms1024m

-Xmx1024m

...

-DAudium.Home=C:\Cisco\CVP\VXMLServer

If this is a lab system - an all in one - there are so many Tomcat processes competing for memory you'd better have lots.

What's the hardware?

What Cisco processes are installed?

What else do you have? A SQL Server for example would be a bad idea.

Regards,

Geoff

Albert Edwards · ‎09-22-2011

Thanks Geoff, Here are the answers, to your questions.

1).Production,

2). MCS 7845 Servers

3). Call Server/VXML

4).SQL not installed

I pulled a of my Hkey file for you review or commits.

HKEY_LOCAL_MACHINE\SOFTWARE\Apache Software Foundation\Procrun 2.0\VXMLServer\Parameters\Java

Djre.home=C:\Cisco\CVP\jre

-Dcatalina.base=C:\Cisco\CVP\VXMLServer\Tomcat

-Dcatalina.home=C:\Cisco\CVP\VXMLServer\Tomcat

-Djava.endorsed.dirs=C:\Cisco\CVP\VXMLServer\Tomcat\common\endorsed

-Djava.io.tmpdir=C:\Cisco\CVP\VXMLServer\Tomcat\temp

-DCVP_HOME=C:\Cisco\CVP

-XX:NewSize=512m

-XX:MaxNewSize=512m

-Xms1024m

-Xmx1024m

-XX:+ForceTimeHighResolution

-XX:SurvivorRatio=5

-XX:TargetSurvivorRatio=90

-XX:MaxTenuringThreshold=12

-XX:+UseConcMarkSweepGC

-XX:+CMSIncrementalMode

-XX:+CMSIncrementalPacing

-XX:+CMSParallelRemarkEnabled

-XX:+UseParNewGC

-XX:+UseTLAB

-XX:+CMSClassUnloadingEnabled

-XX:+CMSPermGenSweepingEnabled

-DAudium.Home=C:\Cisco\CVP\VXMLServer

Thanks,

Albert~

geoff · ‎09-22-2011

So a production box with 4GB of RAM.

It's not an Ops Console so the Tomcats you have are the Call Server and the VXML Server. If you are on 8.0 you will also have the Tomcat 6 for the WSM and it wants memory. Do you have that?

If you look at the system after it's been running for a while and see how much memory the two/three Tomcats are using and how much headroom from that 4GB you have, you may be able to increase the maximum heap space on your VXML server. Java programs often leak and although there is automatic garbage collection, they will often grow over time.

You should monitor the situation for a while. A regular scheduled restart of VXML doesn't hurt.

Regards,

Geoff

Kris Lambrechts · ‎09-23-2011

Thanks for having a further look through the logs, so the reason you see those errors in the Call Server logs is because the VXML Server or at least those apps that were trying to call went down. On the VXML Server logs, you can see indeed quite nicely that the VXML Server unloaded several of your vxml applications.

The VXML Server ran out of memory, that can have two causes

It genuinly needs more memory than it currently has because of the call volume;
Your VXML Server is leaking memory.

In my experience, the bare VXML Server is pretty much rock stable and doesn't really leak memory by itself and leaks that we do find are usually in custom / third-party Java code. So if you want to get to the bottom of this, you'd want to start monitoring your VXML Server memory. From the JVM parameters you've supplied this seems to be a 7.0 (or earlier) CVP, in 8.0 we open up the JMX port by default. You'll easily find documentation on the Tomcat webpage on how to enable the JMX port.

Through JMX you can monitor the memory and CPU utilization inside the VXML Server JVM real-time. You'll want to set a baseline, i.e. how much memory does it consume just after start-up & how much during normal call load. Check it daily, if the memory usage creeps up slowly you have a leak. There's some really cool open source tools that can profile your VXML Server real-time and tell you which threads are retaining all that memory (and which use the most CPU).

Have a look at VisualVM, truely magnificient application to do this kind of analysis.

If this happened only once in a year and you feel all of the above is a bit too much work, you can just allocate the VXML Server some more memory like Geoff explained ofcourse.

Cheers,

Kris