Hi
I have this weird problem with Exim.
Occasionally, for periods of a few minutes every time, exim becomes extremely slow, and takes more than 50 seconds to respond to SMTP commands, thus causing the sending script to timeout and fail the sending.
I've only had the problem with RCPT TO and the CR.CR command that ends the DATA.
I could not find a way to reproduce the problem mechanically or find any logic to when it is happening, but I was able to mark out the following:
1. It's not related to the content or the meta data of the email. I've had the exact same email go through fine at first and then fail with a timeout 4 minutes later.
2. Since not only the RCPT TO command is affected, I believe it has nothing to do with network or DNS issues.
3. While exim is stuck, apache and mysql keep serving pages just fine, so I can't see how it can be a memory or CPU issue.
Below is an example from the log file, have a look on 2010-02-26 17:58:55, when a mail is being sent just fine and it takes 2 seconds, then on 18:02:50 the same email is being sent again, but this time it takes exim 7 seconds only to accept the connection, then the connection is lost at 18:04:39.
In parallel, on 18:03:52 there's another attempt of sending the same email, this time it takes 30(!) seconds only to accept the connection, then the connection is lost at 18:04:24.
Any ideas what might be the cause?
Thanks,
Gilad
The log:
I have this weird problem with Exim.
Occasionally, for periods of a few minutes every time, exim becomes extremely slow, and takes more than 50 seconds to respond to SMTP commands, thus causing the sending script to timeout and fail the sending.
I've only had the problem with RCPT TO and the CR.CR command that ends the DATA.
I could not find a way to reproduce the problem mechanically or find any logic to when it is happening, but I was able to mark out the following:
1. It's not related to the content or the meta data of the email. I've had the exact same email go through fine at first and then fail with a timeout 4 minutes later.
2. Since not only the RCPT TO command is affected, I believe it has nothing to do with network or DNS issues.
3. While exim is stuck, apache and mysql keep serving pages just fine, so I can't see how it can be a memory or CPU issue.
Below is an example from the log file, have a look on 2010-02-26 17:58:55, when a mail is being sent just fine and it takes 2 seconds, then on 18:02:50 the same email is being sent again, but this time it takes exim 7 seconds only to accept the connection, then the connection is lost at 18:04:39.
In parallel, on 18:03:52 there's another attempt of sending the same email, this time it takes 30(!) seconds only to accept the connection, then the connection is lost at 18:04:24.
Any ideas what might be the cause?
Thanks,
Gilad
The log:
Code:
2010-02-26 17:52:13 cwd=/etc/csf 2 args: /usr/sbin/exim -bpc
2010-02-26 17:55:44 SMTP connection from [127.0.0.1]:45671 I=[127.0.0.1]:26 (TCP/IP connection count = 1)
2010-02-26 17:55:46 SMTP connection from localhost [127.0.0.1]:45671 I=[127.0.0.1]:26 closed by QUIT
2010-02-26 17:55:46 no MAIL in SMTP connection from localhost [127.0.0.1]:45671 I=[127.0.0.1]:26 D=2s C=QUIT
2010-02-26 17:55:47 SMTP connection from [127.0.0.1]:58911 I=[127.0.0.1]:25 (TCP/IP connection count = 1)
2010-02-26 17:55:59 SMTP connection from localhost [127.0.0.1]:58911 I=[127.0.0.1]:25 closed by QUIT
2010-02-26 17:55:59 no MAIL in SMTP connection from localhost [127.0.0.1]:58911 I=[127.0.0.1]:25 D=12s A=dovecot_plain:__cpanel__service__auth__exim__twcvcpvd3r4bsbu_1cgmevvjcdsptgpgvaejblridqwquzc5a5ohzxaiy1tsryyq C=EHLO,AUTH,QUIT
2010-02-26 17:57:14 cwd=/etc/csf 2 args: /usr/sbin/exim -bpc
2010-02-26 17:58:55 SMTP connection from [127.0.0.1]:59268 I=[127.0.0.1]:25 (TCP/IP connection count = 1)
2010-02-26 17:58:56 H=localhost (www.nearbynerd.com.au) [127.0.0.1]:59268 I=[127.0.0.1]:25 Warning: Sender rate 1.2 / 1h
2010-02-26 17:58:57 1NkuA4-0008JF-DR <= [email protected] H=localhost (www.nearbynerd.com.au) [127.0.0.1]:59268 I=[127.0.0.1]:25 P=esmtpa A=dovecot_login:[email protected] S=47274 [email protected] T="Replacement login information for RichardE at NearbyNerd" from <[email protected]> for [email protected]
2010-02-26 17:58:57 SMTP connection from localhost (www.nearbynerd.com.au) [127.0.0.1]:59268 I=[127.0.0.1]:25 closed by QUIT
2010-02-26 17:58:57 cwd=/var/spool/exim 3 args: /usr/sbin/exim -Mc 1NkuA4-0008JF-DR
2010-02-26 17:59:00 1NkuA4-0008JF-DR DK: message signed using a=rsa-sha1; q=dns; c=nofws; s=default; d=nearbynerd.com.au; h=Received:Date:To:From:Reply-to:Subject:Message-ID:X-Priority:X-Mailer:Content-Type:Sender:Errors-To:MIME-Version;
2010-02-26 17:59:01 1NkuA4-0008JF-DR => [email protected] F=<[email protected]> P=<[email protected]> R=dk_lookuphost T=dk_remote_smtp S=48241 H=mx3.hotmail.com [65.54.188.94]:25 C="250 <[email protected]> Queued mail for delivery" QT=5s DT=2s
2010-02-26 17:59:01 1NkuA4-0008JF-DR Completed QT=5s
2010-02-26 18:00:22 SMTP connection from [127.0.0.1]:41047 I=[127.0.0.1]:25 (TCP/IP connection count = 1)
2010-02-26 18:00:23 H=localhost (www.nearbynerd.com.au) [127.0.0.1]:41047 I=[127.0.0.1]:25 Warning: Sender rate 2.1 / 1h
2010-02-26 18:00:33 1NkuBT-0007N6-NZ <= [email protected] H=localhost (www.nearbynerd.com.au) [127.0.0.1]:41047 I=[127.0.0.1]:25 P=esmtpa A=dovecot_login:[email protected] S=47274 [email protected] T="Replacement login information for RichardE at NearbyNerd" from <[email protected]> for [email protected]
2010-02-26 18:00:33 cwd=/var/spool/exim 3 args: /usr/sbin/exim -Mc 1NkuBT-0007N6-NZ
2010-02-26 18:00:33 SMTP connection from localhost (www.nearbynerd.com.au) [127.0.0.1]:41047 I=[127.0.0.1]:25 closed by QUIT
2010-02-26 18:00:36 1NkuBT-0007N6-NZ DK: message signed using a=rsa-sha1; q=dns; c=nofws; s=default; d=nearbynerd.com.au; h=Received:Date:To:From:Reply-to:Subject:Message-ID:X-Priority:X-Mailer:Content-Type:Sender:Errors-To:MIME-Version;
2010-02-26 18:00:38 1NkuBT-0007N6-NZ => [email protected] F=<[email protected]> P=<[email protected]> R=dk_lookuphost T=dk_remote_smtp S=48241 H=mx3.hotmail.com [65.55.37.104]:25 C="250 <[email protected]> Queued mail for delivery" QT=15s DT=3s
2010-02-26 18:00:38 1NkuBT-0007N6-NZ Completed QT=15s
2010-02-26 18:00:39 SMTP connection from [127.0.0.1]:53250 I=[127.0.0.1]:26 (TCP/IP connection count = 1)
2010-02-26 18:00:41 SMTP connection from localhost [127.0.0.1]:53250 I=[127.0.0.1]:26 closed by QUIT
2010-02-26 18:00:41 no MAIL in SMTP connection from localhost [127.0.0.1]:53250 I=[127.0.0.1]:26 D=2s C=QUIT
2010-02-26 18:00:41 SMTP connection from [127.0.0.1]:41177 I=[127.0.0.1]:25 (TCP/IP connection count = 1)
2010-02-26 18:00:53 SMTP connection from localhost [127.0.0.1]:41177 I=[127.0.0.1]:25 closed by QUIT
2010-02-26 18:00:53 no MAIL in SMTP connection from localhost [127.0.0.1]:41177 I=[127.0.0.1]:25 D=12s A=dovecot_plain:__cpanel__service__auth__exim__36h5e21fgdyqkodtozekhsbbblxk8envozk99w0hwh38s6mpjfwmzqj4bws2hhbl C=EHLO,AUTH,QUIT
2010-02-26 18:01:36 cwd=/var/spool/exim 2 args: /usr/sbin/exim -q
2010-02-26 18:01:41 Start queue run: pid=17980
2010-02-26 18:01:41 End queue run: pid=17980
2010-02-26 18:02:14 cwd=/etc/csf 2 args: /usr/sbin/exim -bpc
2010-02-26 18:02:50 SMTP connection from [127.0.0.1]:41540 I=[127.0.0.1]:25 (TCP/IP connection count = 1)
2010-02-26 18:02:57 H=localhost (www.nearbynerd.com.au) [127.0.0.1]:41540 I=[127.0.0.1]:25 Warning: Sender rate 3.0 / 1h
2010-02-26 18:03:52 SMTP connection from [127.0.0.1]:41779 I=[127.0.0.1]:25 (TCP/IP connection count = 2)
2010-02-26 18:04:22 H=localhost (www.nearbynerd.com.au) [127.0.0.1]:41779 I=[127.0.0.1]:25 Warning: Sender rate 4.0 / 1h
2010-02-26 18:04:24 SMTP connection from localhost (www.nearbynerd.com.au) [127.0.0.1]:41779 I=[127.0.0.1]:25 lost while reading message data (after header)
2010-02-26 18:04:39 1NkuDy-0002Pu-L4 <= [email protected] H=localhost (www.nearbynerd.com.au) [127.0.0.1]:41540 I=[127.0.0.1]:25 P=esmtpa A=dovecot_login:[email protected] S=47274 [email protected] T="Replacement login information for RichardE at NearbyNerd" from <[email protected]> for [email protected]
2010-02-26 18:04:39 SMTP connection from localhost (www.nearbynerd.com.au) [127.0.0.1]:41540 I=[127.0.0.1]:25 lost
2010-02-26 18:04:39 cwd=/var/spool/exim 3 args: /usr/sbin/exim -Mc 1NkuDy-0002Pu-L4
2010-02-26 18:04:41 1NkuDy-0002Pu-L4 DK: message signed using a=rsa-sha1; q=dns; c=nofws; s=default; d=nearbynerd.com.au; h=Received:Date:To:From:Reply-to:Subject:Message-ID:X-Priority:X-Mailer:Content-Type:Sender:Errors-To:MIME-Version;
2010-02-26 18:04:48 1NkuDy-0002Pu-L4 => [email protected] F=<[email protected]> P=<[email protected]> R=dk_lookuphost T=dk_remote_smtp S=48241 H=mx2.hotmail.com [65.55.92.136]:25 C="250 <[email protected]> Queued mail for delivery" QT=1m50s DT=5s
2010-02-26 18:04:48 1NkuDy-0002Pu-L4 Completed QT=1m50s