RC in some servers brings httpd to 100% CPU

[mavetju]

When trying to use the RoundCube webinterface (www.roundcube.net), I saw that the CPU on my webserver went through the roof due to the httpd using 100% CPU.

Using it on other IMAP servers didn't show this behaviour.

• I've tried it on FreeBSD 6.0 and 6.1.
• I've tried it with Apache 2.0 and 2.2.
• I've tried it with PHP 4 and PHP 5.
• I've tried it with PostgreSQL and MySQL.

People are going to point fingers, saying that the other one is the one who is making the mistake...

[mavetju]

http://www.dbmail.org/mantis/view.php?id=394

[tcat]

My problem is exactly same, but I'm using different config:

- Gentoo 2005.1
- Courier IMAP Server (with Courier MTA)
- PHP 5.1.4, Apache 2.0.x
- SQlite 2.x db

When some IMAP error occurs (read, write or other issues, but not authentication error), my apache thread going to use 100% of cpu time. Apache forks new thread and user can use webmail, but the buggy thread stay there, and eats my cpu. Apache doesnt close it (I have small KeepAlive?), maybe the buggy thread generates output?

Here is some IMAP example from error log :

Could not connect to localhost at port 143

IMAP Error: Could not delete message from Drafts in /mnt/sda1/www/localhost/htdocs/roundcube/program/steps/mail/sendmail.inc on line 0

Could not delete message from Drafts

Invalid password

The CPU eating allways occurs when "PHP Warning: Cannot modify header information - headers already sent in /mnt/sda1/www/localhost/htdocs/roundcube/program/include/rcube_shared.inc on line 132" PHP error follows the IMAP error.

In most of case we have authentication errors (IMAP Error: Authentication for xxxx@… failed (AUTH): "a000 NO Login failed."), but after this type of IMAP error I don't see any PHP header error, and anything works fine.

The easy way to test this bug: create a mailbox account but no maildir (or mbox). IMAP server generates read/write errors, and the thread will eat the CPU.

(Sorry for my bad english, I'm exert to learn it.)

[fabio]

I experience the same on a Gentoo box running the following:

- Apache 2.0.58 - PHP 5.1.6 - MySQL 4.1.21 and this setup is connecting to a FreeBSD box running imap-2004g.

So far no consistant behavior here. Quite annoying though, we sorta deployed RC on a system with alot of users, this slows even a quad xeon box down.

[fabio]

Uncommenting line 1571 in program/lib/imap.inc seems to fix this problem.

function iil_C_CountUnseen(&$conn, $folder){

/* 	$index = iil_C_Search($conn, $folder, "ALL UNSEEN");

	if (is_array($index)){

		$str = implode(",", $index);

		if (empty($str)) return false;

		else return count($index);

	}else return false;*/

	return false;

}

[tcat]

I debugged this error (using zend debugger) by deleting maildir in courier-imap on a working mailbox (this error is potentially forces rouncube to endless loop when user try to login).

The loop found in imap.inc when the connection is successfully opened, and imap lib wants to read from socket, but nothing returned (including closing \n character).

I've put a small protection to iil_ReadLine to prevent it from endless loops. When nothing was red from socket continually 1000time, reading will break.

Index: imap.inc
===================================================================
--- imap.inc
+++ imap.inc
@@ -126,10 +126,15 @@
 }
 
 function iil_ReadLine($fp, $size){
-       $line="";
+       $line=""; $i=0;
        if ($fp){
               do{
-                     $buffer = fgets($fp, 2048);
+                     if ($buffer = fgets($fp, 2048)) {
+                            //reset counter
+                            $i = 0;
+                     } else {
+                            if (++$i > 1000) break;
+                     }
                      $line.=$buffer;
               }while($buffer[strlen($buffer)-1]!="\n");
        }

Maybe this can be useful for trunk version

[tcat]

Hi everyone!

I've found an other function in imap.inc wich can make endless loop:

--- program/lib/imap.inc	2007-01-08 17:22:56.000000000 +0100
+++ program/lib/imap.inc	2007-01-08 17:32:23.000000000 +0100
@@ -160,7 +160,6 @@
 	$len = 0;
 	do{
 		$data.=fread($fp, $bytes-$len);
+		if ($len == strlen($data)) break; //nothing was read -> exit to avoid apache lockups
 		$len = strlen($data);
 	}while($len<$bytes);
 	return $data;
@@ -363,7 +362,7 @@
 	}

