session invalidate when dovecot auth processes busy.

[rcubetrac]

Reported by scorcher on 7 Dec 2010 10:40 UTC as Trac ticket #1487450

Sometimes, when dovecot authentication processes are busy, dovecot write reply "Waiting for authentication process to respond.." to client. Roundcubemail do not understand it and invalidate user session.

System:
[roundcubemail](www@mail)$ cat /etc/redhat-release
CentOS release 5.5 (Final)

[roundcubemail](www@mail)$ uname -a
Linux mail 2.6.18-194.3.1.el5.centos.plus #1 SMP Wed May 19 09:15:55 EDT 2010 i686 i686 i386 GNU/Linux

[roundcubemail](www@mail)$ php -v
PHP 5.2.10 (cli) (built: Nov 13 2009 11:24:03)
Copyright (c) 1997-2009 The PHP Group
Zend Engine v2.2.0, Copyright (c) 1998-2009 Zend Technologies

[roundcubemail](www@mail)$ rpm -qa dovecot
dovecot-1.0.7-7.el5

Rouncubemail 0.4-stable
[roundcubemail](www@mail)$ grep '$Id' program/include/rcube_imap_generic.php
 $Id: rcube_imap_generic.php 3866 2010-08-04 13:49:48Z alec $

Part of configuration file of dovecot:
=================================================
# Should each login be processed in it's own process (yes), or should one
# login process be allowed to process multiple connections (no)? Yes is more
# secure, espcially with SSL/TLS enabled. No is faster since there's no need
# to create processes all the time.
login_process_per_connection = yes

# Number of login processes to keep for listening new connections.
login_processes_count = 3

# Maximum number of login processes to create. The listening process count
# usually stays at login_processes_count, but when multiple users start logging
# in at the same time more extra processes are created. To prevent fork-bombing
# we check only once in a second if new processes should be created - if all
# of them are used at the time, we double their amount until the limit set by
# this setting is reached.
login_max_processes_count = 128

# Maximum number of connections allowed per each login process. This setting
# is used only if login_process_per_connection=no. Once the limit is reached,
# the process notifies master so that it can create a new login process.
login_max_connections = 256
=================================================

My recipies to fix this problem:

1. increase login_processes_count option dovecot.conf. But it is not a solution, because in one good :) moment there will be specified count of users online.
2. Check reply from imap server when trying to authenticate. If it contains "Waiting for authentication process to respond" then wait a moment and try again. Dovecot check usage of auth processess every second and if it is needed fork twice "current count of auth processes".

Second solution realised in patch which enclosured in ticket.

Keywords: session invalid dovecot authentication Migrated-From: http://trac.roundcube.net/ticket/1487450

[rcubetrac]

Comment by scorcher on 7 Dec 2010 10:44 UTC

Oh damn... Sorry for formatting in ticket... :(

[rcubetrac]

Comment by @alecpl on 7 Dec 2010 11:09 UTC

Why did you add checkWaitingAuth() after STARTTLS?

[rcubetrac]

Milestone changed by @alecpl on 7 Dec 2010 11:09 UTC

later => 0.5-stable

[rcubetrac]

Comment by scorcher on 7 Dec 2010 11:18 UTC

First of all, i did not check this consider TLS connection.

But bahavior of dovecot looks like it reply "Wait for..." after first command about auth. And I think that with TLS it will be exactly after STARTTLS command. But i can mistake.

I have checked it about CRAM-MD5 authentication. And already about two days we didn't get "session invalid" messages.

[rcubetrac]

Comment by scorcher on 7 Dec 2010 11:25 UTC

And i didnt add checkWaitingAuth in PLAIN method, because it do not have command before sending login&password and it uses another method "readReply". I had not free time to examine readReply method and its surrounding code.

[rcubetrac]

Comment by @till on 8 Dec 2010 00:35 UTC

1. Do you guys know what the reason is that Dovecot will say, "waiting"?
2. How long does it keep the process waiting?

The reason I'm asking is that I wonder if waiting for dovecot to respond will bear other issues for RoundCube or for the server it is hosted on.

Waiting on dovecot effectively blocks current the PHP process. In case of php-cgi, that is a process running on the OS and in case of Apache and mod_php, this means an Apache child.

There is probably a bigger implication on on large scale setups, e.g. let's say you have a couple 100 people on RoundCube at the same time. In the event of everyone waiting, it'll take your server down.

[rcubetrac]

Comment by scorcher on 8 Dec 2010 05:49 UTC

Replying to till:

1. Do you guys know what the reason is that Dovecot will say, "waiting"?
2. How long does it keep the process waiting?

From dovecot.conf: Maximum number of login processes to create. The listening process count usually stays at login_processes_count, but when multiple users start logging in at the same time more extra processes are created. To prevent fork-bombing we check only once in a second if new processes should be created - if all of them are used at the time, we double their amount until the limit set by this setting is reached.

So, maximum time to wait dovecot - 1 second. Other way: to say user that i cant connect to imap, but how to say it if you showing message with couple of images attached to the message (each image - new connection to imap ;)). It is like a snowslide, and after 1 second dovecot will ready to accept it.

