Project

General

Profile

Message not delivered until stream management timeout time expires

Luca Stucchi
Added almost 4 years ago

Hi there,

I am experiencing a curious behavior and I wanted to ask you if this is expected or not, and how to improve the situation.

Let me go straight to the issue: I am testing on Tigase 7.0.0 this scenario, with Stream Management on both on server and client:

  • A mobile device is logged in the server.

  • That device successfully logs out and correctly announces the disconnection

  • After a few seconds I send a message to that user (same resource)

  • The message can't be delivered, but it's not persisted immediately on the DB (I kinda expected it, but it does not happen)

  • After the stream management timeout triggers, the message is either persisted (if the device didn't return online) or sent directly to the device

Is this behavior correct or at least expected ?

Is there a way to activate the stream management that does not imply waiting the timeout before receiving such a message for users that correctly logged out of the server ?

Below there is an extract of the logs in which we see that

2015-04-16 15:20:21.503 [pool-14-thread-1]  StreamManagementIOProcessor.serviceStopped()  FINEST: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, type: accept, Socket: TLS: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029 Socket[unconnected], jid: user@vhost.acme.net/XMPPFramework, service stopped - checking resumption timeout
2015-04-16 15:21:21.503 [scheduler_pool-6-thread-1-c2s]  ConnectionManager.serviceStopped()  FINER: [[c2s]] Connection stopped: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, type: accept, Socket: TLS: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029 Socket[unconnected], jid: user@vhost.acme.net/XMPPFramework
2015-04-16 15:21:21.503 [scheduler_pool-6-thread-1-c2s]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029
2015-04-16 15:21:21.504 [scheduler_pool-6-thread-1-c2s]  ClientConnectionManager.xmppStreamClosed()  FINE: Service stopped, sending packet: from=c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, to=sess-man@localhost, DATA=<iq from="c2s@localhost/172.31.18.86_5222_151.44.133.199_63029" to="sess-man@localhost" id="ecd44759-4cf1-4ec8-ad98-ab25f43b006a" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>user@vhost.acme.net/XMPPFramework</value></field></x></command></iq>, SIZE=356, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-16 15:21:21.504 [scheduler_pool-6-thread-1-c2s]  StreamManagementIOProcessor.serviceStopped()  FINEST: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, type: accept, Socket: TLS: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029 Socket[unconnected], jid: user@vhost.acme.net/XMPPFramework, service stopped - checking resumption timeout
2015-04-16 15:21:21.504 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, to=sess-man@localhost, DATA=<iq from="c2s@localhost/172.31.18.86_5222_151.44.133.199_63029" to="sess-man@localhost" id="ecd44759-4cf1-4ec8-ad98-ab25f43b006a" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>user@vhost.acme.net/XMPPFramework</value></field></x></command></iq>, SIZE=356, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-16 15:21:21.504 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@localhost
2015-04-16 15:21:21.504 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@localhost
2015-04-16 15:21:21.504 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@localhost, from=c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, to=sess-man@localhost, DATA=<iq from="c2s@localhost/172.31.18.86_5222_151.44.133.199_63029" to="sess-man@localhost" id="ecd44759-4cf1-4ec8-ad98-ab25f43b006a" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>user@vhost.acme.net/XMPPFramework</value></field></x></command></iq>, SIZE=356, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-16 15:21:21.504 [in_6-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, to=sess-man@localhost, DATA=<iq from="c2s@localhost/172.31.18.86_5222_151.44.133.199_63029" to="sess-man@localhost" id="ecd44759-4cf1-4ec8-ad98-ab25f43b006a" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>CData size: 38</value></field></x></command></iq>, SIZE=356, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-16 15:21:21.504 [in_6-sess-man]    SessionManager.processCommand()    FINER:    STREAM_CLOSED command from: c2s@localhost/172.31.18.86_5222_151.44.133.199_63029
2015-04-16 15:21:21.504 [session-close Queue Worker 3]  SessionManager$SessionCloseProc.process()  FINEST: Executing connection close for: from=c2s@localhost/172.31.18.86_5222_151.44.133.199_63029, to=sess-man@localhost, DATA=<iq from="c2s@localhost/172.31.18.86_5222_151.44.133.199_63029" to="sess-man@localhost" id="ecd44759-4cf1-4ec8-ad98-ab25f43b006a" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>user@vhost.acme.net/XMPPFramework</value></field></x></command></iq>, SIZE=356, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

Thanks in advance,

Luca


Replies (9)

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam almost 4 years ago

I never have a case in which proper device logout caused stream resumption to keep stream open. In every case in 7.0.0 when stream was closed properly then stream resumption did not start resumption timeout as this timeout is only started when client closes connection without sending stream termination, but if XMPP client fails to send:

</stream:stream>

then stream management starts timeout which will lead to this behavior.

From attached log I cannot say if client sent stream termination as this was in log before attached part. This part only shows handling of stream termination due to TCP connection disconnection.

As for keeping messages in memory during stream management timeout - this is correct and expected behavior.

Added by Luca Stucchi almost 4 years ago

Hi Andrzej,

I found this row in the logs, but it looks like this is the server sending something to the client, while you suggested to look at something on the opposite way:

2015-04-17 10:55:22.595 [in_2-c2s]         ClientConnectionManager.processCommand()  FINEST: Sending stream close to the client: <stream:error><conflict xmlns="urn:ietf:params:xml:ns:xmpp-streams"/></stream:error></stream:stream>

Does this mean that the server received the message and that answered back or there is something missing ?

BTW, if I reconnect I find the row:

2015-04-17 10:56:19.896 [pool-14-thread-5]  ClientConnectionManager.xmppStreamOpened()  FINER: Writing raw data to the socket: <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' from='vhost.acme.net' id='7a01531d-5610-41e1-b5f4-ff054c8dcfd1' version='1.0' xml:lang='en'>

But this is just the stream opening, nothing related with the logout process.

Does this give you any hint to see if there is something wrong going on ?

Thanks in advance,

Luca

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam almost 4 years ago

The first log entry, stream error: conflict means that there was a new user's connection opened for a resource for which a connection was already open. So the server sends a stream error to the old connection to close it, as there is a new connection active for the resource.

Added by Luca Stucchi almost 4 years ago

Hi Artur,

let me be more precise, so that I can explain better the situation: I made a fresh attempt being sure that I am using Stream Management in both server and client, and here is an extensive log of the operations that I read in the application log at connection and disconnection time:

11:34:59 AM SENT (0): <stream:stream xmlns='jabber:client' to='virtualhost.domain.tld' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en'>
11:34:59 AM RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' from='virtualhost.domain.tld' id='8705778f-0439-4905-85df-1d0cea6aad87' version='1.0' xml:lang='en'>
11:34:59 AM RECV (0): <stream:features><sm xmlns="urn:xmpp:sm:3"/><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/><ver xmlns="urn:xmpp:features:rosterver"/><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required/></starttls><compression xmlns="http://jabber.org/features/compress"><method>zlib</method></compression></stream:features>
11:34:59 AM SENT (0): <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'></starttls>
11:34:59 AM RECV (0): <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>
11:34:59 AM SENT (0): <stream:stream xmlns='jabber:client' to='virtualhost.domain.tld' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' xml:lang='en'>
11:34:59 AM RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' from='virtualhost.domain.tld' id='8705778f-0439-4905-85df-1d0cea6aad87' version='1.0' xml:lang='en'>
11:34:59 AM RECV (0): <
11:34:59 AM RECV (0): stream:features><sm xmlns="urn:xmpp:sm:3"/><auth xmlns="http://jabber.org/features/iq-auth"/><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms><ver xmlns="urn:xmpp:features:rosterver"/><compression xmlns="http://jabber.org/features/compress"><method>zlib</method></compression></stream:features>
11:34:59 AM SENT (0): <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN'>foofoofoo==</auth>
11:34:59 AM RECV (0): <
11:34:59 AM RECV (0): success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/>
11:34:59 AM SENT (0): <stream:stream xmlns='jabber:client' to='virtualhost.domain.tld' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' id='8705778f-0439-4905-85df-1d0cea6aad87' xml:lang='en'>
11:34:59 AM RECV (0): <
11:34:59 AM RECV (0): ?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' from='virtualhost.domain.tld' id='8705778f-0439-4905-85df-1d0cea6aad87' version='1.0' xml:lang='en'>
11:34:59 AM RECV (0): <
11:34:59 AM RECV (0): stream:features><sm xmlns="urn:xmpp:sm:3"/><ver xmlns="urn:xmpp:features:rosterver"/><compression xmlns="http://jabber.org/features/compress"><method>zlib</method></compression><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></stream:features>
11:34:59 AM SENT (0): <compress xmlns='http://jabber.org/protocol/compress'><method>zlib</method></compress>
11:34:59 AM RECV (0): <
11:34:59 AM RECV (0): compressed xmlns="http://jabber.org/protocol/compress"/>
11:34:59 AM SENT (0): <stream:stream xmlns='jabber:client' to='virtualhost.domain.tld' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' id='8705778f-0439-4905-85df-1d0cea6aad87' xml:lang='en'>
11:35:00 AM RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' from='virtualhost.domain.tld' id='8705778f-0439-4905-85df-1d0cea6aad87' version='1.0' xml:lang='en'>
11:35:00 AM RECV (0): <stream:features><sm xmlns="urn:xmpp:sm:3"/><ver xmlns="urn:xmpp:features:rosterver"/><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/></stream:features>
11:35:00 AM SENT (0): <iq id='9aXNX-3' type='set'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><resource>Smack</resource></bind></iq>
11:35:00 AM RECV (0): <iq xmlns="jabber:client" id="9aXNX-3" to="103@virtualhost.domain.tld/Smack" type="result"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>103@virtualhost.domain.tld/Smack</jid></bind></iq>
11:35:00 AM SENT (0): <iq id='9aXNX-5' type='set'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></iq>
11:35:00 AM RECV (0): <iq xmlns="jabber:client" id="9aXNX-5" to="103@virtualhost.domain.tld/Smack" type="result"/>
11:35:00 AM SENT (0): <enable xmlns='urn:xmpp:sm:3' resume='true'/>
11:35:00 AM RECV (0): <enabled xmlns='urn:xmpp:sm:3' id='42256f2b-2f3b-4ccf-a747-04ff29c5171e' resume='true' max='60' location='localhost' />
11:35:00 AM User logged (0): 103@virtualhost.domain.tld:5222/Smack
11:35:00 AM XMPPConnection authenticated (0)
11:35:00 AM SENT (0): <iq id='9aXNX-7' type='get'><query xmlns='jabber:iq:roster'></query></iq>
11:35:00 AM SENT (0): <presence id='9aXNX-8'><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.igniterealtime.org/projects/smack' ver='NfJ3flI83zSdUDzCEICtbypursw='/></presence>
11:35:00 AM RECV (0): <iq xmlns="jabber:client" id="9aXNX-7" to="103@virtualhost.domain.tld/Smack" type="result"><query xmlns="jabber:iq:roster"/></iq>
11:35:00 AM RECV (0): <presence xmlns="jabber:client" id="9aXNX-8" from="103@virtualhost.domain.tld/Smack" to="103@virtualhost.domain.tld"><c xmlns="http://jabber.org/protocol/caps" node="http://www.igniterealtime.org/projects/smack" hash="sha-1" ver="NfJ3flI83zSdUDzCEICtbypursw="/></presence>
11:35:05 AM SENT (0): <presence id='9aXNX-11' type='unavailable'><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.igniterealtime.org/projects/smack' ver='NfJ3flI83zSdUDzCEICtbypursw='/></presence>
11:35:05 AM SENT (0): <a xmlns='urn:xmpp:sm:3' h='2'/>
11:35:05 AM SENT (0): </stream:stream>
11:35:05 AM XMPPConnection closed 

it looks like the stream is closed (but please, correct me if I am wrong, I would even be glad of finding out it !). Nevertheless after 60 seconds I gee this flow of messages in Tigase, which includes the DB storing notification

2015-04-20 10:04:11.723 [scheduler_pool-6-thread-1-c2s]  ConnectionManager.serviceStopped()  FINER: [[c2s]] Connection stopped: c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, type: accept, Socket: TLS: c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030 Socket[unconnected], jid: 103@virtualhost.domain.tld/XMPPFramework
2015-04-20 10:04:11.723 [scheduler_pool-6-thread-1-c2s]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030
2015-04-20 10:04:11.724 [scheduler_pool-6-thread-1-c2s]  ClientConnectionManager.xmppStreamClosed()  FINE: Service stopped, sending packet: from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=sess-man@domain.tld, DATA=<iq type="set" from="c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030" id="43999bf9-2a55-425a-af2f-ec6f1dc22490" to="sess-man@domain.tld"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>103@virtualhost.domain.tld/XMPPFramework</value></field></x></command></iq>, SIZE=360, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-20 10:04:11.724 [scheduler_pool-6-thread-1-c2s]  StreamManagementIOProcessor.serviceStopped()  FINEST: c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, type: accept, Socket: TLS: c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030 Socket[unconnected], jid: 103@virtualhost.domain.tld/XMPPFramework, service stopped - checking resumption timeout
2015-04-20 10:04:11.724 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=sess-man@domain.tld, DATA=<iq type="set" from="c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030" id="43999bf9-2a55-425a-af2f-ec6f1dc22490" to="sess-man@domain.tld"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>103@virtualhost.domain.tld/XMPPFramework</value></field></x></command></iq>, SIZE=360, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@domain.tld
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@domain.tld
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@domain.tld, from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=sess-man@domain.tld, DATA=<iq type="set" from="c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030" id="43999bf9-2a55-425a-af2f-ec6f1dc22490" to="sess-man@domain.tld"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>103@virtualhost.domain.tld/XMPPFramework</value></field></x></command></iq>, SIZE=360, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=null, DATA=<message xmlns="jabber:client" id="aad2a" to="103@virtualhost.domain.tld" from="admin@domain.tld/iMac-di-foo">
<subject>test psi</subject><body>test psi</body><nick xmlns="http://jabber.org/protocol/nick">admin</nick><delivery-error xmlns="http://tigase.org/delivery-error"/></message>, SIZE=274, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : 103@virtualhost.domain.tld
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): 103@virtualhost.domain.tld, for map: [amp@domain.tld, ws2s@domain.tld, monitor@domain.tld, sess-man@domain.tld, bosh@domain.tld, c2s@domain.tld, stats@domain.tld, basic-conf@domain.tld, vhost-man@domain.tld, s2s@domain.tld, androidrepushcomponent@domain.tld, bootstrapcomponent@domain.tld]; trying VHost lookup
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): 103@virtualhost.domain.tld, for map: [validitycomponent, vhost-man, c2s, amp, monitor, ws2s, bosh, bootstrapcomponent, stats, s2s, basic-conf, fallbackcomponent, sess-man, message-router, androidrepushcomponent], for all VHosts: [domain.tld, virtualhost.domain.tld]; trying other forms of addressing
2015-04-20 10:04:11.725 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: 103@virtualhost.domain.tld, for comp: [validitycomponent, vhost-man, c2s, amp, monitor, ws2s, bosh, bootstrapcomponent, stats, s2s, basic-conf, fallbackcomponent, sess-man, message-router, androidrepushcomponent], basename: domain.tld
2015-04-20 10:04:11.726 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : 103@virtualhost.domain.tld
2015-04-20 10:04:11.726 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): 103@virtualhost.domain.tld, for map: [ amp@domain.tld, ws2s@domain.tld, monitor@domain.tld, sess-man@domain.tld, bosh@domain.tld, c2s@domain.tld, stats@domain.tld, basic-conf@domain.tld, vhost-man@domain.tld, s2s@domain.tld, androidrepushcomponent@domain.tld, bootstrapcomponent@domain.tld]; trying VHost lookup
2015-04-20 10:04:11.726 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): 103@virtualhost.domain.tld, for map: [validitycomponent, vhost-man, c2s, amp, monitor, ws2s, bosh, bootstrapcomponent, stats, s2s, basic-conf, fallbackcomponent, sess-man, message-router, androidrepushcomponent], for all VHosts: [domain.tld, virtualhost.domain.tld]; trying other forms of addressing
2015-04-20 10:04:11.726 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: 103@virtualhost.domain.tld, for comp: [validitycomponent, vhost-man, c2s, amp, monitor, ws2s, bosh, bootstrapcomponent, stats, s2s, basic-conf, fallbackcomponent, sess-man, message-router, androidrepushcomponent], basename: domain.tld
2015-04-20 10:04:11.726 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   2. Packet will be processed by: sess-man@domain.tld, from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=null, DATA=<message xmlns="jabber:client" id="aad2a" to="103@virtualhost.domain.tld" from="admin@domain.tld/iMac-di-foo">
<subject>test psi</subject><body>test psi</body><nick xmlns="http://jabber.org/protocol/nick">admin</nick><delivery-error xmlns="http://tigase.org/delivery-error"/></message>, SIZE=274, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2015-04-20 10:04:11.725 [in_10-sess-man]   SessionManager.processPacket()     FINEST:   Received packet: from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=sess-man@domain.tld, DATA=<iq type="set" from="c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030" id="43999bf9-2a55-425a-af2f-ec6f1dc22490" to="sess-man@domain.tld"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>CData size: 38</value></field></x></command></iq>, SIZE=360, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-20 10:04:11.727 [in_10-sess-man]   SessionManager.processCommand()    FINER:    STREAM_CLOSED command from: c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030
2015-04-20 10:04:11.727 [in_10-sess-man]   SessionManager.processPacket()     FINEST:   Received packet: from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=null, DATA=<message xmlns="jabber:client" id="aad2a" to="103@virtualhost.domain.tld" from="admin@domain.tld/iMac-di-foo">
<subject>test psi</subject><body>test psi</body><nick xmlns="http://jabber.org/protocol/nick">CData size: 5</nick><delivery-error xmlns="http://tigase.org/delivery-error"/></message>, SIZE=274, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2015-04-20 10:04:11.727 [in_10-sess-man]   SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: 103@virtualhost.domain.tld
2015-04-20 10:04:11.727 [in_10-sess-man]   SessionManager.getResourceConnection()  FINEST: Session not null, searching session for jid: 103@virtualhost.domain.tld
2015-04-20 10:04:11.727 [in_10-sess-man]   SessionManager.getResourceConnection()  FINEST: Found session: null, for jid: 103@virtualhost.domain.tld
2015-04-20 10:04:11.728 [in_10-sess-man]   JDBCMsgRepository.storeMessage()   FINEST:   Storring expired: null message: <message xmlns="jabber:client" id="aad2a" to="103@virtualhost.domain.tld" from="admin@domain.tld/iMac-di-foo">
<subject>test psi</subject><body>test psi</body><nick xmlns="http://jabber.org/protocol/nick">admin</nick><delivery-error xmlns="http://tigase.org/delivery-error"/><delay xmlns="urn:xmpp:delay" stamp="2015-04-20T10:04:11.728Z" from="virtualhost.domain.tld">Offline Storage - domain.tld</delay></message>
2015-04-20 10:04:11.727 [session-close Queue Worker 3]  SessionManager$SessionCloseProc.process()  FINEST: Executing connection close for: from=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, to=sess-man@domain.tld, DATA=<iq type="set" from="c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030" id="43999bf9-2a55-425a-af2f-ec6f1dc22490" to="sess-man@domain.tld"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>103@virtualhost.domain.tld/XMPPFramework</value></field></x></command></iq>, SIZE=360, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-04-20 10:04:11.728 [session-close Queue Worker 3]  SessionManager.closeConnection()  FINER: Stream closed from: c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030
2015-04-20 10:04:11.728 [session-close Queue Worker 3]  SessionManager.closeSession()  FINE: Closing connection for: 103@virtualhost.domain.tld/XMPPFramework
2015-04-20 10:04:11.728 [session-close Queue Worker 3]  SessionManager.closeSession()  FINE: Found parent session for: 103@virtualhost.domain.tld/XMPPFramework
2015-04-20 10:04:11.728 [session-close Queue Worker 3]  SessionManager.closeSession()  FINER: Number of user sessions: 4
2015-04-20 10:04:11.728 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=sess-man@domain.tld, to=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, DATA=<iq type="result" id="43999bf9-2a55-425a-af2f-ec6f1dc22490" from="sess-man@domain.tld" to="c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030"/>, SIZE=149, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=result
2015-04-20 10:04:11.729 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030
2015-04-20 10:04:11.729 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, for map: [ amp@domain.tld, ws2s@domain.tld, monitor@domain.tld, sess-man@domain.tld, bosh@domain.tld, c2s@domain.tld, stats@domain.tld, basic-conf@domain.tld, vhost-man@domain.tld, s2s@domain.tld, androidrepushcomponent@domain.tld, bootstrapcomponent@domain.tld]; trying VHost lookup
2015-04-20 10:04:11.729 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030
2015-04-20 10:04:11.729 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, for map: [ amp@domain.tld, ws2s@domain.tld, monitor@domain.tld, sess-man@domain.tld, bosh@domain.tld, c2s@domain.tld, stats@domain.tld, basic-conf@domain.tld, vhost-man@domain.tld, s2s@domain.tld, androidrepushcomponent@domain.tld, bootstrapcomponent@domain.tld]; trying VHost lookup
2015-04-20 10:04:11.729 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: c2s@domain.tld, from=sess-man@domain.tld, to=c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030, DATA=<iq type="result" id="43999bf9-2a55-425a-af2f-ec6f1dc22490" from="sess-man@domain.tld" to="c2s@domain.tld/172.31.18.86_5222_10.0.0.2_13030"/>, SIZE=149, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=result
2015-04-20 10:04:11.730 [in_2-c2s]         ClientConnectionManager$StoppedHandler.responseReceived()  FINEST: Response for stop received...

