[dovecot] Re: STARTTLS hangs due to client_skip_line (Was: Re: Plain auth broken)

[Amelia A.Lewis]

Dear Timo,

On 02 Feb 2003 09:15:19 +0200
Timo Sirainen <tss at iki.fi> wrote:

> On Sun, 2003-02-02 at 08:28, Amelia A.Lewis wrote:
> > Adding debugging to client_skip_line (i_info with the
> > contents of data) shows that, after the starttls command,
> > client_skip_line discards the whole next command (in my case, a0002
> > CAPABILITY).  The client is waiting for a response.  The server is
> > waiting for a command (having discarded one).  login times out sixty
> > seconds later, for inactivity.
> 
> Yes, so it seems.
> 
> > No one else seems to be having this sort of problem, though.  Is
> > that because most folks are using TLS on the imaps port?  Or have I
> > got a misconfiguration that runs somehow deeper?  I don't *think*
> > I'm chasing a wild hare.
> 
> I've tested STARTTLS only with Evolution which I guess didn't mind
> about not getting a reply to next command.
> 
> Here's a patch, thanks for bug report :)

Thank you!  Only it doesn't work.  I don't quite know why, either (it's
almost exactly what I tried, but skipping over the skip_line seems to
mean that it can't find the tag to read).  Which seems weird.  Is it
possible that client->parser->input != client->input?  Such that
client->parser->input still points at the original fd?

For whatever it might be worth, here's two runs of mutt, one without,
and one with the patch.  Most of the stuff occurs inside
client_handle_input.

Feb  2 10:55:51 talifane imap-master: Dovecot starting up
Feb  2 10:55:52 talifane imap-auth: Login process 6 connected
Feb  2 10:55:52 talifane imap-auth: Login process 7 connected
Feb  2 10:55:52 talifane imap-auth: Login process 8 connected
Feb  2 10:55:52 talifane imap-auth: Login process 8 sent handshake: PID
9137
Feb  2 10:55:52 talifane imap-auth: Login process 7 sent handshake: PID
9138
Feb  2 10:55:52 talifane imap-auth: Login process 6 sent handshake: PID
9139
Feb  2 10:55:53 talifane imap-login: client_handle_input: cmd_tag is
null
Feb  2 10:55:53 talifane imap-login: client_handle_input: cmd_name is
null
Feb  2 10:55:53 talifane imap-login: client_handle_input: cmd_finished:
cmd_tag: a0000 ; cmd_name: CAPABILITY
Feb  2 10:55:53 talifane imap-login: Skipping line in data: 
Feb  2 10:55:53 talifane imap-login: Skipped 2 chars
Feb  2 10:55:53 talifane imap-login: client_handle_input: cmd_tag is
null
Feb  2 10:55:53 talifane imap-login: client_handle_input: cmd_name is
null
Feb  2 10:55:53 talifane imap-login: gnutls ssl_proxy_new
Feb  2 10:55:54 talifane imap-auth: Login process 9 connected
Feb  2 10:55:54 talifane imap-auth: Login process 9 sent handshake: PID
9141
Feb  2 10:55:54 talifane imap-login: client_handle_input: cmd_finished:
cmd_tag: a0001 ; cmd_name: STARTTLS
Feb  2 10:55:54 talifane imap-login: Skipping line in data: a0002
CAPABILITY
Feb  2 10:55:54 talifane imap-login: Skipped 18 chars
Feb  2 10:55:54 talifane imap-login: client_handle_input: cmd_tag is
null
Feb  2 10:55:54 talifane imap-login: client_handle_input: can't fill
cmd_tag (need more data)
Feb  2 10:56:54 talifane imap-login: Disconnected: Inactivity
[127.0.0.1]
Feb  2 10:56:54 talifane imap-auth: Login process 8 disconnected

The next one is with the patch applied.

Feb  2 11:00:41 talifane imap-master: Dovecot starting up
Feb  2 11:00:42 talifane imap-auth: Login process 6 connected
Feb  2 11:00:42 talifane imap-auth: Login process 7 connected
Feb  2 11:00:42 talifane imap-auth: Login process 8 connected
Feb  2 11:00:42 talifane imap-auth: Login process 8 sent handshake: PID
9361
Feb  2 11:00:42 talifane imap-auth: Login process 7 sent handshake: PID
9362
Feb  2 11:00:42 talifane imap-auth: Login process 6 sent handshake: PID
9363
Feb  2 11:00:47 talifane imap-login: client_handle_input: cmd_tag is
null
Feb  2 11:00:47 talifane imap-login: client_handle_input: cmd_name is
null
Feb  2 11:00:47 talifane imap-login: client_handle_input: cmd_finished:
cmd_tag: a0000 ; cmd_name: CAPABILITY
Feb  2 11:00:47 talifane imap-login: Skipping line in data: 
Feb  2 11:00:47 talifane imap-login: Skipped 2 chars
Feb  2 11:00:47 talifane imap-login: client_handle_input: cmd_tag is
null
Feb  2 11:00:47 talifane imap-login: client_handle_input: cmd_name is
null
Feb  2 11:00:47 talifane imap-login: gnutls ssl_proxy_new
Feb  2 11:00:47 talifane imap-auth: Login process 9 connected
Feb  2 11:00:47 talifane imap-auth: Login process 9 sent handshake: PID
9365
Feb  2 11:00:48 talifane imap-login: client_handle_input: cmd_finished:
cmd_tag: a0001 ; cmd_name: STARTTLS
Feb  2 11:00:48 talifane imap-login: client_handle_input: cmd_tag is
null
Feb  2 11:00:48 talifane imap-login: client_handle_input: can't fill
cmd_tag (need more data)
Feb  2 11:01:48 talifane imap-login: Disconnected: Inactivity
[127.0.0.1]
Feb  2 11:01:48 talifane imap-auth: Login process 8 disconnected

As you can see, the major difference is that it doesn't discard the
command, but it still can't seem to see it (client_handle_input: can't
fill cmd_tag (need more data) happens in just the place where "need more
data" appears as a comment).  Now, looking around, it appears that
skip_line uses i_stream_get_data on client->input, while filling the tag
calls imap_parser_read_word, which uses i_stream_get_data on
parser->input.  Does all the necessary information for the parser get
reset in starttls?

Amy!
-- 
Amelia A. Lewis                    amyzing {at} talsever.com
Early to bed and early to rise
makes a man stupid and blind in the eyes.