If you have a lot users online, you just need to increase login_processes_count option in dovecot.conf to some value a little bit more than usualy users online.

The reason I'm asking is that I wonder if waiting for dovecot to respond will bear other issues for RoundCube or for the server it is hosted on.

Waiting on dovecot effectively blocks current the PHP process. In case of php-cgi, that is a process running on the OS and in case of Apache and mod_php, this means an Apache child.

Using cgi in highload application is bad idea :)

There is probably a bigger implication on on large scale setups, e.g. let's say you have a couple 100 people on RoundCube at the same time. In the event of everyone waiting, it'll take your server down.

If you will have hundreds online users who using imap to fetch (e.g. some page (20 msgs) of folder with thousands messages) your first problem will be iowait, because this operation is to expensive for HDD, and you will wait much more time than 1 second ;)

[rcubetrac]

Comment by @alecpl on 8 Dec 2010 10:29 UTC

@scorcher: I think my patch fixes this issue properly. Could you confirm using svn-trunk version with this patch applied?

[rcubetrac]

Comment by @till on 8 Dec 2010 11:16 UTC

Replying to scorcher:

Using cgi in highload application is bad idea :)

No FUD please. The opposite is true. php-cgi implies fastcgi or fpm.

[rcubetrac]

Comment by scorcher on 8 Dec 2010 13:46 UTC

Replying to alec:

@scorcher: I think my patch fixes this issue properly. Could you confirm using svn-trunk version with this patch applied?

I think your patch is not needed, because:

1. there is one line "17:06:08 +0500: S: * OK Waiting for authentication process to respond..", not multi or untagged.
2. problem was in algorithm of method connect:

rcube_mail_generic.php: function connect
...
'''!!!!!! here is $result = false;
!!!!!! $this->errornum = 0;'''
if ($auth_method == 'AUTH') {
    // do CRAM-MD5 authentication
    $this->putLine("a000 AUTHENTICATE CRAM-MD5");
    $line = trim($this->readLine(1024));
'''!!!!!! $line = '* OK Waiting for authentication process to respond..';

!!!!!! then you cant go inside it'''
    if ($line[== '+') {
        // got a challenge string, try CRAM-MD5
        $result = $this->authenticate($user, $password, substr($line,2));

        // stop if server sent BYE response
        if ($result == -3) {
            return false;
        }
    }

**!!!!!! then you cant go inside it, because $orig_method = 'AUTH' (from config)**
    if (!is_resource($result) && $orig_method == 'CHECK') {
        $auth_method = 'PLAIN';
    }
}

**!!!!!! then you cant go inside it**
if ($auth_method == 'PLAIN') {
    // do plain text auth
    $result = $this->login($user, $password);
}

if (is_resource($result)) {
    if ($this->prefs['force_caps'](0])) {
        $this->clearCapability();
    }
    $this->getNamespace();
    $this->logged = true;

    return true;
} else {
'''!!!!!! then you go here and return false in rcube_imap.php and then to rcmail.php: function imap_connect (see below)
!!!!!! there is additional line $this->closeConnection(); in code from trunk, before return false.'''
    return false;
}

public function imap_connect()
{
    if (!$this->imap)
        $this->imap_init();

    if ($_SESSION[&& !$this->imap->conn->connected()) {
        if (!$this->imap->connect($_SESSION['imap_host']('imap_host']), $_SESSION[$this->decrypt($_SESSION['password']('username'],)), $_SESSION[$_SESSION['imap_ssl']('imap_port'],))) {
            if ($this->output)
**!!!!!! then you wrote "sessionerror", because $this->imap->error_code = 0**
            $this->output->show_message($this->imap->error_code == -1 ? 'imaperror' : 'sessionerror', 'error');
        }
        else {
            $this->set_imap_prop();
            return $this->imap->conn;
        }
    }

    return false;
}

