Problems with 5.1.1 milter

[Mark Sapiro]

This is basically just a report of things I encountered with the milter
option in MailScanner 5.1.1. I don't think I have enough information to
actually debug these issues, and for now at least, I have reverted to
the Postfix hold queue option.

I first set up the milter option on a local test server. Mail wasn't
being scanned, but this was because I was submitting the test mail from
localhost. When I submitted mail remotely, all seemed to work well, so I
then set up the milter option on my not too busy production server. I
set it up at about 9:30 p.m. on Friday. It seemed to be working well.

At some point Saturday, I noticed some delays so I began to investigate.

I saw this in mail.log

Oct  6 08:35:50 sbh16 MailScanner[3301]: Requeue: 2BA30E13AF.AAFEC to
DB2E81180AC8
Oct  6 08:35:50 sbh16 postfix/smtpd[6686]: connect from
localhost.localdomain[127.0.0.1]
Oct  6 08:36:20 sbh16 postfix/smtpd[6686]: warning: milter
inet:127.0.0.1:33333: can't read SMFIC_OPTNEG reply packet header:
Connection timed out
Oct  6 08:36:20 sbh16 postfix/smtpd[6686]: warning: milter
inet:127.0.0.1:33333: read error in initial handshake

This seemed to be a one time occurrence. Mail was processed normally until

Oct  6 11:16:39 sbh16 MailScanner[7312]: Requeue: B679E47A37.A9D7F to
A7D441181110
Oct  6 11:16:39 sbh16 postfix/smtpd[27861]: connect from
localhost.localdomain[127.0.0.1]
...
Oct  6 11:17:09 sbh16 postfix/smtpd[27861]: warning: milter
inet:127.0.0.1:33333: can't read SMFIC_OPTNEG reply packet header:
Connection timed out
Oct  6 11:17:09 sbh16 postfix/smtpd[27861]: warning: milter
inet:127.0.0.1:33333: read error in initial handshake
...
Oct  6 11:17:10 sbh16 postfix/smtpd[27861]: connect from
unknown[185.36.81.145]
Oct  6 11:17:40 sbh16 postfix/smtpd[27861]: warning: milter
inet:127.0.0.1:33333: can't read SMFIC_OPTNEG reply packet header:
Connection timed out
Oct  6 11:17:40 sbh16 postfix/smtpd[27861]: warning: milter
inet:127.0.0.1:33333: read error in initial handshake

at which point these seemed to occur with every connect even though
'netstat -lntp' showed the milter listening on port

About an hour later, I reverted to the non-milter configuration and
things became normal again.

Also during the 14 hours that the milter was configured, I saw 4 of these

Oct  5 22:58:44 sbh16 MailScanner[7746]: Quarantined message ... as it
caused MailScanner to crash several times

I have those 4 messages and have reprocessed them following reversion to
the hold queue method with no problem. I also processed them through my
test server running the milter without crashing MailScanner. On the test
server, I did see

Oct  6 15:21:39 msapiro MailScanner[13351]: Unable to kick message
/var/spool/MailScanner/milterout/5ECA5340128, will retry soon...

on 3 of the four messages which remained in milterout, but this may have
been related to the fact that I submitted all 4 in one manual smtp
session and then never submitted any more messages before reverting that
to the hold queue method.

So, I don't think that the "caused MailScanner to crash" issue was
related to the actual message content.

My milter config overrides defaults with

---------------------------------
Incoming Queue Dir = /var/spool/MailScanner/milterin
Outgoing Queue Dir = /var/spool/MailScanner/milterout
MTA = msmail
MSMail Queue Type = short
Milter Scanner = yes
Milter Max Children = 1
---------------------------------

I wonder if people are successfully using this in production or if
people have seen issues such as this?

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan