[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