#1134 BOSH broken in trunk

Reporter lovetox
Owner Nobody
Created
Updated
Stars ★★ (2)
Tags
  • Milestone-0.11
  • Type-Defect
  • Status-NeedInfo
  • Priority-Medium
  1. lovetox on

    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

  2. lovetox on

    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 '/>

  3. lovetox on

    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

  4. Zash on

    Thanks for the report. IIRC in the chatroom we determined that this is a regression casued by #402

    Changes
    • tags Milestone-0.11 Status-Accepted
  5. Zash on

    Was this fixed by https://hg.prosody.im/trunk/rev/d5ff0982d3e6 ?

    Changes
    • tags Status-NeedInfo
  6. lovetox on

    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

  7. 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

  8. 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?

  9. MattJ on

    Waiting for update on this. Bumping to 0.12.

    Changes
    • tags Milestone-0.12
  10. lovetox on

    I tested and we did not see either of these 2 new debug messages

  11. 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

  12. Zash on

    What configuration is involved?

  13. 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.

  14. 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.

  15. 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.

  16. Zash on

    Did these changes help this issue? https://hg.prosody.im/trunk/log?rev=816591db764d%3A%3Aa6f54df39624

  17. Zash on

    We need to know if the current state is working or if we need to revert something.

    Changes
    • tags Milestone-0.11

New comment

Not published. Used for spam prevention and optional update notifications.