Tigase Forge
Dashboards
Projects
Pull Requests
Issues
Builds
Packages
Code Search
server-core
Code
Pull Requests
Issues
List
Boards
Iterations
Builds
Packages
Statistics
Child Projects
OneDev 11.5.2
Documentation Support & Bug Report RESTful API Incompatibilities License Agreement Check Update
Projects tigase _server server-core Issues #1175
Connection with diebesban.de stopped with invalid-namespace error (#1175)
wojciech.kapcia@tigase.net opened 4 years ago
Affected versions
tigase-issue #8.0.0

Reported in our MUC
wojciech.kapcia@tigase.net commented 4 years ago

Logs from the reporter:

grep s2sin5565a354ff30 /var/log/prosody/prosody.debug
Jul 28 07:58:24 s2sin5565a354ff30       debug   Incoming s2s connection
Jul 28 07:58:24 s2sin5565a354ff30       debug   Incoming s2s received <stream:stream version='1.0' from='push.tigase.im' to='diebesban.de' xmlns='http://etherx.jabber.org/streams'>
Jul 28 07:58:24 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <?xml version='1.0'?>
Jul 28 07:58:24 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <stream:stream version='1.0' from='diebesban.de' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xml:lang='en' to='push.tigase.im' id='459d51d9-9c16-415e-a51c-4c572f82da4a'>
Jul 28 07:58:24 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <stream:features>
Jul 28 07:58:24 s2sin5565a354ff30       debug   SEND: <stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'><required/></starttls></stream:features>
Jul 28 07:58:24 s2sin5565a354ff30       debug   RECV: <starttls xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
Jul 28 07:58:24 s2sin5565a354ff30       debug   Received[s2sin_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls' xml:lang='en'>
Jul 28 07:58:24 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
Jul 28 07:58:24 s2sin5565a354ff30       debug   SEND: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
Jul 28 07:58:24 s2sin5565a354ff30       debug   TLS negotiation started for s2sin_unauthed...
Jul 28 07:58:25 s2sin5565a354ff30       info    Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384)
Jul 28 07:58:25 s2sin5565a354ff30       debug   Incoming s2s received <stream:stream version='1.0' from='push.tigase.im' to='diebesban.de' xmlns='http://etherx.jabber.org/streams'>
Jul 28 07:58:25 s2sin5565a354ff30       debug   certificate chain validation result: valid
Jul 28 07:58:25 s2sin5565a354ff30       debug   certificate identity validation result: valid
Jul 28 07:58:25 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <?xml version='1.0'?>
Jul 28 07:58:25 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <stream:stream version='1.0' from='diebesban.de' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xml:lang='en' to='push.tigase.im' id='900605df-8d52-4a22-9105-92b365480969'>
Jul 28 07:58:25 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <stream:features>
Jul 28 07:58:25 s2sin5565a354ff30       debug   SEND: <stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>EXTERNAL</mechanism></mechanisms><bidi xmlns='urn:xmpp:features:bidi'/></stream:features>
Jul 28 07:58:25 s2sin5565a354ff30       debug   RECV: <auth mechanism='EXTERNAL' xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>=</auth>
Jul 28 07:58:25 s2sin5565a354ff30       debug   Received[s2sin_unauthed]: <auth mechanism='EXTERNAL' xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jul 28 07:58:25 s2sin5565a354ff30       debug   Sending[s2sin_unauthed]: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Jul 28 07:58:25 s2sin5565a354ff30       debug   SEND: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>
Jul 28 07:58:25 s2sin5565a354ff30       debug   connection push.tigase.im->diebesban.de is now authenticated for push.tigase.im
Jul 28 07:58:25 s2sin5565a354ff30       info    Incoming s2s connection push.tigase.im->diebesban.de complete
Jul 28 07:58:25 s2sin5565a354ff30       debug   Incoming s2s received <stream:stream version='1.0' from='push.tigase.im' to='diebesban.de' xmlns='http://etherx.jabber.org/streams'>
Jul 28 07:58:25 s2sin5565a354ff30       debug   Sending[s2sin]: <?xml version='1.0'?>
Jul 28 07:58:25 s2sin5565a354ff30       debug   Sending[s2sin]: <stream:stream version='1.0' from='diebesban.de' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xml:lang='en' to='push.tigase.im' id='39b23db9-c66b-4ef8-bd17-4965020fbb6e'>
Jul 28 07:58:25 s2sin5565a354ff30       debug   Sending[s2sin]: <stream:features>
Jul 28 07:58:25 s2sin5565a354ff30       debug   SEND: <stream:features/>
Jul 28 07:58:26 s2sin5565a354ff30       debug   RECV: <iq type='result' from='push.tigase.im' xml:lang='en' to='diebesban.de' id='efcbf378b1df67a21a41a92a77941ae1c03943f913cae94978330c862e04eaf2'/>
Jul 28 07:58:26 s2sin5565a354ff30       debug   Received[s2sin]: <iq type='result' from='push.tigase.im' xml:lang='en' to='diebesban.de' id='efcbf378b1df67a21a41a92a77941ae1c03943f913cae94978330c862e04eaf2'>
Jul 28 07:58:26 s2sin5565a354ff30       info    Session closed by remote with error: invalid-namespace
Jul 28 07:58:26 s2sin5565a354ff30       debug   Sending[s2sin]: </stream:stream>
Jul 28 07:58:26 s2sin5565a354ff30       info    Incoming s2s stream push.tigase.im->diebesban.de closed: invalid-namespace
Jul 28 07:58:26 s2sin5565a354ff30       debug   Destroying incoming session push.tigase.im->diebesban.de: invalid-namespace
Jul 28 07:58:26 s2sin5565a354ff30       debug   Discarding data received from resting session: table: 0x5565a5663340
Jul 28 07:58:26 s2sin5565a354ff30       debug   s2s disconnected: <nil>-><nil> (closed)

In our logs there is following log:

[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] XMPPIOService.processSocketData(): CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, READ:<?xml version='1.0'?><stream:stream version='1.0' from='diebesban.de' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xml:lang='en' to='push.tigase.im' id='e5fe7f30-31ef-4bed-9129-00c7fb6fcffe'><stream:features/>
[2020-07-28 11:14:18:582] [FINER   ] [      pool-30-thread-5 ] S2SConnectionManager.xmppStreamOpened(): CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Stream opened: {xmlns:stream=http://etherx.jabber.org/streams, xmlns=jabber:server, xml:lang=en, from=diebesban.de, to=push.tigase.im, id=e5fe7f30-31ef-4bed-9129-00c7fb6fcffe, version=1.0}
[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] StreamOpen.streamOpened()        : CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Connect Stream opened for: push.tigase.im@diebesban.de, session ide5fe7f30-31ef-4bed-9129-00c7fb6fcffe
[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] StreamOpen.streamOpened()        : CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, stream open for cid: push.tigase.im@diebesban.de, outgoint: 1, incoming: 1
[2020-07-28 11:14:18:582] [FINER   ] [      pool-30-thread-5 ] S2SConnectionManager.xmppStreamOpened(): CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Sending stream open:
[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] XMPPIOService.xmppStreamOpened() : CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Sending data: null
[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] XMPPIOService.moveParsedPacketsToReceived(): CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Read packet: <features xmlns="http://etherx.jabber.org/streams"/>
[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] S2SConnectionManager.processSocketData(): Processing socket data: from=null, to=null, DATA=<features xmlns="http://etherx.jabber.org/streams"/>, SIZE=52, XMLNS=http://etherx.jabber.org/streams, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
[2020-07-28 11:14:18:582] [FINER   ] [      pool-30-thread-5 ] PacketChecker.filter()           : CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Invalid namespace for packet: from=null, to=null, DATA=<features xmlns="http://etherx.jabber.org/streams"/>, SIZE=52, XMLNS=http://etherx.jabber.org/streams, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] S2SAbstract.generateStreamError(): CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Sending stream error: <stream:error><invalid-namespace xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
java.lang.Throwable
        at tigase.server.xmppserver.proc.S2SAbstract.generateStreamError(S2SAbstract.java:81)
        at tigase.server.xmppserver.proc.PacketChecker.filter(PacketChecker.java:122)
        at tigase.server.xmppserver.S2SConnectionManager.processSocketData(S2SConnectionManager.java:289)
        at tigase.server.xmppserver.S2SConnectionManager.processSocketData(S2SConnectionManager.java:50)
        at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:347)
        at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:61)
        at tigase.net.IOService.call(IOService.java:197)
        at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:146)
        at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:51)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:834)
