I can't figure out why Ejabberd (14.07 & 14.12) is Closing a BOSH session after receiving an 'available' stanza for that same session.
I am using JsJac as web client lib and the session is being prebound server side and JsJac is doing 'inherit' on first page load and als on restart. The scenario in which this happens is after a successful connection and chat, i disable the network connection using chrome developer tools.
Ejabberd pings every 15 Seconds and is set to 'kill' on timeout. The Inactivity_timeout for BOSH in ejabberd.yml is set to 480.
The user can then click a link to try to reconnect. This is calling the exact same function as the initial prebind+client side inherit. After seemingly successful reconnect, a few seconds later, this:
Close session for
anonymous.c6502a950667fc79c3e1534559cc02e0@localhost/7f317c7fcbb9fb1b79c414c2d8afe05c
appears in the ejabberd log and a stanza of unavailable is sent to the other party in the chat.
Question: anybody have any idea why the BOSH session might be closed?
Here is the relevant piece of the Ejabberd log
2015-01-09 18:25:21.308 [debug] <0.2710.0>@ejabberd_receiver:process_data:343 Received XML on stream = <<"<presence from=\"anonymous.c6502a950667fc79c3e1534559cc02e0@jaxlecho.localhost\" type=\"available\"/>">>
2015-01-09 18:25:21.309 [debug] <0.2710.0>@shaper:update:117 State: {maxrate,50000,1899.4311619841992,1420824321273332}, Size=97
M=0.9887812185897407, I=35.836
2015-01-09 18:25:21.390 [info] <0.2709.0>@ejabberd_listener:accept:313 (#Port<0.41723>) Accepted connection ::FFFF:127.0.0.1:58483 -> ::FFFF:127.0.0.1:5280
2015-01-09 18:25:21.391 [debug] <0.5331.0>@ejabberd_http:init:145 S: [{[<<"presence">>],mod_webpresence},{[<<"captcha">>],ejabberd_captcha},{[<<"admin">>],ejabberd_web_admin},{[<<"http-bind">>],mod_http_bind},{[<<"http-poll">>],ejabberd_http_poll}]
2015-01-09 18:25:21.391 [info] <0.5331.0>@ejabberd_http:init:149 started: {gen_tcp,#Port<0.41723>}
2015-01-09 18:25:21.392 [debug] <0.5331.0>@ejabberd_http:process_header:277 (#Port<0.41723>) http query: 'POST' /http-bind
2015-01-09 18:25:21.392 [debug] <0.5331.0>@ejabberd_http:process_request:438 client data: <<"<body rid='876185' sid='a1e29cded4325f591bdc5b3646a8f3c78553cdd8' xmlns='http://jabber.org/protocol/httpbind' key='38516e6b293e317ee957f6ef74fa23c68a003d19'/>">>
2015-01-09 18:25:21.392 [debug] <0.5331.0>@ejabberd_http:process:350 [<<"http-bind">>] matches [<<"http-bind">>]
2015-01-09 18:25:21.393 [debug] <0.5331.0>@ejabberd_http:process:354 [{'Accept-Language',<<"en-US,en;q=0.8,es;q=0.6,und;q=0.4,nl;q=0.2,ca;q=0.2">>},{'Accept-Encoding',<<"gzip, deflate">>},{'Referer',<<"http://localhost:9080/">>},{'Accept',<<"*/*">>},{'Content-Type',<<"text/xml; charset=UTF-8">>},{'User-Agent',<<"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36">>},{<<"Origin">>,<<"http://localhost:9080">>},{'Content-Length',<<"158">>},{'Connection',<<"close">>},{'Host',<<"vagrant.localhost">>}]
2015-01-09 18:25:21.393 [debug] <0.5331.0>@mod_http_bind:process:68 Incoming data: <body rid='876185' sid='a1e29cded4325f591bdc5b3646a8f3c78553cdd8' xmlns='http://jabber.org/protocol/httpbind' key='38516e6b293e317ee957f6ef74fa23c68a003d19'/>
2015-01-09 18:25:21.393 [debug] <0.5331.0>@ejabberd_http_bind:parse_request:1128 --- incoming data ---
<body rid='876185' sid='a1e29cded4325f591bdc5b3646a8f3c78553cdd8' xmlns='http://jabber.org/protocol/httpbind' key='38516e6b293e317ee957f6ef74fa23c68a003d19'/>
--- END ---
2015-01-09 18:25:21.394 [debug] <0.5331.0>@ejabberd_http_bind:http_put:792 Looking for session: <<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>
2015-01-09 18:25:21.394 [debug] <0.4052.0>@ejabberd_http_bind:handle_sync_event:440 New request: {http_put,876185,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"876185">>},{<<"sid">>,<<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>},{<<"key">>,<<"38516e6b293e317ee957f6ef74fa23c68a003d19">>}],[],158,1,<<>>,{{0,0,0,0,0,65535,32512,1},58483}}
2015-01-09 18:25:21.395 [debug] <0.4052.0>@ejabberd_http_bind:handle_http_put_event:575 New request: {http_put,876185,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"876185">>},{<<"sid">>,<<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>},{<<"key">>,<<"38516e6b293e317ee957f6ef74fa23c68a003d19">>}],[],158,1,<<>>,{{0,0,0,0,0,65535,32512,1},58483}}
2015-01-09 18:25:21.395 [debug] <0.4052.0>@ejabberd_http_bind:rid_allow:866 Previous rid / New rid: 876184/876185
2015-01-09 18:25:21.396 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:608 Actually processing request: {http_put,876185,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"876185">>},{<<"sid">>,<<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>},{<<"key">>,<<"38516e6b293e317ee957f6ef74fa23c68a003d19">>}],[],158,1,<<>>,{{0,0,0,0,0,65535,32512,1},58483}}
2015-01-09 18:25:21.396 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:619 Key/OldKey/NextKey: 38516e6b293e317ee957f6ef74fa23c68a003d19/85e12ff1c2c9590328a5f0a1e58c14e52a8c6c42/85e12ff1c2c9590328a5f0a1e58c14e52a8c6c42
2015-01-09 18:25:21.397 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:659 -- SaveKey: 38516e6b293e317ee957f6ef74fa23c68a003d19
2015-01-09 18:25:21.397 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:671 reqlist: [{hbr,876185,<<"85e12ff1c2c9590328a5f0a1e58c14e52a8c6c42">>,[]},{hbr,876184,<<"85e12ff1c2c9590328a5f0a1e58c14e52a8c6c42">>,[{xmlstreamelement,{xmlel,<<"presence">>,[{<<"from">>,<<"anonymous.c6502a950667fc79c3e1534559cc02e0@jaxlecho.localhost">>},{<<"to">>,<<"agent1@localhost/cb_operator_1420818758533">>},{<<"type">>,<<"available">>},{<<"show">>,<<"chat">>}],[]}}]}]
2015-01-09 18:25:21.398 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:717 really sending now: []
2015-01-09 18:25:31.193 [debug] <0.2648.0>@ejabberd_router:do_route:322 route
from {jid,<<>>,<<"localhost">>,<<>>,<<>>,<<"localhost">>,<<>>}
to {jid,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>}
packet {xmlel,<<"iq">>,[{<<"id">>,<<"4293567110">>},{<<"type">>,<<"get">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}
2015-01-09 18:25:31.194 [debug] <0.2648.0>@ejabberd_local:do_route:296 local route
from {jid,<<>>,<<"localhost">>,<<>>,<<>>,<<"localhost">>,<<>>}
to {jid,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>}
packet {xmlel,<<"iq">>,[{<<"id">>,<<"4293"...>>},{<<"type">>,<<...>>}],[{xmlel,<<...>>,...}]}
2015-01-09 18:25:31.194 [debug] <0.2648.0>@ejabberd_sm:do_route:514 session manager
from {jid,<<>>,<<"localhost">>,<<>>,<<>>,<<"localhost">>,<<>>}
to {jid,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>}
packet {xmlel,<<"iq">>,[{<<"id">>,<<"4293"...>>},{<<"type">>,<<...>>}],[{xmlel,<<...>>,...}]}
2015-01-09 18:25:31.194 [debug] <0.2648.0>@ejabberd_sm:do_route:612 sending to process <0.4053.0>
2015-01-09 18:25:31.195 [debug] <0.5331.0>@ejabberd_http_bind:prepare_response:914 OutPacket: [{xmlstreamelement,{xmlel,<<"iq">>,[{<<"from">>,<<"localhost">>},{<<"to">>,<<"agent1@localhost/cb_operator_1420818758533">>},{<<"id">>,<<"4293567110">>},{<<"type">>,<<"get">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}}]
2015-01-09 18:25:31.195 [debug] <0.5331.0>@ejabberd_http_bind:send_outpacket:1056 --- outgoing data ---
<body xmlns='http://jabber.org/protocol/httpbind'><iq xmlns='jabber:client' from='localhost' to='agent1@localhost/cb_operator_1420818758533' id='4293567110' type='get'><ping xmlns='urn:xmpp:ping'/></iq></body>
--- END ---
2015-01-09 18:25:31.228 [info] <0.2709.0>@ejabberd_listener:accept:313 (#Port<0.41753>) Accepted connection ::FFFF:127.0.0.1:58484 -> ::FFFF:127.0.0.1:5280
2015-01-09 18:25:31.230 [debug] <0.5332.0>@ejabberd_http:init:145 S: [{[<<"presence">>],mod_webpresence},{[<<"captcha">>],ejabberd_captcha},{[<<"admin">>],ejabberd_web_admin},{[<<"http-bind">>],mod_http_bind},{[<<"http-poll">>],ejabberd_http_poll}]
2015-01-09 18:25:31.231 [info] <0.5332.0>@ejabberd_http:init:149 started: {gen_tcp,#Port<0.41753>}
2015-01-09 18:25:31.231 [debug] <0.5332.0>@ejabberd_http:process_header:277 (#Port<0.41753>) http query: 'POST' /http-bind
2015-01-09 18:25:31.231 [debug] <0.5332.0>@ejabberd_http:process_request:438 client data: <<"<body rid='876186' sid='a1e29cded4325f591bdc5b3646a8f3c78553cdd8' xmlns='http://jabber.org/protocol/httpbind' key='9cffab80935471f419ce5c9201475df5935108d5'><iq xmlns=\"jabber:client\" to=\"localhost\" id=\"4293567110\" type=\"result\"><ping xmlns=\"urn:xmpp:ping\"/></iq></body>">>
2015-01-09 18:25:31.231 [debug] <0.5332.0>@ejabberd_http:process:350 [<<"http-bind">>] matches [<<"http-bind">>]
2015-01-09 18:25:31.232 [debug] <0.5332.0>@ejabberd_http:process:354 [{'Accept-Language',<<"en-US,en;q=0.8,es;q=0.6,und;q=0.4,nl;q=0.2,ca;q=0.2">>},{'Accept-Encoding',<<"gzip, deflate">>},{'Referer',<<"http://localhost:9080/">>},{'Accept',<<"*/*">>},{'Content-Type',<<"text/xml; charset=UTF-8">>},{'User-Agent',<<"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36">>},{<<"Origin">>,<<"http://localhost:9080">>},{'Content-Length',<<"269">>},{'Connection',<<"close">>},{'Host',<<"vagrant.localhost">>}]
2015-01-09 18:25:31.233 [debug] <0.5332.0>@mod_http_bind:process:68 Incoming data: <body rid='876186' sid='a1e29cded4325f591bdc5b3646a8f3c78553cdd8' xmlns='http://jabber.org/protocol/httpbind' key='9cffab80935471f419ce5c9201475df5935108d5'><iq xmlns="jabber:client" to="localhost" id="4293567110" type="result"><ping xmlns="urn:xmpp:ping"/></iq></body>
2015-01-09 18:25:31.233 [debug] <0.5332.0>@ejabberd_http_bind:parse_request:1128 --- incoming data ---
<body rid='876186' sid='a1e29cded4325f591bdc5b3646a8f3c78553cdd8' xmlns='http://jabber.org/protocol/httpbind' key='9cffab80935471f419ce5c9201475df5935108d5'><iq xmlns="jabber:client" to="localhost" id="4293567110" type="result"><ping xmlns="urn:xmpp:ping"/></iq></body>
--- END ---
2015-01-09 18:25:31.234 [debug] <0.5332.0>@ejabberd_http_bind:http_put:792 Looking for session: <<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>
2015-01-09 18:25:31.234 [debug] <0.4052.0>@ejabberd_http_bind:handle_sync_event:440 New request: {http_put,876186,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"876186">>},{<<"sid">>,<<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>},{<<"key">>,<<"9cffab80935471f419ce5c9201475df5935108d5">>}],[{xmlel,<<"iq">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"localhost">>},{<<"id">>,<<"4293567110">>},{<<"type">>,<<"result">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}],269,1,<<>>,{{0,0,0,0,0,65535,32512,1},58484}}
2015-01-09 18:25:31.234 [debug] <0.4052.0>@ejabberd_http_bind:handle_http_put_event:575 New request: {http_put,876186,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"876186">>},{<<"sid">>,<<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>},{<<"key">>,<<"9cffab80935471f419ce5c9201475df5935108d5">>}],[{xmlel,<<"iq">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"localhost">>},{<<"id">>,<<"4293567110">>},{<<"type">>,<<"result">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}],269,1,<<>>,{{0,0,0,0,0,65535,32512,1},58484}}
2015-01-09 18:25:31.234 [debug] <0.4052.0>@ejabberd_http_bind:rid_allow:866 Previous rid / New rid: 876185/876186
2015-01-09 18:25:31.234 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:608 Actually processing request: {http_put,876186,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"876186">>},{<<"sid">>,<<"a1e29cded4325f591bdc5b3646a8f3c78553cdd8">>},{<<"key">>,<<"9cffab80935471f419ce5c9201475df5935108d5">>}],[{xmlel,<<"iq">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"localhost">>},{<<"id">>,<<"4293567110">>},{<<"type">>,<<"result">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}],269,1,<<>>,{{0,0,0,0,0,65535,32512,1},58484}}
2015-01-09 18:25:31.234 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:619 Key/OldKey/NextKey: 9cffab80935471f419ce5c9201475df5935108d5/38516e6b293e317ee957f6ef74fa23c68a003d19/38516e6b293e317ee957f6ef74fa23c68a003d19
2015-01-09 18:25:31.234 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:659 -- SaveKey: 9cffab80935471f419ce5c9201475df5935108d5
2015-01-09 18:25:31.234 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:671 reqlist: [{hbr,876186,<<"38516e6b293e317ee957f6ef74fa23c68a003d19">>,[]},{hbr,876185,<<"38516e6b293e317ee957f6ef74fa23c68a003d19">>,[{xmlstreamelement,{xmlel,<<"iq">>,[{<<"from">>,<<"localhost">>},{<<"to">>,<<"agent1@localhost/cb_operator_1420818758533">>},{<<"id">>,<<"4293567110">>},{<<"type">>,<<"get">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}}]}]
2015-01-09 18:25:31.235 [debug] <0.4052.0>@ejabberd_http_bind:process_http_put:717 really sending now: [{xmlel,<<"iq">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"localhost">>},{<<"id">>,<<"4293567110">>},{<<"type">>,<<"result">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}]
2015-01-09 18:25:31.235 [debug] <0.4053.0>@ejabberd_router:do_route:322 route
from {jid,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>}
to {jid,<<>>,<<"localhost">>,<<>>,<<>>,<<"localhost">>,<<>>}
packet {xmlel,<<"iq">>,[{<<"to">>,<<"localhost">>},{<<"id">>,<<"4293567110">>},{<<"type">>,<<"result">>}],[{xmlel,<<"ping">>,[{<<"xmlns">>,<<"urn:xmpp:ping">>}],[]}]}
2015-01-09 18:25:31.235 [debug] <0.4053.0>@ejabberd_local:do_route:296 local route
from {jid,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>,<<"agent1">>,<<"localhost">>,<<"cb_operator_1420818758533">>}
to {jid,<<>>,<<"localhost">>,<<>>,<<>>,<<"localhost">>,<<>>}
packet {xmlel,<<"iq">>,[{<<"to">>,<<"loca"...>>},{<<"id">>,<<...>>},{<<...>>,...}],[{xmlel,<<...>>,...}]}
2015-01-09 18:25:31.570 [info] <0.5318.0>@ejabberd_c2s:terminate:1757 ({socket_state,ejabberd_http_bind,{http_bind,<0.5317.0>,{{0,0,0,0,0,65535,32512,1},58451}},ejabberd_http_bind}) Close session for anonymous.c6502a950667fc79c3e1534559cc02e0@localhost/2b8e1ac2921d6d3713396edff70a0d2a
2015-01-09 18:25:31.571 [debug] <0.5318.0>@mod_pubsub:node_action:5143 node_action <<"pubsub.localhost">> <<"flat">> get_entity_affiliations [<<"pubsub.localhost">>,{<<"anonymous.c6502a950667fc79c3e1534559cc02e0">>,<<"localhost">>,<<"2b8e1ac2921d6d3713396edff70a0d2a">>}]
2015-01-09 18:25:31.571 [debug] <0.5318.0>@mod_pubsub:node_call:5124 node_call <<"flat">> get_entity_affiliations [<<"pubsub.localhost">>,{<<"anonymous.c6502a950667fc79c3e1534559cc02e0">>,<<"localhost">>,<<"2b8e1ac2921d6d3713396edff70a0d2a">>}]
2015-01-09 18:25:31.571 [debug] <0.5318.0>@mod_pubsub:node_action:5143 node_action <<"pubsub.localhost">> <<"hometree">> get_entity_affiliations [<<"pubsub.localhost">>,{<<"anonymous.c6502a950667fc79c3e1534559cc02e0">>,<<"localhost">>,<<"2b8e1ac2921d6d3713396edff70a0d2a">>}]
2015-01-09 18:25:31.572 [debug] <0.5318.0>@mod_pubsub:node_call:5124 node_call <<"hometree">> get_entity_affiliations [<<"pubsub.localhost">>,{<<"anonymous.c6502a950667fc79c3e1534559cc02e0">>,<<"localhost">>,<<"2b8e1ac2921d6d3713396edff70a0d2a">>}]
2015-01-09 18:25:31.572 [debug] <0.5318.0>@mod_pubsub:node_action:5143 node_action <<"pubsub.localhost">> <<"pep">> get_entity_affiliations [<<"pubsub.localhost">>,{<<"anonymous.c6502a950667fc79c3e1534559cc02e0">>,<<"localhost">>,<<"2b8e1ac2921d6d3713396edff70a0d2a">>}]
2015-01-09 18:25:31.572 [debug] <0.5318.0>@mod_pubsub:node_call:5124 node_call <<"pep">> get_entity_affiliations [<<"pubsub.localhost">>,{<<"anonymous.c6502a950667fc79c3e1534559cc02e0">>,<<"localhost">>,<<"2b8e1ac2921d6d3713396edff70a0d2a">>}]
2015-01-09 18:25:31.573 [debug] <0.5318.0>@mod_carboncopy:disable:246 disabling for <<"anonymous.c6502a950667fc79c3e1534559cc02e0">>
2015-01-09 18:25:31.574 [debug] <0.5318.0>@mod_shared_roster:unset_presence:1081 unset_presence for <<"anonymous.c6502a950667fc79c3e1534559cc02e0">> @ <<"localhost">> / <<"2b8e1ac2921d6d3713396edff70a0d2a">> -> <<>> (0 resources)
2015-01-09 18:25:31.574 [debug] <0.5318.0>@ejabberd_router:do_route:322 route
More of the log is here. https://gist.github.com/Elexy/052a6a428fb57147bf4e