This blog entry was never intended to be made public  but as I have picked up  so many things from reading other people’s blogs, I thought I’d add this entry here in case its of use to anyone . Anyway, the reason behind this work is very simple: In order to find a problem when looking at the logs of broken device, you first of all need to know what they look like when everything is working fine.

The following is an output from  the jabber logs (CSF-UNIFIED.LOG)that I collected from one of my Lab PC (s) running jabber 9.1.5  that was  registered to cucm and presence server 9.x.

Jabber  processes are starting.

————————————————–

Starting new instance of Cisco Jabber

————————————————–

[lugin-runtime\impl\PluginRuntime.cpp(93)] [plugin-runtime] [initialize] – Initializing plugin runtime

\JabberCoreUiPlugin.cpp(48)] [plugin-runtime] [initPlugin] – Jabber Core UI Plugin initializing...

Jabber front-end /

 

IMPStackCap::StackManager::initialise] – LoginMgr started…

[IMPStackCap::StackManager::initialise] – PresenceClient started…

[IMPStackCap::StackManager::initialise] – Config started…

2013-12-01 00:27:31,448 INFO  [0x000003c8] [esets\adapters\imp\StackManager.cpp(118)] [csf-unified.imp.stackManager] [IMPStackCap::StackManager::initialise] – BuddyList started…

2013-12-01 00:27:31,448 INFO  [0x000003c8] [esets\adapters\imp\StackManager.cpp(121)] [csf-unified.imp.stackManager] [IMPStackCap::StackManager::initialise] – Presence started…

2013-12-01 00:27:31,448 INFO  [0x000003c8] [esets\adapters\imp\StackManager.cpp(124)] [csf-unified.imp.stackManager] [IMPStackCap::StackManager::initialise] – IMP2P started…

[csf-unified.imp.stackManager] [IMPStackCap::StackManager::initialise] – Group Chat started…

csf-unified.imp.stackManager] [IMPStackCap::StackManager::initialise] – EnterpriseGroups started…

csf-unified.imp.stackManager] [IMPStackCap::StackManager::initialise] – …Initialized

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

In the output below, the jabber client notices that I did not configure any ip or dns names in the jabber client so  jabber decides that it will have to dynamically sends out a DNS service request (SRV) request to the DNS server that is configured on the local network interfaces card in order to find out the IP address of the presence server. However, before doing that, it checks whether it has any presence server  IP-addresses stored locally in its database–and because this is not the first time that jabber has found this server, it discovers a cashed copy of its presence server host-name and uses it  It then goes on to login with my user-ID of ‘ user2’. In case you are reading this and wondering how jabber manages to  find its presence/webex server without having it configured on the jabber client,  just copy the following into Google and you will find everyone talking about it :   _cuplogin._tcp

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

[AddUpdateSubItem] – Setting Status:  status of Presence to Connecting

No CUP server specified, will attempt DNS SRV with domainlist: voiceinitiate.com

[LoginMgr.dll]: LoginMgrImpl::Login, type:1, serv:, user:user2, resource:jabber_6742, jw-ver:0.9.2.4420, app-ver:9.2.6.12639

[LoginMgr.dll]: login, clear login data. deep:1

[LoginMgr.dll]: dns, cup-domain:voiceinitiate.com

[LoginMgr.dll]: CLoginContext::ChangeState now:1 auto:0

[LoginMgr.dll]: CGetProxy::Connect login, CGetProxy::Connect

[LoginMgr.dll]: CLoginContext::ChangeState now:1 auto:0

[LoginMgr.dll]: dns, login, with cached cup server:pubcup.voiceinitiate.com

[LoginMgr.dll]: CLoginCup::_connect

[LoginMgr.dll]: ha, soap-servers:pubcup.voiceinitiate.com

[LoginMgr.dll]: login, cup:pubcup.voiceinitiate.com

inCommands::SignOn] –

[csf-unified.imp.LoginCommands] [IMPStackCap::LoginCommands::SignOn] – Signing into Presence Server. Account: user2, server: , login mode: ON_PREM, result: 0

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Jabber successfully connects to presence server and then verifies the certificate of the presence server.

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

[csf-unified.imp.LoginCommands] [IMPStackCap::LoginCommands::SignOn] – Dispatcher::doExecute] – LoginCommands::SignOnResult: 0

[csf-unified.imp.PresenceAdapter.SignOnState] [SignOnState::isComplete] – isComplete: 0[csf.cert.win32] [cert::Win32CertVerifier::Win32CertVerifier] – Windows CertVerifier constructor

[cert::CertVerifier::checkResult] – finalResult: SUCCESS

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