Do you see anything wrong / unexpected in these logs ?

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam almost 4 years ago

Hi,

are both logs from same attemept? I ask as you say 60seconds while I see bigger difference between server and client logs?

Log from client side looks correct however Tigase XMPP Server should receive

</stream:stream>

but I do not see in logs from server side that it received.

This might be an issue on client side in which client writes data to Socket instance but as socket usually is buffering data, then fast call to close the socket may cause some data to not be sent from socket buffer to network.

Added by Luca Stucchi over 3 years ago

Hi there,

I replicated the test disabling TLS in order to be able to use wireshark and sniff the packets going back and forth.

Disabling TLS, as you can see in the image below, the client sends a

and the server answers with a similar message. Notice that I can't find any reference to this message exchange in tigase logs, could you please verify that those message are logged ? (I suspect that they are not)

!image2.png!

So, disabling TLS all the expected messages are exchanged and, unexpectedly, if I send a message right after the disconnection I find it in the *msg_history*, immediately ! 

Now, this could mean that TLS is somehow interfering with the stream closure, or that in this particular situation Tigase stream management does not work in the correct way.

Re-enabling TLS bring us back in a state in which the timeout must be reached in order to have the message stored.
I considered the fact that the client library could be bugged, so I repeated the same test with another library, with the same results.

