Smack needs to initiate new stream after establishing TLS session

Andreas_Schildbach · February 28, 2006, 7:17pm

Hello everyone,

Could you have a look at the following thread?

http://mail.jabber.org/pipermail/jabberd/2006-February/003221.html

I’'ll quote Stephen Marquard:

After establishing a TLS session, the client

needs to initiate a new stream before sending any further

stanzas. It looks a bug in that version of Smack.

This is with Smack 2.1.0 and jabberd 2.0s10. The server is configured to offer but not require TLS.

Here is the client code:

connection = new XMPPConnection(host);

connection.login(username, password, resource);

Regards,

Andreas

Gaston_Dombiak · March 2, 2006, 4:36am

Hey Andreas,

Is that the complete log of exchanged packets? I don’‘t see where TLS was negotiated. In fact, I don’'t see that the server and the client are including version=1.0 in the stream header. Can you post the complete set of exchanged stanzas?

Thanks,

– Gato

Andreas_Schildbach · March 2, 2006, 10:46am

The log is the complete set of debug messages that are emitted by c2s -D.

I’‘d prefer to include some debug from Smack as well, but I don’'t know how to trace messages on a server (both Debug implementations are GUI based; is there an alternative?)

Gaston_Dombiak · March 3, 2006, 2:19am

Hey Andreas,

To open the Smack debugger you can:

Before creating an XMPPConnection you can execute:

XMPPConnection.DEBUG_ENABLED = true;[/code]

Add the following parameter -Dsmack.debugEnabled=true when launching the Smack application

Regards,

– Gato

Andreas_Schildbach · March 3, 2006, 6:59am

Yes, I know. The problem is I have no GUI available on the headless server. So the debuggers (also the enhanced one) will have troubles to open. I’'m searching for some kind of logfile.

Jay · March 3, 2006, 6:27pm

Goonie: Assuming your server is on some Unix, can you do remote X display to a local workstation? OSX, Linux and the BSDs all can do this without too much extra setup. If you are on Windows- well you could install cygwin, but that might be overkill to just debug this one app

Gaston_Dombiak · March 3, 2006, 6:34pm

Hey guys,

For these cases is that we included the ConsoleDebugger.

To enable the debugger set this environment variable: -Dsmack.debugEnabled=true.

To indicate that you want to use the ConsoleDebugger set this environment variable: -Dsmack.debuggerClass=org.jivesoftware.smack.debugger.ConsoleDebugger

All debugged information will be redirected to stdout.

Regards,

– Gato

Andreas_Schildbach · March 5, 2006, 7:50am

Ok, now I have all the logs. This is the client side (Smack):

08:42:51 AM SENT (12306126):

java.net.SocketException: Broken pipe

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)

at java.net.SocketOutputStream.write(SocketOutputStream.java:136)

at com.sun.net.ssl.internal.ssl.OutputRecord.writeBuffer(OutputRecord.java:283)

at com.sun.net.ssl.internal.ssl.OutputRecord.write(OutputRecord.java:272)

at com.sun.net.ssl.internal.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:663)

at com.sun.net.ssl.internal.ssl.AppOutputStream.write(AppOutputStream.java:59)

at sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(StreamEncoder.java:336)

at sun.nio.cs.StreamEncoder$CharsetSE.implFlushBuffer(StreamEncoder.java:404)

at sun.nio.cs.StreamEncoder$CharsetSE.implFlush(StreamEncoder.java:408)

at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:152)

at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:213)

at java.io.BufferedWriter.flush(BufferedWriter.java:236)

at org.jivesoftware.smack.util.ObservableWriter.flush(ObservableWriter.java:48)

at org.jivesoftware.smack.PacketWriter.writePackets(PacketWriter.java:249)

at org.jivesoftware.smack.PacketWriter.access$000(PacketWriter.java:34)

at org.jivesoftware.smack.PacketWriter$1.run(PacketWriter.java:69)

stream:error (bad-format)

at org.jivesoftware.smack.PacketReader.parsePackets(PacketReader.java:310)

at org.jivesoftware.smack.PacketReader.access$000(PacketReader.java:43)

at org.jivesoftware.smack.PacketReader$1.run(PacketReader.java:63)

For completeness, here is the server log (jabberd2, c2s) of the same run:

