12002 Error Code
81 views
Skip to first unread message
lboynton
Aug 25, 2011, 5:35:00 AM8/25/11
to Punjab
Hi
I'm not sure if this is a problem with strophe or punjab. The issue
I'm seeing is affecting quite a few IE users on our site. Strophe will
sometimes get an error when sending a request with a response code of
12002, and therefore send it again. On the punjab side, it seems to
get each request as I can see the same RIDs in the log. Eventually
though, punjab will think the RIDs have gone outside the window and
the user gets disconnected.
Here's the relevant parts of the log from strophe:
0 request id 216.0 posting
0 request id 216.0 state changed to 1
0 request id 216.0 state changed to 1
0 Out: <body rid='1102481758' xmlns='http://jabber.org/protocol/
httpbind' sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
0 request id 216.1 state changed to 4
3 request id 216.1 error 12002 happened
2 request errored, status: 12002, number of errors: 1
0 _throttledRequestHandler called with 1 requests
0 request id 217.1 posting
0 request id 217.1 state changed to 1
0 request id 217.1 state changed to 1
0 Out: <body rid='1102481758' xmlns='http://jabber.org/protocol/
httpbind' sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
0 request id 217.2 state changed to 2
0 request id 217.2 state changed to 3
0 request id 217.2 state changed to 4
0 removing request
0 _throttledRequestHandler called with 0 requests
0 request id 217 should now be removed
3 request id 217.2 error 404 happened
2 request errored, status: 404, number of errors: 2
1 _doDisconnect was called
And for punjab:
[HTTPChannel,310,10.100.0.1] <body rid='1102481757' xmlns='http://
jabber.org/protocol/httpbind'
sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
[HTTPChannel,310,10.100.0.1] 1102481757
[HTTPChannel,310,10.100.0.1]
[HTTPChannel,310,10.100.0.1]
[HTTPChannel,310,10.100.0.1] RETURN HTTPB 1314112081.43:
[HTTPChannel,310,10.100.0.1] <body xmlns='http://jabber.org/protocol/
httpbind'><presence xmlns='jabber:client' to='us...@abc.com/
39689403871314111636755622'
from='dfc1eb8896ceeea5b180...@conference.abc.com/
user2' type='unavailable'><x xmlns='http://jabber.org/protocol/
muc#user'><item affiliation='none' jid='us...@abc.com/
413497061314110579686917' role='none'/></x></presence></body>
[HTTPChannel,310,10.100.0.1] 1102481757
[HTTPChannel,310,10.100.0.1] 10.100.0.1 - - [23/Aug/2011:15:08:01
+0000] "POST /http-bind/ HTTP/1.0" 200 416 "http://abc.com" "Mozilla/
4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
[HTTPChannel,311,10.100.0.1] HEADERS 1314112081.59:
[HTTPChannel,311,10.100.0.1] {'content-length': '115', 'accept-
language': 'en-gb', 'accept-encoding': 'gzip, deflate', 'x-forwarded-
for': '1.2.3.4', 'connection': 'close', 'accept': '*/*', 'user-agent':
'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)', 'host':
'2.3.4.5:5283', 'referer': 'http://abc.com', 'cache-control': 'no-
cache', 'x-real-ip': '1.2.3.4', 'cookie': 'PHPSESSID=abc'}
[HTTPChannel,311,10.100.0.1] HTTPB POST :
[HTTPChannel,311,10.100.0.1] <body rid='1102481758' xmlns='http://
jabber.org/protocol/httpbind'
sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
[HTTPChannel,311,10.100.0.1] 1102481758
[HTTPChannel,312,10.100.0.1] HEADERS 1314112091.69:
[HTTPChannel,312,10.100.0.1] {'content-length': '115', 'accept-
language': 'en-gb', 'accept-encoding': 'gzip, deflate', 'x-forwarded-
for': '1.2.3.4', 'connection': 'close', 'accept': '*/*', 'user-agent':
'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)', 'host':
'2.3.4.5:5283', 'referer': 'http://abc.com', 'cache-control': 'no-
cache', 'x-real-ip': '1.2.3.4', 'cookie': 'PHPSESSID=abc'}
[HTTPChannel,312,10.100.0.1] HTTPB POST :
[HTTPChannel,312,10.100.0.1] <body rid='1102481758' xmlns='http://
jabber.org/protocol/httpbind'
sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
[HTTPChannel,312,10.100.0.1] 1102481758
[HTTPChannel,312,10.100.0.1] This rid is invalid 1102481758
1102481762
[HTTPChannel,312,10.100.0.1] HTTPB Error 404
This happens a few times in the logs until the requests go outside of
the window and there is a 404 error.
I was wondering if anyone had any ideas about what's going on? I know
that when punjab receives a duplicate request (one with the same RID)
it is supposed to return the body it sent for the original request. I
have tested this and it seems to do this as expected.
I'm not sure if this is a problem with strophe or punjab. The issue
I'm seeing is affecting quite a few IE users on our site. Strophe will
sometimes get an error when sending a request with a response code of
12002, and therefore send it again. On the punjab side, it seems to
get each request as I can see the same RIDs in the log. Eventually
though, punjab will think the RIDs have gone outside the window and
the user gets disconnected.
Here's the relevant parts of the log from strophe:
0 request id 216.0 posting
0 request id 216.0 state changed to 1
0 request id 216.0 state changed to 1
0 Out: <body rid='1102481758' xmlns='http://jabber.org/protocol/
httpbind' sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
0 request id 216.1 state changed to 4
3 request id 216.1 error 12002 happened
2 request errored, status: 12002, number of errors: 1
0 _throttledRequestHandler called with 1 requests
0 request id 217.1 posting
0 request id 217.1 state changed to 1
0 request id 217.1 state changed to 1
0 Out: <body rid='1102481758' xmlns='http://jabber.org/protocol/
httpbind' sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
0 request id 217.2 state changed to 2
0 request id 217.2 state changed to 3
0 request id 217.2 state changed to 4
0 removing request
0 _throttledRequestHandler called with 0 requests
0 request id 217 should now be removed
3 request id 217.2 error 404 happened
2 request errored, status: 404, number of errors: 2
1 _doDisconnect was called
And for punjab:
[HTTPChannel,310,10.100.0.1] <body rid='1102481757' xmlns='http://
jabber.org/protocol/httpbind'
sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
[HTTPChannel,310,10.100.0.1] 1102481757
[HTTPChannel,310,10.100.0.1]
[HTTPChannel,310,10.100.0.1]
[HTTPChannel,310,10.100.0.1] RETURN HTTPB 1314112081.43:
[HTTPChannel,310,10.100.0.1] <body xmlns='http://jabber.org/protocol/
httpbind'><presence xmlns='jabber:client' to='us...@abc.com/
39689403871314111636755622'
from='dfc1eb8896ceeea5b180...@conference.abc.com/
user2' type='unavailable'><x xmlns='http://jabber.org/protocol/
muc#user'><item affiliation='none' jid='us...@abc.com/
413497061314110579686917' role='none'/></x></presence></body>
[HTTPChannel,310,10.100.0.1] 1102481757
[HTTPChannel,310,10.100.0.1] 10.100.0.1 - - [23/Aug/2011:15:08:01
+0000] "POST /http-bind/ HTTP/1.0" 200 416 "http://abc.com" "Mozilla/
4.0 (compatible; MSIE 8.0; Windows NT 6.0)"
[HTTPChannel,311,10.100.0.1] HEADERS 1314112081.59:
[HTTPChannel,311,10.100.0.1] {'content-length': '115', 'accept-
language': 'en-gb', 'accept-encoding': 'gzip, deflate', 'x-forwarded-
for': '1.2.3.4', 'connection': 'close', 'accept': '*/*', 'user-agent':
'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)', 'host':
'2.3.4.5:5283', 'referer': 'http://abc.com', 'cache-control': 'no-
cache', 'x-real-ip': '1.2.3.4', 'cookie': 'PHPSESSID=abc'}
[HTTPChannel,311,10.100.0.1] HTTPB POST :
[HTTPChannel,311,10.100.0.1] <body rid='1102481758' xmlns='http://
jabber.org/protocol/httpbind'
sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
[HTTPChannel,311,10.100.0.1] 1102481758
[HTTPChannel,312,10.100.0.1] HEADERS 1314112091.69:
[HTTPChannel,312,10.100.0.1] {'content-length': '115', 'accept-
language': 'en-gb', 'accept-encoding': 'gzip, deflate', 'x-forwarded-
for': '1.2.3.4', 'connection': 'close', 'accept': '*/*', 'user-agent':
'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.0)', 'host':
'2.3.4.5:5283', 'referer': 'http://abc.com', 'cache-control': 'no-
cache', 'x-real-ip': '1.2.3.4', 'cookie': 'PHPSESSID=abc'}
[HTTPChannel,312,10.100.0.1] HTTPB POST :
[HTTPChannel,312,10.100.0.1] <body rid='1102481758' xmlns='http://
jabber.org/protocol/httpbind'
sid='be41b6b3bc49d688b5a710b1c4191ef8ae90c79d'/>
[HTTPChannel,312,10.100.0.1] 1102481758
[HTTPChannel,312,10.100.0.1] This rid is invalid 1102481758
1102481762
[HTTPChannel,312,10.100.0.1] HTTPB Error 404
This happens a few times in the logs until the requests go outside of
the window and there is a 404 error.
I was wondering if anyone had any ideas about what's going on? I know
that when punjab receives a duplicate request (one with the same RID)
it is supposed to return the body it sent for the original request. I
have tested this and it seems to do this as expected.
Jack Moffitt
Aug 25, 2011, 11:52:34 AM8/25/11
to punja...@googlegroups.com
> I'm not sure if this is a problem with strophe or punjab. The issue
> I'm seeing is affecting quite a few IE users on our site. Strophe will
> sometimes get an error when sending a request with a response code of
> 12002, and therefore send it again. On the punjab side, it seems to
> get each request as I can see the same RIDs in the log. Eventually
> though, punjab will think the RIDs have gone outside the window and
> the user gets disconnected.
> I'm seeing is affecting quite a few IE users on our site. Strophe will
> sometimes get an error when sending a request with a response code of
> 12002, and therefore send it again. On the punjab side, it seems to
> get each request as I can see the same RIDs in the log. Eventually
> though, punjab will think the RIDs have gone outside the window and
> the user gets disconnected.
12002 is a timeout error returned by IE. It means it couldn't talk to
the other side. It's certainly possible that the data can get through
in this case, but the ACK doesn't get back. Strophe is correct to
resend the same data. It should resend it with exactly the same RID.
From your log I can see the RID is indeed the same, so this looks like
a Punjab bug.
What's weird is that this definitely used to work.
jack.
Christopher Zorn
Aug 25, 2011, 12:45:36 PM8/25/11
to punja...@googlegroups.com
This is odd. Could it be something happening before this that makes the rid count go up without sending requests?
jack.
--
You received this message because you are subscribed to the Google Groups "Punjab" group.
To post to this group, send email to punja...@googlegroups.com.
To unsubscribe from this group, send email to punjab-xmpp...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/punjab-xmpp?hl=en.
lboynton
Aug 25, 2011, 5:58:00 PM8/25/11
to Punjab
There's two things I don't understand:
- Why is the first request punjab receives with RID of 1102481758 ok?
Shouldn't it say that it is an invalid RID the first time? I neglected
to include the times in the log, but there was 10 seconds between the
first body with RID of 1102481758 and the second. I thought there
might be a race condition occurring between the requests coming in and
the requests being cached, but 10 seconds should be enough time to
cache them I'd have thought.
- Secondly, punjab doesn't seem to return any data for the first
1102481758 request. I guess this is because the server (ejabberd)
doesn't have anything to send yet?
I did test if punjab returned the cached response when it receives a
duplicate RID by editing strophe to not increment RIDs, and punjab did
indeed return the cached responses.
I'll scan the log again tomorrow and try to provide a bit more
information.
Also, I noticed in the strophe log that when a 12002 error occurs the
ready state does not go past 1, which I believe means the request
hasn't actually been sent yet? This doesn't really make sense to me
because it looks like punjab does actually receive it. So perhaps this
is just an IE bug. I also thought that maybe the simultaneous request
limit is being hit in IE, but it is limited to 6 in IE8 so I thought
this would be unlikely.
Thanks for your thoughts so far!
Lee.
On Aug 25, 5:45 pm, Christopher Zorn <christopher.z...@gmail.com>
wrote:
- Why is the first request punjab receives with RID of 1102481758 ok?
Shouldn't it say that it is an invalid RID the first time? I neglected
to include the times in the log, but there was 10 seconds between the
first body with RID of 1102481758 and the second. I thought there
might be a race condition occurring between the requests coming in and
the requests being cached, but 10 seconds should be enough time to
cache them I'd have thought.
- Secondly, punjab doesn't seem to return any data for the first
1102481758 request. I guess this is because the server (ejabberd)
doesn't have anything to send yet?
I did test if punjab returned the cached response when it receives a
duplicate RID by editing strophe to not increment RIDs, and punjab did
indeed return the cached responses.
I'll scan the log again tomorrow and try to provide a bit more
information.
Also, I noticed in the strophe log that when a 12002 error occurs the
ready state does not go past 1, which I believe means the request
hasn't actually been sent yet? This doesn't really make sense to me
because it looks like punjab does actually receive it. So perhaps this
is just an IE bug. I also thought that maybe the simultaneous request
limit is being hit in IE, but it is limited to 6 in IE8 so I thought
this would be unlikely.
Thanks for your thoughts so far!
Lee.
On Aug 25, 5:45 pm, Christopher Zorn <christopher.z...@gmail.com>
wrote:
Christopher Zorn
Aug 26, 2011, 8:23:47 PM8/26/11
to punja...@googlegroups.com
On Thu, Aug 25, 2011 at 2:58 PM, lboynton <not...@gmail.com> wrote:
There's two things I don't understand:
- Why is the first request punjab receives with RID of 1102481758 ok?
Shouldn't it say that it is an invalid RID the first time? I neglected
to include the times in the log, but there was 10 seconds between the
first body with RID of 1102481758 and the second. I thought there
might be a race condition occurring between the requests coming in and
the requests being cached, but 10 seconds should be enough time to
cache them I'd have thought.
This is a good question. The following line shows that the rid is out of the window:
[HTTPChannel,312,10.100.0.1] This rid is invalid 1102481758 1102481762
If the request was in cache then it would have returned the cached request and never get to the failed code. Cache is not held onto very long. It only holds onto a few items. Also, if there has not been a return on that request then it would not be in cache. From your question below I believe that may be the case here.
I can only guess as to what happened. It may be easier with full logs.
- Secondly, punjab doesn't seem to return any data for the first
1102481758 request. I guess this is because the server (ejabberd)
doesn't have anything to send yet?
Yes, it waits until the timeout or there is data to send.
I did test if punjab returned the cached response when it receives a
duplicate RID by editing strophe to not increment RIDs, and punjab did
indeed return the cached responses.
I'll scan the log again tomorrow and try to provide a bit more
information.
Also, I noticed in the strophe log that when a 12002 error occurs the
ready state does not go past 1, which I believe means the request
hasn't actually been sent yet? This doesn't really make sense to me
because it looks like punjab does actually receive it. So perhaps this
is just an IE bug. I also thought that maybe the simultaneous request
limit is being hit in IE, but it is limited to 6 in IE8 so I thought
this would be unlikely.
Thanks for your thoughts so far!
No problem, a larger log to get a better picture of what is happening may be best here.
Reply all
Reply to author
Forward
0 new messages