Jabber for Windows 9.2 Deskphone Control

James Hawkins · ‎08-06-2013

Hi,

I have a deployment with:

CUCM 9.1(1a) (9.1.1.20000-5)

IM and Presence 9.1(1a) 9.1.1.20000-5

Jabber for Windows 9.2.3(4417)

I have got most features working but Deskphone Control is not working. I can see the devices associated with my user from within Jabber when I select "Use my phone for calls" but cannot control them.

The connection status page shows the correct IP address for the CTI server.

I have spent hours reading through various documents and forums which seem to contain contradictory advice.

To clarify theserver versions that I have deployed support the new UC Services which are referenced from a Service Profile which is assigned to the user.

I am not making any progress resolving this issue. Does anyone have any advice on how to move forward with this?

Thanks

James

James Hawkins · ‎08-06-2013

Cisco really need better control of their documentation. The IM and Presence Guide 9.1 tells me to create CTI gateways on the Presence server but this functionality has moved to CUCM - see the incorrect info below:

http://www.cisco.com/en/US/partner/docs/voice_ip_comm/cucm/im_presence/deployment/9_1_1/CUP0_BK_D5B4C107_00_deployment-guide-for-imp-91_chapter_01010.html#CUP0_TK_CA27A982_00

I still cannot get the CTI control to work - anyone got any advice before I start deploying Lync

James Hawkins · ‎08-12-2013

Hi,

I logged a TAC case for this and the engineer traced the problem to a dodgy LDAP filter applied to the CUCM LDAP Directory setup that was not RFC compliant.

He did this by turning on CTI debugging, recreating the issue and then examining the logs which included the text below.

00105509.067 |12:10:17.461 |AppInfo  |LDAP Search complete. Code: -7
00105509.068 |12:10:17.461 |AppInfo  |Failed to find user in directory: LDAP code: -7
00105509.069 |12:10:17.461 |AppInfo  |LDAP failure getting user entry: Bad search filter
00105509.070 |12:10:17.461 |AppInfo 
|authenticationLDAP::authenticateUserWithPassword():Exit on LDAP error(-5005)
00105509.071 |12:10:17.461 |AppInfo  |authenticationDB::login (Done Authenticating using
LDAP)
00105509.072 |12:10:17.461 |AppInfo  |authenticationDB::login (LDAP FAILED) (-5005)

The original filter was:

(&((objectclass=user)(!(objectclass=Computer))(!(UserAccountControl:1.2.840.113556.1.4.803:=2)))((|(ipPhone=3*)(ipPhone=43*)(ipPhone=52*)(ipPhone=83*))))

This filter limits import to active user objects with an ipPhone attribute starting with 3,43,52 or 83. It worked ok to import users to CUCM from AD and to authenticate logins to ccmuser and Jabber but failed on CTI control.

The TAC engineer came up with the updated filter below:

(&(objectclass=user)(!(objectclass=Computer))(!(UserAccountControl:1.2.840.113556.1.4.803:=2))(|(ipPhone=3*)(ipPhone=43*)(ipPhone=52*)(ipPhone=83*)))

This worked fine.

Caution needs to be exercised when playing about with filters on a live system - if you put in something that does not work and try to sync the users can be marked inactive which means that Extension Mobility logins fail even though these do not get authenticated against AD.

Anyway thanks to the guys in Cisco TAC for doing a great job and hopefully this may help others who encounter this issue.

Smp01bank · ‎08-12-2013

This gateway configuring in CUCM - User Managment - User Settings - UC Service!

Create the new service CTI - with ip adress CUCM Publisher!!!

Sorry for Google translate!

P.S.

Instruction wrote what that jackass.

Greed Cisco will lose it!

daamador · ‎08-18-2013

Hello James,

I hope you are doing fine!

Allow me to provide you my comments with this problem that you have

First an important fact when using this feature of Deskphone control

Jabber uses CTI protocol to control a phone device. With this statement you need to keep on mind "CTI Manager".

Let's first make sure you have the following checked:

Desktop Phone control