Sun Mar 5 08:42:51 2006 c2s.c:417 accept action on fd 9

Sun Mar 5 08:42:51 2006 connect

sx (sx.c:55) allocated new sx for 9

sx (server.c:236) doing server init for sx 9

sx (server.c:251) waiting for stream header

sx (server.c:254) tag 9 event 0 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:33 want read

Sun Mar 5 08:42:51 2006 c2s.c:381 read action on fd 9

sx (io.c:159) 9 ready for reading

sx (io.c:165) tag 9 event 2 data 0x80c8978

Sun Mar 5 08:42:51 2006 c2s.c:43 reading from 9

Sun Mar 5 08:42:51 2006 c2s.c:97 read 1 bytes

sx (io.c:181) passed 1 read bytes

sx (chain.c:93) calling io read chain

sx (io.c:205) decoded read data (1 bytes):

Sun Mar 5 08:42:51 2006 c2s.c:381 read action on fd 9

sx (io.c:159) 9 ready for reading

sx (io.c:165) tag 9 event 2 data 0x80c8990

Sun Mar 5 08:42:51 2006 c2s.c:43 reading from 9

Sun Mar 5 08:42:51 2006 c2s.c:97 read 115 bytes

sx (io.c:181) passed 115 read bytes

sx (chain.c:93) calling io read chain

sx (io.c:205) decoded read data (115 bytes):

sx (chain.c:79) calling io write chain

sx (io.c:312) handing app 50 bytes to write

sx (io.c:313) tag 9 event 3 data 0x80dffc8

Sun Mar 5 08:42:51 2006 c2s.c:104 writing to 9

Sun Mar 5 08:42:51 2006 c2s.c:108 50 bytes written

sx (ssl.c:33) preparing for starttls

sx (sx.c:148) resetting stream state

sx (sx.c:72) freeing sx for 9

sx (sx.c:55) allocated new sx for 9

sx (server.c:236) doing server init for sx 9

sx (ssl.c:517) preparing for ssl accept for 9

sx (chain.c:28) adding io plugin

sx (server.c:251) waiting for stream header

sx (server.c:254) tag 9 event 0 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:33 want read

sx (io.c:346) tag 9 event 0 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:33 want read

Sun Mar 5 08:42:51 2006 c2s.c:381 read action on fd 9

sx (io.c:159) 9 ready for reading

sx (io.c:165) tag 9 event 2 data 0x80dffc8

Sun Mar 5 08:42:51 2006 c2s.c:43 reading from 9

Sun Mar 5 08:42:51 2006 c2s.c:97 read 100 bytes

sx (io.c:181) passed 100 read bytes

sx (chain.c:93) calling io read chain

sx (ssl.c:322) in sxssl_rio

sx (ssl.c:326) loading 100 bytes into ssl read buffer

sx (ssl.c:152) secure channel not established, handshake in progress

sx (io.c:199) tag 9 event 1 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:38 want write

Sun Mar 5 08:42:51 2006 c2s.c:395 write action on fd 9

sx (io.c:293) 9 ready for writing

sx (io.c:251) encoding 0 bytes for writing:

sx (chain.c:79) calling io write chain

sx (ssl.c:220) in sxssl_wio

sx (ssl.c:152) secure channel not established, handshake in progress

sx (ssl.c:302) prepared 649 ssl bytes for write

sx (io.c:312) handing app 649 bytes to write

sx (io.c:313) tag 9 event 3 data 0x80dffc8

Sun Mar 5 08:42:51 2006 c2s.c:104 writing to 9

Sun Mar 5 08:42:51 2006 c2s.c:108 649 bytes written

sx (io.c:346) tag 9 event 0 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:33 want read

Sun Mar 5 08:42:51 2006 c2s.c:381 read action on fd 9

sx (io.c:159) 9 ready for reading

sx (io.c:165) tag 9 event 2 data 0x80dffc8

Sun Mar 5 08:42:51 2006 c2s.c:43 reading from 9

Sun Mar 5 08:42:51 2006 c2s.c:97 read 139 bytes

sx (io.c:181) passed 139 read bytes

sx (chain.c:93) calling io read chain

sx (ssl.c:322) in sxssl_rio

sx (ssl.c:326) loading 139 bytes into ssl read buffer

