Re: UCCE 11.5 - CVP Errors and incoming calls being dropped

Slavik Bialik · ‎10-14-2017

Hi all,

I need help investigating a problem. I have a client that lately something is wrong with his CVPs and the custom VXML application that are on it.

It usually when we get a call from the client that he tell us that incoming calls aren't working. When you try to call, you get the famous "I'm sorry..." prompt.

I just need to mention before all, that those custom CVP application that are running on his CVP, are running in all of our customers and everything works smoothly.

Anyway, just some background:

We're running UCCE 11.5 - 2000 Agent deployment. With a VVB servers as VXML gateways.

All of UCCE components are on the same LAN, so there's nothing between like Firewalls and such.

Investigating further, I found errors in all kind of logs.

When going to one of the VXML application error logs, I have lots of:

10.100.50.24 - is the IP of CVP.

10.100.50.24.1507036165309.353248.CheckBehavior,10/03/2017 16:10:11.012,An error was encountered while attempting to log an event with the ID "elementExit". The error was: java.lang.IllegalStateException: getAttribute: Session already invalidated The error was: java.lang.IllegalStateException: getAttribute: Session already invalidated

java.lang.IllegalStateException: getAttribute: Session already invalidated

at org.apache.catalina.session.StandardSession.getAttribute(StandardSession.java:1190)

at org.apache.catalina.session.StandardSessionFacade.getAttribute(StandardSessionFacade.java:103)

at com.audium.server.session.ControllerData.getSessionLoggerScratchData(ControllerData.java:698)

at com.audium.server.session.ControllerData.removeLoggerScratchData(ControllerData.java:5068)

at com.audium.server.session.ControllerData.setLoggerScratchData(ControllerData.java:5048)

at com.audium.server.session.LoggerAPI.setLoggerScratchData(LoggerAPI.java:127)

at com.audium.logger.application.activity.ActivityLogger.doElementExit(ActivityLogger.java:538)

at com.audium.logger.application.activity.ActivityLogger.log(ActivityLogger.java:144)

at com.audium.server.logger.ApplicationLoggerBase.runLogger(ApplicationLoggerBase.java:178)

at com.audium.server.logger.LoggerRunner.execute(LoggerRunner.java:34)

at com.audium.server.logger.LoggerRunner.run(LoggerRunner.java:24)

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)

at java.util.concurrent.FutureTask.run(FutureTask.java:262)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at java.lang.Thread.run(Thread.java:745)

In other VXML application:

10.100.50.24.1507035351542.351831.QueueActions,10/03/2017 15:56:48.698,An error was encountered while attempting to log an event with the ID "end". The error was: java.lang.IllegalStateException: getAttribute: Session already invalidated The error was: java.lang.IllegalStateException: getAttribute: Session already invalidated
java.lang.IllegalStateException: getAttribute: Session already invalidated
at org.apache.catalina.session.StandardSession.getAttribute(StandardSession.java:1190)
at org.apache.catalina.session.StandardSessionFacade.getAttribute(StandardSessionFacade.java:103)
at com.audium.server.session.ControllerData.getSessionLoggerScratchData(ControllerData.java:698)
at com.audium.server.session.ControllerData.setLoggerScratchData(ControllerData.java:5050)
at com.audium.server.session.LoggerAPI.setLoggerScratchData(LoggerAPI.java:127)
at com.audium.logger.application.activity.ActivityLogger.log(ActivityLogger.java:161)
at com.audium.server.logger.ApplicationLoggerBase.runLogger(ApplicationLoggerBase.java:178)
at com.audium.server.logger.LoggerRunner.execute(LoggerRunner.java:34)
at com.audium.server.logger.LoggerRunner.run(LoggerRunner.java:24)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

Those logs are repeating every few seconds, actually when a call is being attempted (but not only, I think) becuase at the end of the day, each error log file is something like: 1.5GB.

There are times that I'm seeing this kind of log:

10.100.50.24.1507091784231.6643.Actions,10/04/2017 07:36:24.252,CustomerDetails_01,interaction,audio_group,initial_audio_group

10.100.50.24.1507091784231.6643.Actions,10/04/2017 07:36:36.262,CustomerDetails_01,element,error,error.badfetch: request (http://10.100.50.24:7000/CVP/Server) was timed out after 10000 milliseconds.

And:

28193: 10.100.50.24: Oct 03 2017 16:22:53.607 +0300: %CVP_11_5_Infrastructure-2-HEARTBEATS_STOPPED: Heartbeats from VXML1 stopped. Unilaterally setting state to PARTIAL_SERVICE. Sending update. [id:1011]

28194: 10.100.50.24: Oct 03 2017 16:22:53.607 +0300: %CVP_11_5_Infrastructure-5-RECEIVED_STATE_MSG: StateManager: Subsystem [VXML1] reported change to state [Partial Service] due to [Missing Heartbeat] [id:1014]

And finally, there's a log from the catalina tomcat log file that is stating that there is a low memory, see here:

03-Oct-2017 16:23:03.873 SEVERE [http-processor71] org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun

java.lang.OutOfMemoryError: Java heap space

at org.apache.coyote.http11.AbstractOutputBuffer.<init>(AbstractOutputBuffer.java:124)

at org.apache.coyote.http11.InternalNioOutputBuffer.<init>(InternalNioOutputBuffer.java:50)

at org.apache.coyote.http11.Http11NioProcessor.<init>(Http11NioProcessor.java:74)

at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.createProcessor(Http11NioProtocol.java:264)

at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.createProcessor(Http11NioProtocol.java:139)

at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:621)

