Problem logging in with XMPP/Bosh and custom client

Hi all,

Sorry, I found no better forum to ask this rather technical question.

I am working on a homegrown XMPP client (not yet open sourced). So far it works with Prosody (XMPP and XMPP Bosh). Now I am trying to get it compatible with ejabberd.

The XMPP login sequence works, but I have problems with XMPP/BOSH.

I tried ejabberd 2.1.5 (Ubuntu) and 2.1.9 (compiled from source).

Perhaps someone knows my protocol error or tell me who could I ask for an advice?

When it comes to restarting after authentication it tells me the following:

-->

Which is issued from prepare_output_response (A,B,C,true) on line 1010
{200, ?HEADER, ""}

The whole HTTP traffic sequence is like following:
--> received from server
<-- send to server

The ejabberd (debug!) log is like following:

=INFO REPORT==== 2011-11-14 17:42:29 ===
I(<0.362.0>:ejabberd_listener:281) : (#Port<0.3021>) Accepted connection {{127,0,0,1},50494} -> {{127,0,0,1},5280}

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http:141) : S: [{["captcha"],ejabberd_captcha},
{["admin"],ejabberd_web_admin},
{["http-bind"],mod_http_bind},
{["http-poll"],ejabberd_http_poll}]

=INFO REPORT==== 2011-11-14 17:42:29 ===
I(<0.384.0>:ejabberd_http:143) : started: {gen_tcp,#Port<0.3021>}

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http:260) : (#Port<0.3021>) http query: 'POST' /http-bind/

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http:430) : client data: "\n\n"

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http:329) : ["http-bind"] matches ["http-bind"]

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:mod_http_bind:69) : Incoming data:

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http_bind:1131) : --- incoming data ---

--- END ---

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http_bind:124) : Starting session

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.385.0>:ejabberd_http_bind:313) : started: {"ed946ed47f2a96788b6a9b3c145e0afcce6126ad",
[],
{{127,0,0,1},50494}}

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http_bind:245) : got pid: <0.385.0>

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http_bind:285) : Create session: "ed946ed47f2a96788b6a9b3c145e0afcce6126ad"

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.384.0>:ejabberd_http_bind:807) : Looking for session: "ed946ed47f2a96788b6a9b3c145e0afcce6126ad"

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.385.0>:ejabberd_http_bind:429) : New request: {http_put,8238034047,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"xmlns:xmpp",
"urn:xmpp:xbosh"},
{"hold","1"},
{"rid","8238034047"},
{"to","localhost"},
{"ver","1.10"},
{"wait","60"},
{"xmpp:version","1.0"}],
[],168,1,
{"localhost","1.0"},
{{127,0,0,1},50494}}

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.385.0>:ejabberd_http_bind:569) : New request: {http_put,8238034047,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"xmlns:xmpp",
"urn:xmpp:xbosh"},
{"hold","1"},
{"rid","8238034047"},
{"to","localhost"},
{"ver","1.10"},
{"wait","60"},
{"xmpp:version","1.0"}],
[],168,1,
{"localhost","1.0"},
{{127,0,0,1},50494}}

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.385.0>:ejabberd_http_bind:606) : Actually processing request: {http_put,
8238034047,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"xmlns:xmpp",
"urn:xmpp:xbosh"},
{"hold",
"1"},
{"rid",
"8238034047"},
{"to",
"localhost"},
{"ver",
"1.10"},
{"wait",
"60"},
{"xmpp:version",
"1.0"}],
[],168,1,
{"localhost",
"1.0"},
{{127,0,0,
1},
50494}}

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.385.0>:ejabberd_http_bind:669) : -- SaveKey:

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.385.0>:ejabberd_http_bind:687) : reqlist: [{hbr,8238034047,[],[]}]

=INFO REPORT==== 2011-11-14 17:42:29 ===
D(<0.385.0>:ejabberd_http_bind:735) : really sending now: []

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.384.0>:ejabberd_http_bind:919) : OutPacket: [{xmlstreamstart,
"stream:stream",
[{"version","1.0"},
{"xml:lang","en"},
{"xmlns","jabber:client"},
{"xmlns:stream",
"http://etherx.jabber.org/streams"},
{"id","3022778670"},
{"from","localhost"}]},
{xmlstreamelement,
{xmlelement,
"stream:features",[],
[{xmlelement,
"mechanisms",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-sasl"}],
[{xmlelement,
"mechanism",[],
[{xmlcdata,"PLAIN"}]},
{xmlelement,
"mechanism",[],
[{xmlcdata,
"DIGEST-MD5"}]},
{xmlelement,
"mechanism",[],
[{xmlcdata,
"SCRAM-SHA-1"}]}]},
{xmlelement,"c",
[{"xmlns",
"http://jabber.org/protocol/caps"},
{"hash","sha-1"},
{"node",
"http://www.process-one.net/en/ejabberd/"},
{"ver",
"yy7di5kE0syuCXOQTXNBTclpNTo="}],
[]},
{xmlelement,"register",
[{"xmlns",
"http://jabber.org/features/iq-register"}],
[]}]}}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
I(<0.362.0>:ejabberd_listener:281) : (#Port<0.3023>) Accepted connection {{127,0,0,1},50495} -> {{127,0,0,1},5280}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http:141) : S: [{["captcha"],ejabberd_captcha},
{["admin"],ejabberd_web_admin},
{["http-bind"],mod_http_bind},
{["http-poll"],ejabberd_http_poll}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
I(<0.387.0>:ejabberd_http:143) : started: {gen_tcp,#Port<0.3023>}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http:260) : (#Port<0.3023>) http query: 'POST' /http-bind/

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http:430) : client data: "\n\n"

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http:329) : ["http-bind"] matches ["http-bind"]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:mod_http_bind:69) : Incoming data:

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http_bind:1131) : --- incoming data ---

