Missing 'to' attribute, ignoring packet… for stream:features (#1056)

Wojciech Kapcia (Tigase) opened 6 years ago

2019-08-02 20:48:26.143 [in_1-s2s]         ConnectionManager$ConnectionListenerImpl.accept()  FINEST: Accept called for service: null@null, port_props: {remote-host=localhost, port-no=5269, new-connections-throttling=100, ifc=[Ljava.lang.String;@1aa7d66e, socket=plain, type=accept}
2019-08-02 20:48:26.144 [in_1-s2s]         ConnectionManager.serviceStarted()      FINER:    [[s2s]] Connection started: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null
2019-08-02 20:48:26.144 [in_1-s2s]         S2SConnectionManager.serviceStarted()   FINEST:   s2s connection opened: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null
2019-08-02 20:48:26.144 [in_1-s2s]         S2SConnectionManager.xmppStreamOpened()  FINER:   CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Stream opened: {xmlns:stream=http://etherx.jabber.org/streams, xmlns=jabber:server, from=tigase.im, to=hefczyc.net, version=1.0, xmlns:db=jabber:server:dialback}
2019-08-02 20:48:26.144 [in_1-s2s]         S2SAbstract.generateStreamError()       FINEST:   Called from: 
java.lang.Throwable
	at tigase.server.xmppserver.proc.S2SAbstract.generateStreamError(S2SAbstract.java:94)
	at tigase.server.xmppserver.proc.StreamOpen.streamOpened(StreamOpen.java:219)
	at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:471)
	at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:50)
	at tigase.xmpp.XMPPIOService.xmppStreamOpened(XMPPIOService.java:580)
	at tigase.xmpp.XMPPDomBuilderHandler.startElement(XMPPDomBuilderHandler.java:238)
	at tigase.xml.SimpleParser.parse(SimpleParser.java:293)
	at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:484)
	at tigase.net.IOService.call(IOService.java:182)
	at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:144)
	at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:49)
	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)
2019-08-02 20:48:26.144 [in_1-s2s]         S2SAbstract.generateStreamError()       FINEST:   CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Sending stream error: [stream:error][host-unknown xmlns='urn:ietf:params:xml:ns:xmpp-streams'/][/stream:error][/stream:stream]
2019-08-02 20:48:26.144 [in_1-s2s]         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]
2019-08-02 20:48:26.144 [in_1-s2s]         S2SConnectionManager.xmppStreamOpened()  FINER:   CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Sending stream open: 
2019-08-02 20:48:26.144 [in_1-s2s]         ConnectionManager.serviceStopped()      FINER:    [[s2s]] Connection stopped: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null
2019-08-02 20:48:26.144 [in_1-s2s]         S2SConnectionManager.processPacket()    FINEST:   Processing 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
2019-08-02 20:48:26.145 [in_1-s2s]         S2SConnectionManager.processPacket()    WARNING:  Missing 'to' attribute, ignoring 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
 This most likely happens due to missconfiguration of components domain names.
2019-08-02 20:49:16.011 [in_1-s2s]         ConnectionManager.serviceStopped()      FINER:    [[c2s]] Connection stopped: c2s@ip-10-0-28-108.us-west-2.compute.internal/10.0.28.108_5223_10.0.23.240_23809, type: accept, Socket: TLS: c2s@ip-10-0-28-108.us-west-2.compute.internal/10.0.28.108_5223_10.0.23.240_23809 Socket[unconnected], jid: null
2019-08-02 20:49:16.011 [in_1-s2s]         ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@ip-10-0-28-108.us-west-2.compute.internal/10.0.28.108_5223_10.0.23.240_23809

