I built a chat client on top of JSJaC and upon logging in, it does a number of things, such as request the roster, read some offline data from the XMPP storage, announces presence, and joins a number of chat rooms (3 in this case), and subsequently requests the membership list from each room.
On occasion, a 404 error will be encountered mid-stream, followed by a response from ejabberd in a subsequent request to terminate the session. My chat client responds to disconnects by trying to connect again, so this loop continues 2 to 5 times before success.
I see in the log (can I upload it somewhere?) a response with 3 stanzas in it announcing my presence in the 3 chat rooms it joined. Then it receives a request
with jid="599276", which, coincidentally, is the request that gets a 404 response from the client perspective. But the request is in the log, which begs the question, how can the client get a 404 if the request was actually received by the server?
It spits this request into the log then appears to put this request in a queue:
D(<0.948.0>:ejabberd_http_bind:804) : Looking for session: "05bab942815a5b6e3c8cf63537193c953230b48f"
D(<0.976.0>:ejabberd_http_bind:421) : Shaper timer for RID 599276: {wait,965}
D(<0.948.0>:ejabberd_http_bind:788) : Trafic Shaper: Delaying request 599276
It then receives another request, with rid="599277", spits it into the log, then appears to process it:
D(<0.955.0>:ejabberd_http_bind:804) : Looking for session: "05bab942815a5b6e3c8cf63537193c953230b48f"
D(<0.976.0>:ejabberd_http_bind:421) : Shaper timer for RID 599277: {wait,777}
D(<0.955.0>:ejabberd_http_bind:788) : Trafic Shaper: Delaying request 599277
D(<0.955.0>:ejabberd_http_bind:804) : Looking for session: "05bab942815a5b6e3c8cf63537193c953230b48f"
D(<0.948.0>:ejabberd_http_bind:804) : Looking for session: "05bab942815a5b6e3c8cf63537193c953230b48f"
D(<0.976.0>:ejabberd_http_bind:426) : New request: {http_put,599277,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","599277"},
{"sid",
"05bab942815a5b6e3c8cf63537193c953230b48f"},
{"key",
"ec3e954d3f521b5aed462442127ccad3558fde94"}],
-- snip --
437,1,[],
{{192,168,1,100},56922}}
D(<0.976.0>:shaper:61) : State: {maxrate,1000,999.9725231843436, 1358465231253001}, Size=437
M=436.9879929614733, I=3.999
D(<0.976.0>:ejabberd_http_bind:566) : New request: {http_put,599277,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","599277"},
{"sid",
"05bab942815a5b6e3c8cf63537193c953230b48f"},
{"key",
"ec3e954d3f521b5aed462442127ccad3558fde94"}],
-- snip --
437,1,[],
{{192,168,1,100},56922}}
Note:
D(<0.976.0>:ejabberd_http_bind:867) : Previous rid / New rid: 599275/599277
There is a request with rid="599275" much earlier in the log, prior to a string of output stanzas that eventually ended with the chat room presence for the three chat rooms mentioned above. The log continues...
D(<0.976.0>:ejabberd_http_bind:574) : Buffered request: {http_put,599277,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","599277"},
{"sid",
"05bab942815a5b6e3c8cf63537193c953230b48f"},
{"key",
"ec3e954d3f521b5aed462442127ccad3558fde94"}],
-- snip --
437,1,[],
{{192,168,1,100},
56922}}
D(<0.976.0>:ejabberd_http_bind:586) : reqlist: [{hbr,599277, "bcfa4199c465281cea50393364b2e382b2a72bb7", []}]
It then mentions the older request again, as if put on hold once again:
D(<0.976.0>:ejabberd_http_bind:421) : Shaper timer for RID 599276: {wait,433}
D(<0.948.0>:ejabberd_http_bind:788) : Trafic Shaper: Delaying request 599276
Then it receives another request, rid="599278", spits it into the log, followed by:
D(<0.955.0>:ejabberd_http_bind:804) : Looking for session: "05bab942815a5b6e3c8cf63537193c953230b48f"
D(<0.976.0>:ejabberd_http_bind:421) : Shaper timer for RID 599278: {wait,417}
D(<0.955.0>:ejabberd_http_bind:788) : Trafic Shaper: Delaying request 599278
D(<0.955.0>:ejabberd_http_bind:804) : Looking for session: "05bab942815a5b6e3c8cf63537193c953230b48f"
D(<0.948.0>:ejabberd_http_bind:804) : Looking for session: "05bab942815a5b6e3c8cf63537193c953230b48f"
D(<0.976.0>:ejabberd_http_bind:426) : New request: {http_put,599278,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","599278"},
{"sid",
"05bab942815a5b6e3c8cf63537193c953230b48f"},
{"key",
"97e40603551420b4928f033668b5e308b77bb7f1"}],
-- snip --
437,1,[],
{{192,168,1,100},56922}}
D(<0.976.0>:shaper:61) : State: {maxrate,1000,999.9862615921718, 1358465231690001}, Size=437
M=436.993996398259, I=3.999
D(<0.976.0>:ejabberd_http_bind:566) : New request: {http_put,599278,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","599278"},
{"sid",
"05bab942815a5b6e3c8cf63537193c953230b48f"},
{"key",
"97e40603551420b4928f033668b5e308b77bb7f1"}],
-- snip --
437,1,[],
{{192,168,1,100},56922}}
D(<0.976.0>:ejabberd_http_bind:867) : Previous rid / New rid: 599275/599278
D(<0.976.0>:ejabberd_http_bind:603) : Actually processing request: {http_put,
599278,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid",
"599278"},
{"sid",
"05bab942815a5b6e3c8cf63537193c953230b48f"},
{"key",
"97e40603551420b4928f033668b5e308b77bb7f1"}],
-- snip --
437,1,[],
{{192,168,
1,100},
56922}}
Then it mentions the original rid 599276 request one more time before killing the session, then once more afterward:
D(<0.976.0>:ejabberd_http_bind:421) : Shaper timer for RID 599276: {wait,433}
D(<0.955.0>:ejabberd_http_bind:782) : Error on HTTP put. Reason: bad_key
D(<0.976.0>:ejabberd_http_bind:406) : Closing bind session "05bab942815a5b6e3c8cf63537193c953230b48f" - Reason: {put_error,
D(<0.976.0>:ejabberd_http_bind:547) : []: Deleting session 05bab942815a5b6e3c8cf63537193c953230b48f
I(<0.977.0>:ejabberd_c2s:1502) : ({socket_state,ejabberd_http_bind,{http_bind,<0.976.0>,{{192,168,1,100},56922}},ejabberd_http_bind})
Close session for uone@sabasite/chat2012-client-webkit:1358465248918
D(<0.948.0>:ejabberd_http_bind:788) : Trafic Shaper: Delaying request 599276
Seems like a bug to me. I need a fix for this as this chat client is going to production very soon in a major enterprise app. Any clue as to what is happening here?
Bueller? Bueller?
Bueller? Bueller?