--- END ---

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http_bind:807) : Looking for session: "ed946ed47f2a96788b6a9b3c145e0afcce6126ad"

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:429) : New request: {http_put,8238034048,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","8238034048"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"}],
[],123,1,[],
{{127,0,0,1},50495}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:shaper:61) : State: {maxrate,1000,0,1321288949975638}, Size=123
M=61.5, I=103.505

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:569) : New request: {http_put,8238034048,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","8238034048"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"}],
[],123,1,[],
{{127,0,0,1},50495}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:870) : Previous rid / New rid: 8238034047/8238034048

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:606) : Actually processing request: {http_put,
8238034048,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid",
"8238034048"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"}],
[],123,1,
[],
{{127,0,0,
1},
50495}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:669) : -- SaveKey:

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:687) : reqlist: [{hbr,8238034048,[],[]},
{hbr,8238034047,[],
[{xmlstreamelement,
{xmlelement,
"stream:features",[],
[{xmlelement,
"mechanisms",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-sasl"}],
[{xmlelement,
"mechanism",[],
[{xmlcdata,"PLAIN"}]},
{xmlelement,
"mechanism",[],
[{xmlcdata,
"DIGEST-MD5"}]},
{xmlelement,
"mechanism",[],
[{xmlcdata,
"SCRAM-SHA-1"}]}]},
{xmlelement,"c",
[{"xmlns",
"http://jabber.org/protocol/caps"},
{"hash","sha-1"},
{"node",
"http://www.process-one.net/en/ejabberd/"},
{"ver",
"yy7di5kE0syuCXOQTXNBTclpNTo="}],
[]},
{xmlelement,"register",
[{"xmlns",
"http://jabber.org/features/iq-register"}],
[]}]}},
{xmlstreamstart,
"stream:stream",
[{"version","1.0"},
{"xml:lang","en"},
{"xmlns","jabber:client"},
{"xmlns:stream",
"http://etherx.jabber.org/streams"},
{"id","3022778670"},
{"from","localhost"}]}]}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:735) : really sending now: []

=INFO REPORT==== 2011-11-14 17:42:30 ===
I(<0.362.0>:ejabberd_listener:281) : (#Port<0.3025>) Accepted connection {{127,0,0,1},50496} -> {{127,0,0,1},5280}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:ejabberd_http:141) : S: [{["captcha"],ejabberd_captcha},
{["admin"],ejabberd_web_admin},
{["http-bind"],mod_http_bind},
{["http-poll"],ejabberd_http_poll}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
I(<0.388.0>:ejabberd_http:143) : started: {gen_tcp,#Port<0.3025>}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:ejabberd_http:260) : (#Port<0.3025>) http query: 'POST' /http-bind/

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:ejabberd_http:430) : client data: "XXXXXXXXXXXXXXXX\n\n"

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:ejabberd_http:329) : ["http-bind"] matches ["http-bind"]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:mod_http_bind:69) : Incoming data: XXXXXXXXXXXXXXXX

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:ejabberd_http_bind:1131) : --- incoming data ---
XXXXXXXXXXXXXX

--- END ---

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:ejabberd_http_bind:807) : Looking for session: "ed946ed47f2a96788b6a9b3c145e0afcce6126ad"

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:429) : New request: {http_put,8238034049,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","8238034049"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"}],
[{xmlelement,"auth",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-sasl"},
{"mechanism","PLAIN"}],
[{xmlcdata,
<<"XXXXXXXXXXXXXXX">>}]}],
223,1,[],
{{127,0,0,1},50496}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:shaper:61) : State: {maxrate,1000,594.1167946674395,
1321288950079153}, Size=223
M=158.61915069057926, I=27.84

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:569) : New request: {http_put,8238034049,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid","8238034049"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"}],
[{xmlelement,"auth",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-sasl"},
{"mechanism","PLAIN"}],
[{xmlcdata,
<<"XXXXXXXXXXXXXXXX">>}]}],
223,1,[],
{{127,0,0,1},50496}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:870) : Previous rid / New rid: 8238034048/8238034049

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:606) : Actually processing request: {http_put,
8238034049,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"rid",
"8238034049"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"}],
[{xmlelement,
"auth",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-sasl"},
{"mechanism",
"PLAIN"}],
[{xmlcdata,
<<"XXXXXXXXXXXXXXXX">>}]}],
223,1,[],
{{127,0,0,
1},
50496}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:669) : -- SaveKey:

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:687) : reqlist: [{hbr,8238034049,[],[]},
{hbr,8238034048,[],[]}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:735) : really sending now: [{xmlelement,
"auth",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-sasl"},
{"mechanism",
"PLAIN"}],
[{xmlcdata,
<<"XXXXXXXXXXXXXXXXXX">>}]}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
I(<0.386.0>:ejabberd_c2s:631) : ({socket_state,ejabberd_http_bind,{http_bind,<0.385.0>,{{127,0,0,1},50494}},ejabberd_http_bind}) Accepted authentication for autotest1 by ejabberd_auth_internal

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http_bind:919) : OutPacket: [{xmlstreamelement,
{xmlelement,"success",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-sasl"}],
[]}}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.387.0>:ejabberd_http_bind:1057) : --- outgoing data ---

