What steps will reproduce the problem?
1. Connect to a server running trunk with BOSH
What do you see instead?
Apr 28 11:21:55 anon.jabberfr.org:bosh debug Handling new request table: 0x55ebeb9d32a0: <body xmlns="http://jabber.org/protocol/httpbind" content="text/xml; charset=utf-8" hold="1" route="xmpp:jabber.fr:5223"
to="jabber.fr" wait="30" xml:lang="de" xmpp:version="1.0" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" rid="160977786294374" ack="1" newkey="bfe4f018995214f7c7b5aef01bc6d94862eea2bc" />
----------
Apr 28 11:21:55 anon.jabberfr.org:bosh debug BOSH body open (sid: <none>)
What version of the product are you using? On what operating system?
trunk version c63db78f4ae0 from 2 months and 1 week ago.
Please provide any additional information below.
XEP says sid MUST NOT be in the inital body, so looking for it there seems wrong
Further logs which i didnt post
Apr 28 11:21:55 anon.jabberfr.org:bosh warn Unable to associate request with a session (incomplete request?)
Apr 28 11:21:55 anon.jabberfr.org:bosh debug Request destroyed: table: 0x55ec0192e140
Apr 28 11:21:55 socket debug try to close client connection with id: 55ebd1d70d50
Apr 28 11:21:55 socket debug closing delayed until writebuffer is empty
Apr 28 11:21:55 socket debug closing client after writing
Apr 28 11:21:55 socket debug closing client with id: 55ebd1d70d50 client to close
Zash
on
Thanks for the report.
IIRC in the chatroom we determined that this is a regression casued by #402
seems not to fix the issue
but the stanzas look now different
_____________
POST / HTTP/1.1
Host: bosh.jabberfr.org:443
User-Agent: Gajim
Content-Type: text/xml; charset=utf-8
Content-Length: 299
Connection: Keep-Alive
<body xmlns="http://jabber.org/protocol/httpbind" content="text/xml; charset=utf-8" hold="1" route="xmpp:jabber.fr:5223" to="jabber.fr" wait
="30" xml:lang="de" xmpp:version="1.0" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" rid="103060377197309" ack="1" newkey="1133c6e679188d1ba60868b06
51fa97d8d958d04" />
_____________
14.05.2018 18:35:49 (D) gajim.c.ged: stanza-sent Args: (<gajim.common.connection_handlers_events.StanzaSentEvent object at 0x09bf44d0>,)
14.05.2018 18:35:49 (I) nbxmpp.transports_nb: pollin called, state == CONNECTED
14.05.2018 18:35:49 (I) nbxmpp.idlequeue: read timeout removed for fd 1220
14.05.2018 18:35:49 (I) nbxmpp.client_nb: raising event from transport: :::::DATA RECEIVED::::
_____________
HTTP/1.1 404 Not Found
Server: nginx/1.14.0
Date: Mon, 14 May 2018 16:35:49 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 422
Connection: keep-alive
Strict-Transport-Security: max-age=31536000; includeSubDomains
X-Content-Type-Options: nosniff
X-Frame-Options: DENY
Referrer-Policy: strict-origin-when-cross-origin
Content-Security-Policy: frame-ancestors 'none'; default-src 'none'; img-src https://bosh.jabberfr.org/favicon.ico; report-uri /report-csp-v
iolation
<!DOCTYPE html>
<html>
<head>
<meta charset="utf-8">
<title>404 Not Found</title>
<style>
body{
margin-top:14%;
text-align:center;
background-color:#F8F8F8;
font-family:sans-serif;
}
h1{
font-size:xx-large;
}
p{
font-size:x-large;
}
p+p {
font-size:large;
font-family:courier;
}
</style>
</head>
<body>
<h1>404 Not Found</h1>
<p>Whatever you were looking for is not here. Keep looking.</p>
<p></p>
</body>
</html>
_____________
14.05.2018 18:35:49 (D) gajim.c.ged: stanza-received Args: (<gajim.common.connection_handlers_events.StanzaReceivedEvent object at 0x09bf4a1
0>,)
14.05.2018 18:35:49 (E) nbxmpp.transports_nb: HTTP Error: 404 Not Found
lovetox
on
Server Side
May 14 18:35:49 socket debug accepted incoming client connection from: ::1 41748 to 5280
May 14 18:35:49 http.server debug Firing event: POST anon.jabberfr.org/http-bind/
May 14 18:35:49 anon.jabberfr.org:bosh debug Handling new request table: 0x55ebdf4dbfe0: <body xmlns="http://jabber.org/protocol/httpbind" content="text/xml; charset=utf-8" hold="1" route="xmpp:jabber.fr:5223"
to="jabber.fr" wait="30" xml:lang="de" xmpp:version="1.0" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" rid="103060377197309" ack="1" newkey="1133c6e679188d1ba60868b0651fa97d8d958d04" />
----------
May 14 18:35:49 anon.jabberfr.org:bosh debug BOSH body open (sid: <none>)
May 14 18:35:49 anon.jabberfr.org:bosh debug Request destroyed: table: 0x55ec11369c80
Zash
on
Additional logging for this issue was added in https://hg.prosody.im/trunk/rev/f69b3e39e0c1
Is this still happening and if so, do the lines in the above change show up in the log?
MattJ
on
Waiting for update on this. Bumping to 0.12.
Changes
tags Milestone-0.12
lovetox
on
I tested and we did not see either of these 2 new debug messages
Minami-o
on
Hi,
I'm moved from 0.10.2 to trunk on Debian stretch via the prosody-provided trunk version (refreshed last night), and I realized bosh was no longer working.
I had a look at the debug logs, and saw one of the messages that were added in the mentioned change: Ignoring this request.
Note that I have a proxy redirection in place via my webserver towards port 5280, which worked well on 0.10.2.
As a matter of fact, GET requests still work, only POST requests fail.
See full log below:
Sep 02 11:33:55 socket debug server.lua: accepted new client connection from 127.0.0.1:41276 to 5280
Sep 02 11:33:55 http.server debug Firing event: POST localhost/http-bind/
Sep 02 11:33:55 localhost:bosh debug Handling new request table: 0x55a07a0b8380: <body rid='123456' xmlns='http://jabber.org/protocol/httpbind' to='biboumail.fr' xml:lang='en' wait='60' hold='1' content='text/xml; charset=utf-8' ver='1.6' xmpp:version='1.0' xmlns:xmpp='urn:xmpp:xbosh'/>
----------
Sep 02 11:33:55 localhost:bosh debug BOSH body open (sid: <none>)
Sep 02 11:33:55 localhost:bosh debug Ignoring this request
Sep 02 11:33:55 localhost:bosh debug Request destroyed: table: 0x55a07a0b8820
Sep 02 11:33:56 biboumail.fr:mam debug Removing old messages for user "xmpp-test"
Sep 02 11:33:57 socket debug server.lua: client 127.0.0.1:41276 read error: closed
Sep 02 11:33:57 socket debug server.lua: closed client handler and removed socket from list
Zash
on
What configuration is involved?
Minami-o
on
Config files can be downloaded here: https://www.biboumail.fr/dl.php?file=MjI4OTdjOGRjMzQx
I'm currently running "trunk nightly build 962 (2018-08-31, 83375ec33619)" on Debian Stretch, based on the Prosody repo.
The main host is biboumail.fr, there is another one (brie.tech) with the same config (adapted to the host).
I'm also running a web server (h2o) which redirects https://www.biboumail.fr/http-bind towards http://localhost:5280/http-bind
This config worked perfectly well with 0.10.2.
Zash
on
Per your log you are talking to the host 'localhost'. It does not serve BOSH for 'biboumail.fr'. What you see is the fix for #371 working as intended.
I believe this issue, #1134, to be about a case where the BOSH URL for all hosts really is configured to be identical, in which case dispatch to the correct host does not work as intended.
Minami-o
on
You're right, sorry for the noise…
MattJ on the chatroom helped me realize there was some additional config needed at web server level to preserve the host while proxying, the behaviour of BOSH having changed due to #371 as you mentioned.
What steps will reproduce the problem? 1. Connect to a server running trunk with BOSH What do you see instead? Apr 28 11:21:55 anon.jabberfr.org:bosh debug Handling new request table: 0x55ebeb9d32a0: <body xmlns="http://jabber.org/protocol/httpbind" content="text/xml; charset=utf-8" hold="1" route="xmpp:jabber.fr:5223" to="jabber.fr" wait="30" xml:lang="de" xmpp:version="1.0" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" rid="160977786294374" ack="1" newkey="bfe4f018995214f7c7b5aef01bc6d94862eea2bc" /> ---------- Apr 28 11:21:55 anon.jabberfr.org:bosh debug BOSH body open (sid: <none>) What version of the product are you using? On what operating system? trunk version c63db78f4ae0 from 2 months and 1 week ago. Please provide any additional information below. XEP says sid MUST NOT be in the inital body, so looking for it there seems wrong
Thats the view clientside: _____________ POST / HTTP/1.1 Host: bosh.jabberfr.org:443 User-Agent: Gajim Content-Type: text/xml; charset=utf-8 Content-Length: 299 Connection: Keep-Alive <body xmlns="http://jabber.org/protocol/httpbind" content="text/xml; charset=utf-8" hold="1" route="xmpp:jabber.fr:5223" to="jabber.fr" wait ="30" xml:lang="de" xmpp:version="1.0" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" rid="160977786294374" ack="1" newkey="bfe4f018995214f7c7b5aef01 bc6d94862eea2bc" /> _____________ 28.04.2018 11:21:54 (D) gajim.c.ged: stanza-sent Args: (<gajim.common.connection_handlers_events.StanzaSentEvent object at 0x06ebcf50>,) 28.04.2018 11:21:54 (I) nbxmpp.transports_nb: pollin called, state == CONNECTED 28.04.2018 11:21:54 (I) nbxmpp.idlequeue: read timeout removed for fd 1348 28.04.2018 11:21:54 (I) nbxmpp.client_nb: raising event from transport: :::::DATA RECEIVED:::: _____________ HTTP/1.1 200 OK Server: nginx/1.12.2 Date: Sat, 28 Apr 2018 09:21:55 GMT Content-Type: text/xml; charset=utf-8 Content-Length: 144 Connection: keep-alive Strict-Transport-Security: max-age=31536000; includeSubDomains X-Content-Type-Options: nosniff X-Frame-Options: DENY Referrer-Policy: strict-origin-when-cross-origin Content-Security-Policy: frame-ancestors 'none'; default-src 'none'; img-src https://bosh.jabberfr.org/favicon.ico; report-uri /report-csp-v iolation <body type='terminate' xmlns='http://jabber.org/protocol/httpbind' condition='item-not-found' xmlns:stream='http://etherx.jabber.org/streams '/>
Further logs which i didnt post Apr 28 11:21:55 anon.jabberfr.org:bosh warn Unable to associate request with a session (incomplete request?) Apr 28 11:21:55 anon.jabberfr.org:bosh debug Request destroyed: table: 0x55ec0192e140 Apr 28 11:21:55 socket debug try to close client connection with id: 55ebd1d70d50 Apr 28 11:21:55 socket debug closing delayed until writebuffer is empty Apr 28 11:21:55 socket debug closing client after writing Apr 28 11:21:55 socket debug closing client with id: 55ebd1d70d50 client to close
Thanks for the report. IIRC in the chatroom we determined that this is a regression casued by #402
ChangesWas this fixed by https://hg.prosody.im/trunk/rev/d5ff0982d3e6 ?
Changesseems not to fix the issue but the stanzas look now different _____________ POST / HTTP/1.1 Host: bosh.jabberfr.org:443 User-Agent: Gajim Content-Type: text/xml; charset=utf-8 Content-Length: 299 Connection: Keep-Alive <body xmlns="http://jabber.org/protocol/httpbind" content="text/xml; charset=utf-8" hold="1" route="xmpp:jabber.fr:5223" to="jabber.fr" wait ="30" xml:lang="de" xmpp:version="1.0" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" rid="103060377197309" ack="1" newkey="1133c6e679188d1ba60868b06 51fa97d8d958d04" /> _____________ 14.05.2018 18:35:49 (D) gajim.c.ged: stanza-sent Args: (<gajim.common.connection_handlers_events.StanzaSentEvent object at 0x09bf44d0>,) 14.05.2018 18:35:49 (I) nbxmpp.transports_nb: pollin called, state == CONNECTED 14.05.2018 18:35:49 (I) nbxmpp.idlequeue: read timeout removed for fd 1220 14.05.2018 18:35:49 (I) nbxmpp.client_nb: raising event from transport: :::::DATA RECEIVED:::: _____________ HTTP/1.1 404 Not Found Server: nginx/1.14.0 Date: Mon, 14 May 2018 16:35:49 GMT Content-Type: text/html; charset=utf-8 Content-Length: 422 Connection: keep-alive Strict-Transport-Security: max-age=31536000; includeSubDomains X-Content-Type-Options: nosniff X-Frame-Options: DENY Referrer-Policy: strict-origin-when-cross-origin Content-Security-Policy: frame-ancestors 'none'; default-src 'none'; img-src https://bosh.jabberfr.org/favicon.ico; report-uri /report-csp-v iolation <!DOCTYPE html> <html> <head> <meta charset="utf-8"> <title>404 Not Found</title> <style> body{ margin-top:14%; text-align:center; background-color:#F8F8F8; font-family:sans-serif; } h1{ font-size:xx-large; } p{ font-size:x-large; } p+p { font-size:large; font-family:courier; } </style> </head> <body> <h1>404 Not Found</h1> <p>Whatever you were looking for is not here. Keep looking.</p> <p></p> </body> </html> _____________ 14.05.2018 18:35:49 (D) gajim.c.ged: stanza-received Args: (<gajim.common.connection_handlers_events.StanzaReceivedEvent object at 0x09bf4a1 0>,) 14.05.2018 18:35:49 (E) nbxmpp.transports_nb: HTTP Error: 404 Not Found
Server Side May 14 18:35:49 socket debug accepted incoming client connection from: ::1 41748 to 5280 May 14 18:35:49 http.server debug Firing event: POST anon.jabberfr.org/http-bind/ May 14 18:35:49 anon.jabberfr.org:bosh debug Handling new request table: 0x55ebdf4dbfe0: <body xmlns="http://jabber.org/protocol/httpbind" content="text/xml; charset=utf-8" hold="1" route="xmpp:jabber.fr:5223" to="jabber.fr" wait="30" xml:lang="de" xmpp:version="1.0" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" rid="103060377197309" ack="1" newkey="1133c6e679188d1ba60868b0651fa97d8d958d04" /> ---------- May 14 18:35:49 anon.jabberfr.org:bosh debug BOSH body open (sid: <none>) May 14 18:35:49 anon.jabberfr.org:bosh debug Request destroyed: table: 0x55ec11369c80
Additional logging for this issue was added in https://hg.prosody.im/trunk/rev/f69b3e39e0c1 Is this still happening and if so, do the lines in the above change show up in the log?
Waiting for update on this. Bumping to 0.12.
ChangesI tested and we did not see either of these 2 new debug messages
Hi, I'm moved from 0.10.2 to trunk on Debian stretch via the prosody-provided trunk version (refreshed last night), and I realized bosh was no longer working. I had a look at the debug logs, and saw one of the messages that were added in the mentioned change: Ignoring this request. Note that I have a proxy redirection in place via my webserver towards port 5280, which worked well on 0.10.2. As a matter of fact, GET requests still work, only POST requests fail. See full log below: Sep 02 11:33:55 socket debug server.lua: accepted new client connection from 127.0.0.1:41276 to 5280 Sep 02 11:33:55 http.server debug Firing event: POST localhost/http-bind/ Sep 02 11:33:55 localhost:bosh debug Handling new request table: 0x55a07a0b8380: <body rid='123456' xmlns='http://jabber.org/protocol/httpbind' to='biboumail.fr' xml:lang='en' wait='60' hold='1' content='text/xml; charset=utf-8' ver='1.6' xmpp:version='1.0' xmlns:xmpp='urn:xmpp:xbosh'/> ---------- Sep 02 11:33:55 localhost:bosh debug BOSH body open (sid: <none>) Sep 02 11:33:55 localhost:bosh debug Ignoring this request Sep 02 11:33:55 localhost:bosh debug Request destroyed: table: 0x55a07a0b8820 Sep 02 11:33:56 biboumail.fr:mam debug Removing old messages for user "xmpp-test" Sep 02 11:33:57 socket debug server.lua: client 127.0.0.1:41276 read error: closed Sep 02 11:33:57 socket debug server.lua: closed client handler and removed socket from list
What configuration is involved?
Config files can be downloaded here: https://www.biboumail.fr/dl.php?file=MjI4OTdjOGRjMzQx I'm currently running "trunk nightly build 962 (2018-08-31, 83375ec33619)" on Debian Stretch, based on the Prosody repo. The main host is biboumail.fr, there is another one (brie.tech) with the same config (adapted to the host). I'm also running a web server (h2o) which redirects https://www.biboumail.fr/http-bind towards http://localhost:5280/http-bind This config worked perfectly well with 0.10.2.
Per your log you are talking to the host 'localhost'. It does not serve BOSH for 'biboumail.fr'. What you see is the fix for #371 working as intended. I believe this issue, #1134, to be about a case where the BOSH URL for all hosts really is configured to be identical, in which case dispatch to the correct host does not work as intended.
You're right, sorry for the noise… MattJ on the chatroom helped me realize there was some additional config needed at web server level to preserve the host while proxying, the behaviour of BOSH having changed due to #371 as you mentioned.
Did these changes help this issue? https://hg.prosody.im/trunk/log?rev=816591db764d%3A%3Aa6f54df39624
We need to know if the current state is working or if we need to revert something.
ChangesThis seems fixed on JabberFR.
Thanks
Changes