sx (ssl.c:152) secure channel not established, handshake in progress

Sun Mar 5 08:42:51 2006 c2s.c:381 read action on fd 9

sx (io.c:159) 9 ready for reading

sx (io.c:165) tag 9 event 2 data 0x80dffe0

Sun Mar 5 08:42:51 2006 c2s.c:43 reading from 9

Sun Mar 5 08:42:51 2006 c2s.c:97 read 43 bytes

sx (io.c:181) passed 43 read bytes

sx (chain.c:93) calling io read chain

sx (ssl.c:322) in sxssl_rio

sx (ssl.c:326) loading 43 bytes into ssl read buffer

sx (ssl.c:152) secure channel not established, handshake in progress

sx (ssl.c:166) secure channel established

sx (ssl.c:171) using cipher RC4-MD5 (128 bits)

sx (io.c:199) tag 9 event 1 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:38 want write

Sun Mar 5 08:42:51 2006 c2s.c:395 write action on fd 9

sx (io.c:293) 9 ready for writing

sx (io.c:251) encoding 0 bytes for writing:

sx (chain.c:79) calling io write chain

sx (ssl.c:220) in sxssl_wio

sx (ssl.c:302) prepared 43 ssl bytes for write

sx (io.c:312) handing app 43 bytes to write

sx (io.c:313) tag 9 event 3 data 0x80dffe0

Sun Mar 5 08:42:51 2006 c2s.c:104 writing to 9

Sun Mar 5 08:42:51 2006 c2s.c:108 43 bytes written

sx (io.c:346) tag 9 event 0 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:33 want read

Sun Mar 5 08:42:51 2006 c2s.c:381 read action on fd 9

sx (io.c:159) 9 ready for reading

sx (io.c:165) tag 9 event 2 data 0x80dffe0

Sun Mar 5 08:42:51 2006 c2s.c:43 reading from 9

Sun Mar 5 08:42:51 2006 c2s.c:97 read 149 bytes

sx (io.c:181) passed 149 read bytes

sx (chain.c:93) calling io read chain

sx (ssl.c:322) in sxssl_rio

sx (ssl.c:326) loading 149 bytes into ssl read buffer

sx (io.c:205) decoded read data (128 bytes):

sx (server.c:91) tag 9 event 8 data 0xbffff490

Sun Mar 5 08:42:51 2006 error: Stream error (Expected stream start)

sx (error.c:79) prepared error: <stream:stream xmlns:stream=’‘http://etherx.jabber.org/streams’’ version=’‘1.0’’><stream:error xmlns:stream=’‘http://etherx.jabber.org/streams’’><bad-format xmlns=’‘urn:ietf:params:xml:ns:xmpp-streams’’/></stream:error></stream:stream>

sx (io.c:440) 9 state change from 0 to 5

sx (io.c:221) tag 9 event 1 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:38 want write

Sun Mar 5 08:42:51 2006 c2s.c:395 write action on fd 9

sx (io.c:293) 9 ready for writing

sx (io.c:251) encoding 227 bytes for writing: <stream:stream xmlns:stream=’‘http://etherx.jabber.org/streams’’ version=’‘1.0’’><stream:error xmlns:stream=’‘http://etherx.jabber.org/streams’’><bad-format xmlns=’‘urn:ietf:params:xml:ns:xmpp-streams’’/></stream:error></stream:stream>

sx (chain.c:79) calling io write chain

sx (ssl.c:220) in sxssl_wio

sx (ssl.c:224) queueing buffer for write

sx (ssl.c:240) preparing queued buffer for write

sx (ssl.c:302) prepared 248 ssl bytes for write

sx (io.c:312) handing app 248 bytes to write

sx (io.c:313) tag 9 event 3 data 0x80dffc8

Sun Mar 5 08:42:51 2006 c2s.c:104 writing to 9

Sun Mar 5 08:42:51 2006 c2s.c:108 248 bytes written

sx (io.c:338) 9 state change from 5 to 6

sx (io.c:339) tag 9 event 7 data 0x0

Sun Mar 5 08:42:51 2006 c2s.c:400 close action on fd 9

Sun Mar 5 08:42:51 2006 disconnect

sx (sx.c:72) freeing sx for 9

Sun Mar 5 08:42:51 2006 ssl.c:548 cleaning up conn state