--- END ---

=INFO REPORT==== 2011-11-14 17:42:30 ===
I(<0.362.0>:ejabberd_listener:281) : (#Port<0.3027>) Accepted connection {{127,0,0,1},50497} -> {{127,0,0,1},5280}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http:141) : S: [{["captcha"],ejabberd_captcha},
{["admin"],ejabberd_web_admin},
{["http-bind"],mod_http_bind},
{["http-poll"],ejabberd_http_poll}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
I(<0.389.0>:ejabberd_http:143) : started: {gen_tcp,#Port<0.3027>}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http:260) : (#Port<0.3027>) http query: 'POST' /http-bind/

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http:430) : client data: "\n\n"

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http:329) : ["http-bind"] matches ["http-bind"]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:mod_http_bind:69) : Incoming data:

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http_bind:1131) : --- incoming data ---

--- END ---

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http_bind:807) : Looking for session: "ed946ed47f2a96788b6a9b3c145e0afcce6126ad"

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:424) : Shaper timer for RID 8238034050: {wait,
51}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http_bind:791) : Trafic Shaper: Delaying request 8238034050

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http_bind:807) : Looking for session: "ed946ed47f2a96788b6a9b3c145e0afcce6126ad"

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:429) : New request: {http_put,8238034050,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"xmlns:xmpp",
"urn:xmpp:xbosh"},
{"rid","8238034050"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"},
{"xmpp:restart","true"}],
[],171,1,
{"localhost","1.0"},
{{127,0,0,1},50497}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:shaper:61) : State: {maxrate,1000,999.0005421919149,
1321288950237998}, Size=171
M=170.82926335888652, I=1.152

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:569) : New request: {http_put,8238034050,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"xmlns:xmpp",
"urn:xmpp:xbosh"},
{"rid","8238034050"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"},
{"xmpp:restart","true"}],
[],171,1,
{"localhost","1.0"},
{{127,0,0,1},50497}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:870) : Previous rid / New rid: 8238034049/8238034050

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:606) : Actually processing request: {http_put,
8238034050,
[{"xmlns",
"http://jabber.org/protocol/httpbind"},
{"xmlns:xmpp",
"urn:xmpp:xbosh"},
{"rid",
"8238034050"},
{"sid",
"ed946ed47f2a96788b6a9b3c145e0afcce6126ad"},
{"xmpp:restart",
"true"}],
[],171,1,
{"localhost",
"1.0"},
{{127,0,0,
1},
50497}}

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:669) : -- SaveKey:

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:687) : reqlist: [{hbr,8238034050,[],[]},
{hbr,8238034049,[],[]}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.385.0>:ejabberd_http_bind:735) : really sending now: []

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.388.0>:ejabberd_http_bind:919) : OutPacket: [{xmlstreamstart,
"stream:stream",
[{"version","1.0"},
{"xml:lang","en"},
{"xmlns","jabber:client"},
{"xmlns:stream",
"http://etherx.jabber.org/streams"},
{"id","2199184664"},
{"from","localhost"}]}]

=INFO REPORT==== 2011-11-14 17:42:30 ===
D(<0.389.0>:ejabberd_http_bind:919) : OutPacket: [{xmlstreamelement,
{xmlelement,
"stream:features",[],
[{xmlelement,"bind",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-bind"}],
[]},
{xmlelement,"session",
[{"xmlns",
"urn:ietf:params:xml:ns:xmpp-session"}],
[]},
{xmlelement,"c",
[{"xmlns",
"http://jabber.org/protocol/caps"},
{"hash","sha-1"},
{"node",
"http://www.process-one.net/en/ejabberd/"},
{"ver",
"yy7di5kE0syuCXOQTXNBTclpNTo="}],
[]},
{xmlelement,"register",
[{"xmlns",
"http://jabber.org/features/iq-register"}],
[]}]}}]

=INFO REPORT==== 2011-11-14 17:43:00 ===
I(<0.385.0>:ejabberd_http_bind:509) : Session timeout. Closing the HTTP bind session: "ed946ed47f2a96788b6a9b3c145e0afcce6126ad"

=INFO REPORT==== 2011-11-14 17:43:00 ===
D(<0.385.0>:ejabberd_http_bind:550) : terminate: Deleting session ed946ed47f2a96788b6a9b3c145e0afcce6126ad