Re: S2S connection problem, no 'from' attribute

Dave Mon, 10 Jun 2013 13:36:43 -0700

in ProtocolWorker we do map incoming messages from a server namespace toa client namespace, when that message is addressed to the server itself.


// rewrite namespace

stanza = StanzaBuilder.rewriteNamespace(stanza,NamespaceURIs.JABBER_SERVER, NamespaceURIs.JABBER_CLIENT);

but I'm not sure we do the opposite when closing the connection at theend of the dialback handshake.

Interestingly, the above namespace re-write only occurs for stanzasaddressed to the server, or a local node. I'm trying to use a component(such as the muc module - advertised on a subdomain: muc.remote.co.uk),and I can't figure out what codepath an incoming stanza is supposed totake. Is it possible that this isn't implemented / supported at the moment?


Anyway - thanks for taking a look!

Dave


On 10/06/13 21:00, Bernd Fondermann wrote:

I need to look into s2s. Since I'm not the original developer of s2s, I
might need some ramp up time.

However, as far as I remember, there is some inner logic to map "client" to
"server" namespaces in s2s connections.

   Bernd

On Fri, Jun 7, 2013 at 8:22 PM, Dave <[email protected]> wrote:

Hi Ashkan,

I see this also.  This message appears to come as a result of the dialback
connection closing after dialback has completed.  In DbVerifyHandler, the
connection is closed with:

sessionContext.endSession(**SessionTerminationCause.**CLIENT_BYEBYE);

As a result, the session context then tries to send an UNAVAILABLE
presence stanza, I guess informing the other end that we're going off-line
- which seems odd given the connection has only just been initiated.  Iirc,
this presence stanza is sent by the server, rather than a specific user -
which might be why the 'from' attribute is complained about? Looking at the
comments, the code is expecting to use this unavailable presence stanza for
client connections, so maybe it shouldn't be sent for server connections at
all?

I don't know vysper or the xmpp spec's well enough to understand what
should be happening here, but maybe the above gives someone else an idea
about what's going wrong?

Dave



On 07/06/13 18:46, Ashkan Rezaei wrote:

Hi,

I am trying Vysper on 2 federated server, running on different machines
in the network.

I built the project using the default maven file

I have set the RelayingToFederationServers to true:

ServerRuntimeContext runtimeCtx = ((SpringCompatibleXMPPServer)**
ctx.getBean("server")).**getServerRuntimeContext();
          runtimeCtx.getServerFeatures()**.**
setRelayingToFederationServers**(true);

I send a message from 
"[email protected].**at<[email protected]>"
to "[email protected].**at <[email protected]>"

I can see from the log file that the Authentication, TLS and callback
stage between servers got executed just fine. But yet I don't see any
response or error coming for the other user on my client, I have tried both
Psi and Adium on Mac, I don't see any error stanza on the psi debug console
either.

I tried to debug the code on receiving side. There is an empty incoming
presence stanza within client namespace (!), which triggers the "no from
attribute" but I'm not sure if that is the ultimate fatal bug here. I am
not able to understand whats going on in low level. I observed all the
outgoing stanzas from the sending server via debugger. All stanzas do have
'from' attribute. There should be something wrong with servers negotiations
Moreover all the XMPP ping stanza either fail with service-unavailable or
with error IQStanza, even though the ping Module is added by initialization
and I can verify it in the log file.

I have tried everything I could think of or that I would suspect. But
nothing works. Has anyone had any similar experience? I should mention that
I use the up-to-date 0.8-SNAPSHOT version.

I append the logs I get after sending the message stanza.

Sorry if it's too long ;)

  Thanks

Ashkan


sender log:

