[imp] IMAP Alert command (was Performance after upgrade)
Stephen A. Cochran Lists
stephen.a.cochran.lists at cahir.net
Thu Nov 2 09:10:35 PST 2006
I've found the source of the problem, although I'm not sure of a
solution yet. The problem is that our IMAP server issues an alert at
login as show below, which seems to throw IMP for a loop, literally:
11/02/2006 10:22:51 [166400648] C: 00000000 CAPABILITY
11/02/2006 10:22:51 [166400648] S: 00000000 OK CAPABILITY completed
11/02/2006 10:22:51 [166400648] C: LOGIN Test1
11/02/2006 10:22:51 IMAPS Logged on: Test1 23868; currently: 1; peak:
10 from 129.170.208.37
11/02/2006 10:22:51 [166400648] S: * OK [ALERT] This account is
scheduled to be deactivated on 5-Nov-2006. Contact the Postmaster for
more information.
11/02/2006 10:22:51 [166400648] S: 00000001 OK Login completed
11/02/2006 10:22:51 [166400648] C: 00000002 CAPABILITY
11/02/2006 10:22:51 [166400648] S: 00000002 OK CAPABILITY completed
Note that the alert comes between the client command and the server
response. I can't be exactly sure why, but this sends imp/apache into
some kind of infinite loop, with each process hit by this trying to
take 100% of the CPU. The execution stops in Session.php at line 298:
$_SESSION['imp']['namespace'] = $imapclient->namespace
($user_namespace);
In the logs, the client then opens a second connection, and this time
gets farther, getting to the the LIST command. Unfortunately the
browser is still hung up waiting for a response from the first
process that is now locked at 100% CPU. The logs below show the IMAP
commands as logged by the server, and some debug lines I added into
Session.php at the following locations. Last is a few lines from top
showing the runaway processes:
Horde::logMessage("SAC_DEBUG: 1", __FILE__, __LINE__, PEAR_LOG_INFO);
$res = $imapclient->login($_SESSION['imp']['user'], $password);
if (is_a($res, 'PEAR_Error')) {
$auth_imp->IMPsetAuthErrorMsg($res-
>getMessage());
unset($_SESSION['imp']);
return false;
}
Horde::logMessage("SAC_DEBUG: 2", __FILE__, __LINE__, PEAR_LOG_INFO);
$_SESSION['imp']['namespace'] = $imapclient->namespace
($user_namespace);
Horde::logMessage("SAC_DEBUG: 3", __FILE__, __LINE__, PEAR_LOG_INFO);
11/02/2006 12:00:02 [166461296] SSL Client arriving from 129.170.208.37
11/02/2006 12:00:02 [166461296] SSL accept
11/02/2006 12:00:02 [166461296] C: 00000000 CAPABILITY
11/02/2006 12:00:02 [166461296] S: 00000000 OK CAPABILITY completed
11/02/2006 12:00:02 [166461296] C: LOGIN Test1
11/02/2006 12:00:02 IMAPS Logged on: Test1 23868; currently: 1; peak:
10 from 129.170.208.37
11/02/2006 12:00:02 [166461296] S: * OK [ALERT] This account is
scheduled to be deactivated on 5-Nov-2006. Contact the Postmaster for
more information.
11/02/2006 12:00:02 [166461296] S: 00000001 OK Login completed
11/02/2006 12:00:02 [166461296] C: 00000002 CAPABILITY
11/02/2006 12:00:02 [166461296] S: 00000002 OK CAPABILITY completed
11/02/2006 12:00:02 [164551208] SSL Client arriving from 129.170.208.37
11/02/2006 12:00:02 [164551208] SSL accept
11/02/2006 12:00:02 [164551208] C: A001 CAPABILITY
11/02/2006 12:00:02 [164551208] S: A001 OK CAPABILITY completed
11/02/2006 12:00:02 [164551208] C: LOGIN Test1
11/02/2006 12:00:02 IMAPS Logged on: Test1 23868; currently: 2; peak:
10 from 129.170.208.37
11/02/2006 12:00:02 [164551208] S: * OK [ALERT] This account is
scheduled to be deactivated on 5-Nov-2006. Contact the Postmaster for
more information.
11/02/2006 12:00:02 [164551208] S: A002 OK Login completed
11/02/2006 12:00:02 [164551208] C: A003 LIST "" ""
11/02/2006 12:00:02 [164551208] S: * LIST () "/" ""
11/02/2006 12:00:02 [164551208] S: A003 OK command completed
Nov 02 12:00:04 HORDE [info] [imp] SAC_DEBUG: 1 [on line 293 of "/var/
www/html/mail/horde/imp/lib/Session.php"]
Nov 02 12:00:04 HORDE [info] [imp] SAC_DEBUG: 2 [on line 299 of "/var/
www/html/mail/horde/imp/lib/Session.php"]
Nov 02 12:00:07 HORDE [info] [imp] SAC_DEBUG: 1 [on line 293 of "/var/
www/html/mail/horde/imp/lib/Session.php"]
Nov 02 12:00:07 HORDE [info] [imp] SAC_DEBUG: 2 [on line 299 of "/var/
www/html/mail/horde/imp/lib/Session.php"]
Nov 02 12:00:07 HORDE [info] [imp] SAC_DEBUG: 3 [on line 301 of "/var/
www/html/mail/horde/imp/lib/Session.php"]
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
27694 apache 25 0 44928 24m 16m R 99.5 2.4 7:01.78 httpd
27742 apache 25 0 44676 23m 16m R 98.2 2.3 9:43.38 httpd
Any help in what is actually causing the runaway process or a fix
would be appreciated.
Steve Cochran
Dartmouth College
More information about the imp
mailing list