Ejabberd gives 404 errors - suspect ejabberd bug

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?

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.

Bueller? Bueller?

Bueller? Bueller?

Syndicate content