18:32:18,880 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <message xmlns="jabber:client" id="ab04a" to="
user2@sat016.**researchstudio.at <[email protected]>
"><subject>**hi</subject><body>hi user 2</body><nick xmlns="
http://jabber.org/**protocol/nick <http://jabber.org/protocol/nick>
">user1</nick></**message>
18:32:18,881 | INFO  | stanza.client | message.subject
18:32:18,900 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| Starting XMPP server connector to sat016.researchstudio.at
18:32:19,129 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| Connecting to XMPP server sat016.researchstudio.at at
sat016.researchstudio.at/192.**168.124.48:5269<http://sat016.researchstudio.at/192.168.124.48:5269>
18:32:19,187 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = INITIATED
18:32:19,187 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = INITIATED
18:32:19,193 | INFO  | stanza.server | stream
18:32:19,207 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:stream xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>" id="**
b02adac84032499595d393c3bc3b53**b1" from="sat016.researchstudio.at**"
version="1.0"></stream:stream>
18:32:19,210 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:features xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>"><starttls
xmlns="urn:ietf:params:xml:ns:**xmpp-tls"></starttls><dialback
xmlns="urn:xmpp:features:**dialback"></dialback></stream:**features>
18:32:19,211 | INFO  | stanza.client | stream
18:32:19,212 | INFO  | stanza.client | features
18:32:19,216 | INFO  | org.apache.vysper.xmpp.server.**s2s.FeaturesHandler
| XMPP server connector to sat016.researchstudio.at is starting TLS
18:32:19,218 | INFO  | stanza.server | starttls
18:32:19,232 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <proceed xmlns="urn:ietf:params:xml:ns:**
xmpp-tls"></proceed>
18:32:19,232 | INFO  | stanza.client | proceed
18:32:19,233 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = ENCRYPTION_STARTED
18:32:19,234 | DEBUG | org.apache.vysper.xmpp.server.**s2s.TlsProceedHandler
| XMPP server connector switching to TLS
18:32:19,371 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = ENCRYPTED
18:32:19,372 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat016.researchstudio.at secured using TLS
18:32:19,374 | DEBUG | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat016.researchstudio.at restarting stream
18:32:19,379 | INFO  | stanza.server | stream
18:32:19,399 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:stream xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>" id="**
b02adac84032499595d393c3bc3b53**b1" from="sat016.researchstudio.at**"
version="1.0"></stream:stream>
18:32:19,403 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:features xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>"><dialback
xmlns="urn:xmpp:features:**dialback"></dialback></stream:**features>
18:32:19,404 | INFO  | stanza.client | stream
18:32:19,409 | INFO  | stanza.client | features
18:32:19,423 | INFO  | stanza.server | result
18:32:19,748 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = INITIATED
18:32:19,769 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:stream xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>" to="
sat001.researchstudio.at" xml:lang="en_US" from="sat016.researchstudio.at
**" version="1.0"></stream:stream>
18:32:19,770 | INFO  | stanza.client | stream
18:32:19,772 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = STARTED
18:32:19,774 | INFO  | stanza.server | stream.starttls
18:32:19,795 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <db:verify xmlns:db="jabber:server:**dialback"
id="**b02adac84032499595d393c3bc3b53**b1" to="sat001.researchstudio.at"
from="sat016.researchstudio.at**">**497e1dd09d8db2786b922755f8fc55**
5140672bf2588d8896791a0f9b8974**3790</db:verify>
18:32:19,795 | INFO  | stanza.client | verify
18:32:19,805 | INFO  | stanza.server | verify
18:32:19,916 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <db:result xmlns:db="jabber:server:**dialback"
to="sat001.researchstudio.at" from="sat016.researchstudio.at**"
type="valid"></db:result>
18:32:19,922 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = CLOSED
18:32:19,920 | INFO  | stanza.client | result
18:32:19,924 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = AUTHENTICATED
18:32:19,924 | INFO  | org.apache.vysper.xmpp.**
modules.extension.xep0220_**server_dailback.**DbResultHandler | XMPP
server connector to sat016.researchstudio.at authenticated using dialback
18:32:19,925 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat016.researchstudio.at authenticated
18:32:19,938 | INFO  | stanza.server | message.subject
18:32:19,961 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <message xmlns="jabber:client" id="ab04a" to="
user1@sat001.**researchstudio.at/**8235cb3fd07f41d68ce1956fc37d9f**0e<http://[email protected]/8235cb3fd07f41d68ce1956fc37d9f0e>"
from="sat016.researchstudio.at**" type="error"><subject>hi</**subject><body>hi
user 2</body><nick 
xmlns="http://jabber.org/**protocol/nick<http://jabber.org/protocol/nick>
">user1</nick><**error type="cancel"><service-**unavailable
xmlns="urn:ietf:params:xml:ns:**xmpp-stanzas"></service-**
unavailable></error></message>
18:32:19,962 | INFO  | stanza.client | message.subject
18:32:49,946 | INFO  | stanza.server | iq.id='xmppping-ddf6883f-8443-**
487a-82e9-1fc25f466e9d'.to='sa**t016.researchstudio.at<http://sat016.researchstudio.at>
'.from='**sat001.researchstudio.at <http://sat001.researchstudio.at>'.**
type='get'.ping.xmlns='urn:**xmpp:ping'
18:32:49,961 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <iq xmlns="jabber:client"
id="xmppping-ddf6883f-8443-**487a-82e9-1fc25f466e9d" to="
sat001.researchstudio.at" from="sat016.researchstudio.at**"
type="error"><ping xmlns="urn:xmpp:ping"></ping><**error
type="cancel"><service-**unavailable xmlns="urn:ietf:params:xml:ns:**
xmpp-stanzas"></service-**unavailable></error></iq>
18:32:49,964 | INFO  | stanza.client | iq.id='xmppping-ddf6883f-8443-**
487a-82e9-1fc25f466e9d'.to='sa**t001.researchstudio.at<http://sat001.researchstudio.at>
'.from='**sat016.researchstudio.at <http://sat016.researchstudio.at>'.**
type='error'.ping.xmlns='urn:**xmpp:ping'
18:32:59,948 | DEBUG | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat016.researchstudio.at timed out, closing
18:33:19,938 | INFO  | stanza.server | iq.id='xmppping-f2619e88-fb20-**
4dd7-9717-c3f815ce48b5'.to='sa**t016.researchstudio.at<http://sat016.researchstudio.at>
'.from='**sat001.researchstudio.at <http://sat001.researchstudio.at>'.**
type='get'.ping.xmlns='urn:**xmpp:ping'
18:33:19,952 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <iq xmlns="jabber:client"
id="xmppping-f2619e88-fb20-**4dd7-9717-c3f815ce48b5" to="
sat001.researchstudio.at" from="sat016.researchstudio.at**"
type="error"><ping xmlns="urn:xmpp:ping"></ping><**error
type="cancel"><service-**unavailable xmlns="urn:ietf:params:xml:ns:**
xmpp-stanzas"></service-**unavailable></error></iq>
18:33:19,955 | INFO  | stanza.client | iq.id='xmppping-f2619e88-fb20-**
4dd7-9717-c3f815ce48b5'.to='sa**t001.researchstudio.at<http://sat001.researchstudio.at>
'.from='**sat016.researchstudio.at <http://sat016.researchstudio.at>'.**
type='error'.ping.xmlns='urn:**xmpp:ping'
18:33:29,940 | DEBUG | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat016.researchstudio.at timed out, closing

<<<<<<<

receiver side: sat016

18:32:14,604 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = INITIATED
18:32:14,628 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:stream xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>" to="
sat016.researchstudio.at" xml:lang="en_US" from="sat001.researchstudio.at
**" version="1.0"></stream:stream>
18:32:14,629 | INFO  | stanza.client | stream
18:32:14,633 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = STARTED
18:32:14,639 | INFO  | stanza.server | stream.starttls
18:32:14,654 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <starttls xmlns="urn:ietf:params:xml:ns:**
xmpp-tls"></starttls>
18:32:14,655 | INFO  | stanza.client | starttls
18:32:14,656 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = ENCRYPTION_STARTED
18:32:14,763 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = ENCRYPTED
18:32:14,764 | INFO  | stanza.server | proceed
18:32:14,820 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:stream xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>" to="
sat016.researchstudio.at" xml:lang="en_US" from="sat001.researchstudio.at
**" version="1.0"></stream:stream>
18:32:14,820 | INFO  | stanza.client | stream
18:32:14,828 | INFO  | stanza.server | stream
18:32:14,863 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <db:result xmlns:db="jabber:server:**dialback"
to="sat016.researchstudio.at" from="sat001.researchstudio.at**">**
497e1dd09d8db2786b922755f8fc55**5140672bf2588d8896791a0f9b8974**
3790</db:result>
18:32:14,864 | INFO  | stanza.client | result
18:32:14,881 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| Starting XMPP server connector to sat001.researchstudio.at
18:32:15,132 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| Connecting to XMPP server sat001.researchstudio.at at
sat001.researchstudio.at/192.**168.124.33:5269<http://sat001.researchstudio.at/192.168.124.33:5269>
18:32:15,200 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = INITIATED
18:32:15,200 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = INITIATED
18:32:15,202 | INFO  | stanza.server | stream
18:32:15,213 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:stream xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>" id="**
32d6ec05c852454389ee1e07ebd077**f3" from="sat001.researchstudio.at**"
version="1.0"></stream:stream>
18:32:15,215 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <stream:features xmlns:stream="http://etherx.**
jabber.org/streams <http://etherx.jabber.org/streams>"><starttls
xmlns="urn:ietf:params:xml:ns:**xmpp-tls"></starttls><dialback
xmlns="urn:xmpp:features:**dialback"></dialback></stream:**features>
18:32:15,215 | INFO  | stanza.client | stream
18:32:15,216 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = AUTHENTICATED
18:32:15,218 | INFO  | stanza.client | features
18:32:15,223 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat001.researchstudio.at authenticated
18:32:15,228 | INFO  | stanza.server | verify
18:32:15,241 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <db:verify xmlns:db="jabber:server:**dialback"
id="**b02adac84032499595d393c3bc3b53**b1" to="sat016.researchstudio.at"
from="sat001.researchstudio.at**" type="valid"></db:verify>
18:32:15,242 | INFO  | stanza.client | verify
18:32:15,243 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = AUTHENTICATED
18:32:15,245 | INFO  | stanza.server | result
18:32:15,248 | WARN  | org.apache.vysper.xmpp.**
modules.core.base.handler.**XMPPCoreStanzaHandler | no 'from' attribute,
and cannot uniquely determine sending resource for initiating entity
sat001.researchstudio.at in session 32d6ec05c852454389ee1e07ebd077**f3
18:32:15,249 | DEBUG | org.apache.vysper.xmpp.**protocol.SessionStateHolder
| session state changed to = CLOSED
18:32:15,250 | INFO  | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector socket closed, closing connector
18:32:15,378 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <message xmlns="jabber:server" to="
user2@sat016.**researchstudio.at <[email protected]>"
id="ab04a" from="user1@sat001.**researchstudio.at/**
8235cb3fd07f41d68ce1956fc37d9f**0e<http://[email protected]/8235cb3fd07f41d68ce1956fc37d9f0e>
"><subject>hi</subject><**body>hi user 2</body><nick xmlns="
http://jabber.org/**protocol/nick <http://jabber.org/protocol/nick>
">user1</nick></**message>
18:32:15,379 | INFO  | stanza.client | message.subject
18:32:15,386 | INFO  | stanza.server | message.subject
18:32:45,385 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <iq xmlns="jabber:server"
id="xmppping-ddf6883f-8443-**487a-82e9-1fc25f466e9d" to="
sat016.researchstudio.at" from="sat001.researchstudio.at**"
type="get"><ping xmlns="urn:xmpp:ping"></ping><**/iq>
18:32:45,388 | INFO  | stanza.client | iq.id='xmppping-ddf6883f-8443-**
487a-82e9-1fc25f466e9d'.to='sa**t016.researchstudio.at<http://sat016.researchstudio.at>
'.from='**sat001.researchstudio.at <http://sat001.researchstudio.at>'.**
type='get'.ping.xmlns='urn:**xmpp:ping'
18:32:45,393 | INFO  | stanza.server | iq.id='xmppping-ddf6883f-8443-**
487a-82e9-1fc25f466e9d'.to='sa**t001.researchstudio.at<http://sat001.researchstudio.at>
'.from='**sat016.researchstudio.at <http://sat016.researchstudio.at>'.**
type='error'.ping.xmlns='urn:**xmpp:ping'
18:32:55,232 | DEBUG | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat001.researchstudio.at timed out, closing
18:33:15,376 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <iq xmlns="jabber:server"
id="xmppping-f2619e88-fb20-**4dd7-9717-c3f815ce48b5" to="
sat016.researchstudio.at" from="sat001.researchstudio.at**"
type="get"><ping xmlns="urn:xmpp:ping"></ping><**/iq>
18:33:15,377 | INFO  | stanza.client | iq.id='xmppping-f2619e88-fb20-**
4dd7-9717-c3f815ce48b5'.to='sa**t016.researchstudio.at<http://sat016.researchstudio.at>
'.from='**sat001.researchstudio.at <http://sat001.researchstudio.at>'.**
type='get'.ping.xmlns='urn:**xmpp:ping'
18:33:15,381 | INFO  | stanza.server | iq.id='xmppping-f2619e88-fb20-**
4dd7-9717-c3f815ce48b5'.to='sa**t001.researchstudio.at<http://sat001.researchstudio.at>
'.from='**sat016.researchstudio.at <http://sat016.researchstudio.at>'.**
type='error'.ping.xmlns='urn:**xmpp:ping'
18:33:25,228 | DEBUG | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat001.researchstudio.at timed out, closing
18:33:45,376 | DEBUG | org.apache.vysper.xml.decoder.**XMPPContentHandler
| Decoder writing stanza: <iq xmlns="jabber:server"
id="xmppping-6d5a633e-c15c-**40f9-ac8b-27ce85ffeb60" to="
sat016.researchstudio.at" from="sat001.researchstudio.at**"
type="get"><ping xmlns="urn:xmpp:ping"></ping><**/iq>
18:33:45,377 | INFO  | stanza.client | iq.id='xmppping-6d5a633e-c15c-**
40f9-ac8b-27ce85ffeb60'.to='sa**t016.researchstudio.at<http://sat016.researchstudio.at>
'.from='**sat001.researchstudio.at <http://sat001.researchstudio.at>'.**
type='get'.ping.xmlns='urn:**xmpp:ping'
18:33:45,381 | INFO  | stanza.server | iq.id='xmppping-6d5a633e-c15c-**
40f9-ac8b-27ce85ffeb60'.to='sa**t001.researchstudio.at<http://sat001.researchstudio.at>
'.from='**sat016.researchstudio.at <http://sat016.researchstudio.at>'.**
type='error'.ping.xmlns='urn:**xmpp:ping'
18:33:55,228 | DEBUG | 
org.apache.vysper.xmpp.server.**s2s.DefaultXMPPServerConnector
| XMPP server connector to sat001.researchstudio.at timed out, closing

Re: S2S connection problem, no 'from' attribute

Reply via email to