Related
- Error packet from disconnected client generates error which causes "WARNING: Packet with TO attribute set to NULL" (#1075) Closed
- "Missing 'to' attribute, ignoring packet" for s2s sasl-external success (#1320) Closed

Activities

Wojciech Kapcia (Tigase) commented 5 years ago

[2019-11-27 18:00:19:558] [FINER   ] [      pool-36-thread-4 ] TLSIO.read()                     : Read bytes: 128, TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269]
[2019-11-27 18:00:19:558] [FINEST  ] [      pool-36-thread-4 ] XMPPIOService.processSocketData(): CID: tigase.im@meachersglobal.com, null, type: accept, Socket: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269], jid: null, READ:<presence from="jcook@meachersglobal.com/Jerry-T470s" to="jerrycook@tigase.im" type="unavailable"/>
[2019-11-27 18:00:19:558] [FINEST  ] [      pool-36-thread-4 ] XMPPIOService.moveParsedPacketsToReceived(): CID: tigase.im@meachersglobal.com, null, type: accept, Socket: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269], jid: null, Read packet: <presence from="jcook@meachersglobal.com/Jerry-T470s" to="jerrycook@tigase.im" type="unavailable"/>
[2019-11-27 18:00:19:558] [FINEST  ] [      pool-36-thread-4 ] S2SConnectionManager.processSocketData(): Processing socket data: from=null, to=null, DATA=<presence from="jcook@meachersglobal.com/Jerry-T470s" to="jerrycook@tigase.im" type="unavailable"/>, SIZE=99, XMLNS=null, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable
[2019-11-27 18:00:19:558] [FINER   ] [      pool-36-thread-4 ] PacketChecker.filter()           : CID: tigase.im@meachersglobal.com, null, type: accept, Socket: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269], jid: null, Invalid hostname from the remote server for packet: from=null, to=null, DATA=<presence xmlns="jabber:server" from="jcook@meachersglobal.com/Jerry-T470s" to="jerrycook@tigase.im" type="unavailable"/>, SIZE=121, XMLNS=jabber:server, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, authenticated domains for this connection: []
[2019-11-27 18:00:19:558] [FINEST  ] [      pool-36-thread-4 ] S2SAbstract.generateStreamError(): Called from:
java.lang.Throwable
        at tigase.server.xmppserver.proc.S2SAbstract.generateStreamError(S2SAbstract.java:94)
        at tigase.server.xmppserver.proc.PacketChecker.filter(PacketChecker.java:113)
        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:185)
        at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:145)
        at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:50)
        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)

[2019-11-27 18:00:19:558] [FINEST  ] [      pool-36-thread-4 ] S2SAbstract.generateStreamError(): CID: tigase.im@meachersglobal.com, null, type: accept, Socket: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269], jid: null, Sending stream error: <stream:error><invalid-from xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
[2019-11-27 18:00:19:559] [FINER   ] [      pool-36-thread-4 ] TLSIO.write()                    : TLS - Writing data, remaining: 104, loop_cnt: 0, TLSIO: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269], tlsWrapper: JcaTLSWrapper[WrapperStatus = OK, TLSEngineStatus = OK, HandshakeStatus = NOT_HANDSHAKING]
[2019-11-27 18:00:19:559] [FINER   ] [      pool-36-thread-4 ] TLSIO.writeBuff()                : TLS - Writing data, remaining: 0, run 0 of 1,000, TLSIO: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269], tlsWrapper: JcaTLSWrapper[WrapperStatus = OK, TLSEngineStatus = OK, HandshakeStatus = NOT_HANDSHAKING]
[2019-11-27 18:00:19:559] [FINER   ] [      pool-36-thread-4 ] IOService.forceStop()            : Socket: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269], Force stop called...
[2019-11-27 18:00:19:559] [FINER   ] [      pool-36-thread-4 ] IOService.forceStop()            : Calling stop on: TLS: nullSocket[addr=/87.252.53.130,port=53085,localport=5269]
[2019-11-27 18:00:19:559] [FINER   ] [      pool-36-thread-4 ] IOService.forceStop()            : Calling stop on the listener: tigase.server.xmppserver.S2SConnectionManager@45dfb6a4
[2019-11-27 18:00:19:559] [FINER   ] [      pool-36-thread-4 ] ConnectionManager.serviceStopped(): [[s2s]] Connection stopped: CID: tigase.im@meachersglobal.com, null, type: accept, Socket: TLS: nullSocket[unconnected], jid: null
[2019-11-27 18:00:19:559] [FINEST  ] [  ConnectionOpenThread ] ConnectionManager$ConnectionListenerImpl.accept(): Accept called for service: null@null, port_props: {remote-host=localhost, port-no=5280, new-connections-throttling=1000, ifc=[Ljava.lang.String;@7655fdce, socket=plain, type=accept}

Wojciech Kapcia (Tigase) commented 5 years ago
Problem again relates to processing packet over broken connection (s2s here) and (seemingly) trying to re-deliver those packets.

Most likely a concurrency issue: this particular packet seem to be removed from waitingPackets queue (below line is after .poll())

[2020-08-30 05:10:11:702] [FINEST ] [ in_1-s2s ] XMPPIOService.processWaitingPackets(): CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, authenticated: false, SENT: [stream:features][starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/][dialback xmlns="urn:xmpp:features:dialback"/][/stream:features]

Yet the exception is thrown on writeRawData() method:

at tigase.xmpp.XMPPIOService.writeRawData(XMPPIOService.java:276) at tigase.xmpp.XMPPIOService.processWaitingPackets(XMPPIOService.java:236)

But probably due to concurrency it manages to get slated for re-delivery in tigase.server.ConnectionManager#serviceStopped.

As a fix I modified tigase.server.xmppserver.S2SConnectionManager#processUndeliveredPacket to ignore re-delivery of stream:features as it doesn't make much sense here and added more debug information.
Login to comment

Type	Bug
Priority	Normal
Assignee	Wojciech Kapcia (Tigase)
Version	tigase-server-8.2.0
Spent time	0

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#1056