Author Message
GaborFenyvesi2
Joined: Dec 17, 2013
Messages: 30
Offline
Hi,

Sometimes our application receives a ServerConnectionDownEvent after UnregisterTerminalRequest timed out.
I think the timeout is 60 seconds.
This is a Java DMCC app, doing multiple registrations call recording, client media mode.

I collected the relevant logs:



dmcc-api

2015-02-24 16.01.35,359 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 1643 Routing request=session[session C895277CFFD77DFC23533B713D22F13C-204] com.avaya.csta.binding.UnregisterTerminalRequest@1d1209b
2015-02-24 16.01.35,359 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 1643 Received com.avaya.platform.broker.impl.AsyncResponse@84e3f9 in response to session[session C895277CFFD77DFC23533B713D22F13C-204] com.avaya.csta.binding.UnregisterTerminalRequest@1d1209b



dmcc-error

2015-02-24 16.02.35,368 com.avaya.async.impl.AsyncCallbackImpl handleException
WARNING: A service method threw an Exception when invoked!
ServiceMethod: com.avaya.platform.broker.impl.AsyncServiceMethodImpl@a1cb94[com.avaya.cmapi.extsvc.H323RegistrationServices@d647d8, public void com.avaya.cmapi.extsvc.H323RegistrationServices.unregisterTerminal(com.avaya.csta.binding.UnregisterTerminalRequest,com.avaya.api.async.AsynchronousCallback) throws ch.ecma.csta.errors.CstaException]
Exception: com.avaya.platform.broker.impl.AsyncServiceMethodImpl$TimeoutException: Request: com.avaya.csta.binding.UnregisterTerminalRequest timed out
Request: session[session C895277CFFD77DFC23533B713D22F13C-204] com.avaya.csta.binding.UnregisterTerminalRequest@1d1209b
com.avaya.platform.broker.impl.AsyncServiceMethodImpl$TimeoutException: Request: com.avaya.csta.binding.UnregisterTerminalRequest timed out
at com.avaya.platform.broker.impl.AsyncServiceMethodImpl$TimeoutTask.run(AsyncServiceMethodImpl.java:301)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
2015-02-24 16.02.38,926 com.avaya.cs.callcontrol.delegs.CCSEventHandler cstaUnsolicited
WARNING: cstaUnsolicited caught an exception
java.security.InvalidParameterException: extension must be specified
at com.avaya.cs.callcontrol.delegs.Csta1To3.createDeviceIDContent(Csta1To3.java:750)
at com.avaya.cs.callcontrol.delegs.Csta1To3.createDeviceIDContent(Csta1To3.java:742)
at com.avaya.cs.callcontrol.delegs.Csta1To3.localDeviceID1To3(Csta1To3.java:643)
at com.avaya.cs.callcontrol.delegs.Csta1To3.connectionId1To3(Csta1To3.java:311)
at com.avaya.cs.callcontrol.delegs.CCSEventHandler.convertSendConnectionClearedEvent(CCSEventHandler.java:1391)
at com.avaya.cs.callcontrol.delegs.CCSEventHandler.cstaUnsolicited(CCSEventHandler.java:333)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventDistributor.handleEvent(TsapiEventDistributor.java:113)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventQueue.run(TsapiEventQueue.java:103)
2015-02-24 16.03.01,282 com.avaya.async.impl.AsyncCallbackImpl handleException
WARNING: A service method threw an Exception when invoked!
ServiceMethod: com.avaya.platform.broker.impl.AsyncServiceMethodImpl@473f4c[com.avaya.cmapi.extsvc.H323RegistrationServices@d647d8, public void com.avaya.cmapi.extsvc.H323RegistrationServices.registerTerminal(com.avaya.csta.binding.RegisterTerminalRequest,com.avaya.api.async.AsynchronousCallback) throws ch.ecma.csta.errors.CstaException]
Exception: com.avaya.platform.broker.impl.AsyncServiceMethodImpl$TimeoutException: Request: com.avaya.csta.binding.RegisterTerminalRequest timed out
Request: session[session C895277CFFD77DFC23533B713D22F13C-204] com.avaya.csta.binding.RegisterTerminalRequest@25b804
com.avaya.platform.broker.impl.AsyncServiceMethodImpl$TimeoutException: Request: com.avaya.csta.binding.RegisterTerminalRequest timed out
at com.avaya.platform.broker.impl.AsyncServiceMethodImpl$TimeoutTask.run(AsyncServiceMethodImpl.java:301)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
2015-02-24 16.03.06,533 com.avaya.mvcs.station.h323.ras.ErrorToString getErrName
WARNING: Please add description of error code =18308 to ErrorToString.java
2015-02-24 16.03.10,756 com.avaya.mvcs.ccms.CcmsDownlinkParser parseTransparentVdtMessage
WARNING: Parse error, index=3,buffer={e1,50,1a,1a,2a,99,b,a0,c7,3d,c1,8c,f3,3}
2015-02-24 16.03.22,187 com.avaya.mvcs.ccms.CcmsDownlinkParser parseTransparentVdtMessage
WARNING: Parse error, index=0,buffer={80,11,a}
2015-02-24 16.03.25,793 com.avaya.mvcs.ccms.CcmsDownlinkParser parseTransparentVdtMessage
WARNING: Parse error, index=0,buffer={80,11,a}
2015-02-24 16.03.50,789 com.avaya.sessionsvc.SessionServicesImpl logThrowable
WARNING: could not find old session: C895277CFFD77DFC23533B713D22F13C-204
java.lang.Throwable: could not find old session: C895277CFFD77DFC23533B713D22F13C-204
at com.avaya.sessionsvc.SessionServicesImpl.asyncStartApplicationSession(SessionServicesImpl.java:221)
at com.avaya.sessionsvc.SessionServicesImpl.access$000(SessionServicesImpl.java:93)
at com.avaya.sessionsvc.SessionServicesImpl$SASAsyncTask.run(SessionServicesImpl.java:143)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)



