First connection is broken

[kousu]

I installed xcauth on my server (as in #44) and I find that the first time I try to connect I get Unable to interpret data from auth process, [62 bytes] in my prosody logs:

socket                        debug server.lua: accepted new client connection from 216.16.230.126:46026 to 5222
c2s1169710                    info  Client connected
c2s1169710                    debug Client sent opening <stream:stream> to sunflowercollective.org
c2s1169710                    debug Sent reply <stream:stream> to client
c2s1169710                    debug Not offering authentication on insecure connection
c2s1169710                    debug Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
socket                        debug server.lua: we need to do tls, but delaying until send buffer empty
c2s1169710                    debug TLS negotiation started for c2s_unauthed...
socket                        debug server.lua: attempting to start tls on tcp{client}: 0x10fba08
socket                        debug server.lua: ssl handshake done
c2s1169710                    debug Client sent opening <stream:stream> to sunflowercollective.org
c2s1169710                    debug Sent reply <stream:stream> to client
c2s1169710                    info  Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384)
c2s1169710                    debug Received[c2s_unauthed]: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
sunflowercollective.org:auth_external  debug    Started auth process
sunflowercollective.org:auth_external  warn Unable to interpret data from auth process, [62 bytes]
sunflowercollective.org:saslauth       debug    sasl reply: <failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><not-authorized/><text>Unable to authorize you with the authentication credentials you&apos;ve sent.</text></failure>
socket                                 debug    server.lua: client 216.16.230.126:46026 read error: closed
c2s1169710                             info Client disconnected: closed
c2s1169710                             debug    Destroying session for (unknown) ((unknown)@sunflowercollective.org): closed
socket                                 debug    server.lua: closed client handler and removed socket from list

But if I sign in a second time immediately after I get

socket                                 debug    server.lua: accepted new client connection from 216.16.230.126:46046 to 5222
c2s127c340                             info Client connected
c2s127c340                             debug    Client sent opening <stream:stream> to sunflowercollective.org
c2s127c340                             debug    Sent reply <stream:stream> to client
c2s127c340                             debug    Not offering authentication on insecure connection
c2s127c340                             debug    Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
socket                                 debug    server.lua: we need to do tls, but delaying until send buffer empty
c2s127c340                             debug    TLS negotiation started for c2s_unauthed...
socket                                 debug    server.lua: attempting to start tls on tcp{client}: 0x1278888
socket                                 debug    server.lua: ssl handshake done
c2s127c340                             debug    Client sent opening <stream:stream> to sunflowercollective.org
c2s127c340                             debug    Sent reply <stream:stream> to client
c2s127c340                             info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384)
c2s127c340                             debug    Received[c2s_unauthed]: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
c2s127c340                             info Authenticated as kousu@sunflowercollective.org
sunflowercollective.org:saslauth       debug    sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>

I sniffed the conversation prosody is having with xcauth and all I see is

auth:kousu:sunflowercollective.org:*************************
1
auth:kousu:sunflowercollective.org:*************************
1

The first auth line fails, the second succeeds. I don't know what 62 bytes could refer to; it's also a consistent 62 bytes. Do you have a clue? Have you seen this?

Maybe this is actually a bug in mod_auth_external.

[kousu]

I may have seen this a second time post-boot. I logged in successfully on one account, but then two different accounts, trying with Gajim and oJSXC, momentarily reported incorrect passwords. But I didn't catch the logs to go with it so this is just a bit better than hearsay. I don't know if this is because xcauth crashed and was restarted by Prosody or if there's something deeper. I mean, I have no explanation for why this message happens at all.

[kousu]

This is not a bug in xmpp-cloud-auth. I wrote my own implementation because I was frustrated with the glitch, and got the exact same error message about the 62 bytes.

It must be something involving lpty.

[kousu]

For the record, it is lpty. I added more logging to mod_auth_external and now I see:

Jan 12 05:03:41 sunflowercollective.org prosody[6661]: sunflowercollective.org:auth_external: Started auth process   
Jan 12 05:03:41 sunflowercollective.org prosody[6661]: sunflowercollective.org:auth_external: Got response from auth provider:               
Jan 12 05:03:41 sunflowercollective.org prosody[6661]: sunflowercollective.org:auth_external: auth:kousu:sunflowercollective.org:***************************
Jan 12 05:03:41 sunflowercollective.org prosody[6661]: sunflowercollective.org:auth_external: ----------------                                              
Jan 12 05:03:41 sunflowercollective.org prosody[6661]: sunflowercollective.org:auth_external: Unable to interpret data from auth process, [62 bytes]

lpty is copying its input to its output, even though no_local_echo = true in the settings. Its README has a dismissive warning about this:

The local echo thing

As written in the description of the no_local_echo flag, this may not always work as expected. Programs are free to set their terminals to whatever settings they like, and indeed some programs do, or even completely roll their own local echo policy. The most notable piece of code to do this is Gnu readline, though it seems that this does not happen for all versions of it. On Mac OS X, it certainly does, whereas on my Ubuntu Box it does not. So if you write something using lpty that is supposed to be used on different unixen, you better not rely on no_local_echo to do what you think it should.

[kousu]

And apparently you already fixed this: https://github.com/jsxc/xmpp-cloud-auth/commit/0d0154f66bdda50b40846491cfc9c63a8c0f9311#diff-c33707595019efa87a2ea715407721ea

[MarcelWaldvogel]

Duplicate of #21

@kousu Thanks for lpty investigation and your clever fix in Prosody issue 855