Project

General

Profile

Tigase 7.0.0 S2SConnectionManager exception

Igor Khomenko
Added about 4 years ago

I've got a fresh installation of Tigase 7.0.0

but after startup I started getting next exception every 2 seconds:

2015-03-18 13:02:46.534 [scheduler_pool-5-thread-1-s2s]  ConnectionManager$1.run()  FINE: Reconnecting service for component: s2s, to remote host: ip-10-222-235-20.ec2.internal on port: 5269
2015-03-18 13:02:46.535 [ConnectionOpenThread]  ConnectionManager$ConnectionListenerImpl.accept()  FINEST: Accept called for service: chat.my.com@ip-10-222-235-20.ec2.internal, port_props: {cert-required-domain=ip-10-222-235-20.ec2.internal, cid=chat.my.com@ip-10-222-235-20.ec2.internal, ifc=[Ljava.lang.String;@436cd7fc, local-hostname=chat.my.com, port-no=5269, remote-hostname=ip-10-222-235-20.ec2.internal, remote-ip=222, s2s-connection-key=S2S: null, socket=plain, srv-type=_xmpp-server._tcp, type=connect}
2015-03-18 13:02:46.535 [ConnectionOpenThread]  ConnectionManager.serviceStarted()  FINER: [[s2s]] Connection started: CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null
2015-03-18 13:02:46.535 [ConnectionOpenThread]  S2SConnectionManager.serviceStarted()  FINEST: s2s connection opened: CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null
2015-03-18 13:02:46.536 [ConnectionOpenThread]  StreamOpen.serviceStarted()   FINEST:   CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, sending: <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='chat.my.com' to='ip-10-222-235-20.ec2.internal' version='1.0'>
2015-03-18 13:02:46.536 [ConnectionOpenThread]  XMPPIOService.xmppStreamOpen()  FINEST: CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, Sending data: <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='chat.my.com' to='ip-10-222-235-20.ec2.internal' version='1.0'>
2015-03-18 13:02:46.536 [ConnectionOpenThread]  ConnectionManager$ConnectionListenerImpl.accept()  FINEST: Accept called for service: null@null, port_props: {type=accept, socket=plain, ifc=[Ljava.lang.String;@272965b6, remote-host=localhost, required=false, port-no=5269}
2015-03-18 13:02:46.536 [ConnectionOpenThread]  ConnectionManager.serviceStarted()  FINER: [[s2s]] Connection started: CID: null, null, type: accept, Socket: nullSocket[addr=/10.222.235.20,port=62837,localport=5269], jid: null
2015-03-18 13:02:46.537 [ConnectionOpenThread]  S2SConnectionManager.serviceStarted()  FINEST: s2s connection opened: CID: null, null, type: accept, Socket: nullSocket[addr=/10.222.235.20,port=62837,localport=5269], jid: null
2015-03-18 13:02:46.537 [pool-11-thread-3]  XMPPIOService.processSocketData()  FINEST:  CID: null, null, type: accept, Socket: nullSocket[addr=/10.222.235.20,port=62837,localport=5269], jid: null, READ:<stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='chat.my.com' to='ip-10-222-235-20.ec2.internal' version='1.0'>
2015-03-18 13:02:46.537 [pool-11-thread-3]  XMPPDomBuilderHandler.startElement()  FINEST: Start element name: stream:stream
2015-03-18 13:02:46.537 [pool-11-thread-3]  XMPPDomBuilderHandler.startElement()  FINEST: Element attributes names: [xmlns:stream, xmlns, xmlns:db, from, to, version]
2015-03-18 13:02:46.537 [pool-11-thread-3]  XMPPDomBuilderHandler.startElement()  FINEST: Element attributes values: [http://etherx.jabber.org/streams, jabber:server, jabber:server:dialback, chat.my.com, ip-10-222-235-20.ec2.internal, 1.0]
2015-03-18 13:02:46.537 [pool-11-thread-3]  XMPPDomBuilderHandler.startElement()  FINEST: Namespace found: http://etherx.jabber.org/streams
2015-03-18 13:02:46.537 [pool-11-thread-3]  XMPPDomBuilderHandler.startElement()  FINEST: Namespace found: jabber:server:dialback
2015-03-18 13:02:46.537 [pool-11-thread-3]  S2SConnectionManager.xmppStreamOpened()  FINER: CID: null, null, type: accept, Socket: nullSocket[addr=/10.222.235.20,port=62837,localport=5269], jid: null, Stream opened: {to=ip-10-222-235-20.ec2.internal, xmlns:stream=http://etherx.jabber.org/streams, from=chat.my.com, xmlns=jabber:server, xmlns:db=jabber:server:dialback, version=1.0}
2015-03-18 13:02:46.537 [pool-11-thread-3]  S2SAbstractProcessor.generateStreamError()  FINEST: Called from: 
java.lang.Throwable
    at tigase.server.xmppserver.proc.S2SAbstractProcessor.generateStreamError(S2SAbstractProcessor.java:154)
    at tigase.server.xmppserver.proc.StreamOpen.streamOpened(StreamOpen.java:252)
    at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:534)
    at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:71)
    at tigase.xmpp.XMPPIOService.xmppStreamOpened(XMPPIOService.java:817)
    at tigase.xmpp.XMPPDomBuilderHandler.startElement(XMPPDomBuilderHandler.java:286)
    at tigase.xml.SimpleParser.parse(SimpleParser.java:314)
    at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:686)
    at tigase.net.IOService.call(IOService.java:252)
    at tigase.net.IOService.call(IOService.java:94)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)