wojciech.kapcia@tigase.net commented 4 years ago

There are more invalid-namespace errors!

[2020-07-28 11:14:21:504] [FINEST  ] [      pool-30-thread-1 ] S2SConnectionManager.processSocketData(): Processing socket data: from=null, to=null, DATA=<challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl">=</challenge>, SIZE=65, XMLNS=urn:ietf:params:xml:ns:xmpp-sasl, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
[2020-07-28 11:14:21:504] [FINER   ] [      pool-30-thread-1 ] PacketChecker.filter()           : CID: tigase.im@yansat.com, null, type: connect, Socket: TLS: nullSocket[addr=/185.18.52.154,port=5269,localport=54251], jid: null, authenticated: false, Invalid namespace for packet: from=null, to=null, DATA=<challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl">=</challenge>, SIZE=65, XMLNS=urn:ietf:params:xml:ns:xmpp-sasl, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
[2020-07-28 11:14:21:504] [FINEST  ] [      pool-30-thread-1 ] S2SAbstract.generateStreamError(): CID: tigase.im@yansat.com, null, type: connect, Socket: TLS: nullSocket[addr=/185.18.52.154,port=5269,localport=54251], jid: null, authenticated: false, Sending stream error: <stream:error><invalid-namespace xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
java.lang.Throwable
        at tigase.server.xmppserver.proc.S2SAbstract.generateStreamError(S2SAbstract.java:81)
        at tigase.server.xmppserver.proc.PacketChecker.filter(PacketChecker.java:122)

