Understanding AOL Heart Beat Correspondence

Dan_Spiegel · January 17, 2008, 8:32pm

I need help diagnosing a problem by reviewing log file output. One of my customers lost connectivity to AOL through OpenFire for the first time in months but twice in one day. Our application sends heart beat messages through OpenFire to AOL every 5 minutes. I was wondering if someone could help me understand the OSCAR protocol so that I can diagnose what I saw in my log files.

A healthy heart beat looked like this in OpenFire’s debug log files:

2008.01.15 11:59:23 Received presence packet: <presence id=“TlB4o-41655” to=“aim.wildfire.OUR_DOMAIN.com” from=“USER_aim@wildfire.OUR_DOMAIN.com/Smack”><status/><priority&gt ;10</priority></presence>

2008.01.15 11:59:23 An existing resource has changed status: USER_aim@wildfire.OUR_DOMAIN.com/Smack

2008.01.15 11:59:23 Sending SNAC command: SetInfoCmd: info=InfoData:

2008.01.15 11:59:23 Setting up SNAC request and listener: SetInfoCmd: info=InfoData:,null

2008.01.15 11:59:23 Handling request SnacRequest for SetInfoCmd: info=InfoData:: listeners: null, responses: null

2008.01.15 11:59:23 Sending SNAC command: SetExtraInfoCmd: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=00 00 00 00>]

2008.01.15 11:59:23 Setting up SNAC request and listener: SetExtraInfoCmd: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=00 00 00 00>],null

2008.01.15 11:59:23 Handling request SnacRequest for SetExtraInfoCmd: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=00 00 00 00>]: listeners: null, responses: null

2008.01.15 11:59:23 Updating status for TransportSession[USER_aim@wildfire.OUR_DOMAIN.com]

2008.01.15 11:59:23 OSCAR bos snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=21, requests: 21, paused=false, snacPacket=SnacPacket type 0x1/0x21, flag1=0x80: 8 bytes (id=2148754405), snacCommand=ExtraInfoAck: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>, ExtraInfoBlock: type=0xd (null), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=22, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x21, flag1=0x80: 16 bytes (id=2148754405), flapPacket=FlapPacket (channel=2, seq=26435)

2008.01.15 11:59:23 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=21, requests: 21, paused=false, snacPacket=SnacPacket type 0x1/0x21, flag1=0x80: 8 bytes (id=2148754405), snacCommand=ExtraInfoAck: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>, ExtraInfoBlock: type=0xd (null), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=22, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x21, flag1=0x80: 16 bytes (id=2148754405), flapPacket=FlapPacket (channel=2, seq=26435)

2008.01.15 11:59:23 OSCAR bos snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=21, requests: 21, paused=false, snacPacket=SnacPacket type 0x1/0x21, flag1=0x80: 8 bytes (id=2148754406), snacCommand=ExtraInfoAck: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>, ExtraInfoBlock: type=0xd (null), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=22, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x21, flag1=0x80: 16 bytes (id=2148754406), flapPacket=FlapPacket (channel=2, seq=26436)

2008.01.15 11:59:23 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=21, requests: 21, paused=false, snacPacket=SnacPacket type 0x1/0x21, flag1=0x80: 8 bytes (id=2148754406), snacCommand=ExtraInfoAck: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>, ExtraInfoBlock: type=0xd (null), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=>] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=22, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x1/0x21, flag1=0x80: 16 bytes (id=2148754406), flapPacket=FlapPacket (channel=2, seq=26436)

2008.01.15 11:59:23 OSCAR bos snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=21, requests: 21, paused=false, snacPacket=SnacPacket type 0x3/0xb: 92 bytes (id=2148754450), snacCommand=BuddyStatusCmd: userinfo=UserInfo for USER: flags=0x11 (MASK_FREE | MASK_UNCONFIRMED), memberSince=Tue Mar 23 15:12:18 EST 2004, sessLenAim=0min, onSince=Tue Jan 15 11:59:21 EST 2008, extraInfos=[ExtraInfoBlock: type=0x0 (null), extraData=<ExtraInfoData: flags=0x0 (), data=02 01 d2 04 72>, ExtraInfoBlock: type=0x1 (TYPE_ICONHASH), extraData=<ExtraInfoData: flags=0x0 (), data=02 01 d2 04 72>], extraTlvs=[TLV: type=0x23, length=4, uint value=1200416361: 47 8c e6 69, TLV: type=0x29, length=4, uint value=1200416361: 47 8c e6 69, TLV: type=0x26, length=4, uint value=1200416361: 47 8c e6 69], longcaps: [] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=22, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x3/0xb: 92 bytes (id=2148754450), flapPacket=FlapPacket (channel=2, seq=26437)

2008.01.15 11:59:23 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=21, requests: 21, paused=false, snacPacket=SnacPacket type 0x3/0xb: 92 bytes (id=2148754450), snacCommand=BuddyStatusCmd: userinfo=UserInfo for USER: flags=0x11 (MASK_FREE | MASK_UNCONFIRMED), memberSince=Tue Mar 23 15:12:18 EST 2004, sessLenAim=0min, onSince=Tue Jan 15 11:59:21 EST 2008, extraInfos=[ExtraInfoBlock: type=0x0 (null), extraData=<ExtraInfoData: flags=0x0 (), data=02 01 d2 04 72>, ExtraInfoBlock: type=0x1 (TYPE_ICONHASH), extraData=<ExtraInfoData: flags=0x0 (), data=02 01 d2 04 72>], extraTlvs=[TLV: type=0x23, length=4, uint value=1200416361: 47 8c e6 69, TLV: type=0x29, length=4, uint value=1200416361: 47 8c e6 69, TLV: type=0x26, length=4, uint value=1200416361: 47 8c e6 69], longcaps: [] - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=22, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x3/0xb: 92 bytes (id=2148754450), flapPacket=FlapPacket (channel=2, seq=26437)