2015-03-18 13:02:46.538 [pool-11-thread-3]  S2SAbstractProcessor.generateStreamError()  FINEST: CID: null, null, type: accept, Socket: nullSocket[addr=/10.222.235.20,port=62837,localport=5269], jid: null, Sending stream error: <stream:error><host-unknown xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
2015-03-18 13:02:46.538 [pool-11-thread-3]  ConnectionManager.serviceStopped()  FINER:  [[s2s]] Connection stopped: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null
2015-03-18 13:02:46.538 [pool-11-thread-3]  StreamFeatures.streamOpened()     FINEST:   CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Sending stream features: <stream:features><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/><dialback xmlns="urn:xmpp:features:dialback"><required/></dialback></stream:features>
2015-03-18 13:02:46.538 [pool-11-thread-3]  S2SConnectionManager.xmppStreamOpened()  FINER: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Sending stream open: 
2015-03-18 13:02:46.538 [pool-11-thread-3]  XMPPIOService.xmppStreamOpened()  FINEST:   CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Sending data: null
2015-03-18 13:02:46.538 [pool-11-thread-3]  XMPPIOService.processWaitingPackets()  FINEST: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Sending packet: from=null, to=null, DATA=<stream:features><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/><dialback xmlns="urn:xmpp:features:dialback"><required/></dialback></stream:features>, SIZE=153, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2015-03-18 13:02:46.538 [pool-11-thread-3]  XMPPIOService.processWaitingPackets()  FINEST: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, SENT: <stream:features><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/><dialback xmlns="urn:xmpp:features:dialback"><required/></dialback></stream:features>
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPIOService.processSocketData()  FINEST:  CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, READ:<stream:error><host-unknown xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.startElement()  FINEST: Start element name: stream:error
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.startElement()  FINEST: Element attributes names: null
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.startElement()  FINEST: Element attributes values: null
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.startElement()  FINEST: Found prefixed element name, prefix: stream
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.startElement()  FINEST: Start element name: host-unknown
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.startElement()  FINEST: Element attributes names: [xmlns, null, null, null, null, null]
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.startElement()  FINEST: Element attributes values: [urn:ietf:params:xml:ns:xmpp-streams, null, null, null, null, null]
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.endElement()  FINEST: End element name: host-unknown
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.endElement()  FINEST: End element name: stream:error
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.endElement()  FINEST: Adding new request: <stream:error><host-unknown xmlns="urn:ietf:params:xml:ns:xmpp-streams"/></stream:error>
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPDomBuilderHandler.endElement()  FINEST: End element name: stream:stream
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPIOService.processSocketData()  FINEST:  CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, Read packet: <stream:error><host-unknown xmlns="urn:ietf:params:xml:ns:xmpp-streams"/></stream:error>
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPIOService.xmppStreamClosed()  FINEST:   CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, Received STREAM-CLOSE from the client
2015-03-18 13:02:46.539 [pool-11-thread-2]  XMPPIOService.xmppStreamClosed()  FINEST:   CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, Sending data: </stream:stream>
2015-03-18 13:02:46.539 [pool-11-thread-2]  S2SConnectionManager.xmppStreamClosed()  FINER: CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, Stream closed.
2015-03-18 13:02:46.540 [pool-11-thread-2]  S2SConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<stream:error><host-unknown xmlns="urn:ietf:params:xml:ns:xmpp-streams"/></stream:error>, SIZE=88, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2015-03-18 13:02:46.540 [pool-11-thread-2]  S2SAbstractProcessor.generateStreamError()  FINEST: Called from: 
java.lang.Throwable
    at tigase.server.xmppserver.proc.S2SAbstractProcessor.generateStreamError(S2SAbstractProcessor.java:154)
    at tigase.server.xmppserver.proc.PacketChecker.process(PacketChecker.java:111)
    at tigase.server.xmppserver.S2SConnectionManager.processSocketData(S2SConnectionManager.java:355)
    at tigase.server.xmppserver.S2SConnectionManager.processSocketData(S2SConnectionManager.java:71)
    at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:422)
    at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:71)
    at tigase.net.IOService.call(IOService.java:254)
    at tigase.net.IOService.call(IOService.java:94)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)
2015-03-18 13:02:46.540 [pool-11-thread-2]  S2SAbstractProcessor.generateStreamError()  FINEST: CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null, Sending stream error: <stream:error><improper-addressing xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
2015-03-18 13:02:46.540 [pool-11-thread-2]  ConnectionManager.serviceStopped()  FINER:  [[s2s]] Connection stopped: CID: chat.my.com@ip-10-222-235-20.ec2.internal, null, type: connect, Socket: nullSocket[addr=/10.222.235.20,port=5269,localport=62837], jid: null
2015-03-18 13:02:46.540 [pool-11-thread-2]  CIDConnections.checkOpenConnections()  FINEST: Scheduling task for openning a new connection for: chat.my.com@ip-10-222-235-20.ec2.internal
2015-03-18 13:02:46.540 [pool-11-thread-3]  XMPPIOService.processSocketData()  SEVERE:  Packet size is 0. Packet: <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='chat.my.com' to='ip-10-222-235-20.ec2.internal' version='1.0'>
2015-03-18 13:02:46.540 [pool-6-thread-1]  CIDConnections$2.run()             FINEST:   Running scheduled task for openning a new connection for: chat.my.com@ip-10-222-235-20.ec2.internal
2015-03-18 13:02:46.540 [pool-6-thread-1]  CIDConnections.openOutgoingConnections()  FINEST: Checking DNS for host: ip-10-222-235-20.ec2.internal for: chat.my.com@ip-10-222-235-20.ec2.internal
2015-03-18 13:02:46.541 [pool-6-thread-1]  CIDConnections.initNewConnection()  FINEST:  STARTING new connection: chat.my.com@ip-10-222-235-20.ec2.internal
2015-03-18 13:02:46.541 [pool-6-thread-1]  CIDConnections.initNewConnection()  FINEST:  chat.my.com@ip-10-222-235-20.ec2.internal connection params: {cert-required-domain=ip-10-222-235-20.ec2.internal, cid=chat.my.com@ip-10-222-235-20.ec2.internal, ifc=[Ljava.lang.String;@66bc0c3e, local-hostname=chat.my.com, port-no=5269, remote-hostname=ip-10-222-235-20.ec2.internal, remote-ip=10.222.235.20, s2s-connection-key=S2S: null, socket=plain, srv-type=_xmpp-server._tcp, type=connect}
2015-03-18 13:02:46.541 [pool-6-thread-1]  ConnectionManager.reconnectService()  FINER: Reconnecting service for: s2s, scheduling next try in 2secs, cid: chat.my.com@ip-10-222-235-20.ec2.internal, props: {cert-required-domain=ip-10-222-235-20.ec2.internal, cid=chat.my.com@ip-10-222-235-20.ec2.internal, ifc=[Ljava.lang.String;@66bc0c3e, local-hostname=chat.my.com, port-no=5269, remote-hostname=ip-10-222-235-20.ec2.internal, remote-ip=10.222.235.20, s2s-connection-key=S2S: null, socket=plain, srv-type=_xmpp-server._tcp, type=connect}

Here is my init.properties:

config-type = --gen-config-all
--admins = ...

--user-db = ...
--user-db-uri = ...
--auth-db = ...
--auth-db-uri = ...


--data-repo-pool-size = 40
--virt-hosts = chat.my.com

c2s/processors[s]=urn:xmpp:sm:3
c2s/processors/urn\:xmpp\:sm\:3/resumption-timeout[I]=60

ws2s/connections/ports[i]=5290,5291
ws2s/connections/5291/socket=ssl
ws2s/connections/5291/type=accept

bosh/connections/ports[i]=5280,5281
bosh/connections/5281/socket=ssl
bosh/connections/5281/type=accept

--ssl-def-cert-domain = chat.my.com

--monitoring = http:9080,jmx:9050

--sm-plugins=+message-carbons,-jabber:iq:register,-jabber:iq:auth,-msgoffline

I don't use cluster features, so my question is why Tigase still uses S2S component and what is the root of this exception?


Replies (9)

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam about 4 years ago

Most likely this is a result of misconfiguration of the network settings on the server, that is canonical hostname used by the server software and DNS pointing to the hostname. Sometimes if settings are not correct, the server recognizes the machine hostname as an external address and attempts to connect to it.

To help you with this we would need access to unedited copy of your logs (mainly a XMPP packet that triggered the event) and init.properties file.

Added by Igor Khomenko almost 4 years ago

Thanks,

I did some changes around hostname settings.

Previously hostname -f command returned ip-10-222-235-20.ec2.internal

But now I changed this and it prints the same what I set in --virt-hosts -> chat.my.com

and looks like now I don't see that exception

Is it a right way how it should work?

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam almost 4 years ago

Unfortunately your solution will not work if you run Tigase in a cluster mode. In a cluster mode each server needs to have a distinct canonical hostname, and that hostname must be also different form any of vhosts you have.

Added by Igor Khomenko almost 4 years ago

Yes, I also got this point

but what is the right way to fix this?

Here is what I have:

1) Didn't have this issue with Tigase 5.2.0

2) Let's say our Tigase instance DNS is chat.my.com

3) The same value is in init.properties: --virt-hosts = chat.my.com

4) It doesn't work with custom hostname -f

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam almost 4 years ago

You have to make sure your custom hostname has a correct DNS entry.

Added by Igor Khomenko almost 4 years ago

So, you mean that hostname -f should be reachable via Internet?

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam almost 4 years ago

The hostname -f must be reachable from the machine itself (so the server can resolve the hostname into IP address correctly) and from all cluster nodes if the installation runs in a cluster mode. It does not need to be reachable from the internet.

Added by Igor Khomenko almost 4 years ago

Actually I can ping and telnet the value from hostname -f from this machine

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam almost 4 years ago

Hm, it looks like some sort of misconfiguration in either Tigase or on the network level. Can you provide us with a real, unedited init.properties file?

Or maybe, another possibility, is that you have somewhere, in roster or in offline messages a JID with ip-10-222-235-20.ec2.internal as domain, hence the Tigase attempts to send something to that domain.

    (1-9/9)