This stage of authentication and certificate verification is now over and Jabber is now engaged in full communication with the  IM and presence server: Connecting with the XMPP component of the  presence server and retrieving data about the CCMCIP (call-manager) server, TFTP server and CTI server now ensues. The client opens an XMPP stream and starts exchanging data with the IM and Presence server .

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

[IMPStackCap::Log::log] – [LoginMgr.dll]: CLoginCup::OnGetAllConfig

[LoginMgr.dll]: login, jabber, serv:pubcup.voiceinitiate.com

[ [LoginMgr.dll]: login, cup, calc 1-time token(userid:user2@voiceinitiate.com, token:1252341)

[JabberWerx] [IMPStackCap::Log::log] – [XmppSDK.dll]: #0, CXmppClient::Connect , connecting to server by TCP connection……

[JabberWerx] [IMPStackCap::Log::log] – [XmppSDK.dll]: #0, CXmppClient::onStreamEvent ,CXmppClient::onStreamEvent, SessionState_Connecting

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Jabber client retrieves its  details like ccmcip server , buddy list, tftp server etc .

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

[IMPStackCap::RetrieveConfigCommand::RetrieveConfig] – Retrieving config from Presence Server

[IMPStackCap::RetrieveConfigCommand::RetrieveConfig] – Config Retrieved from Presence Server

csf-unified.imp.BuddyListCommands] [IMPStackCap::BuddyListCommands::GetUserJid] – User jid: user2@voiceinitiate.com

[ConfigServiceImpl::OnConfigChanged] – OnConfigChanged key : [CcmcipServer2] value : [192.168.0.12] o

[ConfigServiceImpl::OnConfigChanged] – OnConfigChanged key : [CtiServer1] value : [pubcucm.voiceinitiate.com

 

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Now that that jabber client knows it’s TFTP server, it attempts to download the configuration file.

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Old tftpServer1 address:

New tftpServer1 address:192.168.0.12

Old tftpServer2 address:

New tftpServer2 address:

Old tftpServer3 address:

New tftpServer3 address:

Old configurationFile:jabber-config.xml

New configurationFile:

[TftpConfigStore::onConfigAddedOrUpdated] – attemptNewDownload [true]

[attemptTftpFileDownload] – Downloading file http://192.168.0.12:6970/jabber-config.xml………

[csf.ecc] [doGet] – doGet(http://192.168.0.12:6970/user2.cnf.xml)

[csf.ecc] [doGet] – doGet(http://192.168.0.12:6970/CUPC/AppDialRules.xml)

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

The jabber client then tries to register its softphone.

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

sipio-sent—> REGISTER sip:pubcucm SIP/2.0

Via: SIP/2.0/TCP 192.168.0.9:1588;branch=z9hG4bK00005888

From: <sip:1002@pubcucm>;tag=000c29e2fc390004000060d0-00005d12

To: <sip:1002@pubcucm>

Call-ID: 000c29e2-fc390002-000070b6-00001a66@192.168.0.9

Max-Forwards: 70

Date: Sun, 01 Dec 2013 00:27:36 GMT

CSeq: 102 REGISTER

User-Agent: Cisco-CSF/9.3.2

Sent:REGISTER sip:pubcucm SIP/2.0  Cseq:102 REGISTER CallId:000c29e2-fc390002-000070b6-00001a66@192.168.0.9

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Cisco call manager accepts its registration request.

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

[_SIPCCLoggerFunction] – sipio-recv<— SIP/2.0 200 OK

Via: SIP/2.0/TCP 192.168.0.9:1588;branch=z9hG4bK00005888

From: <sip:1002@pubcucm>;tag=000c29e2fc390004000060d0-00005d12

To: <sip:1002@pubcucm>;tag=833129954

Date: Sun, 01 Dec 2013 00:27:20 GMT

Call-ID: 000c29e2-fc390002-000070b6-00001a66@192.168.0.9

CSeq: 102 REGISTER

Expires: 120

Contact: <sip:6ee27b67-fbf0-5671-2759-64e50cb86304@192.168.0.9:1588;transport=tcp>;+sip.instance=”<urn:uuid:00000000-0000-0000-0000-000c29e2fc39>”;+sip.instance=””;+u.sip!devicename.ccm.cisco.com=”user2″;+u.sip!model.ccm.cisco.com=”503″;video;bfcp

Supported: X-cisco-srtp-fallback,X-cisco-sis-6.0.0

Content-Length: 0

:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

Ok that’s all for now; I will continue to expand this entry whenever I  find time.

For further reading please consider the following links

1)      The basics of XMPP- Envelops, Stanza, Streams etc

http://web.archive.org/web/20120815100411/http://www.adarshr.com/papers/xmpp

2)       For a step by step guide on how to read jabber call flow between two jabber soft-phones      http://www.cisco.com/en/US/partner/products/ps12511/products_tech_note09186a0080c15703.shtml