[ralf]

I am encountering the same problems. Unfortunatly non of the above patches solved my problem. I received a couple of mails which lead to this problem. Others dont. My suspicion is that most of the mails which cause Apache to hog CPU have large http content. Small mails with http content are not causing it. Neither large pure text mails.

Another observation while tracing the imap port was, that something goes wrong while opening/downloading a mail to RC. This does not yet cause Apache to go insane. As soon as the next periodical check for new mail is startet one http process brings the CPU up to 100%.

Reducing max_execution_time in php.ini is no workaround for my problem.

Env:

CORE:   2.6.18-gentoo
IMAP:   uw-imap-2004g (mbox)
APACHE: 2.0.58
PHP:    5.1.6
Browser:Firefox 1.5.0.9 on Linux and M$
RC:     Trunk 455
DB:     MySQL 5.0.26

[foxintampa]

Has anybody found a solution to this? I just downloaded and installed roundcube today and noticed that not only httpd goes into 100% cpu loop, so does IE7 and crashes. I have a P4 2.8 GZ with a gig of ram and the computer freezes up while navigating around. I noticed I can reduce this by only displaying 10 or 20 messages per page, but it still happens. I really like roundcube, but not going to use it if I have to restart apache everytime I check mail.

Ensim Pro 4.1.0-8.rhel.4ES Apache/2.0.52 (Red Hat) PHP 4.3.9 MySQL 4.1.20

[azaiats]

Got a clue.

Something is wrong on messages with content-type and encoding different from default.

Sniffing my own machine, got the clue about some messages that I can read perfectly on roundcube, and the messages that hang roundcube.

The messages that hang my roundcube (every single one that hang it) contains:

Content-Type: text/plain;charset=iso-8859-1

Content-Transfer-Encoding: 8bit

So, I guess something in the hacked code on imap.inc (look at function iil_C_FetchHeaders) is wrong. Maybe something with transfer-encoding parsing...

