XML parse error (not well-formed (invalid token)) in c2s.log for new connection

[Alexander Gorodinski]

connection from some clients fails with XML parse error (not well-formed (invalid token))(for pidgin) or silently(for psi). Pidgin fails only on windows, on linux everything works fine.

more detailed description in gentoo bugtracker:
https://bugs.gentoo.org/show_bug.cgi?id=381279

bug apperars in jabberd 2.2.4 and 2.2.14.

I'm not sure that this is bug, but this error message is too general, I have no idea how to debug it.

[Alexander Gorodinski (testor)]

debug output from pidgin 2.10.0 on windiws:

(19:41:27) util: Writing file accounts.xml to directory C:\Documents and Settings\Administrator\Application Data\.purple
(19:41:27) util: Writing file C:\Documents and Settings\Administrator\Application Data\.purple\accounts.xml
(19:41:28) prefs: /pidgin/blist/list_visible changed, scheduling save.
(19:41:29) prefs: /pidgin/blist/list_visible changed, scheduling save.
(19:41:34) util: Writing file prefs.xml to directory C:\Documents and Settings\Administrator\Application Data\.purple
(19:41:34) util: Writing file C:\Documents and Settings\Administrator\Application Data\.purple\prefs.xml
(19:41:35) prefs: /purple/savedstatus/default changed, scheduling save.
(19:41:35) account: Connecting to account <email address hidden>/windows.
(19:41:35) connection: Connecting. gc = 029F53F0
(19:41:35) dnssrv: querying SRV record for zazoid.com: _xmpp-client._tcp.zazoid.com
(19:41:35) dnssrv: Couldn't look up SRV record. DNS-имя не существует. (9003).
(19:41:35) dnsquery: Performing DNS lookup for zazoid.com
(19:41:35) dnsquery: IP resolved for zazoid.com
(19:41:35) proxy: Attempting connection to 91.149.158.47
(19:41:35) proxy: Connecting to zazoid.com:5222 with no proxy
(19:41:35) proxy: Connection in progress
(19:41:35) proxy: Connecting to zazoid.com:5222.
(19:41:35) proxy: Connected to zazoid.com:5222.
(19:41:35) jabber: Sending (<email address hidden>/windows): <?xml version='1.0' ?>
(19:41:35) jabber: Sending (<email address hidden>/windows): <stream:stream to='zazoid.com' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
(19:41:35) jabber: Recv (244): <?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' from='zazoid.com' version='1.0' id='xbu8yzthrqlffao1ffytcns0ljh0e4kbgfkfeew6' xmlns:ack='http://www.xmpp.org/extensions/xep-0198.html#ns'>
(19:41:35) jabber: Recv (442): <stream:features xmlns:stream='http://etherx.jabber.org/streams'><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><address xmlns='http://affinix.com/jabber/address'>80.94.239.51</address><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism></mechanisms><auth xmlns='http://jabber.org/features/iq-auth'/><register xmlns='http://jabber.org/features/iq-register'/></stream:features>
(19:41:35) jabber: Sending (<email address hidden>/windows): <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
(19:41:35) jabber: Recv (50): <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
(19:41:35) nss: <email address hidden>,CN=Alexander Gorodinski,O=Zazoid.com,L=Minsk,ST=Some-State,C=BY <email address hidden>,CN=Alexander Gorodinski,O=Zazoid.com,L=Minsk,ST=Some-State,C=BY
(19:41:35) certificate/x509/tls_cached: Starting verify for zazoid.com
(19:41:35) certificate/x509/tls_cached: Checking for cached cert...
(19:41:35) certificate/x509/tls_cached: ...Found cached cert
(19:41:35) nss/x509: Loading certificate from C:\Documents and Settings\Administrator\Application Data\.purple\certificates\x509\tls_peers\zazoid.com
(19:41:35) certificate/x509/tls_cached: Peer cert matched cached
(19:41:35) nss/x509: Exporting certificat...

[Alexander Gorodinski (testor)]

same version of pidgin works fine on linux:

(20:00:52) util: Writing file prefs.xml to directory /home/n0153/.purple
(20:00:52) util: Writing file /home/n0153/.purple/prefs.xml
(20:00:52) util: Writing file blist.xml to directory /home/n0153/.purple
(20:00:52) util: Writing file /home/n0153/.purple/blist.xml
(20:00:52) util: Writing file accounts.xml to directory /home/n0153/.purple
(20:00:52) util: Writing file /home/n0153/.purple/accounts.xml
(20:03:03) prefs: /purple/savedstatus/default changed, scheduling save.
(20:03:03) account: Connecting to account <email address hidden>/finch.
(20:03:03) connection: Connecting. gc = 0x91330c8
(20:03:03) dnssrv: querying SRV record for zazoid.com: _xmpp-client._tcp.zazoid.com
(20:03:03) dnssrv: res_query returned an error
(20:03:03) dnsquery: Performing DNS lookup for zazoid.com
(20:03:03) dns: Wait for DNS child 31446 failed: No child processes
(20:03:03) dns: Created new DNS child 31551, there are now 1 children.
(20:03:03) dns: Successfully sent DNS request to child 31551
(20:03:03) dns: Got response for 'zazoid.com'
(20:03:03) dnsquery: IP resolved for zazoid.com
(20:03:03) proxy: Attempting connection to 91.149.158.47
(20:03:03) proxy: Connecting to zazoid.com:5222 with no proxy
(20:03:03) proxy: Connection in progress
(20:03:03) proxy: Connecting to zazoid.com:5222.
(20:03:03) proxy: Connected to zazoid.com:5222.
(20:03:03) jabber: Sending (<email address hidden>/finch): <?xml version='1.0' ?>
(20:03:03) jabber: Sending (<email address hidden>/finch): <stream:stream to='zazoid.com' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
(20:03:03) jabber: Recv (244): <?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' from='zazoid.com' version='1.0' id='xufg7ghv81lg91uo7hhwop943d79om4lhj1ozjk8' xmlns:ack='http://www.xmpp.org/extensions/xep-0198.html#ns'>
(20:03:03) jabber: Recv (442): <stream:features xmlns:stream='http://etherx.jabber.org/streams'><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><address xmlns='http://affinix.com/jabber/address'>80.94.239.51</address><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism></mechanisms><auth xmlns='http://jabber.org/features/iq-auth'/><register xmlns='http://jabber.org/features/iq-register'/></stream:features>
(20:03:03) jabber: Sending (<email address hidden>/finch): <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
(20:03:03) jabber: Recv (50): <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
(20:03:03) gnutls: Starting handshake with zazoid.com
(20:03:03) gnutls: Handshake complete
(20:03:03) gnutls/x509: Key print: 9e:97:af:04:40:6d:9d:0d:71:2a:b0:97:02:6a:3e:53:4b:dd:92:ec
(20:03:03) gnutls: Peer provided 1 certs
(20:03:03) gnutls: Lvl 0 SHA1 fingerprint: 9e:97:af:04:40:6d:9d:0d:71:2a:b0:97:02:6a:3e:53:4b:dd:92:ec
(20:03:03) gnutls: Serial: 00:dc:a6:6f:dc:12:55:f5:ba
(20:03:03) gnutls: Cert DN: C=BY,ST=Some-State,L=Minsk,O=Zazoid.com,CN=Alexander Gorodinski,<email address hidden>
(20:03:03) gnutls: Cert Issuer DN: C=BY,ST=Some-State,L=Minsk,O=Zazoid.com,CN=Alexander Gorodinski,<email address hidden>
(20:03:03) ce...

[Tomasz Sterna (smoku)]

Which version of GSASL do you use?

Please build your jabberd with ./configure --with-debug and run c2s with -D switch to get debugging information from server side.

[Lars (lars-taeuber)]

Hi Tomasz,

here is the log of c2s -D:

