#1040 Some prosody setups cannot connect to jabber.ccc.de (presumably ejabberd)

Reporter Andrey
Owner Zash
Created
Updated
Stars ★★ (2)
Tags
  • Priority-Medium
  • Type-Defect
  • Status-Invalid
  1. Andrey on

    What steps will reproduce the problem? Setup prosody as on trashserver.net or contact the admin for details. What is the expected output? After update to 0.10 all works as before. What do you see instead? No connection to jabber.ccc.de possible. What version of the product are you using? On what operating system? 0.10, I guess on GNU/Linux Please provide any additional information below. https://metalhead.club/@thomas/99002108402317915 --------- trashserver.de side logs: https://haste.tchncs.de/umehoquyas.xml --------- Nov 14 10:27:35 mod_s2s debug First attempt to connect to jabber.ccc.de, starting with SRV lookup... Nov 14 10:27:35 adns debug Records for _xmpp-server._tcp.jabber.ccc.de. not in cache, sending query (thread: 0x55ba9d252d60)... Nov 14 10:27:36 adns debug Reply for _xmpp-server._tcp.jabber.ccc.de. (thread: 0x55ba9d252d60) Nov 14 10:27:36 mod_s2s debug jabber.ccc.de has SRV records, handling... Nov 14 10:27:36 mod_s2s debug Best record found, will connect to jabberd.jabber.ccc.de.:5269 Nov 14 10:27:36 adns debug Records for jabberd.jabber.ccc.de. not in cache, sending query (thread: 0x55baa53a9560)... Nov 14 10:27:36 adns debug Records for jabberd.jabber.ccc.de. not in cache, sending query (thread: 0x55baa9ad9d00)... Nov 14 10:27:36 adns debug Reply for jabberd.jabber.ccc.de. (thread: 0x55baa53a9560) Nov 14 10:27:36 mod_s2s debug DNS reply for jabberd.jabber.ccc.de. gives us 146.255.57.229 Nov 14 10:27:36 adns debug Reply for jabberd.jabber.ccc.de. (thread: 0x55baa9ad9d00) Nov 14 10:27:36 mod_s2s debug DNS reply for jabberd.jabber.ccc.de. gives us 2a02:1b8:10:31::229 Nov 14 10:27:36 s2sout55baa50b65e0 debug Beginning new connection attempt to jabber.ccc.de ([146.255.57.229]:5269) Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 trashserver.net:tls debug jabber.ccc.de is offering TLS, taking up the offer... Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 s2sout55baa50b65e0 debug Beginning new connection attempt to jabber.ccc.de ([2a02:1b8:10:31::229]:5269) Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 trashserver.net:tls debug jabber.ccc.de is offering TLS, taking up the offer... Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 s2sout55baa50b65e0 info Connection failed (out of IP addresses). Attempt #2: This time to jabberd-ipv6.jabber.ccc.de.:5269 Nov 14 10:27:36 adns debug Records for jabberd-ipv6.jabber.ccc.de. not in cache, sending query (thread: 0x55baa7aa0950)... Nov 14 10:27:36 adns debug Records for jabberd-ipv6.jabber.ccc.de. not in cache, sending query (thread: 0x55ba8d3d9cc0)... Nov 14 10:27:36 adns debug Reply for jabberd-ipv6.jabber.ccc.de. (thread: 0x55baa7aa0950) Nov 14 10:27:36 adns debug Reply for jabberd-ipv6.jabber.ccc.de. (thread: 0x55ba8d3d9cc0) Nov 14 10:27:36 mod_s2s debug DNS reply for jabberd-ipv6.jabber.ccc.de. gives us 2a02:1b8:10:31::229 Nov 14 10:27:36 s2sout55baa50b65e0 debug Beginning new connection attempt to jabber.ccc.de ([2a02:1b8:10:31::229]:5269) Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 trashserver.net:tls debug jabber.ccc.de is offering TLS, taking up the offer... Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 s2sout55baa50b65e0 info Connection failed (out of IP addresses). Attempt #3: This time to jabberd-ipv4.jabber.ccc.de.:5269 Nov 14 10:27:36 adns debug Records for jabberd-ipv4.jabber.ccc.de. not in cache, sending query (thread: 0x55baa909e190)... Nov 14 10:27:36 adns debug Records for jabberd-ipv4.jabber.ccc.de. not in cache, sending query (thread: 0x55baa2963760)... Nov 14 10:27:36 adns debug Reply for jabberd-ipv4.jabber.ccc.de. (thread: 0x55baa909e190) Nov 14 10:27:36 mod_s2s debug DNS reply for jabberd-ipv4.jabber.ccc.de. gives us 146.255.57.229 Nov 14 10:27:36 adns debug Reply for jabberd-ipv4.jabber.ccc.de. (thread: 0x55baa2963760) Nov 14 10:27:36 s2sout55baa50b65e0 debug Beginning new connection attempt to jabber.ccc.de ([146.255.57.229]:5269) Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 trashserver.net:tls debug jabber.ccc.de is offering TLS, taking up the offer... Nov 14 10:27:36 s2sout55baa50b65e0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 14 10:27:36 s2sout55baa50b65e0 info Failed in all attempts to connect to jabber.ccc.de Nov 14 10:27:36 mod_s2s debug No other records to try for jabber.ccc.de - destroying Nov 14 10:27:36 s2sout55baa50b65e0 debug Destroying outgoing session trashserver.net->jabber.ccc.de: Connecting failed: closed Nov 14 10:27:36 s2sout55baa50b65e0 info Sending error replies for 1 queued stanzas because of failed outgoing connection to jabber.ccc.de ------ jabber.ccc.de side logs: https://haste.tchncs.de/xisigunaya.coffee ------- ### ### Server: jabber.ccc.de ### ### ### Outbound connections ### 2017-10-16 07:13:59.526 [info] <0.27173.16>@ejabberd_s2s_out:init:279 Outbound s2s connection started: jabber.ccc.de -> conference.trashserver.net 2017-10-16 07:13:59.672 [info] <0.27173.16>@ejabberd_s2s_out:handle_auth_success:218 (tls|<0.27174.16>) Accepted outbound s2s EXTERNAL authentication jabber.ccc.de -> conference.trashserver.net (5.1.76.122) 2017-10-16 07:17:02.756 [info] <0.27173.16>@ejabberd_s2s_out:process_closed:155 Closing outbound s2s connection jabber.ccc.de -> conference.trashserver.net: Connection failed: connection closed ### (no more error messages in between) ### ### Incoming connections: ### 2017-10-16 06:47:45.888 [info] <0.270.0>@ejabberd_listener:accept:302 (<0.25832.15>) Accepted connection 5.1.76.122:53562 -> 146.255.57.229:5269 ----------------------- I've heard from another prosody user, who has lost connection to jabber.ccc.de. P.S. This a very prominent timestamp: Valid from 2017-10-15 19:35:33 UTC, because since then jabber.ccc.de switched at last(!) to Let's Encrypt Certificate.

  2. Zash on

    The log appears to be incomplete, possibly filtered. More context from between those lines are needed.

    Changes
    • tags Status-NeedInfo
  3. Thomas L. on

    Hi everybody, I'm the maintainer of trashserver.net. Thanks to Andrey for reporting this issue! Indeed the log above is not complete. Here's a complete debug log: https://haste.tchncs.de/raw/vinicegoka You can find trashserver.net's configuration here: https://haste.tchncs.de/raw/awujepayos I hope this helps to find the source of the problem. As far as I can tell only connection to jabber.ccc.de (running on Ejabberd) is affected by the problem. Connection jabber.ccc.de => trashserver.net works Connection trashserver.net => jabber.ccc.de does NOT work. There seem to be no problems with other Prosody / Ejabberd servers. (?).

  4. Zash on

    Here it appears as if your server is opening a new stream before the TLS handshake has been completed. If that goes out over the wire, unencrypted, it would break the connection. Nov 18 10:28:40 socket debug ssl handshake of client with id:table: 0x55baa027ab20, attempt:2 Nov 18 10:28:40 s2sout55baadf03540 debug Sending stream header... Nov 18 10:28:40 s2sout55baadf03540 debug sending: <?xml version='1.0'?> Nov 18 10:28:40 s2sout55baadf03540 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' xml:lang='en' from='trashserver.net' to='jabber.ccc.de' version='1.0' xmlns='jabber:server'> Nov 18 10:28:40 socket debug ssl handshake done Nov 18 10:28:40 socket debug connection failed in write event: closed Nov 18 10:28:40 socket debug closing client with id: 55baa027ab20 closed Nov 18 10:28:40 s2sout55baadf03540 debug s2s connection attempt failed: closed

  5. Andrey on

    Now looking at * https://check.messaging.one/result.php?domain=trashserver.net&type=server * https://check.messaging.one/result.php?domain=jabber.ccc.de&type=server there is obviously no overlap in cipher suites. And this has been already reported previously: https://prosody.im/issues/879 https://prosody.im/issues/943 https://prosody.im/issues/951 https://prosody.im/issues/963 Thus the workaround is known: lower security by adding also cipher-suites without PFS (the last HIGH before forbidden suites): - ciphers = "HIGH+kEDH:HIGH+kEECDH:!PSK:!SRP:!3DES:!aNULL"; + ciphers = "HIGH+kEDH:HIGH+kEECDH:HIGH:!PSK:!SRP:!3DES:!aNULL"; Meanwhile on September, 26. lua-sec 0.7alpha has been released. Zash, this suspicious thing in the debug log (and perhaps the main of not identifying the likely reason instantly) is, why prosody opens an unencrypted connection during the ssl handshake, which then appears to be done instead of failing (and then connection fails in a very mysterious way)?

  6. Thomas L. on

    Yes, that solved it! Connection works again! :) More detailed error logging would be nice in this case. Thank you very much, Andrey! Kind regards, Thomas

  7. Zash on

    That suspicious thing could just as well be two unrelated connections doing things at the same time. Or some buffered write that's perfectly fine. So this was a configuration issue? I'll close this then. OpenSSL does not simply let you have useful error messages.

    Changes
    • owner Zash
    • tags Status-Invalid
  8. Andrey on

    > If that goes out over the wire ... > Or some buffered write that's perfectly fine. So prosody logs are not helpful to debug such issues? Could you suggest something else? > So this was a configuration issue? I'll close this then. The original issue, I guess, yes. But why prosody didn't report something like: "Client disconnected: ssl handshake error: no shared cipher" as in https://prosody.im/issues/963?

  9. Zash on

    Since it says "closed", that's all it knows, that the connection was closed. The error might be at the other end or maybe doesn't even get communicated out of OpenSSL/LuaSec. Packet capture might help.

New comment

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