Hope someone can figure it out. I`ll make more research over here too.

AZ.

[vkertesz]

Maybe someone should complete what I started to do. I think the problem is that RoundCube does NOT care about every errorous returning values. My original problem was as mentioned above that after deleting a user's maildir, apache started hanging at 100% cpu. This little patch solves this problem, but it probably doesn't the many others above.

Index: program/lib/imap.inc
===================================================================
--- program/lib/imap.inc        (revision 805)
+++ program/lib/imap.inc        (working copy)
@@ -177,6 +177,7 @@
                if (strcasecmp($a[1], "OK")==0) return 0;
                else if (strcasecmp($a[1], "NO")==0) return -1;
                else if (strcasecmp($a[1], "BAD")==0) return -2;
+               else return -4;
        }else return -3;
 }

@@ -216,11 +217,17 @@
     $line = iil_ReadLine($conn->fp, 1024);

     // process result
-    if (iil_ParseResult($line)==0){
+    switch(iil_ParseResult($line)){
+     case 0: // Ok
         $conn->error .= "";
         $conn->errorNum = 0;
         return $conn->fp;
-    }else{
+       break;
+     case -4: // Unknown Error
+        $conn->error .= 'Authentication for '.$user.' failed with Unknown Error(AUTH): "'.htmlspecialchars($line)."\"";
+        $conn->errorNum = -4;
+        return -1;
+     default: // Fatal Error
         $conn->error .= 'Authentication for '.$user.' failed (AUTH): "'.htmlspecialchars($line)."\"";
         $conn->errorNum = -2;
         return false;
@@ -407,6 +414,11 @@
                        $conn->message.='Got challenge: '.htmlspecialchars($line)."\n";
                        //got a challenge string, try CRAM-5
                        $result = iil_C_Authenticate($conn, $user, $password, substr($line,2));
+                       if($result == -1) {
+                               $iil_error = $conn->error;
+                               $iil_errornum = $conn->errorNum;
+                               return false;
+                       }
                        $conn->message.= "Tried CRAM-MD5: $result \n";
                }else{
                        $conn->message.='No challenge ('.htmlspecialchars($line)."), try plain\n";

What this does is after unsuccessful hash authentication - because of a fatal error from imap server which disconnects afterwards - roundcube should not try to login by another method.

[seansan]

Review in 0.1.1 - lof of responses

[r@…]

Running UW IMAP4rev1 2007.398, there is a direct correspondence between runaway httpd processes, error logs entries of "PHP Fatal error: Maximum execution time of 120 seconds exceeded", and imapd complaining about mailbox contention in the maillogs ("imapd[pid]: Killed (lost mailbox lock) user=someuser host=somehost").

E.g. in the iil_C_Select function in program/lib/imap.inc, "sel1 SELECT INBOX" might be sent to the IMAP server, then a do-while loop repeatedly reads responses from the IMAP server until it sees a response beginning with "sel1". A normal conversation might be as follows:

> sel1 SELECT INBOX

< * 108 EXISTS
< * 0 RECENT
< * OK [UIDVALIDITY 981496340] UID validity status
< * OK [UIDNEXT 170778] Predicted next UID
< * FLAGS ($MDNSent $Forwarded NonJunk Junk $Label1 $Label2 $Label3 $Label4 $Label5 $Label7 \Answered \Flagged \Deleted \Draft \Seen)
< * OK [PERMANENTFLAGS ($MDNSent $Forwarded NonJunk Junk $Label1 $Label2 $Label3 $Label4 $Label5 $Label7 \* \Answered \Flagged \Deleted \Draft \Seen)] Permanent flags
< * OK [UNSEEN 102] first unseen message in /var/mail/someuser
< sel1 OK [READ-WRITE] SELECT completed

After a mailbox contention occurs however, uw imapd just says "BYE", doesn't close the connection (as far as I can tell), and then sends blank responses:

> sel1 SELECT INBOX

< * BYE Killed (lost mailbox lock)
<
<
<
<
...

...and since the do-while loop never sees a line beginning with "sel1" as a response from the IMAP server, the loop never ends. There are a lot of functions in imap.inc where such a case causes an infinite loop.

[till]

Thanks to everyone who supplied a patch, I committed one of the suggestions (r1207).

We are looking into another imap layer for PHP5-only releases, which is why I am postponing this to "later". In case you find more bottlenecks keep, the patches coming.

[add]

installing metal stair rails Interior stair handrail exterior baluster Glass wood stainless wrought CONTEMPORARY designs stairways aluminum modern log banister DECK outdoor price posts vinyl curved rails

[add]

Spindle, Stairs & Railings is a stair builder featuring high quality staircases and curved stairwells for the construction and renovation industry. http://www.jp-wrought-iron.com.cn Stair Supplies is your source for stair parts, iron baluster, iron balusters, wood balusters, handrails, railings, stair treads, stair parts

[moesasji]

I finally stumpled upon this bug-report after first thinking the cause of the problem of long 100% apache load as a result of roundcube-usage was CW-imap. This problem is critical as it makes the webserver go down or become highly unresponsive (Q6600 + 8GB memory running CW-IMAP on slamd64) taking webmail effectively off-line.

I've been testing to see if the problem still exists in the Roundcube-0.2-alpha release and unfortunately it still is (see httpd error-log below, sigterm messages are from apache threads!!).

When I look at the line-numbers indicated by the time-out messages all seem to be related to the iil_ReadLine function in imap.c that communicates with the imap-server. If the switch to another imap-layer is not going to be included in the 0.2 version I would appreciate it if somebody could look into this problem as this bug makes that it is not possible to have roundcube on a live server!!

It seems to be caused by not catching possible errors when communicating with the IMAP-server as pointed out in some of the above posts.

[Sun Jun 22 09:13:00 2008] [error] [client 127.0.0.1] PHP Fatal error:  Maximum execution time of 120 seconds exceeded in /var/www/htdocs/roundcubemail-0.2-alpha/program/lib/imap.inc on line 1891, referer: http://localhost/roundcubemail-0.2-alpha/?_task=mail
[Sun Jun 22 09:17:33 2008] [error] [client 127.0.0.1] PHP Fatal error:  Maximum execution time of 120 seconds exceeded in /var/www/htdocs/roundcubemail-0.2-alpha/program/lib/imap.inc on line 190, referer: http://localhost/roundcubemail-0.2-alpha/?_task=settings&_action=identities
[Sun Jun 22 09:26:50 2008] [error] [client 127.0.0.1] PHP Fatal error:  Maximum execution time of 120 seconds exceeded in /var/www/htdocs/roundcubemail-0.2-alpha/program/lib/imap.inc on line 255, referer: http://localhost/roundcubemail-0.2-alpha/?_task=settings&_action=identities
[Sun Jun 22 09:26:51 2008] [error] [client 127.0.0.1] PHP Fatal error:  Maximum execution time of 120 seconds exceeded in /var/www/htdocs/roundcubemail-0.2-alpha/program/lib/imap.inc on line 727, referer: http://localhost/roundcubemail-0.2-alpha/?_task=settings&_action=
[Sun Jun 22 09:26:52 2008] [error] [client 127.0.0.1] PHP Fatal error:  Maximum execution time of 120 seconds exceeded in /var/www/htdocs/roundcubemail-0.2-alpha/program/lib/imap.inc on line 736, referer: http://localhost/roundcubemail-0.2-alpha/?_task=settings
[Sun Jun 22 09:46:08 2008] [warn] child process 14711 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 14713 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 14714 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 14715 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 14716 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 14840 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 14968 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 15053 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 15056 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:08 2008] [warn] child process 15061 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 14711 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 14713 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 14714 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 14715 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 14716 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 14840 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 14968 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 15053 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 15056 still did not exit, sending a SIGTERM
[Sun Jun 22 09:46:09 2008] [warn] child process 15061 still did not exit, sending a SIGTERM

ps) For completeness. The reason that I originally suspected CW-IMAP is that deleting an email with roundcube triggers the error-message below when deleting an email. However squirrelmail on the same server generates no errors from CW-IMAP at all and deletes messages without triggering this invalid pointer message.

Jun 22 09:11:00 PulsarX4 *** glibc detected *** imapd: free(): invalid pointer: 0x00000000006dd0d0 ***
Jun 22 09:11:00 PulsarX4 ======= Backtrace: =========
Jun 22 09:11:00 PulsarX4 /lib64/libc.so.6[0x2b0b81f94f3a]
Jun 22 09:11:00 PulsarX4 /lib64/libc.so.6(cfree+0x8c)[0x2b0b81f98acc]
Jun 22 09:11:00 PulsarX4 imapd[0x414c3d]
Jun 22 09:11:00 PulsarX4 imapd[0x41e88d]
Jun 22 09:11:00 PulsarX4 imapd[0x406985]
Jun 22 09:11:00 PulsarX4 imapd[0x45624d]
Jun 22 09:11:00 PulsarX4 imapd[0x40f92f]
Jun 22 09:11:00 PulsarX4 /lib64/libc.so.6(__libc_start_main+0xf4)[0x2b0b81f3f164]
Jun 22 09:11:00 PulsarX4 imapd[0x406549]
Jun 22 09:11:00 PulsarX4 ======= Memory map: ========
Jun 22 09:11:00 PulsarX4 00400000-004c2000 r-xp 00000000 08:01 35984560                           /usr/sbin/imapd 006c2000-006c7000 rw-p 000c2000 08:01 35984560                           /usr/sbin/imapd 006c7000-0077a000 rw-p 006c7000 00:00 0                                  [heap] 2b0b8150e000-2b0b8152b000 r-xp 00000000 08:01 33607228                   /lib64/ld-2.7.so 2b0b8152b000-2b0b8152f000 rw-p 2b0b8152b000 00:00 0  2b0b8172a000-2b0b8172c000 rw-p 0001c000 08:01 33607228                   /lib64/ld-2.7.so 2b0b8172c000-2b0b81735000 r-xp 00000000 08:01 33607124                   /lib64/libcrypt-2.7.so 2b0b81735000-2b0b81934000 ---p 00009000 08:01 33607124                   /lib64/libcrypt-2.7.so 2b0b81934000-2b0b81936000 rw-p 00008000 08:01 33607124                   /lib64/libcrypt-2.7.so 2b0b81936000-2b0b81964000 rw-p 2b0b81936000 00:00 0  2b0b81964000-2b0b819a6000 r-xp 00000000 08:01 88655                      /usr/lib64/libssl.so.0.9.8 2b0b819a6000-2b0b81ba6000 ---p 00042000 08:01 88655                      /usr/lib64/libss
Jun 22 09:11:00 PulsarX4 o.0.9.8 2b0b81ba6000-2b0b81bac000 rw-p 00042000 08:01 88655                      /usr/lib64/libssl.so.0.9.8 2b0b81bac000-2b0b81cfa000 r-xp 00000000 08:01 88654                      /usr/lib64/libcrypto.so.0.9.8 2b0b81cfa000-2b0b81efa000 ---p 0014e000 08:01 88654                      /usr/lib64/libcrypto.so.0.9.8 2b0b81efa000-2b0b81f1d000 rw-p 0014e000 08:01 88654                      /usr/lib64/libcrypto.so.0.9.8 2b0b81f1d000-2b0b81f21000 rw-p 2b0b81f1d000 00:00 0  2b0b81f21000-2b0b82074000 r-xp 00000000 08:01 33607122                   /lib64/libc-2.7.so 2b0b82074000-2b0b82274000 ---p 00153000 08:01 33607122                   /lib64/libc-2.7.so 2b0b82274000-2b0b82277000 r--p 00153000 08:01 33607122                   /lib64/libc-2.7.so 2b0b82277000-2b0b82279000 rw-p 00156000 08:01 33607122                   /lib64/libc-2.7.so 2b0b82279000-2b0b8227e000 rw-p 2b0b82279000 00:00 0  2b0b8227e000-2b0b82280000 r-xp 00000000 08:01 33607125                   /lib64/libdl-2.7.so 2b0b82280000-2b0b82480000 ---p 000020
Jun 22 09:11:00 PulsarX4 08:01 33607125                   /lib64/libdl-2.7.so 2b0b82480000-2b0b82482000 rw-p 00002000 08:01 33607125                   /lib64/libdl-2.7.so 2b0b82482000-2b0b82484000 rw-p 2b0b82482000 00:00 0  2b0b82484000-2b0b8248e000 r-xp 00000000 08:01 33607131                   /lib64/libnss_files-2.7.so 2b0b8248e000-2b0b8268d000 ---p 0000a000 08:01 33607131                   /lib64/libnss_files-2.7.so 2b0b8268d000-2b0b8268f000 rw-p 00009000 08:01 33607131                   /lib64/libnss_files-2.7.so 2b0b8268f000-2b0b82696000 r-xp 00000000 08:01 33607129                   /lib64/libnss_compat-2.7.so 2b0b82696000-2b0b82896000 ---p 00007000 08:01 33607129                   /lib64/libnss_compat-2.7.so 2b0b82896000-2b0b82898000 rw-p 00007000 08:01 33607129                   /lib64/libnss_compat-2.7.so 2b0b82898000-2b0b828ad000 r-xp 00000000 08:01 33607128                   /lib64/libnsl-2.7.so 2b0b828ad000-2b0b82aac000 ---p 00015000 08:01 33607128                   /lib64/libnsl-2.7.so 2b0b82aac000-2b0b82aae000 rw-p
Jun 22 09:11:00 PulsarX4 14000 08:01 33607128                   /lib64/libnsl-2.7.so 2b0b82aae000-2b0b82ab0000 rw-p 2b0b82aae000 00:00 0  2b0b82ab0000-2b0b82aba000 r-xp 00000000 08:01 33607133                   /lib64/libnss_nis-2.7.so 2b0b82aba000-2b0b82cb9000 ---p 0000a000 08:01 33607133                   /lib64/libnss_nis-2.7.so 2b0b82cb9000-2b0b82cbb000 rw-p 00009000 08:01 33607133                   /lib64/libnss_nis-2.7.so 2b0b82cdd000-2b0b82cea000 r-xp 00000000 08:01 185                        /usr/lib64/libgcc_s.so.1 2b0b82cea000-2b0b82ee9000 ---p 0000d000 08:01 185                        /usr/lib64/libgcc_s.so.1 2b0b82ee9000-2b0b82eea000 rw-p 0000c000 08:01 185                        /usr/lib64/libgcc_s.so.1 2b0b84000000-2b0b84021000 rw-p 2b0b84000000 00:00 0  2b0b84021000-2b0b88000000 ---p 2b0b84021000 00:00 0  7fff29587000-7fff2959c000 rwxp 7ffffffea000 00:00 0                      [stack] 7fff295fe000-7fff29600000 r-xp 7fff295fe000 00:00 0                      [vdso] ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00
Jun 22 09:11:00 PulsarX4                  [vsyscall]
Jun 22 09:37:22 PulsarX4 -- MARK --

[add]

http://www.cheapwroughtiron.cn