search

tst2005googlecode2 / lxmppd

Automatically exported from code.google.com/p/lxmppd
0 stars 0 forks source link

[mod_smacks] Errors when resuming a stream (by means of XEP-198) and using compression. #433

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago 
I'm currently working on XEP-0198 support for Smack and discovered the 
following problem: If a stream gets resumed (XEP-198) and compression is used, 
prosody 0.9.4 with mod_smacks as of today will reliable report an error and 
close the stream. The type of error is not-deterministic and either
- Received invalid XML (not well-formed (invalid token))
- IllegalState: calling inflate function when stream was previously closed

The not-well-formed stanza looks for example like this:
"<message ></m03V1e-14esenceflo@fo@s up? I&apos;ve been just instantly 
shutdown</body></message>"
Note the corruption of the string, that looks like the message stanza got 
merged with a presence stanza.

Although I can't rule out for sure that this is a issues with the, currently 
under development, XEP-198 support in Smack, there is some evidence that it's a 
prosody issue: 1. The exact same code does work with tigase 2. There are 
different error messages 3. Compression works with prosody, it just doesn't 
work if the stream just got resumed

Attached to this issue report is a file with 3 full traces of an XEP198 session 
with compression that get's resumed. 2 traces show prosody failing, while the 
third is the exact same code run against a tigase server. Also attached is 
raw_compressed_send_data containing the raw TCP payload send by the client 
after it received the <compressed> element from the server. Here prosody 
reports invalid-xml. But using "cat raw_compressed_send_data | openssl zlib -d" 
we see that the xml is in fact well formed.

inputmice (of conversations) points out in chat that he remembers having a 
similar issue which was fixed by using Deflater.FULL_FLUSH and not .SYNC_FLUSH 
( 
https://github.com/siacs/Conversations/commit/c82c6251b8c48692bb929436aa7ff0449b
9e86f3 ). Smack in fact uses SYNC_FLUSH for optimum compression efficiency. But 
the question is why compression works after the stream is initially established 
and fails when it is resumed.

Original issue reported on code.google.com by fschm...@gmail.com on 6 Aug 2014 at 10:39

Attachments:

GoogleCodeExporter commented 9 years ago 
I've extended Smack so that I can switch the flush mode between full and sync. 
Stream resumption with compression works with prosody if I set the flush mode 
to full. I know that there are security considerations when using sync flush, 
but please let the client decide which flush mode to use.

This basically changes the issue to "Please support sync flush when resuming 
streams".

Original comment by fschm...@gmail.com on 7 Aug 2014 at 12:46

GoogleCodeExporter commented 9 years ago 
Any news on this? I also run into an issue with SM and Conversations, and would 
like to rule this one out.

Original comment by devuran...@gmx.net on 25 Nov 2014 at 8:43

GoogleCodeExporter commented 9 years ago 
Conversations switched to using full sync because of this a while ago: 
https://github.com/siacs/Conversations/commit/c82c6251b8c48692bb929436aa7ff0449b
9e86f3

Original comment by fschm...@gmail.com on 25 Nov 2014 at 4:05

GoogleCodeExporter commented 9 years ago 
I've tested this, logged two "resume events":

Nov 29 16:19:27 socket  debug   server.lua: accepted new client connection from 
79.205.93.79:59392 to 5222
Nov 29 16:19:27 c2s1ceddb0      info    Client connected
Nov 29 16:19:27 c2s1ceddb0      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:27 c2s1ceddb0      debug   Sent reply <stream:stream> to client
Nov 29 16:19:27 c2s1ceddb0      debug   Received[c2s_unauthed]: <starttls 
xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
Nov 29 16:19:27 socket  debug   server.lua: we need to do tls, but delaying 
until send buffer empty
Nov 29 16:19:27 c2s1ceddb0      debug   TLS negotiation started for 
c2s_unauthed...
Nov 29 16:19:27 socket  debug   server.lua: attempting to start tls on 
tcp{client}: 0x1ae3f68
Nov 29 16:19:28 socket  debug   server.lua: ssl handshake done
Nov 29 16:19:28 c2s1ceddb0      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:28 c2s1ceddb0      debug   Sent reply <stream:stream> to client
Nov 29 16:19:28 c2s1ceddb0      debug   Received[c2s_unauthed]: <auth 
mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Nov 29 16:19:28 example.com:auth_internal_plain debug   get_password for 
username 'xxx' at host 'example.com'
Nov 29 16:19:28 c2s1ceddb0      info    Authenticated as xxx@example.com
Nov 29 16:19:28 example.com:saslauth    debug   sasl reply: <success 
xmlns='urn:ietf:params:xml:ns:xmpp-sasl'></success>
Nov 29 16:19:28 c2s1ceddb0      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:28 c2s1ceddb0      debug   Sent reply <stream:stream> to client
Nov 29 16:19:28 c2s1ceddb0      debug   Received[c2s]: <compress 
xmlns='http://jabber.org/protocol/compress'>
Nov 29 16:19:28 c2s1ceddb0      debug   zlib compression enabled.
Nov 29 16:19:28 c2s1ceddb0      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:28 c2s1ceddb0      debug   Sent reply <stream:stream> to client
Nov 29 16:19:28 c2s1ceddb0      debug   Received[c2s]: <resume h='84' 
previd='217f0d41-c9ea-4482-a457-f3daccad515c' xmlns='urn:xmpp:sm:3'>
Nov 29 16:19:28 c2s1ceddb0      debug   mod_smacks resuming existing session...
Nov 29 16:19:28 c2s1ceddb0      debug   mod_smacks closing an old connection 
for this session
Nov 29 16:19:28 socket  debug   server.lua: closed client handler and removed 
socket from list
Nov 29 16:19:28 c2s1a16f60      debug   Received[c2s]: <a h='84' 
xmlns='urn:xmpp:sm:3'>
Nov 29 16:19:28 c2s1a16f60      debug   #queue = 0
Nov 29 16:19:28 c2s1ceddb0      debug   #queue = 0
Nov 29 16:19:28 c2s1ceddb0      debug   #queue = 0 -- after send