So, summing up, if I disable TLS stream management works as expected. If I enable it, two client libraries (Smack and XMPPFramework) fail and make us wait until the stream management timeout is reached to have the message stored, as if Tigase didn't receive the </stream:stream> XML

Does this ring any bell ? Could you please verify that everything is fine in the code in this particular scenario (I tried to narrow it as much as I could)

If I have to open an issue, or whatever else, please let me know

Thanks in advance for your help and your support,
  Luca

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam over 3 years ago

Hi,

I checked code once again and it worked fine in my test case, so I checked how Smack and XMPPFramework implemented way of closing XMPP stream. Both libraries decided to send /stream:stream and just after that close TCP connection, while RFC6120 says:

4.4. Closing a Stream

An XML stream from one entity to another can be closed at any time,

either because a specific stream error (Section 4.9) has occurred or

in the absence of an error (e.g., when a client simply ends its

session).

A stream is closed by sending a closing tag.

E: /stream:stream

If the parties are using either two streams over a single TCP

connection or two streams over two TCP connections, *the entity that

sends the closing stream tag MUST behave as follows:

  1. Wait for the other party to also close its outbound stream before

terminating the underlying TCP connection(s); this gives the

other party an opportunity to finish transmitting any outbound

data to the closing entity before the termination of the TCP

