Open guidow opened 10 years ago
it was working fine with jabberd2 on version 2.2.14-r1. did an update yesterday to 2.3.1-r1 and got the same problem. i am not sure if its xabber or jabberd2 since most desktop clients connecting without any problems. just downgraded back to the old version and its working fine again, so its definitely between xabber and jabberd2 version 2.3.1-r1.
I did some debugging and it looks like Xabber requires the optional "session" feature when using SASL authentication. (Connection works when using non-SASL auth method, i.e. when you disable SASL in xabber account options)
Example of server response with feature (jabber.org) stream:features
/stream:features
Example of jabberd2 2.3.x server response compiled without "--with-deprecated":
I did some debugging and it looks like Xabber requires the optional "session" feature when using SASL authentication. (Connection works when using non-SASL auth method, i.e. when you disable SASL in xabber account options)
Example of server response with feature (jabber.org)
<stream:features>
<bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><required/></bind>
<session
xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session>
<sm xmlns='urn:xmpp:sm:2'><optional/></sm>
</stream:features>
Example of jabberd2 2.3.x server response compiled without "--with-deprecated":
<stream:features xmlns:stream='http://etherx.jabber.org/streams'>
<compression
xmlns='http://jabber.org/features/compress'><method>zlib</method></compression>
<ack:ack/>
<bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><required/></bind>
<unbind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/>
<ver xmlns='urn:xmpp:features:rosterver'/>
</stream:features>
Xabber fails on this with the following error: "Session establishment not offered by server."
For reference, per RFC6121 the session is not required:
http://tools.ietf.org/html/rfc6121#section-1.4
Interoperability Note: [RFC3921] specified one additional
precondition: formal establishment of an instant messaging and
presence session. Implementation and deployment experience has
shown that this additional step is unnecessary. However, for
backward compatibility an implementation MAY still offer that
feature. This enables older software to connect while letting
newer software save a round trip.
I have posted this bug to the jabberd2 mailing list. The opinion over there seems to be that, in xabber, the configuration switch "use SASL authentication (recommended)" is somehow inverted, i.e. xabber will not use sasl if it is enabled, and it's enabled by default. Jabberd 2 2.3 does not support non-SASL authentication anymore, except when compiled with "--enable-superseded".
See here for the thread in question:
http://www.mail-archive.com/jabberd2@lists.xiaoka.com/msg02255.html
No, I also checked the communication, it actually DOES use SASL communication correctly, it is NOT inverted.
The only issue is that Xabber seems to barf on the missing (optional) session feature which gets enabled when using "--enable-superseded" and is not needed by yaxim or empathy. (chatsecure however seems to have the same issue as xabber..) This basically gets confirmed by the output in the debug log from xabber ("Session establishment not offered by server.")
So this is actually a Xabber bug, basically requesting it not to require "session" support from the server.
(If you want I can attach the debug log showing the successful SASL authentication..)
The problem is in the used smack client libary: It throws an exception in SASLAuthentication.java on line 478 when no session feature was send.
else if (parser.getName().equals("session")) {
// The server supports sessions
connection.getSASLAuthentication().sessionsSupported();
}
void sessionsSupported() {
sessionSupported = true;
}
/**
* Initializes the internal state in order to be able to be reused. The authentication
* is used by the connection at the first login and then reused after the connection
* is disconnected and then reconnected.
*/
protected void init() {
saslNegotiated = false;
saslFailed = false;
resourceBinded = false;
sessionSupported = false;
}
}
if (sessionSupported) {
Session session = new Session();
collector = connection.createPacketCollector(new PacketIDFilter(session.getPacketID()));
// Send the packet
connection.sendPacket(session);
// Wait up to a certain number of seconds for a response from the server.
IQ ack = (IQ) collector.nextResult(SmackConfiguration.getPacketReplyTimeout());
collector.cancel();
if (ack == null) {
throw new XMPPException("No response from the server.");
}
// If the server replied with an error, throw an exception.
else if (ack.getType() == IQ.Type.ERROR) {
throw new XMPPException(ack.getError());
}
}
else {
// Server never offered session establishment
throw new XMPPException("Session establishment not offered by server");
}
There has been a major version jump at the Smack library in the meantime. Maybe the bug has been fixed there?
I am using from the AppStore Xabber and Xabber Development. In both cases the problem still exist.
I hit this exactly problem today. Xabber 1.0.30 connects and then disconnects from a new server without session offer, over and over again. I have do hack into XMPP server to add session support and reply a fake result to make it work.
Since switching from jabberd14 to jabberd2, xabber can no longer connect to m jabber server.
I can log in to this server with Psi with the same username and password with no problems.
From the point of view of the server, it looks like xabber is connecting once, authenticating successfully, and immediately disconnecting again for no obvious reason. This is an excerpt from the server logs:
Dec 29 15:49:34 blish jabberd/c2s[7186]: [8] [151.217.242.255, port=53329] connect Dec 29 15:49:35 blish jabberd/c2s[7186]: [8] PLAIN authentication succeeded: guido@unknownsite.de 151.217.242.255:53329 TLS Dec 29 15:49:35 blish jabberd/c2s[7186]: [8] bound: jid=guido@unknownsite.de/androidoA7japPJ Dec 29 15:49:36 blish jabberd/sm[7157]: session started: jid=guido@unknownsite.de/androidoA7japPJ Dec 29 15:49:36 blish jabberd/c2s[7186]: [8] [151.217.242.255, port=53329] disconnect jid=guido@unknownsite.de/androidoA7japPJ, packets: 2 Dec 29 15:49:36 blish jabberd/sm[7157]: session ended: jid=guido@unknownsite.de/androidoA7japPJ Dec 29 15:49:36 blish jabberd/sm[7157]: user unloaded jid=guido@unknownsite.de
This is the output from the c2s component when run in debug mode when xabber tries to connect:
Sun Dec 29 04:09:06 2013 c2s.c:584 accept action on fd 8 Sun Dec 29 04:09:06 2013 [notice] [8] [151.217.242.255, port=54423] connect sx (sx.c:65) allocated new sx for 8 sx (server.c:237) doing server init for sx 8 sx (server.c:252) waiting for stream header sx (server.c:255) tag 8 event 0 data 0x0 Sun Dec 29 04:09:06 2013 c2s.c:37 want read Sun Dec 29 04:09:06 2013 c2s.c:547 read action on fd 8 sx (io.c:191) 8 ready for reading sx (io.c:197) tag 8 event 2 data 0xa8e38 Sun Dec 29 04:09:06 2013 c2s.c:47 reading from 8 Sun Dec 29 04:09:06 2013 c2s.c:106 read 119 bytes sx (io.c:216) passed 119 read bytes sx (chain.c:93) calling io read chain sx (io.c:240) decoded read data (119 bytes):
sx (server.c:119) stream request: to unknownsite.de from (null) version 1.0
sx (server.c:134) 8 state change from 0 to 1
sx (server.c:152) stream id is nlw6rk454o4l3tefn68d1btk7bo7oj7c43jwon2s
Sun Dec 29 04:09:06 2013 ack.c:30 hacking ack namespace decl onto stream header
sx (server.c:182) prepared stream response: <?xml version='1.0'?>
sx (io.c:256) tag 8 event 1 data 0x0
Sun Dec 29 04:09:06 2013 c2s.c:42 want write
Sun Dec 29 04:09:06 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 248 bytes for writing: <?xml version='1.0'?>
sx (chain.c:79) calling io write chain
sx (io.c:349) handing app 248 bytes to write
sx (io.c:350) tag 8 event 3 data 0x15db20
Sun Dec 29 04:09:06 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:06 2013 c2s.c:148 248 bytes written
sx (server.c:29) stream established
sx (server.c:39) 8 state change from 1 to 3
sx (server.c:40) tag 8 event 4 data 0x0
sx (server.c:45) building features nad
sx (address.c:34) adding address feature
sx (sasl_gsasl.c:253) ssl not established yet but the app requires it, not offering mechanisms
Sun Dec 29 04:09:06 2013 bind.c:38 not auth'd, offering auth and register
sx (ssl.c:212) offering starttls
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:06 2013 c2s.c:37 want read
Sun Dec 29 04:09:06 2013 c2s.c:547 read action on fd 8
sx (io.c:191) 8 ready for reading
sx (io.c:197) tag 8 event 2 data 0xa96e0
Sun Dec 29 04:09:06 2013 c2s.c:47 reading from 8
Sun Dec 29 04:09:06 2013 c2s.c:106 read 184 bytes
sx (io.c:216) passed 184 read bytes
sx (chain.c:93) calling io read chain
sx (ssl.c:511) in _sx_ssl_rio
sx (ssl.c:515) loading 184 bytes into ssl read buffer
sx (ssl.c:336) secure channel not established, handshake in progress
sx (ssl.c:336) secure channel not established, handshake in progress
sx (io.c:234) tag 8 event 1 data 0x0
Sun Dec 29 04:09:06 2013 c2s.c:42 want write
Sun Dec 29 04:09:06 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 0 bytes for writing:
sx (chain.c:79) calling io write chain
sx (ssl.c:407) in _sx_ssl_wio
sx (ssl.c:336) secure channel not established, handshake in progress
sx (ssl.c:491) prepared 1735 ssl bytes for write
sx (io.c:349) handing app 1735 bytes to write
sx (io.c:350) tag 8 event 3 data 0xa96e0
Sun Dec 29 04:09:06 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:06 2013 c2s.c:148 1735 bytes written
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:06 2013 c2s.c:37 want read
Sun Dec 29 04:09:06 2013 c2s.c:547 read action on fd 8
sx (io.c:191) 8 ready for reading
sx (io.c:197) tag 8 event 2 data 0xa96e0
Sun Dec 29 04:09:06 2013 c2s.c:47 reading from 8
Sun Dec 29 04:09:06 2013 c2s.c:106 read 566 bytes
sx (io.c:216) passed 566 read bytes
sx (chain.c:93) calling io read chain
sx (ssl.c:511) in _sx_ssl_rio
sx (ssl.c:515) loading 566 bytes into ssl read buffer
sx (ssl.c:336) secure channel not established, handshake in progress
sx (ssl.c:350) secure channel established
sx (ssl.c:355) using cipher RC4-MD5 (128 bits)
sx (io.c:234) tag 8 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:42 want write
Sun Dec 29 04:09:07 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 0 bytes for writing:
sx (chain.c:79) calling io write chain
sx (ssl.c:407) in _sx_ssl_wio
sx (ssl.c:491) prepared 43 ssl bytes for write
sx (io.c:349) handing app 43 bytes to write
sx (io.c:350) tag 8 event 3 data 0xa96e0
Sun Dec 29 04:09:07 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:07 2013 c2s.c:148 43 bytes written
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
Sun Dec 29 04:09:07 2013 c2s.c:547 read action on fd 8
sx (io.c:191) 8 ready for reading
sx (io.c:197) tag 8 event 2 data 0xa96e0
Sun Dec 29 04:09:07 2013 c2s.c:47 reading from 8
Sun Dec 29 04:09:07 2013 c2s.c:106 read 140 bytes
sx (io.c:216) passed 140 read bytes
sx (chain.c:93) calling io read chain
sx (ssl.c:511) in _sx_ssl_rio
sx (ssl.c:515) loading 140 bytes into ssl read buffer
sx (io.c:240) decoded read data (119 bytes):
sx (server.c:119) stream request: to unknownsite.de from (null) version 1.0
sx (server.c:134) 8 state change from 0 to 1
sx (server.c:152) stream id is 7de0suny31zevkm78uws18w4rttewlq3z53r0rp3
Sun Dec 29 04:09:07 2013 ack.c:30 hacking ack namespace decl onto stream header
sx (server.c:182) prepared stream response: <?xml version='1.0'?>
sx (io.c:256) tag 8 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:42 want write
Sun Dec 29 04:09:07 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 248 bytes for writing: <?xml version='1.0'?>
sx (chain.c:79) calling io write chain
sx (ssl.c:407) in _sx_ssl_wio
sx (ssl.c:411) queueing buffer for write
sx (ssl.c:427) preparing queued buffer for write
sx (ssl.c:491) prepared 269 ssl bytes for write
sx (io.c:349) handing app 269 bytes to write
sx (io.c:350) tag 8 event 3 data 0xbba00
Sun Dec 29 04:09:07 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:07 2013 c2s.c:148 269 bytes written
sx (server.c:29) stream established
sx (server.c:39) 8 state change from 1 to 3
sx (server.c:40) tag 8 event 4 data 0x0
sx (server.c:45) building features nad
sx (address.c:34) adding address feature
sx (sasl_gsasl.c:258) offering sasl mechanisms
sx (sasl_gsasl.c:694) in _sx_sasl_gsasl_callback, property: 18
sx (sasl_gsasl.c:694) in _sx_sasl_gsasl_callback, property: 18
sx (sasl_gsasl.c:278) offering mechanism: EXTERNAL
sx (sasl_gsasl.c:278) offering mechanism: PLAIN
Sun Dec 29 04:09:07 2013 bind.c:38 not auth'd, offering auth and register
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
Sun Dec 29 04:09:07 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 392 bytes for writing: 151.217.242.255EXTERNAL PLAIN /stream:features
Sun Dec 29 04:09:07 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:07 2013 c2s.c:148 72 bytes written
sx (chain.c:28) adding io plugin
sx (sasl_gsasl.c:299) auth completed, resetting
sx (sx.c:158) resetting stream state
sx (sx.c:82) freeing sx for 8
sx (sx.c:65) allocated new sx for 8
sx (sx.c:215) finished resetting stream state
sx (server.c:237) doing server init for sx 8
sx (server.c:252) waiting for stream header
sx (server.c:255) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
Sun Dec 29 04:09:07 2013 c2s.c:547 read action on fd 8
sx (io.c:191) 8 ready for reading
sx (io.c:197) tag 8 event 2 data 0xa9520
Sun Dec 29 04:09:07 2013 c2s.c:47 reading from 8
Sun Dec 29 04:09:07 2013 c2s.c:106 read 140 bytes
sx (io.c:216) passed 140 read bytes
sx (chain.c:93) calling io read chain
sx (ssl.c:511) in _sx_ssl_rio
sx (ssl.c:515) loading 140 bytes into ssl read buffer
sx (sasl_gsasl.c:148) doing sasl decode
sx (sasl_gsasl.c:164) 119 bytes decoded from sasl channel
sx (io.c:240) decoded read data (119 bytes):
sx (server.c:119) stream request: to unknownsite.de from (null) version 1.0
sx (server.c:134) 8 state change from 0 to 1
sx (server.c:152) stream id is pioa5vjzsb0085s2y7ykx1j35b4w17prqd1v9lu1
Sun Dec 29 04:09:07 2013 ack.c:30 hacking ack namespace decl onto stream header
sx (server.c:182) prepared stream response: <?xml version='1.0'?>
sx (io.c:256) tag 8 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:42 want write
Sun Dec 29 04:09:07 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 248 bytes for writing: <?xml version='1.0'?>
sx (chain.c:79) calling io write chain
sx (sasl_gsasl.c:120) doing sasl encode
sx (sasl_gsasl.c:136) 248 bytes encoded for sasl channel
sx (ssl.c:407) in _sx_ssl_wio
sx (ssl.c:411) queueing buffer for write
sx (ssl.c:427) preparing queued buffer for write
sx (ssl.c:491) prepared 269 ssl bytes for write
sx (io.c:349) handing app 269 bytes to write
sx (io.c:350) tag 8 event 3 data 0xa9730
Sun Dec 29 04:09:07 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:07 2013 c2s.c:148 269 bytes written
sx (server.c:29) stream established
sx (sx.c:144) authenticating stream (method=SASL/PLAIN; id=guido@unknownsite.de)
sx (sx.c:149) 8 state change from 1 to 4
sx (sx.c:150) tag 8 event 5 data 0x0
Sun Dec 29 04:09:07 2013 [notice] [8] PLAIN authentication succeeded: guido@unknownsite.de 151.217.242.255:54423 TLS
sx (server.c:45) building features nad
sx (sasl_gsasl.c:242) already auth'd, not offering sasl mechanisms
Sun Dec 29 04:09:07 2013 bind.c:51 auth'd, offering resource bind and session
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
Sun Dec 29 04:09:07 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 250 bytes for writing: ack:ack/ /stream:features
sx (chain.c:79) calling io write chain
sx (sasl_gsasl.c:120) doing sasl encode
sx (sasl_gsasl.c:136) 250 bytes encoded for sasl channel
sx (ssl.c:407) in _sx_ssl_wio
sx (ssl.c:411) queueing buffer for write
sx (ssl.c:427) preparing queued buffer for write
sx (ssl.c:491) prepared 271 ssl bytes for write
sx (io.c:349) handing app 271 bytes to write
sx (io.c:350) tag 8 event 3 data 0xa9730
Sun Dec 29 04:09:07 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:07 2013 c2s.c:148 271 bytes written
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
Sun Dec 29 04:09:07 2013 c2s.c:547 read action on fd 8
sx (io.c:191) 8 ready for reading
sx (io.c:197) tag 8 event 2 data 0xa9730
Sun Dec 29 04:09:07 2013 c2s.c:47 reading from 8
Sun Dec 29 04:09:07 2013 c2s.c:106 read 144 bytes
sx (io.c:216) passed 144 read bytes
sx (chain.c:93) calling io read chain
sx (ssl.c:511) in _sx_ssl_rio
sx (ssl.c:515) loading 144 bytes into ssl read buffer
sx (sasl_gsasl.c:148) doing sasl decode
sx (sasl_gsasl.c:164) 123 bytes decoded from sasl channel
sx (io.c:240) decoded read data (123 bytes): androidoA7japPJ
sx (io.c:92) completed nad: androidoA7japPJ
sx (chain.c:119) calling nad read chain
sx (io.c:156) tag 8 event 6 data 0xbb590
Sun Dec 29 04:09:07 2013 [notice] [8] bound: jid=guido@unknownsite.de/androidoA7japPJ
Sun Dec 29 04:09:07 2013 sm.c:61 built new route nad for guido@unknownsite.de/androidoA7japPJ action start target guido@unknownsite.de/androidoA7japPJ id 83835ef36f732bda822497591932e04eaa8ea097
sx (chain.c:106) calling nad write chain
sx (io.c:406) queueing for write:
sx (io.c:429) tag 6 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:718 want write
Sun Dec 29 04:09:07 2013 c2s.c:1382 write action on fd 6
sx (io.c:328) 6 ready for writing
sx (io.c:286) encoding 292 bytes for writing:
sx (chain.c:79) calling io write chain
sx (io.c:349) handing app 292 bytes to write
sx (io.c:350) tag 6 event 3 data 0xbb5d8
Sun Dec 29 04:09:07 2013 c2s.c:755 writing to 6
Sun Dec 29 04:09:07 2013 c2s.c:759 292 bytes written
sx (io.c:383) tag 6 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:713 want read
sx (io.c:431) tag 6 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:713 want read
Sun Dec 29 04:09:07 2013 c2s.c:1371 read action on fd 6
sx (io.c:191) 6 ready for reading
sx (io.c:197) tag 6 event 2 data 0xbb5d8
Sun Dec 29 04:09:07 2013 c2s.c:723 reading from 6
Sun Dec 29 04:09:07 2013 c2s.c:748 read 331 bytes
sx (io.c:216) passed 331 read bytes
sx (chain.c:93) calling io read chain
sx (io.c:240) decoded read data (331 bytes):
sx (io.c:92) completed nad:
sx (chain.c:119) calling nad read chain
sx (io.c:156) tag 6 event 6 data 0xbb590
sx (chain.c:106) calling nad write chain
sx (io.c:406) queueing for write: jid>guido@unknownsite.de/androidoA7japPJ</jid
sx (io.c:429) tag 8 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:42 want write
Sun Dec 29 04:09:07 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 159 bytes for writing: jid>guido@unknownsite.de/androidoA7japPJ</jid
sx (chain.c:79) calling io write chain
sx (sasl_gsasl.c:120) doing sasl encode
sx (sasl_gsasl.c:136) 159 bytes encoded for sasl channel
sx (ssl.c:407) in _sx_ssl_wio
sx (ssl.c:411) queueing buffer for write
sx (ssl.c:427) preparing queued buffer for write
sx (ssl.c:491) prepared 180 ssl bytes for write
sx (io.c:349) handing app 180 bytes to write
sx (io.c:350) tag 8 event 3 data 0xbb5d8
Sun Dec 29 04:09:07 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:07 2013 c2s.c:148 180 bytes written
sx (io.c:383) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
sx (io.c:431) tag 8 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:37 want read
Sun Dec 29 04:09:07 2013 c2s.c:547 read action on fd 8
sx (io.c:191) 8 ready for reading
sx (io.c:197) tag 8 event 2 data 0xbb5d8
Sun Dec 29 04:09:07 2013 c2s.c:47 reading from 8
Sun Dec 29 04:09:07 2013 c2s.c:106 read 219 bytes
sx (io.c:216) passed 219 read bytes
sx (chain.c:93) calling io read chain
sx (ssl.c:511) in _sx_ssl_rio
sx (ssl.c:515) loading 219 bytes into ssl read buffer
sx (sasl_gsasl.c:148) doing sasl decode
sx (sasl_gsasl.c:164) 198 bytes decoded from sasl channel
sx (io.c:240) decoded read data (198 bytes):
sx (io.c:92) completed nad:
sx (chain.c:119) calling nad read chain
sx (io.c:156) tag 8 event 6 data 0x9d580
sx (chain.c:106) calling nad write chain
sx (io.c:406) queueing for write:
sx (io.c:429) tag 6 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:718 want write
Sun Dec 29 04:09:07 2013 c2s.c:1382 write action on fd 6
sx (io.c:328) 6 ready for writing
sx (io.c:286) encoding 429 bytes for writing:
sx (chain.c:79) calling io write chain
sx (io.c:349) handing app 429 bytes to write
sx (io.c:350) tag 6 event 3 data 0xba058
Sun Dec 29 04:09:07 2013 c2s.c:755 writing to 6
Sun Dec 29 04:09:07 2013 c2s.c:759 429 bytes written
sx (io.c:383) tag 6 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:713 want read
sx (io.c:431) tag 6 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:713 want read
Sun Dec 29 04:09:07 2013 c2s.c:547 read action on fd 8
sx (io.c:191) 8 ready for reading
sx (io.c:197) tag 8 event 2 data 0xba058
Sun Dec 29 04:09:07 2013 c2s.c:47 reading from 8
Sun Dec 29 04:09:07 2013 c2s.c:106 read 37 bytes
sx (io.c:216) passed 37 read bytes
sx (chain.c:93) calling io read chain
sx (ssl.c:511) in _sx_ssl_rio
sx (ssl.c:515) loading 37 bytes into ssl read buffer
sx (sasl_gsasl.c:148) doing sasl decode
sx (sasl_gsasl.c:164) 16 bytes decoded from sasl channel
sx (io.c:240) decoded read data (16 bytes): /stream:stream
sx (io.c:174) 8 state change from 4 to 5
sx (io.c:256) tag 8 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:42 want write
Sun Dec 29 04:09:07 2013 c2s.c:561 write action on fd 8
sx (io.c:328) 8 ready for writing
sx (io.c:286) encoding 16 bytes for writing: /stream:stream
sx (chain.c:79) calling io write chain
sx (sasl_gsasl.c:120) doing sasl encode
sx (sasl_gsasl.c:136) 16 bytes encoded for sasl channel
sx (ssl.c:407) in _sx_ssl_wio
sx (ssl.c:411) queueing buffer for write
sx (ssl.c:427) preparing queued buffer for write
sx (ssl.c:491) prepared 37 ssl bytes for write
sx (io.c:349) handing app 37 bytes to write
sx (io.c:350) tag 8 event 3 data 0xba058
Sun Dec 29 04:09:07 2013 c2s.c:144 writing to 8
Sun Dec 29 04:09:07 2013 c2s.c:148 37 bytes written
sx (io.c:375) 8 state change from 5 to 6
sx (io.c:376) tag 8 event 7 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:566 close action on fd 8
Sun Dec 29 04:09:07 2013 [notice] [8] [151.217.242.255, port=54423] disconnect jid=guido@unknownsite.de/androidoA7japPJ, packets: 2
Sun Dec 29 04:09:07 2013 sm.c:61 built new route nad for guido@unknownsite.de/androidoA7japPJ action end target (null) id (null)
sx (chain.c:106) calling nad write chain
sx (io.c:406) queueing for write:
sx (io.c:429) tag 6 event 1 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:718 want write
Sun Dec 29 04:09:07 2013 c2s.c:1382 write action on fd 6
sx (io.c:328) 6 ready for writing
sx (io.c:286) encoding 235 bytes for writing:
sx (chain.c:79) calling io write chain
sx (io.c:349) handing app 235 bytes to write
sx (io.c:350) tag 6 event 3 data 0xbc3c8
Sun Dec 29 04:09:07 2013 c2s.c:755 writing to 6
Sun Dec 29 04:09:07 2013 c2s.c:759 235 bytes written
sx (io.c:383) tag 6 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:713 want read
sx (io.c:431) tag 6 event 0 data 0x0
Sun Dec 29 04:09:07 2013 c2s.c:713 want read
sx (sx.c:82) freeing sx for 8
sx (sx.c:115) freeing 5 env plugins
sx (sasl_gsasl.c:682) cleaning up conn state
Sun Dec 29 04:09:07 2013 ssl.c:786 cleaning up conn state
Sun Dec 29 04:09:07 2013 c2s.c:1371 read action on fd 6
sx (io.c:191) 6 ready for reading
sx (io.c:197) tag 6 event 2 data 0xbf7f0
Sun Dec 29 04:09:07 2013 c2s.c:723 reading from 6
Sun Dec 29 04:09:07 2013 c2s.c:748 read 237 bytes
sx (io.c:216) passed 237 read bytes
sx (chain.c:93) calling io read chain
sx (io.c:240) decoded read data (237 bytes):
sx (io.c:92) completed nad:
sx (chain.c:119) calling nad read chain
sx (io.c:156) tag 6 event 6 data 0x9cc58
Sun Dec 29 04:09:07 2013 c2s.c:966 no session for 8
Sun Dec 29 04:14:53 2013 [notice] shutting down
Sun Dec 29 04:14:53 2013 c2s.c:1386 close action on fd 6
Sun Dec 29 04:14:53 2013 [notice] connection to router closed
sx (sx.c:82) freeing sx for 6
sx (sx.c:115) freeing 5 env plugins
sx (sasl_gsasl.c:682) cleaning up conn state
Sun Dec 29 04:14:53 2013 authreg_ldapfull.c:487 unbinded from ldap server