Solved: Re: Jabber Desk Phone mode - CTI connection issue

massimiliano.mariani1 · ‎08-22-2017

Hello All,

We have Jabber Desk Phone mode installed on different Windows OS and on CUCM 8.6. When we perform authentication, client got Connection, but after few seconds we got Disconnection with following error.

|CtiServerHeartbeatTimer                |ready                          |CTIHandler(2,200,22,6)           |SdlTimerService(2,200,3,1)       |2,200,21,1.419^*^*                       |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
112630685 |2017/08/17 17:01:20.199 |200 |AppInfo   |||CTIHandler(2,200,22,6)|||[CTI-APP] [CTIHandler::OutputCtiMessage      ]     CTI   Server Heartbeat   ( application name=CiscoTSP001-172.19.206.121)
112630686 |2017/08/17 17:01:20.199 |200 |AppInfo   |||CTIHandler(2,200,22,6)|||Send CTI Server Heartbeat
112630687 |2017/08/17 17:01:21.104 |200 |AppInfo   |||CTIHandler(2,200,22,9)|||[CTI-APP] [CTIHandler::processIncomingMessage]     CTI   Client Heartbeat   ( application name=Cisco IP IVR)
112630688 |2017/08/17 17:01:21.104 |200 |SdlStat   ||||||Period: 6s #Lines: 15 #Bytes: 3775 Free HWM: 4 Free HWM(total): 1237
112630689 |2017/08/17 17:01:21.104 |200 |SdlSig    |CtiHeartbeat                           |ready                          |CTIHandler(2,200,22,9)           |CTIHandler(2,200,22,9)           |2,200,21,1.3209305^*^*                   |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] UnRestricted = 0
112630690 |2017/08/17 17:01:21.107 |200 |SdlSig    |CtiClientHeartbeatTimer                |ready                          |CTIHandler(2,200,22,6)           |SdlTimerService(2,200,3,1)       |2,200,21,1.419^*^*                       |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
112630691 |2017/08/17 17:01:21.730 |200 |AppInfo   |||CTIHandler(2,200,22,75)|||[CTI-APP] [CTIHandler::processIncomingMessage]     CTI   ProviderCloseRequest    ( seq#=4 )
112630692 |2017/08/17 17:01:21.730 |200 |SdlSig    |CtiProviderCloseReq                    |authenticating                 |CTIHandler(2,200,22,75)          |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] Async Response=4
112630693 |2017/08/17 17:01:21.730 |200 |SdlSig    |CtiHandlerShutdownRequest              |shutting_down                  |CTIHandler(2,200,22,75)          |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0] mShutdownReason=3 mSequenceNumber=4 UserPkid=
112630694 |2017/08/17 17:01:21.730 |200 |SdlSig    |CtiHandlerShutdownRequest              |ready                          |CTIDbAccess(2,200,26,1)          |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0] mShutdownReason=3 mSequenceNumber=4 UserPkid=
112630695 |2017/08/17 17:01:21.730 |200 |SdlSig    |CtiUnsubscribeRegUnRegNotificationInd |ready                          |CTIDeviceRegManager(2,200,24,1) |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] CTIHandlerPid=(2,200,22,75) LoginUserId=ridp52q
112630696 |2017/08/17 17:01:21.730 |200 |AppError |||CTIDeviceRegManager(2,200,24,1)||| UnsubscribeDevicesInAppSubscribedList
112630697 |2017/08/17 17:01:21.730 |200 |AppError |||CTIDeviceRegManager(2,200,24,1)|||     App NOT FOUND CtiPid=(2, 75
112630698 |2017/08/17 17:01:21.730 |200 |SdlSig    |CtiClearSubscriptions                  |ready                          |CTIPickupMgr(2,200,20,1)         |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0]
112630699 |2017/08/17 17:01:21.730 |200 |SdlSig    |DbLoggedInDeviceListCleanupNotify      |ready                          |CTIDbAccess(2,200,26,1)          |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[T:N-H:0,N:1,L:0,V:0,Z:0,D:0] CtiPid=(2,200,22,75)
112630700 |2017/08/17 17:01:21.730 |200 |SdlExcept |DbLoggedInDeviceListCleanupNotify      |ready                          |CTIDbAccess(2,200,26,1)          |                                 |                                         |Error: Description: A transition is not defined for the input signal. Check state machine definition in initStateMachine().
112630701 |2017/08/17 17:01:21.730 |200 |SdlSig    |ProviderSubscriptionUnRegNotify        |ready                          |CTIDbAccess(2,200,26,1)          |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0] userId=0xb26a5134
112630702 |2017/08/17 17:01:21.732 |200 |SdlSig    |CtiQbeProviderUnexpectedShutdown       |shutting_down                  |CTIHandler(2,200,22,75)          |CtiManager(2,200,21,1)           |2,200,13,153.6^*^*                       |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
112630703 |2017/08/17 17:01:21.732 |200 |Stopping |                                       |                               |SdlTCPConnection(2,200,13,153)   |SdlTCPConnection(2,200,13,153)   |                                         |NumOfCurrentInstances: 12
112630704 |2017/08/17 17:01:21.991 |200 |SdlSig    |CtiProviderCleanUpTimer                |shutting_down                  |CTIHandler(2,200,22,75)          |SdlTimerService(2,200,3,1)       |2,200,21,1.3209306^*^*                   |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
112630705 |2017/08/17 17:01:21.991 |200 |SdlError |SdlWriteReq                            |NA                             |SdlTCPConnection(2,200,13,153)   |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |Destination process does not exist
112630706 |2017/08/17 17:01:21.991 |200 |AppInfo   |||CTIHandler(2,200,22,75)|||[CTI-APP] [CTIHandler::OutputCtiMessage      ]     CTI   ProviderCloseResponse    ( seq#=4 result=0 )
112630707 |2017/08/17 17:01:21.991 |200 |SdlExcept |SdlProcessNE                           |shutting_down                  |CTIHandler(2,200,22,75)          |                                 |                                         |Error: Description: A transition is not defined for the input signal. Check state machine definition in initStateMachine().
112630708 |2017/08/17 17:01:21.991 |200 |SdlSig    |CtiQbeProviderClosing                  |ready                          |CtiManager(2,200,21,1)           |CTIHandler(2,200,22,75)          |2,200,21,1.3209306^*^*                   |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
112630709 |2017/08/17 17:01:21.991 |200 |SdlError |SdlCloseReq                            |NA                             |SdlTCPConnection(2,200,13,153)   |CtiManager(2,200,21,1)           |2,200,21,1.3209306^*^*                   |Destination process does not exist
112630710 |2017/08/17 17:01:21.991 |200 |SdlExcept |SdlProcessNE                           |ready                          |CtiManager(2,200,21,1)           |                                 |                                         |Error: Description: A transition is not defined for the input signal. Check state machine definition in initStateMachine().
112630711 |2017/08/17 17:01:22.247 |200 |SdlSig    |CtiProviderClosingTimer                |shutting_down                  |CTIHandler(2,200,22,75)          |SdlTimerService(2,200,3,1)       |2,200,21,1.3209306^*^*                   |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
112630712 |2017/08/17 17:01:22.247 |200 |Stopping |                                       |                               |CTIHandler(2,200,22,75)          |CTIHandler(2,200,22,75)          |                                         |NumOfCurrentInstances: 7
112630713 |2017/08/17 17:01:23.256 |200 |AppInfo   |||CTIHandler(2,200,22,8)|||[CTI-APP] [CTIHandler::processIncomingMessage]     CTI   Client Heartbeat   ( application name=Cisco IP ICD)
112630714 |2017/08/17 17:01:23.256 |200 |SdlSig    |CtiHeartbeat                           |ready                          |CTIHandler(2,200,22,8)           |CTIHandler(2,200,22,8)           |2,200,21,1.3209307^*^*                   |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] UnRestricted = 0
112630715 |2017/08/17 17:01:25.582 |200 |Created   |                                       |                               |SdlTCPConnector(2,200,12,31076) |SdlTCPService(2,200,10,1)        |                                         |NumOfCurrentInstances: 1
112630716 |2017/08/17 17:01:26.150 |200 |AppInfo   |||CTIHandler(2,200,22,1)|||[CTI-APP] [CTIHandler::processIncomingMessage]     CTI   Client Heartbeat   ( application name=Cisco WebDialer)
112630717 |2017/08/17 17:01:26.150 |200 |SdlSig    |CtiHeartbeat                           |ready                          |CTIHandler(2,200,22,1)           |CTIHandler(2,200,22,1)           |2,200,21,1.3209308^*^*                   |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] UnRestricted = 0
112630718 |2017/08/17 17:01:26.818 |200 |SdlSig    |CtiServerHeartbeatTimer                |ready                          |CTIHandler(2,200,22,10)          |SdlTimerService(2,200,3,1)       |2,200,21,1.2752^*^*                      |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0]
112630719 |2017/08/17 17:01:26.818 |200 |AppInfo   |||CTIHandler(2,200,22,10)|||[CTI-APP] [CTIHandler::OutputCtiMessage      ]     CTI   Server Heartbeat   ( application name=Cisco IP ICD)
112630720 |2017/08/17 17:01:26.818 |200 |AppInfo   |||CTIHandler(2,200,22,10)|||Send CTI Server Heartbeat.

