We have an AES set up for OCS integration. We have 10 S8500 servers with CTI links to the AES. The initial site setup is up and running. When we added the second site, the CTI link is up and clean. The issue we are having is when a user from the second site attempts to login from OCS the SIP connection is successful but when AES goes to establish the connection with the PBX server, it appears to select the wrong switch connection. We believe the answer to be in the dial plan but have been unable to resolve the problem.
Below is from the log.
FINE: Returning EnterpriseDirectory AuthorizationList [tel:61827] for user sipCTest@ebglaw.com
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionObjectImpl validate
INFO: Login successful: user=sipCTest@ebglaw.com, clientID=TR-87 Encrypted:10.213.160.14:10.11.185.49:59bac7e453954 97a8781d1597c38ee14
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionObjectImpl validate
FINE: session 256A213E86CD1F41CFE7A62959002D9E-47436 _sessionTimeout=180, _cleanupTimeout=0
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionServicesImpl asyncStartApplicationSession
INFO: Validated session=session 256A213E86CD1F41CFE7A62959002D9E-47436, requested sessionTimeout=180, actual sessionTimeout=180, requested cleanupTimeout=0, actual cleanupTimeout=0
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionMulticaster addSessionListener
FINE: com.avaya.sessionsvc.SessionServicesImpl$MySession Listener@42e197added to com.avaya.sessionsvc.SessionMulticaster@17cfb34
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionObjectImpl start
FINE: session 256A213E86CD1F41CFE7A62959002D9E-47436 is starting.
2011-05-11 09.29.02,290 com.avaya.common.nio.managed.tr87Impl.TR87InviteTr ansaction sendResponse
FINE: Session established with session id: 256A213E86CD1F41CFE7A62959002D9E-47436
2011-05-11 09.29.02,290 com.avaya.common.nio.managed.tr87Impl.TR87Abstract DialogChannel setDmccSessionID
FINE: [59bac7e45395497a8781d1597c38ee14] - dmccSessionID=256A213E86CD1F41CFE7A62959002D9E-47436
2011-05-11 09.29.02,290 com.avaya.common.nio.managed.tr87Impl.TR87Abstract DialogChannel setSessionDuration
FINE: [59bac7e45395497a8781d1597c38ee14] - sessionDuration=180
2011-05-11 09.29.02,291 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 1 Routing request=session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.RequestSystemStatus@39ccea
2011-05-11 09.29.02,292 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 1 Received session[null] ch.ecma.csta.binding.RequestSystemStatusResponse@b c4f2f in response to session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.RequestSystemStatus@39ccea
2011-05-11 09.29.02,514 com.avaya.common.nio.managed.tr87Impl.TR87Connecto r processRequest
FINE: [59bac7e45395497a8781d1597c38ee14] - request received on SIP connector: ACK
2011-05-11 09.29.02,727 com.avaya.common.nio.managed.tr87Impl.TR87Connecto r processRequest
FINE: [59bac7e45395497a8781d1597c38ee14] - request received on SIP connector: INFO
2011-05-11 09.29.02,728 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 2 Routing request=session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.GetCSTAFeatures@30304f
2011-05-11 09.29.02,728 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 2 Received session[null] ch.ecma.csta.binding.GetCSTAFeaturesResponse@1b39b dd in response to session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.GetCSTAFeatures@30304f
2011-05-11 09.29.02,751 com.avaya.common.nio.managed.tr87Impl.TR87Connecto r processRequest
FINE: [59bac7e45395497a8781d1597c38ee14] - request received on SIP connector: INFO
2011-05-11 09.29.02,752 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 3 Routing request=session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.MonitorStart@1d0ab4d
2011-05-11 09.29.02,752 com.avaya.cmapi.monitor.MonitoringServicesImpl acquireCrossRefId
FINE: acquired crossRefID=47352: 35 are now in use, 79965 still available.
2011-05-11 09.29.02,752 com.avaya.cmapi.monitor.MonitoringServicesImpl startMonitor
FINE: started monitor=47352
2011-05-11 09.29.02,752 com.avaya.sessionsvc.SessionMulticaster addSessionListener
FINE: com.avaya.cmapi.monitor.MonitoringServicesImpl$MyS essionListener@9e87a2added to com.avaya.sessionsvc.SessionMulticaster@17cfb34
2011-05-11 09.29.02,753 com.avaya.cmapi.monitor.MonitoringServicesImpl createCallControlServicesListener
FINE: added CallControlListener: 47352, id=[tel:61827;phone-context=enterprise] , listener=com.avaya.cmapi.monitor.OfficeCommunicato rCCSListener@1daa119
2011-05-11 09.29.02,753 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 3 Received com.avaya.platform.broker.impl.AsyncResponse@1c2e8 a4 in response to session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.MonitorStart@1d0ab4d
2011-05-11 09.29.02,856 com.avaya.cs.callcontrol.handlers.AddListenerDeleg ate$MonitorDeviceCallback handleException
HERE IS WHERE IT USES THE INCORRECT SWITCH CONNECTION
FINE: [[tel:61827;phone-context=enterprise] :NYCAES] invoking callback.handleException()
ch.ecma.csta.errors.InvalidDeviceIDException: The specified device ID was invalid: error code 12
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.getCstaException(CallControlConfHandler.jav a:191)
at com.avaya.cs.callcontrol.handlers.MonitorDeviceCon fHandler.getCstaException(MonitorDeviceConfHandler .java:181)
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.handleConf(CallControlConfHandler.java:133)
at com.avaya.jtapi.tsapi.tsapiInterface.TSInvokeID.se tConf(TSInvokeID.java:54)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventDis tributor.handleEvent(TsapiEventDistributor.java:10 3)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventQue ue.run(TsapiEventQueue.java:103)
2011-05-11 09.29.02,856 com.avaya.cmapi.monitor.MonitoringServicesImpl stopMonitor
WARNING: Exception on removeCallControlServicesListeners
ch.ecma.csta.errors.InvalidDeviceStateException: Switch name must be set for [tel:61827;phone-context=enterprise]
at com.avaya.cs.callcontrol.CallControlSnapshotImpl.g etSwitchNameFromDeviceID(CallControlSnapshotImpl.j ava:2462)
at com.avaya.cs.callcontrol.CallControlSnapshotImpl.r emoveCallControlListener(CallControlSnapshotImpl.j ava:2241)
at com.avaya.cmapi.monitor.MonitoringServicesImpl.rem oveCallControlServicesListener(MonitoringServicesI mpl.java:3567)
at com.avaya.cmapi.monitor.MonitoringServicesImpl.sto pMonitor(MonitoringServicesImpl.java:1194)
at com.avaya.cmapi.monitor.MonitoringServicesImpl.cle anupMonitorStart(MonitoringServicesImpl.java:3479)
at com.avaya.cmapi.monitor.AddListenerCallback.handle Exception(AddListenerCallback.java:120)
at com.avaya.cs.callcontrol.handlers.AddListenerDeleg ate$MonitorDeviceCallback.handleException(AddListe nerDelegate.java:369)
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.handleConf(CallControlConfHandler.java:133)
at com.avaya.jtapi.tsapi.tsapiInterface.TSInvokeID.se tConf(TSInvokeID.java:54)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventDis tributor.handleEvent(TsapiEventDistributor.java:10 3)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventQue ue.run(TsapiEventQueue.java:103)
2011-05-11 09.29.02,857 com.avaya.cmapi.monitor.MonitoringServicesImpl stopMonitor
FINE: removed sessionListener for crossRef=47352
2011-05-11 09.29.02,857 com.avaya.cmapi.monitor.MonitoringServicesImpl releaseCrossRefId
FINE: released crossRefID=47352: 34 are now in use, 79966 still available.
2011-05-11 09.29.02,857 com.avaya.cmapi.monitor.MonitoringServicesImpl stopMonitor
FINE: removed monitor=47352
2011-05-11 09.29.02,857 com.avaya.async.impl.AsyncCallbackImpl handleException
WARNING: A service method threw an Exception when invoked!
ServiceMethod: com.avaya.platform.broker.impl.Async...i.monitor.MonitoringServicesImpl@13c550f, public synchronized void com.avaya.cmapi.monitor.MonitoringServicesImpl.sta rtMonitor(ch.ecma.csta.binding.MonitorStart,com.av aya.api.async.AsynchronousCallback) throws ch.ecma.csta.errors.InvalidParameterValueException ,ch.ecma.csta.errors.InvalidMonitorObjectException ,ch.ecma.csta.errors.OverallMonitorLimitExceededEx ception,ch.ecma.csta.errors.OperationException,ch. ecma.csta.errors.InvalidConnectionIDForActiveCallE xception]
Exception: ch.ecma.csta.errors.InvalidDeviceIDException: The specified device ID was invalid: error code 12
Request: session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.MonitorStart@1d0ab4d
ch.ecma.csta.errors.InvalidDeviceIDException: The specified device ID was invalid: error code 12
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.getCstaException(CallControlConfHandler.jav a:191)
at com.avaya.cs.callcontrol.handlers.MonitorDeviceCon fHandler.getCstaException(MonitorDeviceConfHandler .java:181)
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.handleConf(CallControlConfHandler.java:133)
at com.avaya.jtapi.tsapi.tsapiInterface.TSInvokeID.se tConf(TSInvokeID.java:54)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventDis tributor.handleEvent(TsapiEventDistributor.java:10 3)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventQue ue.run(TsapiEventQueue.java:103)
Thanks for thoughts on this.
Below is from the log.
FINE: Returning EnterpriseDirectory AuthorizationList [tel:61827] for user sipCTest@ebglaw.com
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionObjectImpl validate
INFO: Login successful: user=sipCTest@ebglaw.com, clientID=TR-87 Encrypted:10.213.160.14:10.11.185.49:59bac7e453954 97a8781d1597c38ee14
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionObjectImpl validate
FINE: session 256A213E86CD1F41CFE7A62959002D9E-47436 _sessionTimeout=180, _cleanupTimeout=0
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionServicesImpl asyncStartApplicationSession
INFO: Validated session=session 256A213E86CD1F41CFE7A62959002D9E-47436, requested sessionTimeout=180, actual sessionTimeout=180, requested cleanupTimeout=0, actual cleanupTimeout=0
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionMulticaster addSessionListener
FINE: com.avaya.sessionsvc.SessionServicesImpl$MySession Listener@42e197added to com.avaya.sessionsvc.SessionMulticaster@17cfb34
2011-05-11 09.29.02,289 com.avaya.sessionsvc.SessionObjectImpl start
FINE: session 256A213E86CD1F41CFE7A62959002D9E-47436 is starting.
2011-05-11 09.29.02,290 com.avaya.common.nio.managed.tr87Impl.TR87InviteTr ansaction sendResponse
FINE: Session established with session id: 256A213E86CD1F41CFE7A62959002D9E-47436
2011-05-11 09.29.02,290 com.avaya.common.nio.managed.tr87Impl.TR87Abstract DialogChannel setDmccSessionID
FINE: [59bac7e45395497a8781d1597c38ee14] - dmccSessionID=256A213E86CD1F41CFE7A62959002D9E-47436
2011-05-11 09.29.02,290 com.avaya.common.nio.managed.tr87Impl.TR87Abstract DialogChannel setSessionDuration
FINE: [59bac7e45395497a8781d1597c38ee14] - sessionDuration=180
2011-05-11 09.29.02,291 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 1 Routing request=session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.RequestSystemStatus@39ccea
2011-05-11 09.29.02,292 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 1 Received session[null] ch.ecma.csta.binding.RequestSystemStatusResponse@b c4f2f in response to session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.RequestSystemStatus@39ccea
2011-05-11 09.29.02,514 com.avaya.common.nio.managed.tr87Impl.TR87Connecto r processRequest
FINE: [59bac7e45395497a8781d1597c38ee14] - request received on SIP connector: ACK
2011-05-11 09.29.02,727 com.avaya.common.nio.managed.tr87Impl.TR87Connecto r processRequest
FINE: [59bac7e45395497a8781d1597c38ee14] - request received on SIP connector: INFO
2011-05-11 09.29.02,728 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 2 Routing request=session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.GetCSTAFeatures@30304f
2011-05-11 09.29.02,728 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 2 Received session[null] ch.ecma.csta.binding.GetCSTAFeaturesResponse@1b39b dd in response to session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.GetCSTAFeatures@30304f
2011-05-11 09.29.02,751 com.avaya.common.nio.managed.tr87Impl.TR87Connecto r processRequest
FINE: [59bac7e45395497a8781d1597c38ee14] - request received on SIP connector: INFO
2011-05-11 09.29.02,752 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 3 Routing request=session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.MonitorStart@1d0ab4d
2011-05-11 09.29.02,752 com.avaya.cmapi.monitor.MonitoringServicesImpl acquireCrossRefId
FINE: acquired crossRefID=47352: 35 are now in use, 79965 still available.
2011-05-11 09.29.02,752 com.avaya.cmapi.monitor.MonitoringServicesImpl startMonitor
FINE: started monitor=47352
2011-05-11 09.29.02,752 com.avaya.sessionsvc.SessionMulticaster addSessionListener
FINE: com.avaya.cmapi.monitor.MonitoringServicesImpl$MyS essionListener@9e87a2added to com.avaya.sessionsvc.SessionMulticaster@17cfb34
2011-05-11 09.29.02,753 com.avaya.cmapi.monitor.MonitoringServicesImpl createCallControlServicesListener
FINE: added CallControlListener: 47352, id=[tel:61827;phone-context=enterprise] , listener=com.avaya.cmapi.monitor.OfficeCommunicato rCCSListener@1daa119
2011-05-11 09.29.02,753 com.avaya.mvcs.proxy.CstaRouterNode processPacket
FINE: invokeID= 3 Received com.avaya.platform.broker.impl.AsyncResponse@1c2e8 a4 in response to session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.MonitorStart@1d0ab4d
2011-05-11 09.29.02,856 com.avaya.cs.callcontrol.handlers.AddListenerDeleg ate$MonitorDeviceCallback handleException
HERE IS WHERE IT USES THE INCORRECT SWITCH CONNECTION
FINE: [[tel:61827;phone-context=enterprise] :NYCAES] invoking callback.handleException()
ch.ecma.csta.errors.InvalidDeviceIDException: The specified device ID was invalid: error code 12
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.getCstaException(CallControlConfHandler.jav a:191)
at com.avaya.cs.callcontrol.handlers.MonitorDeviceCon fHandler.getCstaException(MonitorDeviceConfHandler .java:181)
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.handleConf(CallControlConfHandler.java:133)
at com.avaya.jtapi.tsapi.tsapiInterface.TSInvokeID.se tConf(TSInvokeID.java:54)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventDis tributor.handleEvent(TsapiEventDistributor.java:10 3)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventQue ue.run(TsapiEventQueue.java:103)
2011-05-11 09.29.02,856 com.avaya.cmapi.monitor.MonitoringServicesImpl stopMonitor
WARNING: Exception on removeCallControlServicesListeners
ch.ecma.csta.errors.InvalidDeviceStateException: Switch name must be set for [tel:61827;phone-context=enterprise]
at com.avaya.cs.callcontrol.CallControlSnapshotImpl.g etSwitchNameFromDeviceID(CallControlSnapshotImpl.j ava:2462)
at com.avaya.cs.callcontrol.CallControlSnapshotImpl.r emoveCallControlListener(CallControlSnapshotImpl.j ava:2241)
at com.avaya.cmapi.monitor.MonitoringServicesImpl.rem oveCallControlServicesListener(MonitoringServicesI mpl.java:3567)
at com.avaya.cmapi.monitor.MonitoringServicesImpl.sto pMonitor(MonitoringServicesImpl.java:1194)
at com.avaya.cmapi.monitor.MonitoringServicesImpl.cle anupMonitorStart(MonitoringServicesImpl.java:3479)
at com.avaya.cmapi.monitor.AddListenerCallback.handle Exception(AddListenerCallback.java:120)
at com.avaya.cs.callcontrol.handlers.AddListenerDeleg ate$MonitorDeviceCallback.handleException(AddListe nerDelegate.java:369)
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.handleConf(CallControlConfHandler.java:133)
at com.avaya.jtapi.tsapi.tsapiInterface.TSInvokeID.se tConf(TSInvokeID.java:54)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventDis tributor.handleEvent(TsapiEventDistributor.java:10 3)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventQue ue.run(TsapiEventQueue.java:103)
2011-05-11 09.29.02,857 com.avaya.cmapi.monitor.MonitoringServicesImpl stopMonitor
FINE: removed sessionListener for crossRef=47352
2011-05-11 09.29.02,857 com.avaya.cmapi.monitor.MonitoringServicesImpl releaseCrossRefId
FINE: released crossRefID=47352: 34 are now in use, 79966 still available.
2011-05-11 09.29.02,857 com.avaya.cmapi.monitor.MonitoringServicesImpl stopMonitor
FINE: removed monitor=47352
2011-05-11 09.29.02,857 com.avaya.async.impl.AsyncCallbackImpl handleException
WARNING: A service method threw an Exception when invoked!
ServiceMethod: com.avaya.platform.broker.impl.Async...i.monitor.MonitoringServicesImpl@13c550f, public synchronized void com.avaya.cmapi.monitor.MonitoringServicesImpl.sta rtMonitor(ch.ecma.csta.binding.MonitorStart,com.av aya.api.async.AsynchronousCallback) throws ch.ecma.csta.errors.InvalidParameterValueException ,ch.ecma.csta.errors.InvalidMonitorObjectException ,ch.ecma.csta.errors.OverallMonitorLimitExceededEx ception,ch.ecma.csta.errors.OperationException,ch. ecma.csta.errors.InvalidConnectionIDForActiveCallE xception]
Exception: ch.ecma.csta.errors.InvalidDeviceIDException: The specified device ID was invalid: error code 12
Request: session[session 256A213E86CD1F41CFE7A62959002D9E-47436] ch.ecma.csta.binding.MonitorStart@1d0ab4d
ch.ecma.csta.errors.InvalidDeviceIDException: The specified device ID was invalid: error code 12
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.getCstaException(CallControlConfHandler.jav a:191)
at com.avaya.cs.callcontrol.handlers.MonitorDeviceCon fHandler.getCstaException(MonitorDeviceConfHandler .java:181)
at com.avaya.cs.callcontrol.handlers.CallControlConfH andler.handleConf(CallControlConfHandler.java:133)
at com.avaya.jtapi.tsapi.tsapiInterface.TSInvokeID.se tConf(TSInvokeID.java:54)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventDis tributor.handleEvent(TsapiEventDistributor.java:10 3)
at com.avaya.jtapi.tsapi.tsapiInterface.TsapiEventQue ue.run(TsapiEventQueue.java:103)
Thanks for thoughts on this.