here is a log of imap dialog (number after date is PID of apache child):

[18:32:40 +0500](08-Dec-2010): 7621: S: * OK Dovecot OFFICE.MAIL ready.
[18:32:40 +0500](08-Dec-2010): 7621: C: A0001 AUTHENTICATE CRAM-MD5
[18:32:40 +0500](08-Dec-2010): 7623: S: * OK Dovecot OFFICE.MAIL ready.
[18:32:40 +0500](08-Dec-2010): 7623: C: A0001 AUTHENTICATE CRAM-MD5
[18:32:40 +0500](08-Dec-2010): 7624: S: * OK Dovecot OFFICE.MAIL ready.
[18:32:40 +0500](08-Dec-2010): 7624: C: A0001 AUTHENTICATE CRAM-MD5
[18:32:40 +0500](08-Dec-2010): 7621: S: * OK Waiting for authentication process to respond..
**$this->closeConnection();**
[18:32:40 +0500](08-Dec-2010): 7621: C: A0002 LOGOUT
**Answer to LOGOUT:**
[18:32:40 +0500](08-Dec-2010): 7621: S: + PDAyODU5MzQ4NjUzNjk3NDAuMTI5MTgxNTE2MEBtYWlsPg==
[18:32:40 +0500](08-Dec-2010): 7623: S: * OK Waiting for authentication process to respond..
[18:32:40 +0500](08-Dec-2010): 7623: C: A0002 LOGOUT
[18:32:40 +0500](08-Dec-2010): 7623: S: + PDMxNzM1NjgzODM3MjI1NjguMTI5MTgxNTE2MEBtYWlsPg==
[18:32:40 +0500](08-Dec-2010): 5481: S: * OK Dovecot OFFICE.MAIL ready.
[18:32:40 +0500](08-Dec-2010): 5481: C: A0001 AUTHENTICATE CRAM-MD5
[18:32:40 +0500](08-Dec-2010): 5481: S: + PDM0OTE3NDQ3ODM3ODQxNTQuMTI5MTgxNTE2MEBtYWlsPg==
[18:32:40 +0500](08-Dec-2010): 5481: C: <secret>
[18:32:40 +0500](08-Dec-2010): 7624: S: * OK Waiting for authentication process to respond..
[18:32:40 +0500](08-Dec-2010): 7624: C: A0002 LOGOUT
[18:32:40 +0500](08-Dec-2010): 7624: S: + PDA3NTY3ODA3Mjg0MzI3MTQuMTI5MTgxNTE2MEBtYWlsPg==
[18:32:40 +0500](08-Dec-2010): 5481: S: A0001 OK Logged in.

So, you must wait, if dovecot says "Waiting for authentication process to respond.." ;)

[rcubetrac]

Comment by @alecpl on 8 Dec 2010 13:52 UTC

Replying to scorcher:

Replying to alec:

@scorcher: I think my patch fixes this issue properly. Could you confirm using svn-trunk version with this patch applied?

I think your patch is not needed, because:

1. there is one line "17:06:08 +0500: S: * OK Waiting for authentication process to respond..", not multi or untagged.
2. problem was in algorithm of method connect:

rcube_mail_generic.php: function connect
...
'''!!!!!! here is $result = false;
!!!!!! $this->errornum = 0;'''
if ($auth_method == 'AUTH') {
  // do CRAM-MD5 authentication
  $this->putLine("a000 AUTHENTICATE CRAM-MD5");
      $line = trim($this->readLine(1024));

I see you didn't apply my patch. Use clean svn-trunk and apply my patch please.

[rcubetrac]

Comment by scorcher on 8 Dec 2010 14:22 UTC

now i have applied this patch. seems to be working fine...

hm.. feof return true only if socket closed, so then you right...

in line 224: fgets() - will waiting for server output... :)

Am i understands true?

PS: when 0.5 became stable?

[rcubetrac]

Comment by @alecpl on 8 Dec 2010 14:26 UTC

Patch applied in 40644528. I think 0.5-stable will be released in January.

[rcubetrac]

Status changed by @alecpl on 8 Dec 2010 14:26 UTC

new => closed