S2S prefix issue
Description
Environment
None
blocks
is related to
relates to
Activity
Show:
Guus der Kinderen October 26, 2023 at 10:25 AM
I'm no longer seeing this on Ignite. It has likely been addressed by the related issues under https://igniterealtime.atlassian.net/browse/OF-2559#icft=OF-2559.
Guus der Kinderen October 20, 2023 at 10:34 AMEdited
I'm seeing this instance of the problem on ignite, after dogfooding the latest code (commit #3013249). I've search/replaced the domain name and IP address of the remote server to protect the innocent.
2023.10.20 10:17:31 DEBUG [S2SOutgoingPromise-4]: org.jivesoftware.openfire.nio.NettySessionInitializer - Opening a new connection to example.com/203.0.113.123:5269 that is initially not encrypted.
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyOutboundConnectionHandler - Adding NettyOutboundConnectionHandler
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Netty XMPP handler added: null
2023.10.20 10:17:31 DEBUG [S2SOutgoingPromise-4]: org.jivesoftware.openfire.nio.NettySessionInitializer - Send the stream header and wait for response...
2023.10.20 10:17:31 TRACE [S2SOutgoingPromise-4]: org.jivesoftware.openfire.nio.NettySessionInitializer - Sending: <?xml version="1.0" encoding="UTF-8"?>
<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:server" xmlns:db="jabber:server:dialback" from="igniterealtime.org" to="example.com" version="1.0">
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <?xml version='1.0'?>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <stream:stream xmlns='jabber:server' id='f3f7f448-4d2b-40bd-94fe-b6dab97c913b' from='example.com' version='1.0' xmlns:stream='http://etherx.jabber.org/streams' xmlns:db='jabber:server:dialback' to='igniterealtime.org' xml:lang='en'>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><dialback xmlns='urn:xmpp:features:dialback'/></stream:features>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnection - Sending: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
2023.10.20 10:17:31 DEBUG [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyOutboundConnectionHandler - TLS negotiation was successful. Connection encrypted. Proceeding with authentication...
2023.10.20 10:17:31 DEBUG [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyOutboundConnectionHandler - SASL authentication will be attempted
2023.10.20 10:17:31 DEBUG [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyOutboundConnectionHandler - Send the stream header and wait for response...
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnection - Sending: <?xml version="1.0" encoding="UTF-8"?>
<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:server" xmlns:db="jabber:server:dialback" from="igniterealtime.org" to="example.com" version="1.0">
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <?xml version='1.0'?>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <stream:stream xmlns='jabber:server' id='13c8bcb5-7def-428f-92f2-c724fd99be49' from='example.com' version='1.0' xmlns:stream='http://etherx.jabber.org/s
treams' xmlns:db='jabber:server:dialback' to='igniterealtime.org' xml:lang='en'>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>EXTERNAL</mechanism></mechanisms><dialback xmlns='urn:xmpp:features:dialback'/></stream:features>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnection - Sending: <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="EXTERNAL">REDACTED</auth>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnection - Sending: <?xml version="1.0" encoding="UTF-8"?>
<stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:server" from="igniterealtime.org" to="example.com" version="1.0">
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <?xml version='1.0'?>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <stream:stream xmlns='jabber:server' id='43f76075-698c-4acc-a46d-4962ff86c68d' from='example.com' version='1.0' xmlns:stream='http://etherx.jabber.org/s
treams' xmlns:db='jabber:server:dialback' to='igniterealtime.org' xml:lang='en'>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-4-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:5269--/203.0.113.123:44362 received: <iq to='igniterealtime.org' id='158-913' from='example.com' type='result'><query xmlns='jabber:iq:version'><name>Prosody</name><version>0.11.10</version><os>Linux</os></query></iq>
2023.10.20 10:17:31 TRACE [nioEventLoopGroup-97-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Handler on /172.31.17.41:40440--example.com/203.0.113.123:5269 received: <stream:features><dialback xmlns='urn:xmpp:features:dialback'/></stream:features>
2023.10.20 10:17:31 ERROR [nioEventLoopGroup-4-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Closing connection on /172.31.17.41:5269--/203.0.113.123:44362 due to error while processing message: <iq to='igniterealtime.org' id='158-913' from='example.com' type='result'><query xmlns='jabber:iq:version'><name>Prosody</name><version>0.11.10</version><os>Linux</os></query></iq>
org.xmlpull.v1.XmlPullParserException: could not determine namespace bound to element prefix stream (position: START_DOCUMENT seen <stream:stream>... @1:15)
at org.xmlpull.mxp1.MXParser.parseStartTag(MXParser.java:1816) ~[xpp3-1.1.4c.jar:?]
at org.xmlpull.mxp1.MXParser.parseProlog(MXParser.java:1479) ~[xpp3-1.1.4c.jar:?]
at org.jivesoftware.openfire.net.MXParser.nextImpl(MXParser.java:337) ~[xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT]
at org.xmlpull.mxp1.MXParser.nextToken(MXParser.java:1100) ~[xpp3-1.1.4c.jar:?]
at org.dom4j.io.XMPPPacketReader.parseDocument(XMPPPacketReader.java:375) ~[xmppserver-4.8.0-SNAPSHOT.jar:?]
at org.dom4j.io.XMPPPacketReader.read(XMPPPacketReader.java:204) ~[xmppserver-4.8.0-SNAPSHOT.jar:?]
at org.jivesoftware.openfire.net.StanzaHandler.processStanza(StanzaHandler.java:185) ~[xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT]
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:116) ~[xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT]
at org.jivesoftware.openfire.nio.NettyConnectionHandler.channelRead0(NettyConnectionHandler.java:140) [xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT]
at org.jivesoftware.openfire.nio.NettyConnectionHandler.channelRead0(NettyConnectionHandler.java:48) [xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT]
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [netty-handler-4.1.100.Final.jar:4.1.100.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]Dan Caseley October 13, 2023 at 7:08 PM
Can’t see any instances of this in Ignites logs any longer.
server-connectiontest.jsp to pade.chat is clean.
Guus der Kinderen September 6, 2023 at 5:26 PMEdited
I have reproduced this once with the remote server pade.chat, which is running Openfire 4.7.5
I wonder if this has to do with Openfire sending <stream:features> in a different way - maybe in a second flush or something, making processing happen outside of where other server’s features would be processed?
Guus der Kinderen September 6, 2023 at 2:48 PM
The code that throws this is using https://igniterealtime.atlassian.net/browse/OF-2556:
final Set<Namespace> namespaces = connection.getAdditionalNamespaces();
if (namespaces.isEmpty()) {
doc = reader.read(new StringReader(stanza)).getRootElement();
}The stream prefix is excluded from the ‘additionalNamespaces’ collection by design. Apparently, Openfire doesn’t expect to process that here.
This issue affects a version of Openfire that is as of yet unreleased. It should not affect anyone running a proper release of Openfire. It is introduced by https://igniterealtime.atlassian.net/browse/OF-2559.
With the latest version of the nightly build, this is being logged. This strongly hints at a regression of https://igniterealtime.atlassian.net/browse/OF-2556
2023.09.06 14:01:48 ERROR [nioEventLoopGroup-75-1]: org.jivesoftware.openfire.nio.NettyConnectionHandler - Closing connection due to error while processing message: <stream:features><c xmlns='http://jabber.org/protocol/caps' ver='+cryNjKbAMQpLkJh9xqLHpVlxBA=' hash='sha-1' node='http://prosody.im'/><dialback xmlns='urn:xmpp:features:dialback'/><sm xmlns='urn:xmpp:sm:2'><optional/></sm><sm xmlns='urn:xmpp:sm:3'><optional/></sm></stream:features> org.xmlpull.v1.XmlPullParserException: could not determine namespace bound to element prefix stream (position: START_DOCUMENT seen <stream:features>... @1:17) at org.xmlpull.mxp1.MXParser.parseStartTag(MXParser.java:1816) ~[xpp3-1.1.4c.jar:?] at org.xmlpull.mxp1.MXParser.parseProlog(MXParser.java:1479) ~[xpp3-1.1.4c.jar:?] at org.jivesoftware.openfire.net.MXParser.nextImpl(MXParser.java:337) ~[xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT] at org.xmlpull.mxp1.MXParser.nextToken(MXParser.java:1100) ~[xpp3-1.1.4c.jar:?] at org.dom4j.io.XMPPPacketReader.parseDocument(XMPPPacketReader.java:375) ~[xmppserver-4.8.0-SNAPSHOT.jar:?] at org.dom4j.io.XMPPPacketReader.read(XMPPPacketReader.java:204) ~[xmppserver-4.8.0-SNAPSHOT.jar:?] at org.jivesoftware.openfire.net.StanzaHandler.processStanza(StanzaHandler.java:173) ~[xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT] at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:120) ~[xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT] at org.jivesoftware.openfire.nio.NettyConnectionHandler.channelRead0(NettyConnectionHandler.java:140) [xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT] at org.jivesoftware.openfire.nio.NettyConnectionHandler.channelRead0(NettyConnectionHandler.java:48) [xmppserver-4.8.0-SNAPSHOT.jar:4.8.0-SNAPSHOT] at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [netty-handler-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) [netty-codec-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) [netty-codec-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1383) [netty-handler-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1246) [netty-handler-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1295) [netty-handler-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529) [netty-codec-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468) [netty-codec-4.1.94.Final.jar:4.1.94.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) [netty-codec-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) [netty-transport-4.1.94.Final.jar:4.1.94.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [netty-common-4.1.94.Final.jar:4.1.94.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.94.Final.jar:4.1.94.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.94.Final.jar:4.1.94.Final] at java.lang.Thread.run(Thread.java:829) [?:?]