Nov 29 16:19:49 socket  debug   server.lua: accepted new client connection from 
79.205.93.79:33175 to 5222
Nov 29 16:19:49 c2s19aee00      info    Client connected
Nov 29 16:19:49 c2s19aee00      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:49 c2s19aee00      debug   Sent reply <stream:stream> to client
Nov 29 16:19:49 c2s19aee00      debug   Received[c2s_unauthed]: <starttls 
xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
Nov 29 16:19:49 socket  debug   server.lua: we need to do tls, but delaying 
until send buffer empty
Nov 29 16:19:49 c2s19aee00      debug   TLS negotiation started for 
c2s_unauthed...
Nov 29 16:19:49 socket  debug   server.lua: attempting to start tls on 
tcp{client}: 0x21c64e8
Nov 29 16:19:49 socket  debug   server.lua: ssl handshake done
Nov 29 16:19:49 c2s19aee00      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:49 c2s19aee00      debug   Sent reply <stream:stream> to client
Nov 29 16:19:50 c2s19aee00      debug   Received[c2s_unauthed]: <auth 
mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Nov 29 16:19:50 example.com:auth_internal_plain debug   get_password for 
username 'xxx' at host 'example.com'
Nov 29 16:19:50 c2s19aee00      info    Authenticated as xxx@example.com
Nov 29 16:19:50 example.com:saslauth    debug   sasl reply: <success 
xmlns='urn:ietf:params:xml:ns:xmpp-sasl'></success>
Nov 29 16:19:50 c2s19aee00      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:50 c2s19aee00      debug   Sent reply <stream:stream> to client
Nov 29 16:19:50 c2s19aee00      debug   Received[c2s]: <compress 
xmlns='http://jabber.org/protocol/compress'>
Nov 29 16:19:50 c2s19aee00      debug   zlib compression enabled.
Nov 29 16:19:50 c2s19aee00      debug   Client sent opening <stream:stream> to 
example.com
Nov 29 16:19:50 c2s19aee00      debug   Sent reply <stream:stream> to client
Nov 29 16:19:50 c2s19aee00      debug   Received[c2s]: <resume h='84' 
previd='217f0d41-c9ea-4482-a457-f3daccad515c' xmlns='urn:xmpp:sm:3'>
Nov 29 16:19:50 c2s19aee00      debug   mod_smacks resuming existing session...
Nov 29 16:19:50 c2s19aee00      debug   mod_smacks closing an old connection 
for this session
Nov 29 16:19:50 socket  debug   server.lua: closed client handler and removed 
socket from list
Nov 29 16:19:50 c2s1a16f60      debug   Received[c2s]: <a h='84' 
xmlns='urn:xmpp:sm:3'>
Nov 29 16:19:50 c2s1a16f60      debug   #queue = 0
Nov 29 16:19:50 c2s19aee00      debug   #queue = 0
Nov 29 16:19:50 c2s19aee00      debug   #queue = 0 -- after send

If i understand right, the problem may be the closing of the old session after 
establishing the new one even if the new one has the same id as the old one. 
(The previd's are the same in both resumes)

Original comment by alex.gae...@googlemail.com on 29 Nov 2014 at 3:51

GoogleCodeExporter commented 9 years ago 
http://permalink.gmane.org/gmane.network.jabber.prosody.user/1070 may be 
related as well.

I installed mod_smacks today and my client (conversations) seems unable to 
connect until my old session expires (that is, resumption is not working) -- it 
seems that may be related to this ticket? Is there a good workaround?

Original comment by singpol...@gmail.com on 13 Jan 2015 at 2:43

GoogleCodeExporter commented 9 years ago 
Disabling mod_compression seems to be my workaround for now.  Fixes the issue 
for me.  Compression should be done at the TLS layer, anyway

Original comment by step...@boltmade.com on 13 Jan 2015 at 3:00

GoogleCodeExporter commented 9 years ago 
[deleted comment]
GoogleCodeExporter commented 9 years ago 
@MWild1: It appears that your patch (attached) did the trick. I ran my prosody 
with the patch the whole day using Smack+StreamMangement+SyncFlush and the 
error log doesn't show anything. \o/

Original comment by fschm...@gmail.com on 8 Feb 2015 at 4:12

Attachments:

GoogleCodeExporter commented 9 years ago

Original comment by MWild1 on 9 Feb 2015 at 11:27