Milter service MSMilter does not start correctly with Ubuntu + Postfix

[dbworth]

Issue:
Milter service MSMilter does not start correctly.

Error in configuration file ... directory /var/spool/MailScanner/incoming/Locks for lockfiledir does not exist ...

Software:
Ubuntu 20.04.2 LTS
Postfix 3.4.13
MailScanner-5.3.4-3.noarch.deb

More details:
I installed MailScanner and MSMilter by following the guide:
https://github.com/MailScanner/v5/blob/master/doc/MailScanner%20Milter%20Guide.pdf

I set the milter to start automatically:
systemctl enable msmilter.service

Reboot the server.

The MailScanner service starts correctly.
The MSMilter service does not (it's active but with a warning message).

$ service msmilter status

● msmilter.service - LSB: MSMilter daemon
     Loaded: loaded (/usr/lib/MailScanner/init/msmilter-init; enabled; vendor preset: enabled)
     Active: active (running) since <TIMESTAMP>
       Docs: man:systemd-sysv-generator(8)
    Process: 725 ExecStart=/usr/lib/MailScanner/init/msmilter-init start (code=exited, status=0/SUCCESS)
   Main PID: 1149 (MSMilter Daemon)
      Tasks: 1 (limit: 9513)
     Memory: 35.8M
     CGroup: /system.slice/msmilter.service
             └─1149 MSMilter Daemon

<HOSTNAME> MSMilter[987]: MSMilter Daemon starting...
<HOSTNAME> MSMilter[987]: Reading configuration file /etc/MailScanner/MailScanner.conf
<HOSTNAME> MSMilter[987]: Reading configuration file /etc/MailScanner/conf.d/README
<HOSTNAME> MSMilter[987]: Could not read directory /var/spool/MailScanner/incoming/Locks
<HOSTNAME> MSMilter[987]: Error in configuration file line 3266, directory /var/spool/MailScanner/incoming/Locks for lockfiledir does not exist (or is not readable)
<HOSTNAME> MSMilter[987]: Read 1500 hostnames from the phishing whitelist
<HOSTNAME> MSMilter[987]: Read 5815 hostnames from the phishing blacklists
<HOSTNAME> root[1158]: MSMilter started
<HOSTNAME> msmilter-init[725]: MSMilter started with process id 1149
<HOSTNAME> systemd[1]: Started LSB: MSMilter daemon.

The permissions on the directories after boot are:

drwxrwx---  root    mtagroup  /var/spool/MailScanner/incoming/
drwxr-xr-x  postfix postfix   /var/spool/MailScanner/incoming/Locks/

If I simply restart MSMilter, the warning/error message is gone:
service msmilter restart

$ service msmilter status
● msmilter.service - LSB: MSMilter daemon
     Loaded: loaded (/usr/lib/MailScanner/init/msmilter-init; enabled; vendor preset: enabled)
     Active: active (running) since <TIMESTAMP>
       Docs: man:systemd-sysv-generator(8)
    Process: 2570 ExecStart=/usr/lib/MailScanner/init/msmilter-init start (code=exited, status=0/SUCCESS)
   Main PID: 2587 (MSMilter Daemon)
      Tasks: 1 (limit: 9513)
     Memory: 33.2M
     CGroup: /system.slice/msmilter.service
             └─2587 MSMilter Daemon

<HOSTNAME> systemd[1]: Starting LSB: MSMilter daemon...
<HOSTNAME> msmilter-init[2570]: MSMilter starting ...
<HOSTNAME> msmilter-init[2586]: Trying to setlogsock(unix)
<HOSTNAME> MSMilter[2586]: MSMilter Daemon starting...
<HOSTNAME> MSMilter[2586]: Reading configuration file /etc/MailScanner/MailScanner.conf
<HOSTNAME> MSMilter[2586]: Reading configuration file /etc/MailScanner/conf.d/README
<HOSTNAME> MSMilter[2586]: Read 1500 hostnames from the phishing whitelist
<HOSTNAME> MSMilter[2586]: Read 5815 hostnames from the phishing blacklists
<HOSTNAME> msmilter-init[2570]: MSMilter started with process id 2587
<HOSTNAME> systemd[1]: Started LSB: MSMilter daemon.

Question:
Is this a race condition or something wrong with my install?

[msapiro]

Are you saying you see the same issue after reboot over multiple reboots, or just the first time?

If it's just once, I suspect the error occurs because the file doesn't exist, but the daemon starts anyway and then creates the file.

[dbworth]

Multiple reboots.
The error/warning message seems to appear every time, but it could be 99.9% of the time.

[msapiro]

Do you really need to restart MSMilter. It appears from your report that it is actually running despite the Could not read directory /var/spool/MailScanner/incoming/Locks message. Is it working or not at that point?

For what it's worth, here's what I see after a reboot

# service msmilter status > zzz
root@mail:~# cat zzz
● msmilter.service - LSB: MSMilter daemon
   Loaded: loaded (/usr/lib/MailScanner/init/msmilter-init; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2021-02-24 09:27:09 PST; 1 day 23h ago
     Docs: man:systemd-sysv-generator(8)
  Process: 1143 ExecStart=/usr/lib/MailScanner/init/msmilter-init start (code=exited, status=0/SUCCESS)
 Main PID: 1531 (MSMilter Daemon)
    Tasks: 1 (limit: 4702)
   CGroup: /system.slice/msmilter.service
           └─1531 MSMilter Daemon

Feb 24 09:27:08 mail.msapiro.net MSMilter[1365]: Reading configuration file /etc/MailScanner/conf.d/00local
Feb 24 09:27:08 mail.msapiro.net MSMilter[1365]: Reading configuration file /etc/MailScanner/conf.d/10milter
Feb 24 09:27:08 mail.msapiro.net MSMilter[1365]: Reading configuration file /etc/MailScanner/conf.d/90virus
Feb 24 09:27:08 mail.msapiro.net MSMilter[1365]: Reading configuration file /etc/MailScanner/conf.d/95web_bug
Feb 24 09:27:08 mail.msapiro.net MSMilter[1365]: Reading configuration file /etc/MailScanner/conf.d/README
Feb 24 09:27:08 mail.msapiro.net MSMilter[1365]: Read 1504 hostnames from the phishing whitelist
Feb 24 09:27:08 mail.msapiro.net MSMilter[1365]: Read 5606 hostnames from the phishing blacklists
Feb 24 09:27:08 mail.msapiro.net root[1534]: MSMilter started
Feb 24 09:27:09 mail.msapiro.net msmilter-init[1143]: MSMilter started with process id 1531
Feb 24 09:27:09 mail.msapiro.net systemd[1]: Started LSB: MSMilter daemon.

and here's my systemd service which I think is unchanged from what MailScanner installed.

# cat /etc/systemd/system/multi-user.target.wants/msmilter.service 
[Unit]
Description=LSB: MSMilter daemon
Documentation=man:systemd-sysv-generator(8)
SourcePath=/usr/lib/MailScanner/init/msmilter-init
After=network-online.target remote-fs.target rsyslog.service
Wants=network-online.target

[Service]
Type=forking
Restart=no
TimeoutSec=1min
IgnoreSIGPIPE=no
KillMode=process
GuessMainPID=no
RemainAfterExit=yes
ExecStart=/usr/lib/MailScanner/init/msmilter-init start
ExecStop=/usr/lib/MailScanner/init/msmilter-init stop
EnvironmentFile=-/etc/MailScanner/defaults
PIDFile=/run/MSMilter.pid

[Install]
WantedBy=multi-user.target

[dbworth]

Thanks for that information @msapiro

I edited the systemd service so that msmilter will start after mailscanner:

$ nano /etc/systemd/system/multi-user.target.wants/msmilter.service

...
After=network-online.target remote-fs.target rsyslog.service mailscanner.service
...

I haven't looked into the code but I assume that warning message was included for a reason. If msmilter is able to ignore a missing lock file, that sounds bad to me.

[shawniverson]

The warning message is coming from reading in the MailScanner configuration when it isn't running, definitely benign since the milter doesn't use it but having it start after mailscanner is a good idea.

[dbworth]

I can submit a PR but I'm not sure what the correct solution is?

1. msmilter.service to wait for mailscanner.service to start.
or
2. msmilter doesn't need to read the configuration if it doesn't use it, so remove that part.

[msapiro]

When Shawn said "doesn't use it", he was referring to the Locks directory. msmilter definitely needs to read the configuration as there are items there specifically for it.