Problem setting up MailScanner 5.1.1 milter support.

Mark Sapiro mark at msapiro.net
Fri Oct 5 22:57:41 UTC 2018


I am experimenting with the new MailScanner milter option.

I have done the following things.

Removed
---------------------------------
/Received: / HOLD
---------------------------------
from /etc/postfix/header_checks

Added
---------------------------------
# MailScanner milter
smtpd_milters = inet:127.0.0.1:33333
---------------------------------
to /etc/postfix/main.cf

Added
---------------------------------
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
---------------------------------
in a conf.d file in my MailScanner config overriding any defaults in
MailScanner.conf added by the installation of 5.1.1

Created those directories owned by Run As User and (re)started all the
services. The milter is listening on port 33333 and everything looks
good, but MailScanner doesn't scan the mail and nothing gets written
into the milterin and milterout directories.

Here's a mail.log entry

> Oct  5 14:43:12 msapiro postfix/smtpd[11012]: connect from localhost[127.0.0.1]
> Oct  5 14:44:30 msapiro postfix/smtpd[11012]: 69BEC340120: client=localhost[127.0.0.1]
> Oct  5 14:45:11 msapiro postfix/cleanup[11438]: 69BEC340120: message-id=<20181005212532.GC2579 at msapiro.net>
> Oct  5 14:45:11 msapiro postfix/qmgr[30689]: 69BEC340120: from=<mark at msapiro.net>, size=665, nrcpt=1 (queue active)
> Oct  5 14:45:11 msapiro postfix/local[11657]: 69BEC340120: to=<mark at msapiro.net>, relay=local, delay=58, delays=58/0.01/0/0.03, dsn=2.0.0, status=sent (delivered to mailbox)
> Oct  5 14:45:11 msapiro postfix/qmgr[30689]: 69BEC340120: removed
> Oct  5 14:45:18 msapiro postfix/smtpd[11012]: disconnect from localhost[127.0.0.1] helo=1 mail=1/2 rcpt=1 data=1 quit=1 commands=5/6

And here are the headers from the delivered mail

> From mark at msapiro.net  Fri Oct  5 14:45:11 2018
> Return-Path: <mark at msapiro.net>
> X-Original-To: mark at msapiro.net
> Delivered-To: mark at msapiro.net
> Received: from msapiro.net (localhost [127.0.0.1])
>         by msapiro.net (Postfix) with SMTP id 69BEC340120
>         for <mark at msapiro.net>; Fri,  5 Oct 2018 14:44:12 -0700 (PDT)
> Date: Fri, 5 Oct 2018 14:25:32 -0700
> From: Mark Sapiro <mark at msapiro.net>
> To: Mark Sapiro <mark at msapiro.net>
> Subject: Yet another
> Message-ID: <20181005212532.GC2579 at msapiro.net>
> MIME-Version: 1.0
> Content-Type: text/plain; charset=us-ascii
> Content-Disposition: inline
> User-Agent: Mutt/1.5.24 (2015-08-30)

I've tried setting debug = yes and running manuallyMailScanner as root.
It hangs at "Building a message batch to scan..." even if I send a
message through Postfix.

This is the full mail.log starting with restarting msmilter