Sun Mar 5 08:43:12 2006 c2s.c:381 read action on fd 7

sx (io.c:159) 7 ready for reading

sx (io.c:165) tag 7 event 2 data 0x80c9a88

Sun Mar 5 08:43:12 2006 c2s.c:43 reading from 7

Sun Mar 5 08:43:12 2006 c2s.c:97 read 197 bytes

sx (io.c:181) passed 197 read bytes

sx (chain.c:93) calling io read chain

sx (ssl.c:322) in sxssl_rio

sx (ssl.c:326) loading 197 bytes into ssl read buffer

sx (io.c:205) decoded read data (1 bytes):

Sun Mar 5 08:43:12 2006 c2s.c:381 read action on fd 8

sx (io.c:159) 8 ready for reading

sx (io.c:165) tag 8 event 2 data 0x80c9920

Sun Mar 5 08:43:12 2006 c2s.c:43 reading from 8

Sun Mar 5 08:43:12 2006 c2s.c:97 read 245 bytes

sx (io.c:181) passed 245 read bytes

sx (chain.c:93) calling io read chain

sx (ssl.c:322) in sxssl_rio

sx (ssl.c:326) loading 245 bytes into ssl read buffer

sx (io.c:205) decoded read data (1 bytes):

Gaston_Dombiak · March 6, 2006, 5:59pm

Hey Goonie,

I see something weird going on here. Smack is sending a new stream header after TLS was negotiated but the server is reporting that “” is in fact being sent instead of the stream header. And to make things more weird I don’'t see in your logs that Smack is sending the auth packet.

I really don’'t have any idea of how can this be happening. Could the debug log of the server be mixed up with some other client trying to log in?

Regards,

– Gato

Andreas_Schildbach · March 6, 2006, 6:59pm

Doesn’‘t the matching stream id guarantee that there can’'t be any mixup happening?

There is one client (gaim) which probably had two connections to the server, but that should have happened well before, and it should have used two domains separate from the one in the log.

However, if you want, I would reproduce the testcase again, without gaim connected. Should I change anything else?

Gaston_Dombiak · March 6, 2006, 10:37pm

Hey Goonie,

Nothing else to change. I’‘m still wondering how did the server receive the packet if Smack didn’'t send it.

Regards,

– Gato

Andreas_Schildbach · March 8, 2006, 8:35am

What to do next? How can I help? I’'m very interested in getting Smack to cooperate with jabberd2.0, or vice versa.

I posted your answer back to the jabberd mailing list at

http://mail.jabber.org/pipermail/jabberd/2006-March/003227.html

but Stephen Marquart did not answer yet.

Regards,

Andreas

Gaston_Dombiak · March 8, 2006, 11:28pm

Hey Goonie,

Unfortunately I don’‘t have much to say. From the client side we saw/confirmed that the client is sending a new stream header after TLS was negotiated. I’'m still wondering how did the server get the packet? Have you tried not using TLS but SASL, compression, resource binding and session establishment? After SASL a new stream header is also sent to the server and the same happens with stream compression so you might want to try that and see how it goes. It may help to gather more info to understand this mystery.

Regards,

– Gato

Jay · March 9, 2006, 2:13pm

After needing this utility for years, I finally found it. Its called ssldump. Its related to tcpdump, but lets you inspect inside SSL/TSL conversations if you have the certificate private key. If you run the server, you do Might help… http://www.rtfm.com/ssldump/

LG1 · March 9, 2006, 5:31pm

Hi Jay,

I hope that I find some time to try ssldump, sounds very interesting.

LG

Adrian1 · March 22, 2006, 11:15am

I’‘m not a java person and I don’‘t really know how Smack works but isn’'t this how the TLS handshake is supposed to worrk ?

Take a look at the xmpp specifications :

http://www.xmpp.org/specs/rfc3920.html#tls

As I understand it, a new stream MUST be intiated after the servers says “Proceed”

Gaston_Dombiak · March 22, 2006, 3:55pm

Hey Adrian,

Smack is in fact opening a new stream after TLS was negotiated successfully. The weird problem here is that jabberd2 is reporting that the client is sending an packet instead of the new open stream sent stanza.

Regards,

– Gato

Adrian1 · March 23, 2006, 9:47am

Now I get it. Forgive my intrusion