connection(s).*

  1. Refrain from sending any further data over its outbound stream to

the other entity, but continue to process data received from the

other entity (and, if necessary, process such data).

  1. Consider both streams to be void if the other party does not send

its closing stream tag within a reasonable amount of time (where

the definition of "reasonable" is a matter of implementation or

deployment).

  1. After receiving a reciprocal closing stream tag from the other

party or waiting a reasonable amount of time with no response,

terminate the underlying TCP connection(s).

Security Warning: In accordance with Section 7.2.1 of [TLS], to

help prevent a truncation attack the party that is closing the

stream MUST send a TLS close_notify alert and MUST receive a

responding close_notify alert from the other party before

terminating the underlying TCP connection(s).

That in fact means that both libraries do not respect how RFC6120 defines way of closing XMPP stream.

I suppose that more than this two libararies may implement closing XMPP stream, so I created task #3017 to prepare workaround for this non standard way of closing XMPP stream and make it work with Stream Management implemented in Tigase XMPP Server properly

Added by Luca Stucchi over 3 years ago

Hey Andrzej !

this was unexpected, but it is completely coherent with the tests I performed ! Thanks for creating the task, if you need a tester, you can count on me !

All the best,

Luca

Added by Luca Stucchi over 3 years ago

Hi Andrzej

I am happy to confirm that using a version including your patch it now works perfectly, immediately storing the messages when we use TLS too !

Well done !

Luca

    (1-9/9)