[2020-07-28 19:33:05:086] [FINER   ] [      pool-30-thread-9 ] PacketChecker.filter()           : CID: tigase.im@xjabber.org, null, type: connect, Socket: TLS: nullSocket[addr=/46.148.26.25,port=5269,localport=45881], jid: null, authenticated: false, Invalid namespace for packet: from=null, to=null, DATA=<challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl">=</challenge>, SIZE=65, XMLNS=urn:ietf:params:xml:ns:xmpp-sasl, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
[2020-07-28 19:33:05:086] [FINEST  ] [      pool-30-thread-9 ] S2SAbstract.generateStreamError(): CID: tigase.im@xjabber.org, null, type: connect, Socket: TLS: nullSocket[addr=/46.148.26.25,port=5269,localport=45881], jid: null, authenticated: false, Sending stream error: <stream:error><invalid-namespace xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
java.lang.Throwable
        at tigase.server.xmppserver.proc.S2SAbstract.generateStreamError(S2SAbstract.java:81)
        at tigase.server.xmppserver.proc.PacketChecker.filter(PacketChecker.java:122)
wojciech.kapcia@tigase.net commented 4 years ago

For diebesban.de issue - this should already be handled in 8.1.0 as there is an exception for features (https://github.com/tigase/tigase-server/blob/old-stable/src/main/java/tigase/server/xmppserver/proc/PacketChecker.java#L119)

[2020-07-28 11:14:18:582] [FINEST  ] [      pool-30-thread-5 ] S2SConnectionManager.processSocketData(): Processing socket data: from=null, to=null, DATA=<features xmlns="http://etherx.jabber.org/streams"/>, SIZE=52, XMLNS=http://etherx.jabber.org/streams, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
[2020-07-28 11:14:18:582] [FINER   ] [      pool-30-thread-5 ] PacketChecker.filter()           : CID: push.tigase.im@diebesban.de, null, type: connect, Socket: TLS: nullSocket[addr=/5.181.50.75,port=5269,localport=27966], jid: null, authenticated: true, Invalid namespace for packet: from=null, to=null, DATA=<features xmlns="http://etherx.jabber.org/streams"/>, SIZE=52, XMLNS=http://etherx.jabber.org/streams, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

Looking at the code (https://github.com/tigase/tigase-server/blob/7c1a51d95e001a5da31318ff67ce8ba3121b027c/src/main/java/tigase/server/xmppserver/proc/PacketChecker.java#L119) I'm wondering whether we should add exceptions for <challenge xmlns="urn:ietf:params:xml:ns:xmpp-sasl">=</challenge> (though, it happens on tigase.im, which doesn't have above fix yet so maybe it doesn't matter) - what you think @andrzej.wojcik ?
Andrzej Wójcik (Tigase) commented 4 years ago

AFAIR, this only happens if the stanza is not process by any S2S processor. In case of <challenge/> it should be processed, so there should not be any issues. As for <features/> if they were empty, they were not processed by any S2S processor and that was causing the issue.
wojciech.kapcia@tigase.net commented 4 years ago

OK, thank you for the explanation. It was said that it's possible to connect to tigase.org, so most likely the issue was fixed in 8.1.0.
issue 1 of 1
Type
Bug
Priority
Normal
Assignee
wojciech.kapcia@tigase.net
Version
tigase-server-8.2.0
Issue Votes (0)
Login to vote
Watchers (0)
Reference
tigase/_server/server-core#1175
Please wait...
Page is in error, reload to recover