2008.01.15 11:59:23 Handling request SnacRequest for IconRequest for USER (code=1): iconInfo=<ExtraInfoData: flags=0x0 (), data=02 01 d2 04 72>: listeners: , responses: null

2008.01.15 11:59:23 Updating status for

The unhealthy heart beat we saw looked like this in OpenFire’s debug log files:

2008.01.15 11:58:30 Received presence packet: <presence id=“TlB4o-41484” to=“aim.wildfire.OUR_DOMAIN.com” from=“USER_aim@wildfire.OUR_DOMAIN.com/Smack”><status/><priority&gt ;10</priority></presence>

2008.01.15 11:58:30 An existing resource has changed status: USER_aim@wildfire.OUR_DOMAIN.com/Smack

2008.01.15 11:58:30 Sending SNAC command: SetInfoCmd: info=InfoData:

2008.01.15 11:58:30 Setting up SNAC request and listener: SetInfoCmd: info=InfoData:,null

2008.01.15 11:58:30 Handling request SnacRequest for SetInfoCmd: info=InfoData:: listeners: null, responses: null

2008.01.15 11:58:30 Sending SNAC command: SetExtraInfoCmd: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=00 00 00 00>]

2008.01.15 11:58:30 Setting up SNAC request and listener: SetExtraInfoCmd: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=00 00 00 00>],null

2008.01.15 11:58:30 Handling request SnacRequest for SetExtraInfoCmd: blocks=[ExtraInfoBlock: type=0x2 (TYPE_AVAILMSG), extraData=<ExtraInfoData: flags=0x4 (FLAG_AVAILMSG_PRESENT), data=00 00 00 00>]: listeners: null, responses: null

2008.01.15 11:58:30 Updating status for TransportSession[USER_aim@wildfire.OUR_DOMAIN.com]

2008.01.15 11:58:31 OSCAR bos snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=277, requests: 18, paused=false, snacPacket=SnacPacket type 0x4/0x7: 225 bytes (id=3903684227), snacCommand=RecvImIcbm: message from UserInfo for MULVI99: flags=0x10 (MASK_FREE), memberSince=Fri Mar 05 08:20:35 EST 1999, sessLenAim=206min, onSince=Tue Jan 15 08:31:38 EST 2008, extraInfos=[ExtraInfoBlock: type=0x1 (TYPE_ICONHASH), extraData=<ExtraInfoData: flags=0x1 (FLAG_HASH_PRESENT), data=a0 a3 02 4a 3b 23 49 9a 81 c4 db 82 77 7b 27 de>]: IM: J08 8.05 strad 1.04 @ 1.06 - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=336, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x4/0x7: 225 bytes (id=3903684227), flapPacket=FlapPacket (channel=2, seq=17440)

2008.01.15 11:58:31 OSCAR snac packet received: SnacPacketEvent: snacProcessor=ClientSnacProcessor: lastreqid=277, requests: 18, paused=false, snacPacket=SnacPacket type 0x4/0x7: 225 bytes (id=3903684227), snacCommand=RecvImIcbm: message from UserInfo for MULVI99: flags=0x10 (MASK_FREE), memberSince=Fri Mar 05 08:20:35 EST 1999, sessLenAim=206min, onSince=Tue Jan 15 08:31:38 EST 2008, extraInfos=[ExtraInfoBlock: type=0x1 (TYPE_ICONHASH), extraData=<ExtraInfoData: flags=0x1 (FLAG_HASH_PRESENT), data=a0 a3 02 4a 3b 23 49 9a 81 c4 db 82 77 7b 27 de>]: IM: J08 8.05 strad 1.04 @ 1.06 - FlapPacketEvent: flapProcessor=FlapProcessor: seqNum=SeqNum: min=0, max=65535, last(current)=336, flapCommand=SnacFlapCmd: packet=SnacPacket type 0x4/0x7: 225 bytes (id=3903684227), flapPacket=FlapPacket (channel=2, seq=17440)

Looks like the unhealthy heart beat missed some OSCAR dialog and the final availability update.

What does this missing dialog tell me about what went wrong for my user and why?

Here are some hypotheses I have about the OSCAR communication protocol that I hope someone can confirm:

OSCAR communication seems to be in couples of bos snac followed by snac communications. Bos snac is the request, Snac is the receipt. The members of the couple have the same snacCommands and flapPacket ids and sequence numbers.
I looked at snacCommands for several heart beats and saw this pattern:

Heart beat at 2008.01.15 11:42:32:

ExtraInfoAck

YourInfoCmd

RecvImIcbm

BuddyStatusCmd

Heart beat at 2008.01.15 11:54:30:

ExtraInfoAck

YourInfoCmd

RecvImIcbm

BuddyStatusCmd

Heart beat at 2008.01.15 11:58:31:

RecvImIcbm

Heart beat at 2008.01.15 11:59:23:

ExtraInfoAck

BuddyStatusCmd

Some of the successful heart beats had the following second to last line:

2008.01.15 11:59:23 Handling request SnacRequest for IconRequest for USER (code=1): iconInfo=<ExtraInfoData: flags=0x0 (), data=02 01 d2 04 72>: listeners: , responses: null

All of the successful heart beats had the following last line:

2008.01.15 11:59:23 Updating status for

The unhealthy heart beat did not have this last line.

What does this OSCAR communication tell me about what went wrong with this user?

Dan_Spiegel · March 18, 2008, 12:43pm

My company is looking to hire an instant messaging software engineer to address issues like this one, but more importantly, to build out new and exciting features and functions. If interested, please go to this link: http://jobs.accolo.com/12366.