[milters] Archive

Lists Index Date Thread Search

Article: 1670
From: Gary Faith
Date: 2007-09-02 17:37:57 -0400
Subject: Milter-Ahead Problem - Maybe

Removal...........: milters-request@milter.info?subject=remove
More information..: http://www.milter.info/#Support
--------------------------------------------------------

I have been having a problem with two many sendmail child processes which was causing
sendmail to stop accepting more connections until one of the processes timed out.  I am
running SuSE Linux 10 SP1 X86_64, all the latest patches, MailScanner 4.63.7-1,
milter-greylist and milter-ahead 1.8.  I was originally running milter-ahead 1.6 and was
having the same problem.  My sendmail installation is sendmail-devel-8.13.6-9.11 &
sendmail-8.13.6-9.11 (rpm's from SuSE). 
 
Sep  1 16:55:37 mscan sendmail-in[16650]: rejecting connections on daemon MTA: 15
children, max 15
Sep  1 16:55:52 mscan sendmail-in[16650]: rejecting connections on daemon MTA: 15
children, max 15
Sep  1 16:56:09 mscan sendmail-in[16650]: accepting connections again for daemon MTA
Sep  1 16:56:10 mscan sendmail-in[16650]: rejecting connections on daemon MTA: 15
children, max 15
Sep  1 16:56:10 mscan sendmail-in[25824]: NOQUEUE: connect from [125.137.20.20]
Sep  1 16:56:10 mscan sendmail-in[25824]: AUTH: available mech=ANONYMOUS LOGIN, allowed
mech=EXTERNAL GSSAPI KERBEROS_V4 DIGEST-MD5 CRAM
 
Problem is that sendmail connections are getting stuck in the "cmd read" state.
 
root      9176  0.0  0.1  25356  3240 ?        S    14:52   0:00  \_ sendmail: server
[200.21.38.223] cmd read            
root      9776  0.0  0.1  25356  3412 ?        S    14:57   0:00  \_ sendmail: server
[221.138.199.228] cmd read          
root      9962  0.0  0.1  25356  3420 ?        S    14:59   0:00  \_ sendmail: server
[61.47.240.132] cmd read            
root     10254  0.0  0.1  25356  3424 ?        S    15:01   0:00  \_ sendmail: server
[61.47.240.132] cmd read            
root     10359  0.0  0.1  25356  3424 ?        S    15:02   0:00  \_ sendmail: server
[221.138.199.228] cmd read          
root     10600  0.0  0.1  25356  3512 ?        S    15:05   0:00  \_ sendmail: server
06.mailmx01.com [207.154.32.6] cmd read
root     10632  0.0  0.1  25356  3420 ?        S    15:05   0:00  \_ sendmail: server
[222.240.196.166] cmd read     
    
After a lot of testing yesterday, I found that when I use only milter-greylist or
milter-ahead, the amount of sendmail processes in the "cmd read" state is
significantly lower.  It seems to be that when they are both running that the problem
occurs.  I have also found that if I shutdown MailScanner that the "stuck"
sendmail processes don't close.  I have to use the kill command or the pkill command to
get the processes to close (pkill sendmail).  Interesting thing is what happens when I
issue the pkill sendmail command:
 
mscan:/etc # pkill sendmail
mscan:/etc #
 
Sep  1 19:19:42 mscan milter-ahead[28265]: 00463 NOQUEUE: filterClose(593d90)
Sep  1 19:19:43 mscan milter-ahead[28265]: 00813 NOQUEUE: filterClose(5db3f0)
Sep  1 19:19:43 mscan milter-ahead[28265]: 00809 NOQUEUE: filterClose(594890)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01101 NOQUEUE: filterClose(5db350)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01097 NOQUEUE: filterClose(594a50)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01088 NOQUEUE: filterClose(5e0490)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01023 NOQUEUE: filterClose(5da4d0)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01048 NOQUEUE: filterClose(5dcae0)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01037 NOQUEUE: filterClose(5def20)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01045 NOQUEUE: filterClose(5db160)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01049 NOQUEUE: filterClose(5d9370)
Sep  1 19:19:43 mscan milter-ahead[28265]: 01090 NOQUEUE: filterClose(5e1cd0)
 
Here is part of the log showing both milters in action. I obfuscated the domain name for
privacy sake. 
 
Sep  1 16:54:37 mscan sendmail-in[25776]: AUTH: available mech=ANONYMOUS LOGIN, allowed
mech=EXTERNAL GSSAPI KERBEROS_V4 DIGEST-MD5 CRAM-MD5
Sep  1 16:54:37 mscan sendmail-in[25776]: l81KsbnJ025776: Milter (greylist): init success
to negotiate
Sep  1 16:54:37 mscan sendmail-in[25776]: l81KsbnJ025776: Milter (milter-ahead): init
success to negotiate
Sep  1 16:54:37 mscan sendmail-in[25776]: l81KsbnJ025776: Milter: connect to filters
Sep  1 16:54:37 mscan sendmail-in[25776]: l81KsbnJ025776: milter=greylist, action=connect,
continue
Sep  1 16:54:37 mscan milter-ahead[25754]: 00002 NOQUEUE: filterOpen(593f50,
'ip86.197.reserved.ish.de', [62.143.197.86])
Sep  1 16:54:37 mscan sendmail-in[25776]: l81KsbnJ025776: milter=milter-ahead,
action=connect, continue
Sep  1 16:54:37 mscan sendmail-in[25776]: l81KsbnJ025776: milter=greylist, action=helo,
continue
Sep  1 16:54:38 mscan sendmail-in[25776]: l81KsbnJ025776: milter=greylist, action=mail,
continue
Sep  1 16:54:38 mscan milter-ahead[25754]: 00002 l81KsbnJ025776: filterMail(593f50,
594910) MAIL='<pres@providentshipyards.com>' (
mailto:pres@providentshipyards.com> )
Sep  1 16:54:38 mscan sendmail-in[25776]: l81KsbnJ025776: milter=milter-ahead,
action=mail, continue
Sep  1 16:54:38 mscan milter-greylist: (local): addr 68.142.229.101 from
<murphyjk@pacbell.net> rcpt <bulszqwi@abc.com>: autowhitelisted entry expired
Sep  1 16:54:38 mscan milter-greylist: l81KsbnJ025776: addr
ip86.197.reserved.ish.de[62.143.197.86] from <pres@providentshipyards.com> to
<graham@abc.com> delayed for 00:14:00 (ACL 240)
Sep  1 16:54:38 mscan sendmail-in[25776]: l81KsbnJ025776: milter=greylist, action=rcpt,
reject=451 4.7.1 Greylisting in action, please come back in 00:14:00
Sep  1 16:54:38 mscan sendmail-in[25776]: l81KsbnJ025776: Milter: to=<xyz@abc.com>,
reject=451 4.7.1 Greylisting in action, please come back in 00:14:00
 
Here is one that works properly:
 
Sep  1 16:56:10 mscan sendmail-in[25824]: AUTH: available mech=ANONYMOUS LOGIN, allowed
mech=EXTERNAL GSSAPI KERBEROS_V4 DIGEST-MD5 CRAM-MD5
Sep  1 16:56:10 mscan sendmail-in[25824]: l81KuAWP025824: Milter (greylist): init success
to negotiate
Sep  1 16:56:10 mscan sendmail-in[25824]: l81KuAWP025824: Milter (milter-ahead): init
success to negotiate
Sep  1 16:56:10 mscan sendmail-in[25824]: l81KuAWP025824: Milter: connect to filters
Sep  1 16:56:10 mscan sendmail-in[25824]: l81KuAWP025824: milter=greylist, action=connect,
continue
Sep  1 16:56:10 mscan milter-ahead[25754]: 00003 NOQUEUE: filterOpen(5949d0,
'[125.137.20.20]', [125.137.20.20])
Sep  1 16:56:10 mscan sendmail-in[25824]: l81KuAWP025824: milter=milter-ahead,
action=connect, continue
Sep  1 16:56:11 mscan sendmail-in[25824]: l81KuAWP025824: milter=greylist, action=helo,
continue
Sep  1 16:56:13 mscan sendmail-in[25824]: l81KuAWP025824: milter=greylist, action=mail,
continue
Sep  1 16:56:13 mscan milter-ahead[25754]: 00003 l81KuAWP025824: filterMail(5949d0,
594910) MAIL='<mikef@thingaboutwords.com>' ( mailto:mikef@thingaboutwords.com> )
Sep  1 16:56:13 mscan sendmail-in[25824]: l81KuAWP025824: milter=milter-ahead,
action=mail, continue
Sep  1 16:56:15 mscan milter-greylist: l81KuAWP025824: addr [125.137.20.20][125.137.20.20]
from <mikef@thingaboutwords.com> to <christines@abc.com> delayed for 00:14:00
(ACL 240)
Sep  1 16:56:15 mscan sendmail-in[25824]: l81KuAWP025824: milter=greylist, action=rcpt,
reject=451 4.7.1 Greylisting in action, please come back in 00:14:00
Sep  1 16:56:15 mscan sendmail-in[25824]: l81KuAWP025824: Milter:
to=<christines@abc.com>, reject=451 4.7.1 Greylisting in action, please come back in
00:14:00
Sep  1 16:56:16 mscan sendmail-in[25824]: l81KuAWP025824: lost input channel from
[125.137.20.20] to MTA after data
Sep  1 16:56:16 mscan milter-ahead[25754]: 00003 NOQUEUE: filterClose(5949d0)
 
After typing this whole message up, I noticed one thing that in the log of the connection
that works properly that the connection from the remote system seems to close after
getting the 451 error (see below) and then milter-ahead closes its
connection/process/whatever you call it.  On the one where the connection doesn't
disappear, milter-ahead never closes.  
 
Sep  1 16:56:16 mscan sendmail-in[25824]: l81KuAWP025824: lost input channel from
[125.137.20.20] to MTA after data
Sep  1 16:56:16 mscan milter-ahead[25754]: 00003 NOQUEUE: filterClose(5949d0)
 
So is this a problem with the improper remote not closing the connection on a 451 error or
milter-ahead not responding properly or something I am missing all together????
 
Sorry for the really long post but I figure I would try to include as much as I could.
 
Thanks in Advance,
 
Gary Faith


Lists Index Date Thread Search