wfleischer
commented
2 years ago The following prosody debug log might be helpful (especially the part Have nothing to say, so leaving request unanswered for now):
connSbtHdzxBLdZp debug New connection FD 16 (172.22.0.3, 56656, 172.22.0.2, 5280) on server FD 8 (*, 5280)
connSbtHdzxBLdZp debug Connected (FD 16 (172.22.0.3, 56656, 172.22.0.2, 5280))
runnerrKBvvaMbi7Gi debug creating new coroutine
http.server debug Firing event: POST /http-bind
http.server debug Firing event: POST meet.jitsi/http-bind
mod_bosh debug Handling new request table: 0xaaab0b6a7a10: <body rid="1026384703" sid="310ffe4b-9891-4689-b972-0dad2b215ece" xmlns="http://jabber.org/protocol/httpbind"><iq id="53fc0cc8-8885-42a1-a256-ecd05f5d5ed7:sendIQ" to="meet.jitsi" type="get" xmlns="jabber:client"><ping xmlns="urn:xmpp:ping"/></iq></body>
----------
mod_bosh debug BOSH body open (sid: 310ffe4b-9891-4689-b972-0dad2b215ece)
bosh310ffe4b-9891-4689-b972-0dad2b215ece debug rid: 1026384703, sess: 1026384702, diff: 1
mod_bosh debug BOSH stanza received: <iq to='meet.jitsi' xml:lang='en' id='53fc0cc8-8885-42a1-a256-ecd05f5d5ed7:sendIQ' type='get'>
bosh310ffe4b-9891-4689-b972-0dad2b215ece debug Received[c2s]: <iq to='meet.jitsi' xml:lang='en' id='53fc0cc8-8885-42a1-a256-ecd05f5d5ed7:sendIQ' type='get'>
mod_bosh debug We have an open request, so sending on that
mod_bosh debug Request destroyed: table: 0xaaab0b680aa0
connXiBK0qcoIflH debug Close after writing remaining buffered data
mod_bosh debug Session 310ffe4b-9891-4689-b972-0dad2b215ece has 1 out of 1 requests open
mod_bosh debug and there are 0 things in the send_buffer:
mod_bosh debug Have nothing to say, so leaving request unanswered for now
runnerrKBvvaMbi7Gi debug changed state from ready to waiting
connXiBK0qcoIflH debug Closing now
saghul
Mupati
damencho
paweldomas
Description:
Replies to bosh requests are deferred to the arrival of the subsequent request.
Steps to reproduce:
Expected behavior:
Bosh requests should take milliseconds to be handled.
Actual behavior:
The reply to the request arrives on the next bosh request.
This is the log of the web container (values rt=10.010 uct="0.002" uht="10.010" urt="10.010" are as described here):
As one can see, every request takes as long as the time passed before the next request.
This is not an error in logging, as one can see on the client:
Additional Information
I came across this bug, when I was debugging why our monitoring system constantly reports responses times of our proxies close to 10s. The response time is somewhat limited to 10s because of the bosh ping being sent every 10s. That's probably why this problem does not break the functionality of bosh clients. Nevertheless, having bosh working properly will certainly improve the functionality.