> Oct  5 15:41:58 msapiro root[29411]: Stopping MSMilter
> Oct  5 15:41:58 msapiro root[29418]: MSMilter stopped
> Oct  5 15:41:58 msapiro root[29423]: Starting MSMilter
> Oct  5 15:41:59 msapiro MSMilter[29431]: MSMilter Daemon starting...
> Oct  5 15:41:59 msapiro MSMilter[29431]: Reading configuration file /etc/MailScanner/MailScanner.conf
> Oct  5 15:41:59 msapiro MSMilter[29431]: Reading configuration file /etc/MailScanner/conf.d/00local
> Oct  5 15:41:59 msapiro MSMilter[29431]: Reading configuration file /etc/MailScanner/conf.d/10milter
> Oct  5 15:41:59 msapiro MSMilter[29431]: Reading configuration file /etc/MailScanner/conf.d/99testing
> Oct  5 15:41:59 msapiro MSMilter[29431]: Reading configuration file /etc/MailScanner/conf.d/README
> Oct  5 15:41:59 msapiro MSMilter[29431]: Read 1501 hostnames from the phishing whitelist
> Oct  5 15:41:59 msapiro MSMilter[29431]: Read 16624 hostnames from the phishing blacklists
> Oct  5 15:41:59 msapiro MSMilter[29433]: initialization:
> Oct  5 15:41:59 msapiro MSMilter[29433]:  PidFile = /var/run/MSMilter.pid
> Oct  5 15:41:59 msapiro MSMilter[29433]:  user = postfix
> Oct  5 15:41:59 msapiro MSMilter[29433]:  group = clamav
> Oct  5 15:41:59 msapiro MSMilter[29433]:  bind = 127.0.0.1
> Oct  5 15:41:59 msapiro MSMilter[29433]:  port = 33333
> Oct  5 15:41:59 msapiro root[29434]: MSMilter started
> Oct  5 15:42:15 msapiro root[29564]: Stopping MailScanner
> Oct  5 15:42:15 msapiro MailScanner[4279]: MailScanner child caught a SIGHUP
> Oct  5 15:42:15 msapiro root[29570]: Found a possible dead PID. Stopping all MailScanner rogue processes ...
> Oct  5 15:42:15 msapiro root[29581]: MailScanner stopped
> Oct  5 15:42:43 msapiro MailScanner[29717]: MailScanner Email Processor version 5.1.1 starting...
> Oct  5 15:42:43 msapiro MailScanner[29717]: Reading configuration file /etc/MailScanner/MailScanner.conf
> Oct  5 15:42:43 msapiro MailScanner[29717]: Reading configuration file /etc/MailScanner/conf.d/00local
> Oct  5 15:42:43 msapiro MailScanner[29717]: Reading configuration file /etc/MailScanner/conf.d/10milter
> Oct  5 15:42:43 msapiro MailScanner[29717]: Reading configuration file /etc/MailScanner/conf.d/99testing
> Oct  5 15:42:43 msapiro MailScanner[29717]: Reading configuration file /etc/MailScanner/conf.d/README
> Oct  5 15:42:43 msapiro MailScanner[29717]: Read 1501 hostnames from the phishing whitelist
> Oct  5 15:42:43 msapiro MailScanner[29717]: Read 16624 hostnames from the phishing blacklists
> Oct  5 15:42:43 msapiro MailScanner[29717]: Using SpamAssassin results cache
> Oct  5 15:42:43 msapiro MailScanner[29717]: Connected to SpamAssassin cache database
> Oct  5 15:42:43 msapiro MailScanner[29717]: Enabling SpamAssassin auto-whitelist functionality...
> Oct  5 15:42:45 msapiro MailScanner[29717]: Connected to Processing Attempts Database
> Oct  5 15:42:45 msapiro MailScanner[29717]: Found 0 messages in the Processing Attempts Database
> Oct  5 15:42:45 msapiro MailScanner[29717]: lock.pl sees Config  LockType =  flock
> Oct  5 15:42:45 msapiro MailScanner[29717]: lock.pl sees have_module =  0
> Oct  5 15:42:45 msapiro MailScanner[29717]: Using locktype = flock
> Oct  5 15:44:15 msapiro postfix/smtpd[30228]: connect from localhost[127.0.0.1]
> Oct  5 15:44:15 msapiro MSMilter[29436]: Localhost relay detected
> Oct  5 15:44:57 msapiro postfix/smtpd[30228]: 2444D340120: client=localhost[127.0.0.1]
> Oct  5 15:45:14 msapiro postfix/cleanup[30434]: 2444D340120: message-id=<20181005224457.2444D340120 at msapiro.net>
> Oct  5 15:45:14 msapiro postfix/qmgr[30689]: 2444D340120: from=<mark at msapiro.net>, size=580, nrcpt=1 (queue active)
> Oct  5 15:45:14 msapiro postfix/local[30540]: 2444D340120: to=<mark at msapiro.net>, relay=local, delay=28, delays=28/0/0/0.03, dsn=2.0.0, status=sent (delivered to mailbox)
> Oct  5 15:45:14 msapiro postfix/qmgr[30689]: 2444D340120: removed
> Oct  5 15:45:21 msapiro postfix/smtpd[30228]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5


There is probably something obvious that I'm missing, but I don't know what.

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


More information about the MailScanner mailing list