Tomasz (and maybe others),

After an upgrade today from 2.2.17 to 2.3.2 a small number of users are unable to connect. The strange thing is that they seem to be thrown out AFTER they have authenticated correctly and the session has started. I have looked but I cannot see why it suddenly should not work any more.


Here is some more info:
I have built with experimental options disabled and superseded options enabled. (The last option was added because many other users could not connect either including myself using the latest Xabber on Android):

../configure --sysconfdir=/etc/jabberd --enable-mysql --enable-mio=epoll --enable-debug --enable-ssl --with-zlib --disable-experimental --enable-superseded

In SM the following is logged (one particular user is chosen):
Sun Dec 21 14:00:38 2014 [notice] session started: jid=xadvente...@jabber.no-sense.net/WippienIM3 Sun Dec 21 14:00:39 2014 [notice] session ended: jid=xadvente...@jabber.no-sense.net/WippienIM3 Sun Dec 21 14:00:39 2014 [notice] user unloaded jid=xadvente...@jabber.no-sense.net
So it seems the session is started but ended at the same second.

in c2s, with debugging on, I see the following:

[.....]
Sun Dec 21 14:00:38 2014 [notice] [20] [<IP removed>, port=63359] connect
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 144 bytes
Sun Dec 21 14:00:38 2014 ack.c:30 hacking ack namespace decl onto stream header
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 253 bytes written
Sun Dec 21 14:00:38 2014 bind.c:38 not auth'd, offering auth and register
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 278 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 51 bytes
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 50 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 124 bytes
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 3626 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 326 bytes
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 59 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 218 bytes
Sun Dec 21 14:00:38 2014 ack.c:30 hacking ack namespace decl onto stream header
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 330 bytes written
Sun Dec 21 14:00:38 2014 bind.c:38 not auth'd, offering auth and register
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 490 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 170 bytes
Sun Dec 21 14:00:38 2014 main.c:437 sx sasl callback: get realm: realm is 'jabber.no-sense.net' Sun Dec 21 14:00:38 2014 main.c:456 sx sasl callback: check pass (authnid=xadventerur, realm=jabber.no-sense.net) Sun Dec 21 14:00:38 2014 authreg_mysql.c:109 prepared sql: SELECT `password` FROM `authreg` WHERE `username` = 'xadventerur' AND `realm` = 'jabber.no-sense.net'
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 122 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 218 bytes
Sun Dec 21 14:00:38 2014 ack.c:30 hacking ack namespace decl onto stream header
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 330 bytes written
Sun Dec 21 14:00:38 2014 [notice] [20] PLAIN authentication succeeded: xadvente...@jabber.no-sense.net <IP removed>:63359 TLS Sun Dec 21 14:00:38 2014 bind.c:51 auth'd, offering resource bind and session
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 474 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 186 bytes
Sun Dec 21 14:00:38 2014 [notice] [20] bound: jid=xadvente...@jabber.no-sense.net/WippienIM3 Sun Dec 21 14:00:38 2014 sm.c:61 built new route nad for xadvente...@jabber.no-sense.net/WippienIM3 action start target xadvente...@jabber.no-sense.net/WippienIM3 id 21aaeab1d88a3dee4d68a7e34bd54697272f6d48
Sun Dec 21 14:00:38 2014 c2s.c:718 want write
Sun Dec 21 14:00:38 2014 c2s.c:1382 write action on fd 7
Sun Dec 21 14:00:38 2014 c2s.c:755 writing to 7
Sun Dec 21 14:00:38 2014 c2s.c:759 304 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:713 want read
Sun Dec 21 14:00:38 2014 c2s.c:713 want read
Sun Dec 21 14:00:38 2014 c2s.c:547 read action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:47 reading from 20
Sun Dec 21 14:00:38 2014 c2s.c:106 read 154 bytes
Sun Dec 21 14:00:38 2014 c2s.c:439 pre-session packet, bye
Sun Dec 21 14:00:38 2014 [notice] [20] packet sent before session start, closing stream
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 298 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:37 want read
Sun Dec 21 14:00:38 2014 c2s.c:42 want write
Sun Dec 21 14:00:38 2014 c2s.c:561 write action on fd 20
Sun Dec 21 14:00:38 2014 c2s.c:144 writing to 20
Sun Dec 21 14:00:38 2014 c2s.c:148 90 bytes written
Sun Dec 21 14:00:38 2014 c2s.c:566 close action on fd 20
Sun Dec 21 14:00:38 2014 [notice] [20] [<IP removed>, port=63359] disconnect jid=xadvente...@jabber.no-sense.net/WippienIM3, packets: 2
[.....]

The main problem seems to be "packet sent before session start, closing stream" but I wonder why this is done AFTER the session has started and, even more important, why it did work on 2.2.17 (and all versions before) without problem?

In the c2s.xml file nothing was changed. STARTTLS is required. plain auth is enabled only after starttls has been sent.

I would really like a fix or an acceptable workaround to have these clients continue to use my XMPP service, there are too many of them who cannot use it any more.

Thanks in advance,

Regards,
Eric.


Reply via email to