This is another attempt to share what I’ve researched in my personal time with other Engineers simply because I have benefited a lot from reading other people’s blogs also. My hope is that this post is useful to someone out there.
Not too long ago, I wrote a post about the boot process of Cisco jabber for windows which can be found here. In continuation of this entry, I thought I’d add share some more information on how to read the logs that are generated when two people who are on Cisco Jabbber clients start chatting or sharing screenshots with each other.
Knowing what to expect in these logs could prove very important if a client complains to you that when he sends chat message to someone the message is never delivered. Anyway, before I start talking too much, lets begin.
Lets starting of by talking about the trace file that should be used when looking into the chat messages or picture exchange between tw0 people on jabber clients. In this regard, the best trace to collect is the XCP Connnecton Manager traces. It is also advisable to set the trace level to detailed before attempting to collect the trace file. So the question is, ‘why the XCP Connection manager trace’ ? Well the XCP Connection Manager helps jabber clients to connect to the IM and Presence Server. It is sort of like an intermediary.
Now that we have that under our belt, the nex thing to know is how to differnciate one chat message for another in a massive pile of traces.
There are several things unique to every chat conversation:
1) The sender and the receiver’s jabber ID (JID)
2) Every message has a Unique ID which is used to identify a message as it is transported across multiple IM and presence servers en-route to it’s destination or jabber user.
When reading jabber traces, the same rule that applies to phones and call-manager applies here too: and that is, you will mostly only find the logs for a given jabber client on the server that it is registered to. This is true for the XCP Connection Manager traces. What I’m trying to say here is that sometimes you have to collect logs from multiple IM and presence servers but most of the interesting logs will piled up in one server.
Now that we understand that, let talk briefly about the message flow.
For every chat message/ conversation there are several messages that are exchanged in the following order.
1) One of the very first messages is the “IN FROM CLIENT” message. This is the trace line that tells us that someone has sent a message via the XCP Connection Manager to the IM and presence server using a jabber client.
2) “OUT TO SERVER” message. This means that the message has now been transferred to the IM and Presence server’s internal processes so that a destination for the message can be calculatated or derived. It is at this stage that components like the XCP Router kicks in.
3) ” IN FROM SERVER” message. This is the message that instructs an IM and presence node to deliver a message to a particular XMPP client. i.e jabber. Please note that if jabber clients are chatting with each other but they are not registered to the same IM and Presence node, you will never see an “OUT TO SERVER” and an ” IN FROM SERVER” message together on any single node for one conversation going in one direction (i.e from sender to receiver).
4) Then there is the “OUT TO CLIENT ” message. This is one of the final messages you will see in the logs when a message is about to be delivered to a recipient jabber client.
Ok now that we’ve discussed this matter at length, let take a look at some logs.
In the logs below, user2@voiceinitiate.com sends a message to User1@voiceinitiate.comand a message ID of 52a46470:00000990:0000010c‘ is assigned to the message
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
[IN FROM CLIENT state:6]: <message id=’uid:52a46470:00000990:0000010c‘ to=’user1@voiceinitiate.com’ type=’chat’><body>hello this is maxwell. i am having a cup of tea so feel free to play your xbox at work</body><thread>connect23313xmlns=’http://jabber.org/protocol/xhtml-im’>hello this is maxwel. i am having a cup of tea so feel free to play your xbox at work
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
The Jabber session manager (cm-1_jsm-1) that is running on server “subcup.voiceinitiate.com”, informs us that this message is being sent out to the server’s internal processes for analysis and message delivery
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
cm-1_jsmcp-1.subcup-voiceinitiate-com [OUT TO SERVER(3)]: from=‘user2@voiceinitiate.com/jabber_22990‘ id=’uid:52a46470:00000990:0000010c‘ to=’user1@voiceinitiate
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
In the output below, the Jabber session manager (cm-1_jsm-1) that is running on server “pubcup.voiceinitiate.com”, informs us that it has received a request to deliver message to user1@voiceinitiate.com to user2@voiceinitiate.com
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
cm-1_jsmcp-1.pubcup-voiceinitiate-com [IN FROM SERVER]: from=’user2@voiceinitiate.com/jabber_22990′ id=’uid:52a46470:00000990:0000010c’ to=’user1@voiceinitiate.com’ type=‘chat’ xml:lang=’en’><body>hello this is maxwell. i am having a cup of tea so feel free to play your xbox at work</body>connect23313xmlns=’http://jabber.org/protocol/xhtml-im’>hello this is maxwel. i am having a cup of tea so feel free to play your xbox at work
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
In the logs below, we see that the message is delivered to the recipient jabber client.
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
cm-1_jsmcp-1_xmppd-1 [OUT TO CLIENT]: <message from=’user2@voiceinitiate.com/jabber_22990′ id=’uid:52a46470:00000990:0000010c’ to=’user1@voiceinitiate.com‘ type=‘chat‘ xml:lang=’en’>hello this is maxwell. i am having a cup of tea so feel free to play your xbox at workconnect23313xmlns=’http://jabber.org/protocol/xhtml-im’>hello this is maxwel. i am having a cup of tea so feel free to play your xbox at work
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
Ok so now that we know how text/ chat messages flow within the server(s), how about when we send a screen-shot to someone via jabber? Well the snapshot below shows me sending a picture from one jabber client to another . I will not show you the full message follow because we already have a general idea of what to expect. However, what I will show here is the actual traces that showed what was happening in the background as the picture was being sent.
Let me first of show you the actual screen-shot that I took while the picture was being transferred between jabber clients. Pay special attention to the name of the file and see if you can see that same file name in the the logs below.
cm-1_jsmcp-1_xmppd-1 [OUT TO CLIENT]: <iq from=’user1@voiceinitiate.com/wbxconnect’ id=’uid:52a45b16:00004d03:000001a7‘ to=‘user2@voiceinitiate.com/jabber_22990′ type=’set’ xml:lang=’en’>Successfully sent file ‘user1@voiceinitiate.com_20131208_150328.png(13613 bytes)’.</x></jingle></iq>
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
The logs above withe XCP Connections Manager logs. Now the presence Engine logs are even more interesting. Check out the logs below that even tells you were the file was saved on the computer hard-drive.
:::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
system.pe.jabber 1308670 INFO ClientEmComponent::onPacket() – PACKET RECEIVED:: <message from=’user1@voiceinitiate.com/wbxconnect’ to=’user2@voiceinitiate.com‘ type=’chat’ xml:lang=’en’> xmlns=’http://webex.com/connect/imcmd’/>Subject<body xmlns=’http://www.w3.org/1999/xhtml’><img alt=’Screen capture‘ contenteditable=’false’ id=‘user1@voiceinitiate.com_20131208_150328.png’ name=‘connect_screen_capture‘ src=’file:///C:/Documents%20and%20Settings/user1/My%20Documents/MyJabberFiles/user1@voiceinitiate.com/user1@voiceinitiate.com_20131208_150328.png‘/></body></html></message>
Anyway, I hope that what has been shared here today will come in handy to someone down the line.
All the best
Maxwell