First, thank you in advance for taking a look at this problem with me.
I'm currently using strophe.js to connect to Punjab over a BOSH connection, which ultimately forwards the messages to Openfire. I'm prebinding on the server and attaching to the connection with strophe. This works fine initially; I can send and receive messages, and when I get an idle ping I am able to successfully respond. However, after some time, I'm getting disconnected.
After examining the Punjab logs, it seems that I don't always get an httpbind acknowledgement from Punjab when I send a message from strophe. Strophe waits a bout 60 seconds, as it is supposed to, and tries sending the message again - a complete duplicate with the same ID. This makes sense, since it has no idea if Punjab ever got the message since it never acknowledged it. However, for some reason, Punjab gets this duplicate message and thinks that it is a new one with an incorrect RID, and so it increments it's internal RID counter as it would any other message. Furthermore, it forwards the message to the Openfire server AGAIN, though I have not seen this have any significant effect as far as I can tell. Finally, after this has happened a number of times, the RID being used by Strophe falls outside of the RID tolerance window and Punjab returns a 404 Not Found error, and ultimately closes the connection.
My question is, why is Punjab not acknowledging some messages as it should - returning <body xmlns='http://jabber.org/protocol/httpbind'/> to strophe.
This process is detailed with examples from the logs below:
2012-06-22 20:17:23-0400 [HTTPChannel,21,127.0.0.1] HEADERS 1340410643.66: Punjab gets a message from the HTTP Bind (this is why we are observing activity in HTTPChannel)
2012-06-22 20:17:23-0400 [HTTPChannel,21,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '191', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=92416C9E3804DF3F6B5661F5B6447314BA070C1FE9BF3D6830AA256AFFA84CAB691B1E3746DBFD4E99692CC18F831C89810CDF256CD12EAF3EA351FEF240605589BE9AE835B9D862265A1672749B5DF9E7AADEE8BEC95006A410CDA5D25271964C9EE065AB968AB3C9521BC9D1059D545FA40575FB477AC3FFDD4F4A702334D2A83C9C90', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:17:23-0400 [HTTPChannel,21,127.0.0.1] HTTPB POST : This is the POST message coming from the BOSH connection
2012-06-22 20:17:23-0400 [HTTPChannel,21,127.0.0.1] You can see that it is in an httpbind protocol body
<body rid='1211827046' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='511-862' xmlns='jabber:client'/>
</body>
2012-06-22 20:17:23-0400 [HTTPChannel,21,127.0.0.1] 1211827046
2012-06-22 20:17:23-0400 [HTTPChannel,21,127.0.0.1] Here, Punjab strips the httpbind body and sends the root message directly to OpenFire
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 => using the direct session connection Punjab has set up for this user (evidenced by the SID).
SEND: "
<iq xmlns='jabber:client' to='codemonkey' type='result' id='511-862'/>"
HOWEVER, HERE WE ARE MISSING THE HTTPBIND CONFIRMATION THAT SHOULD BE SENT BACK TO STROPHE, LETTING IT KNOW THAT THE MESSAGE WAS FORWARDED
THUS, STROPHE SENDS THE SAME MESSAGE AGAIN WITH THE SAME RID, THINKING THAT PUNJAB NEVER GOT THE FIRST ONE.
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] HEADERS 1340410708.95: Punjab gets a message from the HTTP Bind (this is strophes second attempt at sending the message)
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '191', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=92416C9E3804DF3F6B5661F5B6447314BA070C1FE9BF3D6830AA256AFFA84CAB691B1E3746DBFD4E99692CC18F831C89810CDF256CD12EAF3EA351FEF240605589BE9AE835B9D862265A1672749B5DF9E7AADEE8BEC95006A410CDA5D25271964C9EE065AB968AB3C9521BC9D1059D545FA40575FB477AC3FFDD4F4A702334D2A83C9C90', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] HTTPB POST :
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1]
<body rid='1211827046' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='511-862' xmlns='jabber:client'/>
</body>
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] 1211827046
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1]
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 => PUNJAB SENDS THIS TO OPENFIRE AS WELL, EVIDENCE THAT PUNJAB FAILS TO DETECT THAT THIS IS A DUPLICATE MESSAGE
SEND: " It seems that Openfire must disregard this, considering that we haven’t seen issues with openfire receiving these messages.
<iq xmlns='jabber:client' to='codemonkey' type='result' id='511-862'/>" and haven’t seen duplicate messages through chat or anything.
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] RETURN HTTPB 1340410708.95:
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] PUNJAB SENDS OUT THE HTTPBIND ACKNOWLEDGEMENT, AS IT SHOULD HAVE THE FIRST TIME.
<body xmlns='http://jabber.org/protocol/httpbind'/>
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] 1211827046
2012-06-22 20:18:28-0400 [HTTPChannel,22,127.0.0.1] 127.0.0.1 - - [23/Jun/2012:00:18:28 +0000] "POST /bosh HTTP/1.1" 200 51 "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
Since Punjab sees the duplicate request as a new request, it has incremented its internal RID counter for both, meaning we are now off by 1 RID (each message sent from strophe is supposed to increment the RID value by 1). The first few times this happens, the connection remains because Punjab has a tolerance window of about 5. Eventually, we get out of this window, and Punjab closes the connection.
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HEADERS 1340410993.78:
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '191', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=0772CAEB889BB1F853371E4153AC6972595A3A548BAE87D3F8D86AFBB5B88B4C0B8FD61F971816D4678388499B0A71E2517048261B07AD393D9EECDA199FA7EA51CBCD17299047473C6B9A9667BAF9367059319B4F0292B57238A0E2DB2AC737B12E530EAAE85732B1070E1F563E7675A82DF41C57A2C705B358328BE477C581D02DC714', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HTTPB POST :
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1]
<body rid='1211827048' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='600-864' xmlns='jabber:client'/>
</body>
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] 1211827048
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] This rid is invalid 1211827048 1211827052 ITS INTERNAL RID COUNTER HAS INCREASED TO 52 WHILE WE ARE AT 48.
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HTTPB Error 404 The tolerance has been exceeded and the connection is closed.
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] 127.0.0.1 - - [23/Jun/2012:00:23:13 +0000] "POST /bosh HTTP/1.1" 404 - "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
Since Punjab sees the duplicate request as a new request, it has incremented its internal RID counter for both, meaning we are now off by 1 RID (each message sent from strophe is supposed to increment the RID value by 1). The first few times this happens, the connection remains because Punjab has a tolerance window of about 5. Eventually, we get out of this window, and Punjab closes the connection.
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HEADERS 1340410993.78:
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '191', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=0772CAEB889BB1F853371E4153AC6972595A3A548BAE87D3F8D86AFBB5B88B4C0B8FD61F971816D4678388499B0A71E2517048261B07AD393D9EECDA199FA7EA51CBCD17299047473C6B9A9667BAF9367059319B4F0292B57238A0E2DB2AC737B12E530EAAE85732B1070E1F563E7675A82DF41C57A2C705B358328BE477C581D02DC714', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HTTPB POST :
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1]
<body rid='1211827048' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='600-864' xmlns='jabber:client'/>
</body>
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] 1211827048
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] This rid is invalid 1211827048 1211827052 ITS INTERNAL RID COUNTER HAS INCREASED TO 52 WHILE WE ARE AT 48.
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HTTPB Error 404 The tolerance has been exceeded and the connection is closed.
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] 127.0.0.1 - - [23/Jun/2012:00:23:13 +0000] "POST /bosh HTTP/1.1" 404 - "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
Any help would be greatly appreciated. Perhaps I am not fully understanding what Punjab is doing. It seems to me that Punjab gets the message over BOSH from strophe packaged in an httpbind body. It extracts the message from the httpbind body and forwards the bare message to Openfire over the direct session. Finally, it responds to strophe by sending a bare <body xmlns='http://jabber.org/protocol/httpbind'/> message back, letting strophe know that the message was received and dealt with. When messages come in from Openfire, they are shown in the logs under the [XmlStream,client] header as opposed to the [HTTPChannel,21,127.0.0.1] header. These come in from Openfire over the direct session connection, Punjab wraps them in an httpbind body, and forwards them over BOSH to strophe. Strophe then returns an empty <body xmlns='http://jabber.org/protocol/httpbind'/> acknowledging the transaction.
So why is Punjab sometimes failing to acknowledge the message? And why isn't it seeing the duplicate message as a duplicate and just returning the acknowledgement instead of resending it and incrementing it's RID counter erroneously? Again, thank you, thank you, THANK YOU for reading this far. I am at my wits end and any help would be appreciated.
Here is a complete Punjab log of the failure:
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] HEADERS 1340410782.18:
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '191', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=92416C9E3804DF3F6B5661F5B6447314BA070C1FE9BF3D6830AA256AFFA84CAB691B1E3746DBFD4E99692CC18F831C89810CDF256CD12EAF3EA351FEF240605589BE9AE835B9D862265A1672749B5DF9E7AADEE8BEC95006A410CDA5D25271964C9EE065AB968AB3C9521BC9D1059D545FA40575FB477AC3FFDD4F4A702334D2A83C9C90', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] HTTPB POST :
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1]
<body rid='1211827046' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='511-862' xmlns='jabber:client'/>
</body>
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] 1211827046
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] RETURN HTTPB 1340410782.2:
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1]
<body xmlns='http://jabber.org/protocol/httpbind'>
<iq xmlns='jabber:client' from='codemonkey' type='get' id='64-863' to='MySiteadmin@codemonkey/5da9d909-46e0-4dac-8f02-a4113e6490e5'>
<ping xmlns='urn:xmpp:ping'/>
</iq>
</body>
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] 1211827046
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] 127.0.0.1 - - [23/Jun/2012:00:19:42 +0000] "POST /bosh HTTP/1.1" 200 222 "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] HEADERS 1340410782.34:
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '190', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=92416C9E3804DF3F6B5661F5B6447314BA070C1FE9BF3D6830AA256AFFA84CAB691B1E3746DBFD4E99692CC18F831C89810CDF256CD12EAF3EA351FEF240605589BE9AE835B9D862265A1672749B5DF9E7AADEE8BEC95006A410CDA5D25271964C9EE065AB968AB3C9521BC9D1059D545FA40575FB477AC3FFDD4F4A702334D2A83C9C90', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] HTTPB POST :
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1]
<body rid='1211827047' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='64-863' xmlns='jabber:client'/>
</body>
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1] 1211827047
2012-06-22 20:19:42-0400 [HTTPChannel,22,127.0.0.1]
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 =>
SEND: "
<iq xmlns='jabber:client' to='codemonkey' type='result' id='64-863'/>"
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1] HEADERS 1340410850.19:
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '190', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=0772CAEB889BB1F853371E4153AC6972595A3A548BAE87D3F8D86AFBB5B88B4C0B8FD61F971816D4678388499B0A71E2517048261B07AD393D9EECDA199FA7EA51CBCD17299047473C6B9A9667BAF9367059319B4F0292B57238A0E2DB2AC737B12E530EAAE85732B1070E1F563E7675A82DF41C57A2C705B358328BE477C581D02DC714', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1] HTTPB POST :
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1]
<body rid='1211827047' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='64-863' xmlns='jabber:client'/>
</body>
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1] 1211827047
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1]
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 =>
SEND: "
<iq xmlns='jabber:client' to='codemonkey' type='result' id='64-863'/>"
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1] RETURN HTTPB 1340410850.21:
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1]
<body xmlns='http://jabber.org/protocol/httpbind'/>
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1] 1211827047
2012-06-22 20:20:50-0400 [HTTPChannel,21,127.0.0.1] 127.0.0.1 - - [23/Jun/2012:00:20:49 +0000] "POST /bosh HTTP/1.1" 200 51 "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
2012-06-22 20:22:00-0400 [XmlStream,client]
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 =>
RECV: '
<iq type="get" id="600-864" from="codemonkey" to="MySiteadmin@codemonkey/5da9d909-46e0-4dac-8f02-a4113e6490e5">
<ping xmlns="urn:xmpp:ping"/>
</iq>'
2012-06-22 20:22:00-0400 [XmlStream,client] RETURN HTTPB 1340410920.62:
2012-06-22 20:22:00-0400 [XmlStream,client]
<body xmlns='http://jabber.org/protocol/httpbind'>
<iq xmlns='jabber:client' from='codemonkey' type='get' id='600-864' to='MySiteadmin@codemonkey/5da9d909-46e0-4dac-8f02-a4113e6490e5'>
<ping xmlns='urn:xmpp:ping'/>
</iq>
</body>
2012-06-22 20:22:00-0400 [XmlStream,client] 1211827047
2012-06-22 20:22:00-0400 [XmlStream,client] 127.0.0.1 - - [23/Jun/2012:00:21:59+0000] "POST /bosh HTTP/1.1" 200 223 "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] HEADERS 1340410927.48:
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '190', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=0772CAEB889BB1F853371E4153AC6972595A3A548BAE87D3F8D86AFBB5B88B4C0B8FD61F971816D4678388499B0A71E2517048261B07AD393D9EECDA199FA7EA51CBCD17299047473C6B9A9667BAF9367059319B4F0292B57238A0E2DB2AC737B12E530EAAE85732B1070E1F563E7675A82DF41C57A2C705B358328BE477C581D02DC714', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] HTTPB POST :
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1]
<body rid='1211827047' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='64-863' xmlns='jabber:client'/>
</body>
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] 1211827047
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] RETURN HTTPB 1340410927.48:
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1]
<body xmlns='http://jabber.org/protocol/httpbind'>
<iq xmlns='jabber:client' from='codemonkey' type='get' id='600-864' to='MySiteadmin@codemonkey/5da9d909-46e0-4dac-8f02-a4113e6490e5'>
<pingxmlns='urn:xmpp:ping'/>
</iq>
</body>
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] 1211827047
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] 127.0.0.1 - - [23/Jun/2012:00:22:06 +0000] "POST /bosh HTTP/1.1" 200 223 "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] HEADERS 1340410927.67:
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '191', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=0772CAEB889BB1F853371E4153AC6972595A3A548BAE87D3F8D86AFBB5B88B4C0B8FD61F971816D4678388499B0A71E2517048261B07AD393D9EECDA199FA7EA51CBCD17299047473C6B9A9667BAF9367059319B4F0292B57238A0E2DB2AC737B12E530EAAE85732B1070E1F563E7675A82DF41C57A2C705B358328BE477C581D02DC714', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] HTTPB POST :
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1]
<body rid='1211827048' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='600-864' xmlns='jabber:client'/>
</body>
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1] 1211827048
2012-06-22 20:22:07-0400 [HTTPChannel,21,127.0.0.1]
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 =>
SEND: "
<iq xmlns='jabber:client' to='codemonkey' type='result' id='600-864'/>"
2012-06-22 20:22:12-0400 [-]
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 =>
SEND: ' '
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HEADERS 1340410993.78:
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] {'origin': 'http://172.16.160.246', 'content-length': '191', 'accept-language': 'en-US,en;q=0.8', 'accept-encoding': 'gzip,deflate,sdch', 'x-forwarded-host': '172.16.160.246', 'x-forwarded-for': '172.16.122.9', 'host': '127.0.0.1:5280', 'accept': '*/*', 'user-agent':'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5', 'accept-charset': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3', 'connection': 'Keep-Alive', 'referer': 'http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486', 'cookie': 'ASP.NET_SessionId=c4ioeuw2azw21lkedv0nbwlt; .MySiteUniqueCookie=0772CAEB889BB1F853371E4153AC6972595A3A548BAE87D3F8D86AFBB5B88B4C0B8FD61F971816D4678388499B0A71E2517048261B07AD393D9EECDA199FA7EA51CBCD17299047473C6B9A9667BAF9367059319B4F0292B57238A0E2DB2AC737B12E530EAAE85732B1070E1F563E7675A82DF41C57A2C705B358328BE477C581D02DC714', 'x-forwarded-server': 'CODEMONKEY.mydomain.com', 'content-type': 'application/xml'}
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HTTPB POST :
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1]
<body rid='1211827048' xmlns='http://jabber.org/protocol/httpbind' sid='fb03e4779f4b9a4fe15fbf09d5905f455cc54919'>
<iq type='result' to='codemonkey' id='600-864' xmlns='jabber:client'/>
</body>
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] 1211827048
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] This rid is invalid 1211827048 1211827052
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] HTTPB Error 404
2012-06-22 20:23:13-0400 [HTTPChannel,22,127.0.0.1] 127.0.0.1 - - [23/Jun/2012:00:23:13 +0000] "POST /bosh HTTP/1.1" 404 - "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
2012-06-22 20:23:23-0400 [XmlStream,client]
SID: fb03e4779f4b9a4fe15fbf09d5905f455cc54919 =>
RECV: '
<iq type="get" id="180-865" from="codemonkey" to="MySiteadmin@codemonkey/5da9d909-46e0-4dac-8f02-a4113e6490e5">
<ping xmlns="urn:xmpp:ping"/>
</iq>'
2012-06-22 20:23:23-0400 [XmlStream,client] RETURN HTTPB 1340411003.49:
2012-06-22 20:23:23-0400 [XmlStream,client]
<body xmlns='http://jabber.org/protocol/httpbind'>
<iq xmlns='jabber:client' from='codemonkey' type='get' id='180-865' to='MySiteadmin@codemonkey/5da9d909-46e0-4dac-8f02-a4113e6490e5'>
<ping xmlns='urn:xmpp:ping'/>
</iq>
</body>
2012-06-22 20:23:23-0400 [XmlStream,client] 1211827048
2012-06-22 20:23:23-0400 [XmlStream,client] 127.0.0.1 - - [23/Jun/2012:00:23:23+0000] "POST /bosh HTTP/1.1" 200 223 "http://172.16.160.246/MySite/Viewers/InteractiveView?programGuideId=486" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/536.5 (KHTML, like Gecko) Chrome/19.0.1084.56 Safari/536.5"
As it turns out, my understanding of Punjab was flawed. The empty
<body xmlns='http://jabber.org/protocol/httpbind'/>messages are not actually for acknowledging messages over the BOSH connection. As BOSH uses the long polling technique, the client initializes the connection with an empty httpbind body. The server holds this connection open for the duration of the wait time specified - i.e. 60 seconds. If no messages have been received by that 60 second mark, the server closes the connection by responding with an empty httpbind body, and the client reopens a new one by sending another empty body to the server.My problem stems from the fact that I was initializing the prebind connection in C# with the MatriX library. It's default wait time for the connection to be held open is 300 seconds. Thus, it sets up the connection with punjab to close connections after 300 seconds. HOWEVER, strophe's default wait time is 60 seconds. When I attached to the existing MatriX connection with strophe, strophe became confused since punjab wasn't releasing the connection in 60 seconds as it expected.
The fix was to change the strophe wait time to 300 seconds to match the MatriX set up conditions.