Thu Sep 22 12:49:04 2011 c2s.c:562 accept action on fd 11
Thu Sep 22 12:49:04 2011 [notice] [11] [<ip address hidden>, port=2256] connect
sx (sx.c:61) allocated new sx for 11
sx (server.c:237) doing server init for sx 11
sx (server.c:252) waiting for stream header
sx (server.c:255) tag 11 event 0 data 0x0
Thu Sep 22 12:49:04 2011 c2s.c:35 want read
Thu Sep 22 12:49:04 2011 c2s.c:525 read action on fd 11
sx (io.c:191) 11 ready for reading
sx (io.c:197) tag 11 event 2 data 0x69cc10
Thu Sep 22 12:49:04 2011 c2s.c:45 reading from 11
Thu Sep 22 12:49:04 2011 c2s.c:104 read 141 bytes
sx (io.c:216) passed 141 read bytes
sx (chain.c:93) calling io read chain
sx (io.c:240) decoded read data (141 bytes): <?xml version='1.0' ?><stream:stream to='<servername hidden>' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>
sx (server.c:119) stream request: to <servername hidden> from (null) version 1.0
sx (server.c:134) 11 state change from 0 to 1
sx (server.c:152) stream id is r473pmcx2tyn7xbxt9u6i9ckpbfq50uw410uocrq
Thu Sep 22 12:49:04 2011 ack.c:30 hacking ack namespace decl onto stream header
sx (server.c:182) prepared stream response: <?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' from='<servername hidden>' version='1.0' id='r473pmcx2tyn7xbxt9u6i9ckpbfq50uw410uocrq' xmlns:ack='http://www.xmpp.org/extensions/xep-0198.html#ns'>
sx (io.c:256) tag 11 event 1 data 0x0
Thu Sep 22 12:49:04 2011 c2s.c:40 want write
Thu Sep 22 12:49:04 2011 c2s.c:539 write action on fd 11
sx (io.c:328) 11 ready for writing
sx (io.c:286) encoding 248 bytes for writing: <?xml version='1.0'?><stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' from='<servername hidden>' version='1.0' id='r473pmcx2tyn7xbxt9u6i9ckpbfq50uw410uocrq' xmlns:ack='http://www.xmpp.org/extensions/xep-0198.html#ns'>
sx (chain.c:79) calling io write chain
sx (io.c:349) handing app 248 bytes to write
sx (io.c:350) tag 11 event 3 data 0x69cc40
Thu Sep 22 12:49:04 2011 c2s.c:142 writing to 11
Thu Sep 22 12:49:04 2011 c2s.c:146 248 bytes written
sx (server.c:29) stream established
sx (server.c:39) 11 state change from 1 to 3
sx (server.c:40) tag 11 event 4 data 0x0
sx (server.c:45) building features nad
sx (address.c:34) adding address feature
sx (sasl_gsasl.c:355) offering sasl mechanisms
sx (sasl_gsasl.c:779) in _sx_sasl_gsasl_callback, property: 18
sx (sasl_gsasl.c:779) in _sx_sasl_gsasl_callback, property: 18
sx (sasl_gsasl.c:375) offering mechanism: PLAIN
sx (sasl_gsasl.c:375) offering mechanism: DIGEST-MD5
Thu Sep 22 12:49:04 2011 bind.c:38 not auth'd, offering auth and register
sx (io.c:383) tag 11 event 0 data 0x0
Thu Sep 22 12:49:04 2011 c2s.c:35 want read
Thu Sep 22 12:49:04 2011 c2s.c:539 write action on fd 11
sx (io.c:328) 11 ready for writing
sx (io.c:286) encoding 391 bytes for writing: <stream:features xmlns:stream='http://etherx.jabber.org/streams'><address xmlns='http://affinix.com/jabber/address'><ip address hidden></address><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism...

[Tomasz Sterna (smoku)]

CyrusSASL is not supported anymore.

[Lars (lars-taeuber)]

Hi Tomasz,

I'm sorry.
The cyrus-sasl is installed but not used.
libgsasl-1.6.1 is used:

# ldd /usr/local/bin/c2s | fgrep sasl
 libgsasl.so.7 => /usr/local/lib/libgsasl.so.7 (0x00007fdfcd903000)

Does this help?

Thanks
Lars

[Tomasz Sterna (smoku)]

Oh, sorry.

Then this is duplicate of Bug 737229