Authentication goes thorugh LDAP. CTI ports are OK, no firewall in the middle. I never seen this type of error. Attached the full log.

Thanks

Max

massimiliano.mariani1 · ‎09-04-2017

Hello,

Thanks for quick reply, I'll arrange the modify with cutomer and I'll come back to you.

Regards

Max

View solution in original post

Varundeep Chhatwal · ‎08-22-2017

I checked the logs. Jabber is designed to wait for 10 seconds for the response which comes CUCM. The response is for the request which jabber makes to control the deskphone and authenticate the user as well for cti. In your case as per logs from CTI , it started at 17:03:07

112632991 |2017/08/17 17:03:07.329 |200 |AppInfo ||||||CtiLoginCheckReq::authenticateByUserName

Jabber had to wait for 10 seconds and it didn't get a response from cucm and then jabber finally disconects the request.

112633012 |2017/08/17 17:03:17.011 |200 |SdlSig |CtiHandlerShutdownRequest |shutting_down |CTIHandler(2,200,22,76) |CTIHandler(2,200,22,76) |2,200,21,1.3209364^*^*

So basicallly CTI manager was not able to authenticate this user with LDAP server. The possible cause for this are as under :

1. CUCM is unable to resolve the LDAP server if its defined in FQDN.

2. CUCM is unable to authenticate user via LDAP on port 389. If you use port 3268 then this ideally should resolve the issue.