-Associate device to end user - CUCM Admin > User Management > End User

-Specify Primary Extension for end user

-Add end user to Standard CTI Enable group (important)

-Make sure ip phone has "Allow Control of Device from CTI". This is checked by default, but just make sure.

-CTI Manager service running

-As you are running CUCM 9.x and as you already stated, the profiles are now part of CallManager under the "Service Profile Setup"

http://www.cisco.com/en/US/docs/voice_ip_comm/cucm/admin/9_1_1/ccmcfg/CUCM_BK_A34970C5_00_admin-guide-91_chapter_01100001.html

At this point I'm pretty sure you already checked all this and essentially Deskphone Phone should be working. Now let's jump to the troubleshooting steps:

When you initiate a desktop phone control, the following happens in the background

CTI client (Jabber) tries to open a connection to the CTI server providing username and password to authenticate

Provider Open Request ---> CUCM (CTI)

Provider Open Response <--- CUCM (CTI)

Provider Open Completed <--- CUCM (CTI)

We can understand that the following messages are to exchange the "integrity" of the phone that will be control

Device Registered Event

Device Get Line Info Request ---> CUCM (CTI)

Device Get Line Info Response <--- CUCM (CTI)

Device Open Request ---> CUCM (CTI)

Device Open Response <--- CUCM (CTI)

Line Open Request ---> CUCM (CTI)

Line Open Response <--- CUCM (CTI)

Sucessfull phone control

Device In Service Event <--- CUCM (CTI)

You can then see that we have quite some factors to double check here. To have a full overview of these messages, you need to recollect the following logs

CTI Manager (sdi/sdl)

Jabber logs

At any point during these messages exchange, you will see a failure. On most cases the problem is at the Open Provider stage. On the Jabber logs you will see something like this:

Username: test@test.com

2013-07-30 14:22:08,219 INFO  [0x000017c0]
[src\deskphoneprovider\phonelog.cpp(42)] [csf.ecc] [prepareFor2GLogger] -
CDPProvider::Open -- begin: , strIPAddress.c_str()=xxx-xxx-xxx (hostname of CTI server)

DEBUG [0x000017c0] [src\deskphoneprovider\phonelog.cpp(45)] [csf.ecc]
[prepareFor2GLogger] - CDPProvider::Init

INFO  [0x000017c0] [src\deskphoneprovider\phonelog.cpp(42)] [csf.ecc]
[prepareFor2GLogger] - CtiConnection::start

INFO  [0x000017c0] [src\deskphoneprovider\phonelog.cpp(42)] [csf.ecc]
[prepareFor2GLogger] - CtiConnection::start creating thread!

INFO  [0x000017c0] [src\deskphoneprovider\phonelog.cpp(42)] [csf.ecc]
[prepareFor2GLogger] - CDPProvider::Open -- end!

Provider Open Request Message

DEBUG [0x00001150] [src\deskphoneprovider\phonelog.cpp(45)] [csf.ecc] [prepareFor2GLogger] -
CDPProvider::SendRequest -- begin: , msg.sequenceNumber=1,
pObject=0x0D7E6E5C, pdunames[msg.msgID]=PROVIDER_OPEN_REQUEST

DEBUG [0x00001150] [src\deskphoneprovider\phonelog.cpp(45)] [csf.ecc]
[prepareFor2GLogger] - CDPProvider::DispatchMessage -- begin: , nPduNum=4,
pduName=PROVIDER_OPEN_RESPONSE

DEBUG [0x00001150] [src\deskphoneprovider\phonelog.cpp(45)] [csf.ecc]
[prepareFor2GLogger] - CDPProvider::DispatchMessage -- begin: , nPduNum=126,
pduName=PROVIDER_OPEN_COMPLETED_EVENT

Eventually at this point one of the main problem happens, the open provider negotiated
the username and password of this user, you then might see messages like the followings:


WARN  [0x00001150]
[src\deskphoneprovider\phonelog.cpp(39)] [csf.ecc] [prepareFor2GLogger] -
ProviderOpen failed: reason: 0x8ccc0060, Directory login failed - credential
has been locked due to no activity.
WARN  [0x00001150]
[src\deskphoneprovider\phonelog.cpp(39)] [csf.ecc] [prepareFor2GLogger] -
ProviderOpen failed: reason: 0x8ccc0060, Directory login failed - User not present in Standard CTI user group

WARN  [0x00001150]
[src\deskphoneprovider\phonelog.cpp(39)] [csf.ecc] [prepareFor2GLogger] -
ProviderOpen failed: reason: 0x8ccc0060, Directory login failed - User not present in Standard CTI user group




WARN  [0x00001150]
[src\deskphoneprovider\phonelog.cpp(39)] [csf.ecc] [prepareFor2GLogger] -
ProviderOpen failed: reason: 0x8ccc0060, Directory login failed - invalid user credentials



This will give you a start to troubleshoot and understand better this interaction. Allow
me to share a few things to check:

Can you telnet sucessfully to the CTI manager port 2748
  telnet x.x.x.x 2748

Is the PC able to resolve the CUCM hostname (If using hostnames)?

If using Ldap authentication, which port is configured under Ldap directory and Ldap authentication?
 Global catalog port : 3268 (hihgly recommended)
 DC port : 389 


I hope this helps you James. 

Daniel

Regards, Daniel Amador CCIE# 38898 (Voice) Cisco TAC Support Engineer

Guennadi Roussak · ‎01-09-2014

Hi Daniel,

we have a Problem with AD-User and DeskPhone ...

The "Active Local User" can control a DeskPhone

The "Active LDAP Synchronized User" can't control a DeskPhone from same PC, but he can controll a Softphone.

Cisco UCM - 9.1.2.10000-28 with LDAP Sync/Auth via 3269 (success)

Cisco UCMIMP - 9.1.1.31900-1

Cisco Jabber - 9.6.0 Build 17088

564 INFO [0x0000226c] [src\common\thread\WorkerThread.cpp(94)] [csf.ecc] [run] - Started thread: CtiConnection

564 DEBUG [0x0000226c] [utilities\socket\TcpSocketHelper.cpp(82)] [csf.ecc] [connect] - About to connect to 172.20.1.11

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(957)] [csf.ecc] [SendRequest] - CDPProvider::SendRequest, msg.sequenceNumber=1, pObject=0477A214, pdunames[msg.msgID]=PROVIDER_OPEN_REQUEST

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(967)] [csf.ecc] [SendRequest] - SendRequest setting msg.sequenceNumber to , msg.sequenceNumber=2

564 DEBUG [0x0000226c] [oneprovider\QBE\ProtocolElement.cpp(330)] [csf.ecc] [encode] - Message::encode: , msg.protoVersion=0x000e0000, msg.msgID=3, sizeof(Header)=32, fixedSize=108, varSize=90

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(973)] [csf.ecc] [SendRequest] - SendRequest Succeed., pdunames[msg.msgID]=PROVIDER_OPEN_REQUEST, msg.sequenceNumber=2

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(986)] [csf.ecc] [SendEvent] - CDPProvider::SendEvent, pObject=0477A210, nType=1001

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(919)] [csf.ecc] [OnEvent] - CDPProvider::OnEvent, pObject=0477A210, nType=1001, pvThis=0477A210

564 DEBUG [0x0000226c] [pper\DeskPhoneConnectionContext.cpp(317)] [csf.ecc] [ecc::DeskPhoneConnectionContext::OnProviderEventUpdated] - OnProviderEventUpdated(1001), state=STATE_INITIAL_LOGIN, loginstate=LOGINSTATE_OPENING

564 DEBUG [0x0000226c] [c\deskphoneprovider\DPProvider.cpp(1148)] [csf.ecc] [DispatchTheMessage] - CDPProvider::DispatchTheMessage, nPduNum=4, pduName=PROVIDER_OPEN_RESPONSE

