Re: S2S connection problem, no 'from' attribute

Dave Fri, 07 Jun 2013 11:24:25 -0700

Hi Ashkan,

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


sessionContext.endSession(SessionTerminationCause.CLIENT_BYEBYE);

As a result, the session context then tries to send an UNAVAILABLEpresence stanza, I guess informing the other end that we're goingoff-line - which seems odd given the connection has only just beeninitiated. Iirc, this presence stanza is sent by the server, ratherthan a specific user - which might be why the 'from' attribute iscomplained about? Looking at the comments, the code is expecting to usethis unavailable presence stanza for client connections, so maybe itshouldn't be sent for server connections at all?

I don't know vysper or the xmpp spec's well enough to understand whatshould be happening here, but maybe the above gives someone else an ideaabout 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]" to 
"[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="[email protected]"><subject>hi</subject><body>hi user 2</body><nick 
xmlns="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
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"; id="b02adac84032499595d393c3bc3b53b1" 
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";><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"; id="b02adac84032499595d393c3bc3b53b1" 
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";><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"; 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="b02adac84032499595d393c3bc3b53b1" to="sat001.researchstudio.at" 
from="sat016.researchstudio.at">497e1dd09d8db2786b922755f8fc555140672bf2588d8896791a0f9b89743790</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="[email protected]/8235cb3fd07f41d68ce1956fc37d9f0e" from="sat016.researchstudio.at" type="error"><subject>hi</subject><body>hi user 2</body><nick 
xmlns="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='sat016.researchstudio.at'.from='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='sat001.researchstudio.at'.from='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='sat016.researchstudio.at'.from='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='sat001.researchstudio.at'.from='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"; 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"; 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">497e1dd09d8db2786b922755f8fc555140672bf2588d8896791a0f9b89743790</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
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"; id="32d6ec05c852454389ee1e07ebd077f3" 
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";><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="b02adac84032499595d393c3bc3b53b1" 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 32d6ec05c852454389ee1e07ebd077f3
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="[email protected]" id="ab04a" 
from="[email protected]/8235cb3fd07f41d68ce1956fc37d9f0e"><subject>hi</subject><body>hi user 2</body><nick 
xmlns="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='sat016.researchstudio.at'.from='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='sat001.researchstudio.at'.from='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='sat016.researchstudio.at'.from='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='sat001.researchstudio.at'.from='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='sat016.researchstudio.at'.from='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='sat001.researchstudio.at'.from='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