3. CTI timer parameter to authenticate the user needs to be updated with new timer value which should be more than 10 seconds.

try changing the port to 3268 and check.

massimiliano.mariani1 · ‎08-23-2017

Hello Varundeep,

Thanks for reply, just few question ofr our understanding and in order to avoid any other impacts:

1. why ports 3268 exactly? Is used by windows?

2. this CUCM is "live" with many other customers and UCCX, so, LDAP port modify has some impact?

Regards

Max

Varundeep Chhatwal · ‎08-28-2017

when using port 3268 , cucm has less overload in order to authenticate the user. If you planning to change the port , kindly do it in off production hours and do a re-sync once port is changed.

massimiliano.mariani1 · ‎08-29-2017

Hello,
Workaround not yet applied, I'm arranging the activity with my customer, but I'm confident will help. I'll keep you informed.

Regards
Max

massimiliano.mariani1 · ‎09-03-2017

Hello,

After a deeper investigation I have noticed that same LDAP port 389 is used on other CUCMs of the same Customer connected at the same LDAP server and where Jabber Desk Phone wors fine. So, are we sure root cause is the LDAP port? Considering that OK CUCM and KO CUCM with same LDAP port are on different location could impact LDAP communication anyway and port change is still the right solution way?

Thanks in advance

Max

Alok Jaiswal · ‎09-04-2017

I think this is a known issue CTI manager with LDAP port 389.

Sometimes if the LDAP response doesn't receives fast enough then CTI authentication fails. Because of which reasons you point it to port 3268 which is normally used by GC (global catalogue) server. And this way it seems the response is more quicker.

It depends on deployment types but it safe always to keep the port to 3268. That's what i follow for all of my implementations.

Regards,

Alok

massimiliano.mariani1 · ‎09-04-2017

Hello,

Thanks for quick reply, I'll arrange the modify with cutomer and I'll come back to you.

Regards

Max

massimiliano.mariani1 · ‎09-14-2017

Hello All,

I have just founf out (I didn't know) that LDAP port 3268 is used for Global Catalog, so, what means on CUCM side exactly after port change from 389 to 3268?

- CUCM's query will be applied on the complete Global Catalog instead of single Domain Catalog?

If YES, which is the impact on CUCM side? LDAP DB occupancy increasing?

Thanks in advance

Max

massimiliano.mariani1 · ‎09-14-2017

One more question: is this the following sentence right?

Port 3268. This port is used for queries specifically targeted for the global catalog. LDAP requests sent to port 3268 can be used to search for objects in the entire forest. However, only the attributes marked for replication to the global catalog can be returned. For example, a user’s department could not be returned using port 3268 since this attribute is not replicated to the global catalog.

Means that all Users into the CUCM Domain configured on LDAP DB must be replicated on Global Catalog?

Thanks

Max