#986 Libevent breaks incoming s2s

Reporter Stas
Owner MattJ
Created
Updated
Stars ★★ (2)  
Tags
  • Status-New
  • Priority-Medium
  • Type-Defect
  1. Stas on

    1. Set up two identical XMPP servers with different DNS domains using Prosody. 2. Enable TLS s2s link between them. 3. Enable libevent on both ( use_libevent = true; ). 4. Try to send a message from one domain (server) to another domain (server) forth and back. Result: the message forth is delivered, the message back is not. The direction of successful delivery depends on the order of starting the servers. The latest started server can send messages, but can not receive. Disabling libevent solves this issue. Tested with Prosody-0.10 build 410, build 412 on Debian Stretch amd64.

  2. MattJ on

    Hi, thanks for the report! Libevent is working fine for numerous people, including s2s. Any large server requires it, and there are many of those around using s2s just fine. To diagnose your issue, it would help if you could provide some debug logs from s2s establishment (both directions), as well as some more details of your environment. Include the output of 'prosodyctl about' and your libevent package version.

  3. Stas on

    On the sending side everything is as usual, no warnings or errors: ******* Sep 11 18:45:28 c2s56fb7910 debug Received[c2s]: <message id='purple380f25e2' type='chat' to='stas@foo.bar/Virtual'> Sep 11 18:45:28 stanzarouter debug Routing to remote... Sep 11 18:45:28 s2sout5702ca90 debug going to send stanza to foo.bar from fake.domain Sep 11 18:45:28 s2sout5702ca90 debug sending: <message type='chat' to='stas@foo.bar/Virtual' from='stas@fake.domain/WorkPC' id='purple380f25e2'> Sep 11 18:45:28 s2sout5702ca90 debug stanza sent over s2sout ******** On the receiving side there is complete silence. Nothing at all. The same time, tcpdump (tcp packet sniffer) shows active traffic exchange between the two XMPP servers. s2s establishment: ***** Sep 11 18:26:18 s2sin57a7b1c0 debug Received[s2sin_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Sep 11 18:26:18 socket debug try to start ssl at client id: 579c7cc8 Sep 11 18:26:18 socket debug ssl session delayed until writebuffer is empty... Sep 11 18:26:18 s2sin57a7b1c0 debug TLS negotiation started for s2sin_unauthed... Sep 11 18:26:18 socket debug starting ssl handshake after writing Sep 11 18:26:18 socket debug starting handshake... Sep 11 18:26:18 socket debug ssl handshake of client with id:table: 0x579c7cc8, attempt:1 Sep 11 18:26:18 socket debug ssl handshake of client with id:table: 0x579c7cc8, attempt:2 Sep 11 18:26:18 socket debug ssl handshake of client with id:table: 0x579c7cc8, attempt:3 Sep 11 18:26:18 socket debug ssl handshake done Sep 11 18:26:18 s2sin57a7b1c0 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) Sep 11 18:26:18 s2sin57a7b1c0 debug Incoming s2s received <stream:stream to='fake.domain' from='foo.bar' xml:lang='en' xmlns='http://etherx.jabber.org/streams' version='1.0'> Sep 11 18:26:18 s2sin57a7b1c0 debug certificate chain validation result: valid Sep 11 18:26:18 x509 debug Cert dNSName foo.bar matched hostname Sep 11 18:26:18 s2sin57a7b1c0 debug certificate identity validation result: valid Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <?xml version='1.0'?> Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://e therx.jabber.org/streams' xml:lang='en' from='fake.domain' id='a8508b28-f7d5-4342-a708-d8edf3e0cfbd' to='foo.bar' version= '1.0' xmlns='jabber:server'> Sep 11 18:26:18 fake.domain:saslauth debug Offering SASL EXTERNAL Sep 11 18:26:18 mod_s2s debug Sending stream features: <stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp -sasl'><mechanism>EXTERNAL</mechanism></mechanisms><dialback xmlns='urn:xmpp:features:dialback'/></stream:features> Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <stream:features> Sep 11 18:26:18 s2sin57a7b1c0 debug Received[s2sin_unauthed]: <auth mechanism='EXTERNAL' xmlns='urn:ietf:params:xml: ns:xmpp-sasl'> Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Sep 11 18:26:18 fake.domain:saslauth info Accepting SASL EXTERNAL identity from foo.bar Sep 11 18:26:18 s2sin57a7b1c0 debug connection foo.bar->fake.domain is now authenticated for foo.bar Sep 11 18:26:18 s2sin57a7b1c0 info Incoming s2s connection foo.bar->fake.domain complete Sep 11 18:26:18 s2sin57a7b1c0 debug Incoming s2s received <stream:stream to='fake.domain' from='foo.bar' xml:lang='en' xmlns='http://etherx.jabber.org/streams' version='1.0'> Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <?xml version='1.0'?> Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://e therx.jabber.org/streams' xml:lang='en' from='fake.domain' id='79d51896-b3c2-4b2d-ba39-28edd8d62ef1' to='foo.bar' version= '1.0' xmlns='jabber:server'> Sep 11 18:26:18 mod_s2s debug Sending stream features: <stream:features><dialback xmlns='urn:xmpp:features:dialback'/> </stream:features> Sep 11 18:26:18 s2sin57a7b1c0 debug sending: <stream:features> ***** **** Sep 11 18:26:18 mod_s2s debug opening a new outgoing connection for this stanza Sep 11 18:26:18 mod_s2s debug stanza [presence] queued until connection complete Sep 11 18:26:18 mod_s2s debug First attempt to connect to fake.domain, starting with SRV lookup... Sep 11 18:26:18 adns debug Records for _xmpp-server._tcp.fake.domain. not in cache, sending query (thread: 0x80c64630) ... Sep 11 18:26:18 adns debug Sending DNS query to 192.168.0.65 Sep 11 18:26:18 stanzarouter debug Routing to remote... Sep 11 18:26:18 mod_s2s debug opening a new outgoing connection for this stanza Sep 11 18:26:18 s2sout80c63608 debug Received[s2sout_unauthed]: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Sep 11 18:26:18 foo.bar:tls debug Proceeding with TLS on s2sout... Sep 11 18:26:18 s2sout80c63608 debug Sending stream header... Sep 11 18:26:18 s2sout80c63608 debug sending: <?xml version='1.0'?> Sep 11 18:26:18 s2sout80c63608 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://e therx.jabber.org/streams' xml:lang='en' from='foo.bar' to='fake.domain' version='1.0' xmlns='jabber:server'> Sep 11 18:26:18 socket debug ssl handshake done Sep 11 18:26:18 s2sout80c63608 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) Sep 11 18:26:18 s2sout80c63608 debug certificate chain validation result: valid Sep 11 18:26:18 x509 debug Cert dNSName fake.domain matched hostname Sep 11 18:26:18 s2sout80c63608 debug certificate identity validation result: valid Sep 11 18:26:18 s2sout80c63608 debug Received[s2sout_unauthed]: <features xmlns='http://etherx.jabber.org/streams'> Sep 11 18:26:18 foo.bar:tls debug Received features element Sep 11 18:26:18 foo.bar:saslauth debug Initiating SASL EXTERNAL with fake.domain Sep 11 18:26:18 s2sout80c63608 debug sending: <auth mechanism='EXTERNAL' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Sep 11 18:26:18 s2sout80c63608 debug Received[s2sout_unauthed]: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Sep 11 18:26:18 foo.bar:saslauth debug SASL EXTERNAL with fake.domain succeeded Sep 11 18:26:18 s2sout80c63608 debug sending: <?xml version='1.0'?> Sep 11 18:26:18 s2sout80c63608 debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://e therx.jabber.org/streams' xml:lang='en' from='foo.bar' to='fake.domain' version='1.0' xmlns='jabber:server'> Sep 11 18:26:18 s2sout80c63608 debug connection foo.bar->fake.domain is now authenticated for fake.domain Sep 11 18:26:18 s2sout80c63608 debug Received[s2sout]: <features xmlns='http://etherx.jabber.org/streams'> Sep 11 18:26:18 foo.bar:tls debug Received features element Sep 11 18:26:18 s2sout80c63608 info Outgoing s2s connection foo.bar->fake.domain complete Sep 11 18:26:18 s2sout80c63608 debug sending 10 queued stanzas across new outgoing connection to fake.domain ******* prosodyctl about: ***** Prosody 0.10 nightly build 412 (2017-08-29, 85a60e863509) # Prosody directories Data directory: /var/lib/prosody Config directory: /etc/prosody Source directory: /usr/lib/prosody Plugin directories: /usr/lib/prosody/modules/ # Lua environment Lua version: Lua 5.1 Lua module search paths: /usr/lib/prosody/?.lua /usr/local/share/lua/5.1/?.lua /usr/local/share/lua/5.1/?/init.lua /usr/local/lib/lua/5.1/?.lua /usr/local/lib/lua/5.1/?/init.lua /usr/share/lua/5.1/?.lua /usr/share/lua/5.1/?/init.lua Lua C module search paths: /usr/lib/prosody/?.so /usr/local/lib/lua/5.1/?.so /usr/lib/i386-linux-gnu/lua/5.1/?.so /usr/lib/lua/5.1/?.so /usr/local/lib/lua/5.1/loadall.so LuaRocks: Not installed # Lua module versions lfs: LuaFileSystem 1.6.3 libevent: 2.0.21-stable luaevent: 0.4.4 lxp: LuaExpat 1.3.0 socket: LuaSocket 3.0-rc1 ssl: 0.6 ******* # dpkg --list | grep event libevent-2.0-5:i386 2.0.21-stable-3 lua-event:i386 0.4.3-2 # cat /etc/issue Debian GNU/Linux 9 \n \l # uname -a Linux xmpp 4.9.0-3-686-pae #1 SMP Debian 4.9.30-2+deb9u3 (2017-08-06) i686 GNU/Linux

  4. MattJ on

    Hi, thanks for the further information. For testing purposes, can you add to the global section of your config: network_default_read_size = "*a" and then test again with libevent enabled? Thanks!

    Changes
    • owner MattJ
  5. Stas on

    Excuse me for late answer. I confirm, the mentioned directive "network_default_read_size" resolves the issue when libevent is enabled. And one more refinement. The described bug appears only in multi-domain configurations. I mean, when prosody is configured to serve more than one virtual host.

New comment