564 DEBUG [0x0000226c] [c\deskphoneprovider\DPProvider.cpp(1232)] [csf.ecc] [DispatchTheMessage] - Received , pdunames[nPduNum]=PROVIDER_OPEN_RESPONSE, seqNum=2

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(267)] [csf.ecc] [HandleMessage] - CDPProvider::HandleMessage, nPduNum=4

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(407)] [csf.ecc] [HandleResponse_ProviderOpen] - CDPProvider::HandleResponse_ProviderOpen

564 DEBUG [0x0000226c] [oneprovider\QBE\ProtocolElement.cpp(360)] [csf.ecc] [decode] - Message::decode: , totalSize=107, type=0, magic=4294958557, msg.protoVersion=0x000e0000, pduNum=4, hdrSize=32, fixedSize=52, varSize=31

564 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(415)] [csf.ecc] [HandleResponse_ProviderOpen] - CUCM protocol version: , resp.getProtoVersion()=0x000e0000

564 WARN [0x0000226c] [c\deskphoneprovider\DPProvider.cpp(1026)] [csf.ecc] [ResetHeartbeatTimer] - m_heartbeatIntervalS not set, timeout not set.

845 DEBUG [0x0000226c] [c\deskphoneprovider\DPProvider.cpp(1148)] [csf.ecc] [DispatchTheMessage] - CDPProvider::DispatchTheMessage, nPduNum=126, pduName=PROVIDER_OPEN_COMPLETED_EVENT

845 DEBUG [0x0000226c] [c\deskphoneprovider\DPProvider.cpp(1290)] [csf.ecc] [DispatchTheMessage] - PDUTYPE_ProviderEvent or PDUTYPE_Heartbeat, nPduNum=126, pdunames[nPduNum]=PROVIDER_OPEN_COMPLETED_EVENT

845 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(267)] [csf.ecc] [HandleMessage] - CDPProvider::HandleMessage, nPduNum=126

845 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(488)] [csf.ecc] [HandleEvent_ProviderOpenCompleted] - CDPProvider::HandleEvent_ProviderOpenCompleted

845 DEBUG [0x0000226c] [oneprovider\QBE\ProtocolElement.cpp(360)] [csf.ecc] [decode] - Message::decode: , totalSize=161, type=0, magic=4294958557, msg.protoVersion=0x000e0000, pduNum=126, hdrSize=32, fixedSize=72, varSize=65

845 WARN [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(502)] [csf.ecc] [HandleEvent_ProviderOpenCompleted] - ProviderOpen failed: reason: 0x8ccc0060, Directory login failed - authentication failed.

845 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(986)] [csf.ecc] [SendEvent] - CDPProvider::SendEvent, pObject=0477A210, nType=1008

845 DEBUG [0x0000226c] [rc\deskphoneprovider\DPProvider.cpp(919)] [csf.ecc] [OnEvent] - CDPProvider::OnEvent, pObject=0477A210, nType=1008, pvThis=0477A210

845 DEBUG [0x0000226c] [pper\DeskPhoneConnectionContext.cpp(317)] [csf.ecc] [ecc::DeskPhoneConnectionContext::OnProviderEventUpdated] - OnProviderEventUpdated(1008), state=STATE_INITIAL_LOGIN, loginstate=LOGINSTATE_LOGGING_IN

845 DEBUG [0x0000226c] [pper\DeskPhoneConnectionContext.cpp(891)] [csf.ecc] [ecc::DeskPhoneConnectionContext::DPLogoutWorkItem::DPLogoutWorkItem] - create DPLogoutWorkItem

845 DEBUG [0x0000226c] [pper\DeskPhoneConnectionContext.cpp(892)] [csf.ecc] [ecc::DeskPhoneConnectionContext::DPLogoutWorkItem::DPLogoutWorkItem] - Setting _loginState = LOGINSTATE_DISCONNECTING

845 DEBUG [0x0000226c] [c\deskphonewrapper\CC_DPService.cpp(926)] [csf.ecc] [ecc::CC_DPService::raiseLoginFailure] - raiseLoginFailure(5)

845 DEBUG [0x000013a0] [pper\DeskPhoneConnectionContext.cpp(898)] [csf.ecc] [ecc::DeskPhoneConnectionContext::DPLogoutWorkItem::run] - DPLogoutWorkItem::run()

