[Mimedefang] This is fun... (temp failing)

Thu Sep 26 11:49:01 EDT 2002

    I have an old P200 with 224MB of RAM in it (odd number, it's an old machine, okay?) running as our incoming mail gateway.  So, sendmail, SA, MD, File::Scan and ClamAv are all on it.  Last night I changed the MIN/MAX slaves from 3/5 to 5/10 respectively, setting the BUSY/IDLE timeouts to 60/300 respectively.

    This morning I woke up, only to notice exactly one email was delivered right after that change - and it was one I had pushed out of a quarantined folder, so it basically came from localhost.  After that Milter started failing.  This is the section of my maillog as soon as I restarted the whole shebang:

==========
    === First, restart everything:

Sep 26 00:51:46 serpico mimedefang-multiplexor: started; minSlaves=5, maxSlaves=10, maxRequests=100, maxIdleTime=300, busyTimeout=60, clientTimeout=10
Sep 26 00:51:46 serpico mimedefang-multiplexor: Starting slave 0 (pid 10915) (1 running): Bringing slaves up to minSlaves
Sep 26 00:51:47 serpico sm-msp-queue[10930]: starting daemon (8.12.6): queueing at 00:01:00
Sep 26 00:51:47 serpico sm-mta[10925]: starting daemon (8.12.6): SMTP+queueing at 00:01:00
Sep 26 00:51:49 serpico mimedefang-multiplexor: Starting slave 1 (pid 10935) (2 running): Bringing slaves up to minSlaves
Sep 26 00:51:52 serpico mimedefang-multiplexor: Starting slave 2 (pid 10936) (3 running): Bringing slaves up to minSlaves
Sep 26 00:51:55 serpico mimedefang-multiplexor: Starting slave 3 (pid 10937) (4 running): Bringing slaves up to minSlaves
Sep 26 00:51:58 serpico mimedefang-multiplexor: Starting slave 4 (pid 10938) (5 running): Bringing slaves up to minSlaves

    === Okay, everything started okay.  Now let's push the message out:

Sep 26 00:52:04 serpico sendmail[10944]: g8Q6q4l6010944: from=<bounce+OM_18122191683 at cmates.com>, size=12297, class=0, nrcpts=1, msgid=<1494175047.1033021523976.JavaMail.cm_apps at rainadm02.sea2.cmates.com>, relay=root at localhost
Sep 26 00:52:04 serpico sm-mta[10945]: g8Q6q49t010945: from=<bounce+OM_18122191683 at cmates.com>, size=12448, class=0, nrcpts=1, msgid=<1494175047.1033021523976.JavaMail.cm_apps at rainadm02.sea2.cmates.com>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1]
Sep 26 00:53:03 serpico sm-mta[10945]: g8Q6q49t010945: Milter change: header  Content-Type: from multipart/alternative; boundary=635456838.1033021523976.JavaMail.cm_apps.rainadm02.sea2.cmates.com to multipart/alternative; boundary="635456838.1033021523976.JavaMail.cm_apps.rainadm02.sea2.cmates.com"
Sep 26 00:53:03 serpico sm-mta[10945]: g8Q6q49t010945: Milter change: header  MIME-Version: from 1.0 to 1.0
Sep 26 00:53:03 serpico sm-mta[10945]: g8Q6q49t010945: Milter message: body replaced
Sep 26 00:53:03 serpico sm-mta[10945]: g8Q6q49t010945: Milter add: header: X-Scanned-By: MIMEDefang 2.21 (www . roaringpenguin . com / mimedefang)
Sep 26 00:53:03 serpico sendmail[10944]: g8Q6q4l6010944: to=<XXXXXXXX at pcraft.com>, ctladdr=<bounce+OM_18122191683 at cmates.com> (0/0), delay=00:00:59, xdelay=00:00:59, mailer=relay, pri=30627, relay=localhost.pcraft.com. [127.0.0.1], dsn=2.0.0, stat=Sent (g8Q6q49t010945 Message accepted for delivery)
Sep 26 00:53:08 serpico sm-mta[10950]: g8Q6q49t010945: to=<XXXXXXXX at pcraft.com>, delay=00:01:04, xdelay=00:00:05, mailer=esmtp, pri=30778, relay=mx1.pcraft.com. [206.168.220.51], dsn=2.0.0, stat=Sent (g8Q6m4W08584 Message accepted: There, doesn't that feel better?)

    === Message successfully pushed out, and remotely delivered.  As soon as that was done, I started getting these:

Sep 26 00:58:24 serpico sm-mta[10980]: g8Q6wO9t010980: Milter (mimedefang): to error state
Sep 26 00:58:24 serpico sm-mta[10980]: g8Q6wO9t010980: Milter: initialization failed, temp failing commands
Sep 26 00:59:47 serpico sm-mta[10983]: g8Q6xl9t010983: Milter (mimedefang): to error state
Sep 26 00:59:47 serpico sm-mta[10983]: g8Q6xl9t010983: Milter: initialization failed, temp failing commands
Sep 26 01:01:24 serpico sm-mta[10998]: g8Q71O9t010998: Milter (mimedefang): to error state
Sep 26 01:01:24 serpico sm-mta[10998]: g8Q71O9t010998: Milter: initialization failed, temp failing commands
Sep 26 01:02:11 serpico sm-mta[11004]: g8Q72B9t011004: Milter (mimedefang): to error state

    === Now what?

    Nothing else after this got delivered.  For the rest of the night, this is what kept filling the log file.  So, this morning I reset my MIN/MAX to 3/8 (from last night's 5/10) and suddenly everything works again.  Of the several hundred emails that were queued up from all over the world to be delivered to us, everything came through in a matter of about 20 minutes.  MD behaved just fine, informing remote machines when it ran out of slaves, everything worked fine.  All email has now been delivered and we're back to our usual trickle of 30+ emails per hour.

    What caused Milter to start complaining about MD and temp failing everything?


--
H | "Life is the art of drawing without an eraser." - John Gardner
  +--------------------------------------------------------------------
  Ashley M. Kirchner <mailto:ashley at pcraft.com>   .   303.442.6410 x130
  Director of Internet Operations / SysAdmin    .     800.441.3873 x130
  Photo Craft Laboratories, Inc.            .     3550 Arapahoe Ave, #6
  http://www.pcraft.com ..... .  .    .       Boulder, CO 80303, U.S.A.