#499 Random disconnections to another XMPP server using CNAMEs
Reporter
nintux
Owner
MattJ
Created
Updated
Stars
★ (1)
Tags
Priority-Medium
Status-Fixed
Milestone-0.9
Type-Defect
nintux
on
My server Nekmo.org using Prosody 0.9.8 has random disconnections to another server, but only to MUC.
May 28 00:12:00 salas.nekmo.org:saslauth info Accepting SASL EXTERNAL identity from jabberes.org
May 28 00:12:00 s2sin328ae40 info incoming s2s connection jabberes.org->salas.nekmo.org complete
May 28 00:24:58 s2sout2c38ca0 info Out of connection options, can't connect to conf.jabberes.org
May 28 00:24:58 s2sout2c38ca0 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org
May 28 00:25:11 s2sout2541d60 info Out of connection options, can't connect to conf.jabberes.org
May 28 00:25:11 s2sout2541d60 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org
May 28 00:25:16 s2sout2d29a90 info Beginning new connection attempt to conf.jabberes.org ([95.211.10.153]:5269)
May 28 00:25:16 s2sout2d29a90 info outgoing s2s connection nekmo.org->conf.jabberes.org complete
May 28 00:26:46 s2sin3631b70 info incoming s2s stream conf.jabberes.org->nekmo.org closed: connection-timeout
May 28 00:51:09 salas.nekmo.org:saslauth info Accepting SASL EXTERNAL identity from jabberes.org
May 28 00:51:09 s2sin223b200 info incoming s2s connection jabberes.org->salas.nekmo.org complete
May 28 00:51:09 s2sout27caa10 info Beginning new connection attempt to jabberes.org ([95.211.10.153]:5269)
May 28 00:51:10 s2sout27caa10 info outgoing s2s connection salas.nekmo.org->jabberes.org complete
May 28 00:52:27 nekmo.org:saslauth info Accepting SASL EXTERNAL identity from jabberes.org
May 28 00:52:27 s2sin23898b0 info incoming s2s connection jabberes.org->nekmo.org complete
May 28 00:52:39 s2sin319fd30 info incoming s2s stream jabberes.org->salas.nekmo.org closed: connection-timeout
May 28 00:58:50 s2sout273fd90 info Out of connection options, can't connect to conf.jabberes.org
May 28 00:58:50 s2sout273fd90 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org
I think the important line here is:
Out of connection options, can't connect to conf.jabberes.org
This domain does not have SRV, but has DNS alias:
$ host conf.jabberes.org
conf.jabberes.org is an alias for jabberes.org.
jabberes.org has address 95.211.10.153
This error occurs randomly and after several hours (only affects the connection to the remote MUC, conf.jabberes.org). Before everything works fine.
Hi, thanks for the report!
Any chance you could enable debug logging? At the info level it doesn't log individual attempts, or DNS lookups etc., which would all be useful in trying to solve this.
You can enable debug logging in your config, and reload - no need to restart Prosody.
Changes
owner MattJ
nintux
on
Ok, I have enabled debug. I will write again when I have more information. Thanks :)
nintux
on
I filtered through everything that happened at 02:37:xx. Everything happens in the second 46.
May 28 02:37:46 s2sin23ab680 debug Destroying incomplete session conf.jabberes.org->nekmo.org due to inactivity
May 28 02:37:46 s2sin23ab680 debug Disconnecting (unknown host)[s2sin_unauthed], <stream:error> is: connection-timeout
May 28 02:37:46 mod_s2s debug sending: <stream:error>
May 28 02:37:46 mod_s2s debug sending: </stream:stream>
May 28 02:37:46 s2sin23ab680 info incoming s2s stream conf.jabberes.org->nekmo.org closed: connection-timeout
May 28 02:37:46 s2sin23ab680 debug Destroying incoming session conf.jabberes.org->nekmo.org: connection-timeout
May 28 02:37:46 s2sin23ab680 debug s2s disconnected: nil->nil (connection closed)
May 28 02:37:46 socket debug server.lua: closed client handler and removed socket from list
May 28 02:37:46 socket debug server.lua: accepted new client connection from 95.211.10.153:59459 to 5269
May 28 02:37:46 s2sin219e1c0 debug Incoming s2s connection
May 28 02:37:46 s2sin219e1c0 debug Incoming s2s received <stream:stream xmlns='http://etherx.jabber.org/streams' version='1.0' to='nekmo.org' from='conf.jabberes.org'>
May 28 02:37:46 mod_s2s debug sending: <?xml version='1.0'?>
May 28 02:37:46 mod_s2s debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='nekmo.org' id='38b2cbb3-90af-4d38-aa01-0694fe197ccd' to='conf.jabberes.org' xml:lang='en' xmlns='jabber:server'>
May 28 02:37:46 mod_s2s debug Sending stream features: <stream:features><dialback xmlns='urn:xmpp:features:dialback'/><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/></stream:features>
May 28 02:37:46 mod_s2s debug sending: <stream:features>
May 28 02:37:46 s2sin219e1c0 debug Received[s2sin_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
May 28 02:37:46 mod_s2s debug sending: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
May 28 02:37:46 socket debug server.lua: we need to do tls, but delaying until send buffer empty
May 28 02:37:46 s2sin219e1c0 debug TLS negotiation started for s2sin_unauthed...
May 28 02:37:46 socket debug server.lua: attempting to start tls on tcp{client}: 0x2228878
May 28 02:37:46 socket debug server.lua: ssl handshake done
May 28 02:37:46 s2sin219e1c0 debug Incoming s2s received <stream:stream xmlns='http://etherx.jabber.org/streams' version='1.0' to='nekmo.org' from='conf.jabberes.org'>
May 28 02:37:46 s2sin219e1c0 debug certificate chain validation result: valid
May 28 02:37:46 s2sin219e1c0 debug certificate identity validation result: invalid
May 28 02:37:46 mod_s2s debug sending: <?xml version='1.0'?>
May 28 02:37:46 mod_s2s debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='nekmo.org' id='56b76a70-bc6e-42be-9940-6c548d046c4c' to='conf.jabberes.org' xml:lang='en' xmlns='jabber:server'>
May 28 02:37:46 mod_s2s debug Sending stream features: <stream:features><dialback xmlns='urn:xmpp:features:dialback'/></stream:features>
May 28 02:37:46 mod_s2s debug sending: <stream:features>
May 28 02:37:46 s2sin219e1c0 debug Received[s2sin_unauthed]: <result xmlns='jabber:server:dialback' to='nekmo.org' from='conf.jabberes.org'>
May 28 02:37:46 s2sin219e1c0 debug asking conf.jabberes.org if key 1944865565 belongs to them
May 28 02:37:46 mod_s2s debug opening a new outgoing connection for this stanza
May 28 02:37:46 mod_s2s debug stanza [db:verify] queued until connection complete
May 28 02:37:46 mod_s2s debug First attempt to connect to conf.jabberes.org, starting with SRV lookup...
May 28 02:37:46 adns debug Records for _xmpp-server._tcp.conf.jabberes.org. not in cache, sending query (thread: 0x2f83080)...
May 28 02:37:46 adns debug Sending DNS query to 213.186.33.99
May 28 02:37:46 socket debug server.lua: closed client handler and removed socket from list
May 28 02:37:46 adns debug Reply for _xmpp-server._tcp.conf.jabberes.org. (thread: 0x2f83080)
May 28 02:37:46 mod_s2s debug conf.jabberes.org has no SRV records, falling back to A/AAAA
May 28 02:37:46 adns debug Records for conf.jabberes.org not in cache, sending query (thread: 0x3504110)...
May 28 02:37:46 adns debug Sending DNS query to 213.186.33.99
May 28 02:37:46 adns debug Records for conf.jabberes.org not in cache, sending query (thread: 0x2c153f0)...
May 28 02:37:46 adns debug Sending DNS query to 213.186.33.99
May 28 02:37:46 adns debug Reply for conf.jabberes.org (thread: 0x3504110)
May 28 02:37:46 mod_s2s debug Looking up jabberes.org. (DNS depth is 3)
May 28 02:37:46 socket debug server.lua: closed client handler and removed socket from list
May 28 02:37:46 adns debug Reply for conf.jabberes.org (thread: 0x2c153f0)
May 28 02:37:46 mod_s2s debug DNS lookup failed to get a response for conf.jabberes.org
May 28 02:37:46 s2sout22a1440 info Out of connection options, can't connect to conf.jabberes.org
May 28 02:37:46 mod_s2s debug No other records to try for conf.jabberes.org - destroying
May 28 02:37:46 s2sout22a1440 debug Destroying outgoing session nekmo.org->conf.jabberes.org: DNS resolution failed
May 28 02:37:46 s2sout22a1440 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org
nintux
on
I think the reason may be that conf.jabberes.org is an alias and not a record A.
MattJ
on
Correct, CNAME is the issue (you are not the first to report the problem).
We have been working to fix this, and would appreciate it if you could try the latest nightly builds: https://prosody.im/nightly/0.9/
As soon as we are sure that the issue is solved, we will release it as 0.9.9.
Changes
tags Status-Accepted
title Random disconnections to another XMPP server using CNAMEs
My server Nekmo.org using Prosody 0.9.8 has random disconnections to another server, but only to MUC. May 28 00:12:00 salas.nekmo.org:saslauth info Accepting SASL EXTERNAL identity from jabberes.org May 28 00:12:00 s2sin328ae40 info incoming s2s connection jabberes.org->salas.nekmo.org complete May 28 00:24:58 s2sout2c38ca0 info Out of connection options, can't connect to conf.jabberes.org May 28 00:24:58 s2sout2c38ca0 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org May 28 00:25:11 s2sout2541d60 info Out of connection options, can't connect to conf.jabberes.org May 28 00:25:11 s2sout2541d60 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org May 28 00:25:16 s2sout2d29a90 info Beginning new connection attempt to conf.jabberes.org ([95.211.10.153]:5269) May 28 00:25:16 s2sout2d29a90 info outgoing s2s connection nekmo.org->conf.jabberes.org complete May 28 00:26:46 s2sin3631b70 info incoming s2s stream conf.jabberes.org->nekmo.org closed: connection-timeout May 28 00:51:09 salas.nekmo.org:saslauth info Accepting SASL EXTERNAL identity from jabberes.org May 28 00:51:09 s2sin223b200 info incoming s2s connection jabberes.org->salas.nekmo.org complete May 28 00:51:09 s2sout27caa10 info Beginning new connection attempt to jabberes.org ([95.211.10.153]:5269) May 28 00:51:10 s2sout27caa10 info outgoing s2s connection salas.nekmo.org->jabberes.org complete May 28 00:52:27 nekmo.org:saslauth info Accepting SASL EXTERNAL identity from jabberes.org May 28 00:52:27 s2sin23898b0 info incoming s2s connection jabberes.org->nekmo.org complete May 28 00:52:39 s2sin319fd30 info incoming s2s stream jabberes.org->salas.nekmo.org closed: connection-timeout May 28 00:58:50 s2sout273fd90 info Out of connection options, can't connect to conf.jabberes.org May 28 00:58:50 s2sout273fd90 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org I think the important line here is: Out of connection options, can't connect to conf.jabberes.org This domain does not have SRV, but has DNS alias: $ host conf.jabberes.org conf.jabberes.org is an alias for jabberes.org. jabberes.org has address 95.211.10.153 This error occurs randomly and after several hours (only affects the connection to the remote MUC, conf.jabberes.org). Before everything works fine.
AttachmentsHi, thanks for the report! Any chance you could enable debug logging? At the info level it doesn't log individual attempts, or DNS lookups etc., which would all be useful in trying to solve this. You can enable debug logging in your config, and reload - no need to restart Prosody.
ChangesOk, I have enabled debug. I will write again when I have more information. Thanks :)
I filtered through everything that happened at 02:37:xx. Everything happens in the second 46. May 28 02:37:46 s2sin23ab680 debug Destroying incomplete session conf.jabberes.org->nekmo.org due to inactivity May 28 02:37:46 s2sin23ab680 debug Disconnecting (unknown host)[s2sin_unauthed], <stream:error> is: connection-timeout May 28 02:37:46 mod_s2s debug sending: <stream:error> May 28 02:37:46 mod_s2s debug sending: </stream:stream> May 28 02:37:46 s2sin23ab680 info incoming s2s stream conf.jabberes.org->nekmo.org closed: connection-timeout May 28 02:37:46 s2sin23ab680 debug Destroying incoming session conf.jabberes.org->nekmo.org: connection-timeout May 28 02:37:46 s2sin23ab680 debug s2s disconnected: nil->nil (connection closed) May 28 02:37:46 socket debug server.lua: closed client handler and removed socket from list May 28 02:37:46 socket debug server.lua: accepted new client connection from 95.211.10.153:59459 to 5269 May 28 02:37:46 s2sin219e1c0 debug Incoming s2s connection May 28 02:37:46 s2sin219e1c0 debug Incoming s2s received <stream:stream xmlns='http://etherx.jabber.org/streams' version='1.0' to='nekmo.org' from='conf.jabberes.org'> May 28 02:37:46 mod_s2s debug sending: <?xml version='1.0'?> May 28 02:37:46 mod_s2s debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='nekmo.org' id='38b2cbb3-90af-4d38-aa01-0694fe197ccd' to='conf.jabberes.org' xml:lang='en' xmlns='jabber:server'> May 28 02:37:46 mod_s2s debug Sending stream features: <stream:features><dialback xmlns='urn:xmpp:features:dialback'/><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/></stream:features> May 28 02:37:46 mod_s2s debug sending: <stream:features> May 28 02:37:46 s2sin219e1c0 debug Received[s2sin_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> May 28 02:37:46 mod_s2s debug sending: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'> May 28 02:37:46 socket debug server.lua: we need to do tls, but delaying until send buffer empty May 28 02:37:46 s2sin219e1c0 debug TLS negotiation started for s2sin_unauthed... May 28 02:37:46 socket debug server.lua: attempting to start tls on tcp{client}: 0x2228878 May 28 02:37:46 socket debug server.lua: ssl handshake done May 28 02:37:46 s2sin219e1c0 debug Incoming s2s received <stream:stream xmlns='http://etherx.jabber.org/streams' version='1.0' to='nekmo.org' from='conf.jabberes.org'> May 28 02:37:46 s2sin219e1c0 debug certificate chain validation result: valid May 28 02:37:46 s2sin219e1c0 debug certificate identity validation result: invalid May 28 02:37:46 mod_s2s debug sending: <?xml version='1.0'?> May 28 02:37:46 mod_s2s debug sending: <stream:stream xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='nekmo.org' id='56b76a70-bc6e-42be-9940-6c548d046c4c' to='conf.jabberes.org' xml:lang='en' xmlns='jabber:server'> May 28 02:37:46 mod_s2s debug Sending stream features: <stream:features><dialback xmlns='urn:xmpp:features:dialback'/></stream:features> May 28 02:37:46 mod_s2s debug sending: <stream:features> May 28 02:37:46 s2sin219e1c0 debug Received[s2sin_unauthed]: <result xmlns='jabber:server:dialback' to='nekmo.org' from='conf.jabberes.org'> May 28 02:37:46 s2sin219e1c0 debug asking conf.jabberes.org if key 1944865565 belongs to them May 28 02:37:46 mod_s2s debug opening a new outgoing connection for this stanza May 28 02:37:46 mod_s2s debug stanza [db:verify] queued until connection complete May 28 02:37:46 mod_s2s debug First attempt to connect to conf.jabberes.org, starting with SRV lookup... May 28 02:37:46 adns debug Records for _xmpp-server._tcp.conf.jabberes.org. not in cache, sending query (thread: 0x2f83080)... May 28 02:37:46 adns debug Sending DNS query to 213.186.33.99 May 28 02:37:46 socket debug server.lua: closed client handler and removed socket from list May 28 02:37:46 adns debug Reply for _xmpp-server._tcp.conf.jabberes.org. (thread: 0x2f83080) May 28 02:37:46 mod_s2s debug conf.jabberes.org has no SRV records, falling back to A/AAAA May 28 02:37:46 adns debug Records for conf.jabberes.org not in cache, sending query (thread: 0x3504110)... May 28 02:37:46 adns debug Sending DNS query to 213.186.33.99 May 28 02:37:46 adns debug Records for conf.jabberes.org not in cache, sending query (thread: 0x2c153f0)... May 28 02:37:46 adns debug Sending DNS query to 213.186.33.99 May 28 02:37:46 adns debug Reply for conf.jabberes.org (thread: 0x3504110) May 28 02:37:46 mod_s2s debug Looking up jabberes.org. (DNS depth is 3) May 28 02:37:46 socket debug server.lua: closed client handler and removed socket from list May 28 02:37:46 adns debug Reply for conf.jabberes.org (thread: 0x2c153f0) May 28 02:37:46 mod_s2s debug DNS lookup failed to get a response for conf.jabberes.org May 28 02:37:46 s2sout22a1440 info Out of connection options, can't connect to conf.jabberes.org May 28 02:37:46 mod_s2s debug No other records to try for conf.jabberes.org - destroying May 28 02:37:46 s2sout22a1440 debug Destroying outgoing session nekmo.org->conf.jabberes.org: DNS resolution failed May 28 02:37:46 s2sout22a1440 info Sending error replies for 1 queued stanzas because of failed outgoing connection to conf.jabberes.org
I think the reason may be that conf.jabberes.org is an alias and not a record A.
Correct, CNAME is the issue (you are not the first to report the problem). We have been working to fix this, and would appreciate it if you could try the latest nightly builds: https://prosody.im/nightly/0.9/ As soon as we are sure that the issue is solved, we will release it as 0.9.9.
ChangesOk, I installed from mercurial using this PKGBUILD. https://aur.archlinux.org/packages/pr/prosody-hg/PKGBUILD I've modified "trunk" with "0.9". I think that should be enough. I'll tell you what's new. Thanks :)
I have a few days using the latest version of mercurial (0.9) and seems to work fine :)
Excellent, thanks! Considering this issue fixed in https://hg.prosody.im/0.9/rev/45222bfb206f It will be released in 0.9.9 soon.
Changes