845 INFO [0x0000226c] [\deskphonewrapper\CC_DPService.cpp(1078)] [csf.ecc] [ecc::CC_DPService::notifyConnectionStatusObservers] - dispatching ConnectionStatus Change eIdle

845 DEBUG [0x00002788] [c\deskphonewrapper\CC_DPService.cpp(298)] [csf.ecc] [ecc::CC_DPService::start] - Finished waiting for deskphone to go in to service...

845 INFO [0x000013a0] [rc\deskphoneprovider\DPProvider.cpp(218)] [csf.ecc] [Close] - CDPProvider::Close

845 INFO [0x0000226c] [control\CallControlManagerImpl.cpp(3092)] [csf.ecc.evt] [ecc::CallControlManagerImpl::notifyConnectionStatusChange] - CONNECTION_STATUS_CHANGE: eIdle

845 ERROR [0x00002788] [control\CallControlManagerImpl.cpp(1989)] [csf.ecc] [ecc::CallControlManagerImpl::doConnect] - doConnect() returnCode : AuthentincationFailure

845 DEBUG [0x000017a0] [s\telephonyservice\ECCObservers.cpp(153)] [csf-unified.telephony.ECCObserverLogger] [ECCObservers::onConnectionStatusChange] - onConnectionStatusChange(status = eIdle).

845 DEBUG [0x0000226c] [\deskphonewrapper\CC_DPService.cpp(1014)] [csf.ecc] [ecc::CC_DPService::raiseProviderStateChange] - Got cxn change, disconnecting deskphone video Idle

845 DEBUG [0x000013a0] [rc\deskphoneprovider\DPProvider.cpp(957)] [csf.ecc] [SendRequest] - CDPProvider::SendRequest, msg.sequenceNumber=2, pObject=0477A214, pdunames[msg.msgID]=PROVIDER_CLOSE_REQUEST

845 ERROR [0x00002788] [control\CallControlManagerImpl.cpp(2025)] [csf.ecc] [ecc::CallControlManagerImpl::doConnect] - doConnect() returnCode : eDeviceRegAuthenticationFailure

845 DEBUG [0x000017a0] [elephonyservice\BackgroundWorker.cpp(35)] [csf-unified.telephony.BackgroundWorkerLogger] [BackgroundWorker::doTask] - Adding new task to BackgroundWorker. Task name is: TelephonyAdapter::onConnectionStatusChange

845 INFO [0x0000226c] [rc\deskphonevideo\DeskPhoneVideo.cpp(76)] [csf.ecc] [ecc::DeskPhoneVideo::disconnect] - disconnecting

845 DEBUG [0x000013a0] [rc\deskphoneprovider\DPProvider.cpp(967)] [csf.ecc] [SendRequest] - SendRequest setting msg.sequenceNumber to , msg.sequenceNumber=3

845 INFO [0x00002788] [control\CallControlManagerImpl.cpp(2411)] [csf.ecc] [ecc::CallControlManagerImpl::doDisconnect] - --->

845 DEBUG [0x000017a0] [common\processing\TaskDispatcher.cpp(29)] [TaskDispatcher] [Processing::TaskDispatcher::enqueue] - Enqueue TelephonyAdapter::onConnectionStatusChange - Queue Size: 9

845 DEBUG [0x0000226c] [c\deskphonevideo\DeskPhoneVideo.cpp(315)] [csf.ecc] [ecc::DeskPhoneVideo::stopCdp] - Stopping CDP

845 DEBUG [0x000013a0] [oneprovider\QBE\ProtocolElement.cpp(330)] [csf.ecc] [encode] - Message::encode: , msg.protoVersion=0x000e0000, msg.msgID=9, sizeof(Header)=32, fixedSize=4, varSize=0

845 INFO [0x00002788] [pper\DeskPhoneConnectionContext.cpp(267)] [csf.ecc] [ecc::DeskPhoneConnectionContext::stop] - DeskPhoneConnectionContext::stop

