[Mimedefang] MIMEDefang multiplexor refusing connections after overload
Björn Wiberg
Bjorn.Wiberg at data.slu.se
Wed Apr 9 08:58:01 EDT 2003
Hi all!
In an attempt to stress-test MIMEDefang 2.31/F-Secure Anti-Virus for Linux
4.50/sendmail 8.12.9 on a Linux box, I mass-generated e-mails with small
attachments in them (10-20 kB each, one per e-mail) and directed them to the
mail server in question.
The maximum number of slaves has been set to 10. As soon as this number of
slaves are running and new requests arrive, sendmail will give the sender a
"please try again later" error.
However, after this mail/attachment "storm" (during which the number of slaves
has been exceeded), the MIMEDefang multiplexor refuses to accept any new
connections, resulting in a permanent "please try again later" state of
sendmail -- no mail gets through.
I have tried to include the relevant parts of the sendmail log file below
(although it's quite lengthy anyway, sorry about that).
Apr 9 12:58:38 reserv mimedefang-multiplexor: started; minSlaves=2, maxSlaves
=10, maxRequests=500, maxIdleTime=300, busyTimeout=300, clientTimeout=10
Apr 9 12:58:38 reserv mimedefang-multiplexor: Starting slave 0 (pid 13524) (1
running): Bringing slaves up to minSlaves (2)
Apr 9 12:58:38 reserv mimedefang[13526]: Multiplexor alive - entering main lo
op
Apr 9 12:58:40 reserv sendmail[13531]: starting daemon (8.12.9): SMTP+queuein
g at 00:01:00
Apr 9 12:58:40 reserv sendmail[13534]: starting daemon (8.12.9): queueing at 00:
01:00
Apr 9 12:58:40 reserv sendmail[13535]: alias database /etc/mail/aliases rebui
lt by root
Apr 9 12:58:40 reserv sendmail[13535]: /etc/mail/aliases: 4 aliases, longest
30 bytes, 142 bytes total
Apr 9 12:58:41 reserv mimedefang-multiplexor: Starting slave 1 (pid 13537) (2
running): Bringing slaves up to minSlaves (2)
Apr 9 12:59:59 reserv sendmail[13541]: h39Axwxf013541: from=<Bjorn.Wiberg at dat
a.slu.se>, size=43686, class=0, nrcpts=1, msgid=<12656.1049877201 at bw.data.slu.
se>, bodytype=8BITMIME, proto=ESMTP, daemon=MTA, relay=bw.data.slu.se [130.238
.96.43]
(more mails...)
Apr 9 13:00:00 reserv mimedefang-multiplexor: Starting slave 2 (pid 13560) (3
running): About to perform scan
(more mails...)
Apr 9 13:00:06 reserv mimedefang-multiplexor: Starting slave 9 (pid 13583) (1
0 running): About to perform scan
Apr 9 13:00:06 reserv mimedefang[13584]: mfconnect: No free slaves
Apr 9 13:00:06 reserv sendmail[13564]: h39B06xf013564: Milter: connect: host=
bw.data.slu.se, addr=130.238.96.43, temp failing commands
Apr 9 13:00:07 reserv mimedefang[13586]: mfconnect: No free slaves
Apr 9 13:00:07 reserv sendmail[13567]: h39B07xf013567: Milter: connect: host=
bw.data.slu.se, addr=130.238.96.43, temp failing commands
(more errors of this kind...)
Apr 9 13:00:12 reserv sendmail[13585]: h39B0Cxf013585: Milter (mimedefang): e
rror connecting to filter: Connection refused by /var/spool/MIMEDefang/mimedef
ang.sock
Apr 9 13:00:12 reserv sendmail[13541]: h39Axwxf013541: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13542]: h39B00xf013542: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13544]: h39B00xf013544: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13545]: h39B01xf013545: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13546]: h39B02xf013546: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13548]: h39B02xf013548: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13549]: h39B03xf013549: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13551]: h39B04xf013551: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13553]: h39B05xf013553: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13561]: h39B05xf013561: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:12 reserv sendmail[13576]: h39B09xf013576: milter_read(mimedefang
): cmd read returned 0, expecting 5
Apr 9 13:00:17 reserv sendmail[13580]: h39B0Bxf013580: Milter (mimedefang): e
rror connecting to filter: Connection refused by /var/spool/MIMEDefang/mimedef
ang.sock
Apr 9 13:00:17 reserv sendmail[13587]: h39B0Hxf013587: Milter (mimedefang): e
rror connecting to filter: Connection refused by /var/spool/MIMEDefang/mimedef
ang.sock
(more of this...)
Apr 9 13:00:40 reserv sendmail[13561]: h39B05xf013561: Milter (mimedefang): t
o error state
Apr 9 13:00:41 reserv sendmail[13576]: h39B09xf013576: Milter (mimedefang): t
o error state
Apr 9 13:00:17 reserv mimedefang-multiplexor: Slave 0 died prematurely -- che
ck your filter rules
And, SMTP error messages of this kind:
Apr 9 13:00:45 reserv sendmail[13541]: h39Axwxf013541: Milter: data, reject=4
51 4.7.1 Please try again later
After interrupting the mass-mailing, idle slaves get killed:
Apr 9 13:00:48 reserv mimedefang-multiplexor: Slave 3 died prematurely -- che
ck your filter rules
Apr 9 13:00:48 reserv mimedefang-multiplexor: Slave 2 died prematurely -- che
ck your filter rules
Apr 9 13:00:48 reserv mimedefang-multiplexor: Reap: Idle slave 7 (pid 13575)
exited due to signal 9 (SLAVE DIED UNEXPECTEDLY)
Apr 9 13:00:48 reserv mimedefang-multiplexor: Slave 7 resource usage: req=1,
scans=1, user=2.470, sys=1.520, nswap=0, majflt=495, minflt=5053, maxrss=0, bi
=0, bo=0
Apr 9 13:00:48 reserv mimedefang-multiplexor: Reap: Idle slave 4 (pid 13566)
exited due to signal 9 (SLAVE DIED UNEXPECTEDLY)
Apr 9 13:00:48 reserv mimedefang-multiplexor: Slave 4 resource usage: req=1,
scans=1, user=2.280, sys=1.260, nswap=0, majflt=493, minflt=4622, maxrss=0, bi
=0, bo=0
Apr 9 13:00:48 reserv mimedefang-multiplexor: Reap: Idle slave 3 (pid 13563)
exited due to signal 9 (SLAVE DIED UNEXPECTEDLY)
Apr 9 13:00:49 reserv mimedefang-multiplexor: Slave 3 resource usage: req=1,
scans=1, user=1.920, sys=1.190, nswap=0, majflt=492, minflt=3485, maxrss=0, bi
=0, bo=0
Apr 9 13:00:49 reserv mimedefang-multiplexor: Reap: Idle slave 2 (pid 13560)
exited due to signal 9 (SLAVE DIED UNEXPECTEDLY)
Apr 9 13:00:49 reserv mimedefang-multiplexor: Slave 2 resource usage: req=1,
scans=1, user=1.970, sys=0.820, nswap=0, majflt=493, minflt=3568, maxrss=0, bi
=0, bo=0
Apr 9 13:00:49 reserv mimedefang-multiplexor: Reap: Idle slave 1 (pid 13537)
exited due to signal 9 (SLAVE DIED UNEXPECTEDLY)
Apr 9 13:00:49 reserv mimedefang-multiplexor: Slave 1 resource usage: req=1,
scans=1, user=2.660, sys=0.060, nswap=0, majflt=620, minflt=6825, maxrss=0, bi
=0, bo=0
Apr 9 13:00:49 reserv mimedefang-multiplexor: Reap: Idle slave 0 (pid 13524)
exited due to signal 9 (SLAVE DIED UNEXPECTEDLY)
Apr 9 13:00:49 reserv mimedefang-multiplexor: Slave 0 resource usage: req=1,
scans=1, user=2.520, sys=0.050, nswap=0, majflt=488, minflt=5199, maxrss=0, bi
=0, bo=0
But, the MIMEDefang multiplexor refuses to accept any new connections:
Apr 9 13:23:38 reserv sendmail[13725]: h39BNcxf013725: Milter (mimedefang): e
rror connecting to filter: Connection refused by /var/spool/MIMEDefang/mimedef
ang.sock
Apr 9 13:23:38 reserv sendmail[13725]: h39BNcxf013725: Milter (mimedefang): t
o error state
Apr 9 13:23:38 reserv sendmail[13725]: h39BNcxf013725: Milter: initialization
failed, temp failing commands
The pstree command shows the following, which looks normal to me:
root at reserv:/var/spool/MIMEDefang# pstree
init-+-6*[agetty]
...
|-fsavd---2*[fsavd]
...
|-mimedefang-mult---2*[mimedefang.pl]
...
|-2*[sendmail]
...
However, the MIMEDefang spool directory contains left-overs from ten slaves:
root at reserv:/var/spool/MIMEDefang# ls -l
total 48
drwx------ 3 mfilter mfilter 4096 Apr 9 12:59 mdefang-3E93FD2E-0
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD30-0
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD30-1
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD31-0
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD32-0
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD32-1
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD33-0
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD34-0
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD35-0
drwx------ 3 mfilter mfilter 4096 Apr 9 13:00 mdefang-3E93FD36-0
-rw------- 1 mfilter mfilter 6 Apr 9 12:58
mimedefang-multiplexor.pid
srw------- 1 mfilter mfilter 0 Apr 9 12:58
mimedefang-multiplexor.sock
-rw------- 1 mfilter mfilter 6 Apr 9 12:58 mimedefang.pid
srwx------ 1 mfilter mfilter 0 Apr 9 12:58 mimedefang.sock
Restarting MIMEDefang solves the problem (although spool directory left-overs
still remain). Does anyone have any clues?
Best regards,
Björn
--
Björn Wiberg (Bjorn.Wiberg at data.slu.se)
More information about the MIMEDefang
mailing list