our application
the times seems to be 55 seconds ahead the AES logs (AES: 16.01.35 = OUR: 16:00:40)

DEBUG 2015.02.24 16:00:40 com.xxx.avaya.recorder.RegisterListenersThread - Unregister from AES: 2206
...
ERROR 2015.02.24 16:01:40 com.xxx.avaya.recorder.AESListener - serverConnectionDown: com.avaya.cmapi.evt.ServerConnectionDownEvent@1fe12a2
ERROR 2015.02.24 16:01:40 com.xxx.avaya.recorder.AESListener - serverConnectionDown.code: 2
ERROR 2015.02.24 16:01:40 com.xxx.avaya.recorder.AESListener - serverConnectionDown.reason: Exception on request
ERROR 2015.02.24 16:01:40 com.xxx.avaya.recorder.AESListener - serverConnectionDown.exception:
com.avaya.mvcs.proxy.XmlGatewayClient$TimeoutException: Request: session[null] com.avaya.csta.binding.UnregisterTerminalRequest@18450bb timed out
at com.avaya.mvcs.proxy.XmlGatewayClient$TimeoutTask.run(XmlGatewayClient.java:542)
at java.util.TimerThread.mainLoop(Unknown Source)
at java.util.TimerThread.run(Unknown Source)
...
WARN 2015.02.24 16:02:55 com.xxx.avaya.recorder.Starter - Could not unregister extension: 2206
ch.ecma.csta.errors.CstaException: Request: session[null] com.avaya.csta.binding.UnregisterTerminalRequest@18450bb timed out
at com.avaya.mvap.svcproxy.ServiceProxy.marshallRequest(ServiceProxy.java:111)
at com.avaya.mvap.svcproxy.RegistrationServicesProxy.unregisterTerminal(RegistrationServicesProxy.java:106)
at com.xxx.avaya.recorder.Starter.unregisterExtensionFromAESThrow(Starter.java:639)
at com.xxx.avaya.recorder.Starter.unregisterExtensionFromAES(Starter.java:649)
at com.xxx.avaya.recorder.RegisterListenersThread.performUnregister(RegisterListenersThread.java:44)
at com.xxx.avaya.recorder.communication.AlertHandler.reRegister(AlertHandler.java:90)
at com.xxx.avaya.recorder.communication.AlertHandler.alert(AlertHandler.java:124)
at com.xxx.avaya.recorder.communication.AlertHandler.alert(AlertHandler.java:184)
at com.xxx.avaya.recorder.communication.xxxAPIProcessor.stopRecording(xxxAPIProcessor.java:410)
at com.xxx.avaya.recorder.record.Recorder.doStop(Recorder.java:132)
at com.xxx.avaya.recorder.record.Recorder.stop(Recorder.java:455)
at com.xxx.avaya.recorder.record.AvayaCCListener.connectionCleared(AvayaCCListener.java:166)
at com.avaya.mvap.svcproxy.MonitoringServicesProxy.handleEvent(MonitoringServicesProxy.java:848)
at com.avaya.mvap.svcproxy.ServiceProxy$ExecutorTask.run(ServiceProxy.java:225)
at com.avaya.common.util.concurrent.impl.RunnableWrapper.run(RunnableWrapper.java:47)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: com.avaya.mvcs.proxy.XmlGatewayClient$TimeoutException: Request: session[null] com.avaya.csta.binding.UnregisterTerminalRequest@18450bb timed out
at com.avaya.mvcs.proxy.XmlGatewayClient$TimeoutTask.run(XmlGatewayClient.java:542)
at java.util.TimerThread.mainLoop(Unknown Source)
at java.util.TimerThread.run(Unknown Source)


Is there a problem in AES, or in some network configuration, maybe in our application?
Any help would be appriciated.

Regards,
Gabor Fenyvesi
GaborFenyvesi2
Joined: Dec 17, 2013
Messages: 30
Offline
Maybe this is because our app tries to unregister the extension in the connectionCleared event handler? If we put the event into a queue and process it in a worker thread, should that resolve this issue?
Although, nothing should take 1 minute...
Gabor Fenyvesi
MartinFlynn
Joined: Nov 30, 2009
Messages: 1922
Offline
Yes. The connection almost certainly being dropped because the DMCC event thread has been blocked for so long. You should always do any processing in your own worker thread - never in the event thread.

Martin
GaborFenyvesi2
Joined: Dec 17, 2013
Messages: 30
Offline
Hi,
Unfortunately, this happens even if we are calling the UnregisterTerminalRequest in a separated thread. It times out, and the DMCC library triggers a ServerConnectionDownEvent, and we do not receive important events for a while.
Do you have any best-practice on how to avoid this?
Thanks,
Gabor Fenyvesi
Go to:   
Mobile view