845 DEBUG [0x000013a0] [rc\deskphoneprovider\DPProvider.cpp(973)] [csf.ecc] [SendRequest] - SendRequest Succeed., pdunames[msg.msgID]=PROVIDER_CLOSE_REQUEST, msg.sequenceNumber=3

845 DEBUG [0x0000226c] [c\deskphonevideo\DeskPhoneVideo.cpp(318)] [csf.ecc] [ecc::DeskPhoneVideo::stopCdp] - CDP stopped

845 INFO [0x000017a0] [src\AccessoriesManager.cpp(234)] [csf.accessory.event] [accessory::AccessoriesManager::onConnectionStatusChange] - Received onConnectionStatusChange - eIdle

845 DEBUG [0x00002788] [pper\DeskPhoneConnectionContext.cpp(891)] [csf.ecc] [ecc::DeskPhoneConnectionContext::DPLogoutWorkItem::DPLogoutWorkItem] - create DPLogoutWorkItem

845 INFO [0x000013a0] [\deskphoneprovider\CtiConnection.cpp(49)] [csf.ecc] [stop] - CtiConnection::stop

Thanks,

Guennadi

daamador · ‎01-09-2014

Guennadi,

Just something real quick, remember that controlling a desk phone vrs sofphone will be different,as deskphone uses CTI therefore the need to authenticate through the CTI Directory process, that is why is working when using softphone.

I would like you to try something real quick, please run the following command on both scenario - user ldap integrated vrs local cucm user

run sql select u.userid, t.name, p.maxinactivedays FROM enduser as u, credential as c, credentialpolicy as p, typecredential as t WHERE u.pkid = c.fkenduser AND c.fkcredentialpolicy = p.pkid AND t.enum = c.tkcredential AND u.userid = ''

Let me know what it displays.

Regards,

Daniel Amador
CCIE# 38898 (Voice)

Regards, Daniel Amador CCIE# 38898 (Voice) Cisco TAC Support Engineer

Guennadi Roussak · ‎01-09-2014

Hi Daniel,

user ldap integrated - 'roessler':

admin:run sql select u.userid, t.name, p.maxinactivedays FROM enduser as u, credential as c, credentialpolicy as p, typecredential as t WHERE u.pkid=c.fkenduser AND c.fkcredentialpolicy=p.pkid AND t.enum=c.tkcredential AND u.userid='roessler'

userid name maxinactivedays

======== ======== ===============

roessler Password 0

roessler PIN 0

local cucm user - 'dummy'

admin:run sql select u.userid, t.name, p.maxinactivedays FROM enduser as u, credential as c, credentialpolicy as p, typecredential as t WHERE u.pkid=c.fkenduser AND c.fkcredentialpolicy=p.pkid AND t.enum=c.tkcredential AND u.userid='dummy'

userid name maxinactivedays

====== ======== ===============

dummy Password 0

dummy PIN 0

admin:

Regards,

Guennadi

Guennadi Roussak · ‎01-09-2014

Hi Daniel,

I have a workaround (?) ...

I create a UC Service Profile with Directory Service mapped to Active Directory Global Catalog (FQDN, tcp/3269) and this work fine ...

First Directory Service was mapped to UCM via tcp/389. Is it wrong?

Thanks,

Guennadi

daamador · ‎01-09-2014

Guennadi,

AD vrs Global catalog AD shouldn't be a problem to be honest. Some of the Global Catalog functions would be to expedite the search through AD as is always a best practice to use Global Catalog when using Jabber integrations especially if you have a big enduser database.

If the issue is 100% reproducible this could be a bugID. But I would suggest you to open a TAC case so we can take the necessary logs and engage our escalation team and see if this is a new or existing bugID Guennadi.

Regards,

Daniel Amador
CCIE# 38898 (Voice)

Regards, Daniel Amador CCIE# 38898 (Voice) Cisco TAC Support Engineer

Guennadi Roussak · ‎01-09-2014

Hi Daniel,

I mean UCM (as UDS) vrs AD (regardless of type) ...

Best regards,

Guennadi