at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1502)

at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1458)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

at java.lang.Thread.run(Thread.java:745)

03-Oct-2017 16:23:03.873 SEVERE [http-nio-7000-ClientPoller-0] org.apache.tomcat.util.net.NioEndpoint.checkParachute SEVERE:Memory usage is low, parachute is non existent, your system may start failing.

03-Oct-2017 16:23:04.732 SEVERE [http-nio-7000-ClientPoller-1] org.apache.tomcat.util.net.NioEndpoint.checkParachute SEVERE:Memory usage is low, parachute is non existent, your system may start failing.

Only after resetting the the whole CVP server, the issue is gone, and I'm guessing it's because I'm freeing all the RAM or something like that.

Does anyone have an idea how to attack this issue?

Thanks,

Slavik.

Chintan Gajjar · ‎10-16-2017

looks like you have memory leak happening somewhere, and since its the combination of custom java element. you have to ask your developer to check if there is any coding problem which could lead to the memory leak.

There is also possibility to increase the heap memory on VXML server, you need to check with TAC on support ability of it.

also do you have vxml application doing call queuing in infinite loop, i mean the queue music played in loop in VXML app without sending a call back to ICM?

dipmehta33 · ‎10-18-2017

Yes, i remember we experienced the same issue in CVP 11.5. This issue was fixed by following the below mentioned steps

Navigate to:
Start > Run > Regedit
HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Apache Software Foundation\Procrun2.0\VXMLServer\
Parameters\Java\Options
Add the "-XX:MaxPermSize=256M" registry key in order to increase the Virtual Memory PermSpace

If you are interested in knowing the root cause - please see the link below.

This is mentioned on the below links:

http://docwiki.cisco.com/wiki/VXML_Server:_Server_Out_of_Memory_Error_Message

http://www.cisco.com/c/en/us/support/docs/voice-unified-communications/unified-customer-voice-portal/116279-technote-vxml-00.html

Slavik Bialik · ‎10-19-2017

OK, it looks very promising!

I'll try that and I'll update if it solved the issue.

Thanks!

Slavik Bialik · ‎10-19-2017

OK, I did that. But seems like the error logs of the VXML applications are still growing very very fast.

Although, I'm not sure that those errors are about the memory issue.

Here's an example of one of the errors in one of the VXML applications:

10.99.57.24.1508402349090.1937.Actions,10/19/2017 11:40:07.527,An error was encountered while attempting to log an event with the ID "elementEnter". The error was: java.lang.IllegalStateException: getAttribute: Session already invalidated The error was: java.lang.IllegalStateException: getAttribute: Session already invalidated
java.lang.IllegalStateException: getAttribute: Session already invalidated
at org.apache.catalina.session.StandardSession.getAttribute(StandardSession.java:1190)
at org.apache.catalina.session.StandardSessionFacade.getAttribute(StandardSessionFacade.java:103)
at com.audium.server.session.ControllerData.getSessionLoggerScratchData(ControllerData.java:698)
at com.audium.server.session.ControllerData.setLoggerScratchData(ControllerData.java:5050)
at com.audium.server.session.LoggerAPI.setLoggerScratchData(LoggerAPI.java:127)
at com.audium.logger.application.activity.ActivityLogger.doElementEnter(ActivityLogger.java:509)
at com.audium.logger.application.activity.ActivityLogger.log(ActivityLogger.java:142)
at com.audium.server.logger.ApplicationLoggerBase.runLogger(ApplicationLoggerBase.java:178)
at com.audium.server.logger.LoggerRunner.execute(LoggerRunner.java:34)
at com.audium.server.logger.LoggerRunner.run(LoggerRunner.java:24)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

Maybe the log in my original post about the memory issue is fixed now, I hope so. But probably something else is wrong with VXML applications or the whole component because all applications are reporting errors non-stop.

Here's a screen shot of the registry. By the way, the 'Options' key didn't exist, so I created it and under it I created the values.

Slavik Bialik · ‎10-19-2017

Hi Chintan,

The only thing here is that those CVP applications and JAR files are located on all of our client's servers, and only here it happens.

And yes, you're correct, we do have a VXML application that handles queuing. One that checks what to do with the call while the customer is queued and plays music in loop. But in all the logs we can see that all our applications are reporting errors and not only the queue VXML application.

Thanks.

Chintan Gajjar · ‎10-19-2017

Hi Slavik,

The error message "Session Invalidated" and symptom log file filling makes me feel that there should be some kind of loop in vxml application. we had faced it, and probably you can reproduce it also by below call flow:

--> simple script with simple queue where VXML application is used for queuing

--> in VXML application a call loops between two audio element (not menu!!) and never returns to ICM.

just call into the app and you will see even the call queuing indefinitely between these two element until the VXML session gets invalidated which is 30 min by default.

But in your case i see the error is logged when a call is trying to enter into the another element and where it gets invalidated. we have to check if any previous element probably some sort of third party integration class which is taking longer than usual.

Can you please attach the full application log or if you have test version of that app, just attach the log file of the test call made which has the issue covered.

Alternatively you can also check the global VXML server error log at:

C:\Cisco\CVP\VXMLServer\logs

and Tomcat logs at:

C:\Cisco\CVP\VXMLServer\Tomcat\logs

may be there is something which can reveal whats going on.