Procmail and spamassassin woes.

I’ve been having problems with the spamassassin plugin for quite some time now. I’ve narrowed it down to a procmail problem, but I haven’t been able to figure out what. I every couple days pick it up and try to manually trace where the mail might be going (procmail is a bit of a mystery to me).
But I’ve been able to isolate the problem to the fact that the lookup-domain.pl script (any of 3) is not firing. I finally think the problem is /etc/procmailrc

Here is what /etc/procmailrc looks like

[code:1]# Use maildir-style mailbox in user’s home directory
LOGFILE=/var/log/procmail.log
TRAP=//etc/webmin/virtual-server/procmail-logger.pl
:0wi
VIRTUALMIN=|//etc/webmin/virtual-server/lookup-domain.pl $LOGNAME
:0

  • ?/usr/bin/test "$VIRTUALMIN" != ""
    {
    INCLUDERC=//etc/webmin/virtual-server/procmail/$VIRTUALMIN
    }
    ORGMAIL=$HOME/Maildir/
    DEFAULT=$HOME/Maildir/
    DROPPRIVS=yes
    :0
    $DEFAULT
    :0
  • ^X-Spam-Status: Yes
    $DEFAULT[/code:1]

and the log output looks like

[code:1]procmail: Couldn’t read “//etc/webmin/virtual-server/procmail/running /etc/webmin/virtual-server/lookup-domain.pl”
From someone@somewhere.com Wed Jan 23 15:19:34 2008
Subject: Some crazy subject
Folder: /home/domain/homes/tom/Maildir/new/1201123174.24746_0.salvo 2763
Time:1201123174 From:«»someone@somewhere.com To:tom@domain.com User:tom.domain Size:2813 Dest:/home/domain/homes/tom/Maildir/new/1201123174.24746_0.myserveraddrss.mydomain.com Mode:None[/code:1]

that line
procmail: Couldn’t read “//etc/webmin/virtual-server/procmail/running /etc/webmin/virtual-server/lookup-domain.pl”
looks suspicious

and I’ve tried tracing it many times.

And I think it has to do with this line in procmailrc
VIRTUALMIN=|//etc/webmin/virtual-server/lookup-domain.pl $LOGNAME

I tried changing that line to
VIRTUALMIN=//etc/webmin/virtual-server/lookup-domain.pl $LOGNAME

But i think that was more disastrous because i think the mail would get lost

this is what the log output looked like

[code:1]procmail: Skipped "sam.domain"
From acoolguy@anotherplace.com Wed Jan 23 15:27:39 2008
Subject: Re: Fwd: I like procmail
Folder: VIRTUALMIN=//etc/webmin/virtual-server/lookup-domain.pl 0
Time:1201123659 From:acoolguy@anotherplace.com To:«»sam@domain.com User:«»sam.domain Size:5429 Dest:VIRTUALMIN=//etc/webmin/virtual-server/lookup-domain.pl Mode:None
[/code:1]
That
Dest:VIRTUALMIN=//etc/webmin/virtual-server/lookup-domain.pl Mode:None
is the sad part. Do messages that procmail fail to process go to some kind of purgatory somewhere?

I have also tried having Virtualmin reinstall the default procmail, but since virtualmin is a nice guy, it leaves it alone.

Any ideas? anyone?

Ok, I’ve gave myself a little crash course in Procmail. And I see the error of my ways. The error message that appeared in the previous log was caused by a debug message I stuck into one of the scripts, and procmail was trying to process it. Evidently, the other lookup-domain scripts are running, but for some reason Spamassassin doesn’t process the mails. I’ve manually ran the scripts and everything on the processing side is working. I just don’t see what is happening, unless a Procmail rule is dumping out of the script early.

guess I’m still going to have to look.

Hi Sean,

The first thing to check is if the lookup-domain.pl script is outputting a domain ID for the mailbox that is receiving spam. You can do this by running a command like :

/etc/webmin/virtual-server/lookup-domain.pl username.domain </dev/null

where username.domain is the full Unix login (as used for POP3 and IMAP) for the user in question. If this outputs a domain ID number, all should be well.

If not, there are a few possible causes :

  1. The user’s domain doesn’t have the spam feature enabled, on the Edit Virtual Server page.

  2. The user is close to his quota. Unless he has about 10MB free, Virtualmin will not run SpamAssassin, as it requires about that much disk space for temp files … and hangs if it doesn’t get them!

  3. Spam filtering is disabled for the individual user, which can be done on the Edit User page.

Hey Jamie,

/etc/webmin/virtual-server/lookup-domain.pl username.domain </dev/null

Yes, I tried this a bunch of times. The domain ID does get returned.

1) The user's domain doesn't have the spam feature enabled, on the Edit Virtual Server page.
I've check this, and I've enabled and disabled it several times. I've also disabled and enabled the spam and virus plugin in virtualmin.
2) The user is close to his quota. Unless he has about 10MB free, Virtualmin will not run SpamAssassin, as it requires about that much disk space for temp files .. and hangs if it doesn't get them!
This might be the case for some users, but this happens to all users, even ones that don't have quotas.
3) Spam filtering is disabled for the individual user, which can be done on the Edit User page.
I've checked several users, and they all had it enabled. Users that I have that go to me, I have checked this and tried to change it many times. Nothing has made this any different.

I clearly believe that procmail, when it gets to the part where it finds the domain ID (VIRTUALMIN=|/etc/webmin/virtual-server/lookup-domain.pl $LOGNAME), it doesn’t seem to receive the response. Therefore it doesn’t load up the domains custom procmail settings.

This clearly is shown with this output:

procmail: Executing "/usr/bin/test,,!=," procmail: Non-zero exitcode (1) from "/usr/bin/test" procmail: No match on "/usr/bin/test != "

Anything else I can test?

Sean - can you post your current /etc/procmailrc file to this bug report? I suspect that it may differ from the current Virtualmin standard…

Ok, your procmailrc file looks fine.

Another thing to check is the log file /var/webmin/lookup-domain-daemon.log for new lines that get logged when email comes in. This should indicate why spam filtering isn’t done…

You mean /var/log/webmin/lookup-domain-daemon.log, right?
This is strange because the log only has a few entries for this week.

Here is the last 100 lines of that log.

[code:1]
[Wed Jan 16 09:03:14 2008] user=root NOUSER
[Wed Jan 16 10:03:15 2008] user=root NOUSER
[Wed Jan 16 13:03:14 2008] user=root NOUSER
[Wed Jan 16 14:03:14 2008] user=root NOUSER
[Wed Jan 16 15:03:15 2008] user=root NOUSER
[Wed Jan 16 18:03:14 2008] user=root NOUSER
[Wed Jan 16 20:00:01 2008] user=root NOUSER
[Wed Jan 16 20:03:12 2008] user=root NOUSER
[Wed Jan 16 21:03:14 2008] user=root NOUSER
[Thu Jan 17 00:03:15 2008] user=root NOUSER
[Thu Jan 17 01:03:16 2008] user=root NOUSER
[Thu Jan 17 02:03:15 2008] user=root NOUSER
[Thu Jan 17 04:03:14 2008] user=root NOUSER
[Thu Jan 17 05:03:14 2008] user=root NOUSER
[Thu Jan 17 07:00:01 2008] user=root NOUSER
[Thu Jan 17 08:03:15 2008] user=root NOUSER
[Thu Jan 17 11:03:16 2008] user=root NOUSER
[Thu Jan 17 12:03:14 2008] user=root NOUSER
[Thu Jan 17 13:03:14 2008] user=root NOUSER
[Thu Jan 17 17:03:15 2008] user=root NOUSER
[Thu Jan 17 20:00:02 2008] user=root NOUSER
[Thu Jan 17 20:03:15 2008] user=root NOUSER
[Thu Jan 17 21:03:15 2008] user=root NOUSER
[Thu Jan 17 22:03:14 2008] user=root NOUSER
[Thu Jan 17 23:03:15 2008] user=root NOUSER
[Fri Jan 18 01:03:15 2008] user=root NOUSER
[Fri Jan 18 03:03:17 2008] user=root NOUSER
[Fri Jan 18 05:03:15 2008] user=root NOUSER
[Fri Jan 18 07:00:02 2008] user=root NOUSER
[Fri Jan 18 09:03:16 2008] user=root NOUSER
[Fri Jan 18 11:03:15 2008] user=root NOUSER
[Fri Jan 18 12:03:15 2008] user=root NOUSER
[Fri Jan 18 14:03:14 2008] user=root NOUSER
[Fri Jan 18 19:03:14 2008] user=root NOUSER
[Fri Jan 18 20:00:02 2008] user=root NOUSER
[Fri Jan 18 22:03:15 2008] user=root NOUSER
[Sat Jan 19 01:03:14 2008] user=root NOUSER
[Sat Jan 19 02:03:14 2008] user=root NOUSER
[Sat Jan 19 04:03:14 2008] user=root NOUSER
[Sat Jan 19 06:03:14 2008] user=root NOUSER
[Sat Jan 19 07:00:01 2008] user=root NOUSER
[Sat Jan 19 07:03:14 2008] user=root NOUSER
[Sat Jan 19 09:03:15 2008] user=root NOUSER
[Sat Jan 19 11:03:14 2008] user=root NOUSER
[Sat Jan 19 13:03:14 2008] user=root NOUSER
[Sat Jan 19 15:03:15 2008] user=root NOUSER
[Sat Jan 19 17:03:14 2008] user=root NOUSER
[Sat Jan 19 20:00:01 2008] user=root NOUSER
[Sat Jan 19 20:03:14 2008] user=root NOUSER
[Sat Jan 19 22:03:14 2008] user=root NOUSER
[Sun Jan 20 03:00:01 2008] user=root NOUSER
[Sun Jan 20 03:10:24 2008] user=root NOUSER
[Sun Jan 20 06:03:14 2008] user=root NOUSER
[Sun Jan 20 07:00:01 2008] user=root NOUSER
[Sun Jan 20 07:03:14 2008] user=root NOUSER
[Sun Jan 20 08:03:15 2008] user=root NOUSER
[Sun Jan 20 09:03:14 2008] user=root NOUSER
[Sun Jan 20 11:03:15 2008] user=root NOUSER
[Sun Jan 20 15:03:14 2008] user=root NOUSER
[Sun Jan 20 18:03:15 2008] user=root NOUSER
[Sun Jan 20 19:03:15 2008] user=root NOUSER
[Sun Jan 20 20:00:01 2008] user=root NOUSER
[Sun Jan 20 20:03:15 2008] user=root NOUSER
[Sun Jan 20 21:03:15 2008] user=root NOUSER
[Sun Jan 20 22:03:15 2008] user=root NOUSER
[Mon Jan 21 01:03:15 2008] user=root NOUSER
[Mon Jan 21 02:03:15 2008] user=root NOUSER
[Mon Jan 21 03:10:21 2008] user=root NOUSER
[Mon Jan 21 04:03:14 2008] user=root NOUSER
[Mon Jan 21 05:03:14 2008] user=root NOUSER
[Mon Jan 21 06:03:14 2008] user=root NOUSER
[Mon Jan 21 07:00:01 2008] user=root NOUSER
[Mon Jan 21 07:03:14 2008] user=root NOUSER
[Mon Jan 21 09:03:15 2008] user=root NOUSER
[Mon Jan 21 09:37:19 2008] user=sean.spindlex dom=spindlex.com spam=1 client=spamc quota= uquota=
[Mon Jan 21 09:39:05 2008] user=sean.spindlex dom=spindlex.com spam=1 client=spamc quota= uquota=
[Mon Jan 21 09:44:01 2008] user=sean.spindlex dom=spindlex.com spam=1 client=spamc quota= uquota=
[Mon Jan 21 10:03:14 2008] user=root NOUSER
[Mon Jan 21 11:03:14 2008] user=root NOUSER
[Mon Jan 21 12:03:15 2008] user=root NOUSER
[Mon Jan 21 17:03:14 2008] user=root NOUSER
[Mon Jan 21 19:03:15 2008] user=root NOUSER
[Mon Jan 21 20:00:01 2008] user=root NOUSER
[Mon Jan 21 20:03:15 2008] user=root NOUSER
[Mon Jan 21 21:03:12 2008] user=root NOUSER
[Mon Jan 21 23:03:15 2008] user=root NOUSER
[Tue Jan 22 01:03:15 2008] user=root NOUSER
[Tue Jan 22 02:03:14 2008] user=root NOUSER
[Tue Jan 22 04:03:15 2008] user=root NOUSER
[Tue Jan 22 06:03:15 2008] user=root NOUSER
[Tue Jan 22 07:00:02 2008] user=root NOUSER
[Tue Jan 22 10:03:14 2008] user=root NOUSER
[Tue Jan 22 11:03:14 2008] user=root NOUSER
[Tue Jan 22 12:03:14 2008] user=root NOUSER
[Tue Jan 22 13:03:15 2008] user=root NOUSER
[Tue Jan 22 14:03:15 2008] user=root NOUSER
[Tue Jan 22 17:03:14 2008] user=root NOUSER
[Tue Jan 22 20:00:02 2008] user=root NOUSER
[Tue Jan 22 20:03:15 2008] user=root NOUSER
[Tue Jan 22 21:03:15 2008] user=root NOUSER
[/code:1]

If this is suppose to get an entry for every email, something is wrong because this server gets a TON of email. At least 2 emails a minute.

When you run lookup-domain.pl as root from the command line, does an entry get logged to that file?

One thing to check is if Procmail is being run as the right user (root). In a standard Virtualmin install, your /etc/postfix/main.cf file should contain a line like :

[code:1]mailbox_command = /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME[/code:1]

and the /usr/bin/procmail-wrapper command should be setuid root :

[code:1]-rwsr-sr-x 1 root root 2916 2006-10-14 23:18 /usr/bin/procmail-wrapper[/code:1]

I have the same issue - have followed all the troubleshooting steps so far and it all seems ok so far. I have similar entries in the logs to the other user - mail just seems not to get processed by spamassassin. So all help greatly appreciated!

Nick

I have done some further investigations on my server by looking at the procmail log - there are loads of entries for root, but none for any other user - see below:

Time:1201986014 From:root@www.niuk.net To:root@www.niuk.net User:root Size:913 Dest:/root/Maildir/new/1201986001.11169_1.www.niuk.net Mode:None
From root@www.niuk.net Sat Feb 2 21:00:01 2008
Subject: Cron <root@www> /usr/share/clamav/freshclam-sleep
Folder: /root/Maildir/new/1201986001.11172_1.www.niuk.net 861
Time:1201986025 From:root@www.niuk.net To:root@www.niuk.net User:root Size:911 Dest:/root/Maildir/new/1201986001.11172_1.www.niuk.net Mode:None
From root@www.niuk.net Sat Feb 2 21:00:01 2008
Subject: Cron <root@www> /usr/share/clamav/freshclam-sleep
Folder: /root/Maildir/new/1201986001.11171_1.www.niuk.net 851

I wonder if Procmail is even being run by Postfix on your system?
If you send email to a non-root user, do you see log entries in /var/log/maillog or mail.log showing that Procmail is being called?

Just for testing purposes, I installed Virtualmin Pro 3.51 on a fresh CentOS 5 box, and verified that spam filtering was working OK. And that the expected entries appear in /var/webmin/lookup-domain-daemon.log .

Hey Jamie,

I am certain that procmail is running. Every email that comes in, I see it get logged in /var/log/procmail.log.

Here is an example of postfix activity:

[code:1]Feb 2 20:07:39 salvonexus postfix/local[25201]: 9672625395D: to=<billy.mydomain@salvonexus.someserver.com>, orig_to=<billy@mydomain.com>, relay=local, delay=0.28, delays=0.26/0/0/0.02, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)[/code:1]

Just a note, I’ve had this issue since I installed Virtualmin on this machine in October.

The only other thing I can think of is to check if the lookup-domain-daemon.pl process is running (it gets started by the /etc/init.d/lookup-domain-daemon boot script).

If that doesn’t help, to debug this further I’d need to login to the system myself… contact me via email at jcameron@virtualmin.com if that is possible. I’ll post any findings to this forum…

Also, I did this, just to test that the daemon is responding:

[code:1]
salvonexus seanwolfe # telnet localhost 11000
Trying 127.0.0.1…
Connected to localhost.
Escape character is ‘^]’.
sean.spindlex
11680492405802 spindlex.com 1 1 UNLIMITED
Connection closed by foreign host.
[/code:1]

So, it seems to be doing something.

Ok, that all looks fine to me.
I’d have to login to see what is really going wrong, so I have emailed you my public keys…

Jamie

I am having similar issues - I can see mail is being processed by procmail as per logs below:

Feb 3 15:17:37 www postfix/smtpd[12166]: connect from py-out-1112.google.com[64.233.166.180] Feb 3 15:17:37 www postfix/smtpd[12166]: C75032A803D: client=py-out-1112.google.com[64.233.166.180] Feb 3 15:17:38 www postfix/cleanup[12283]: C75032A803D: message-id=<866917ad0802030717k11ece977o6b8b015037bb9e2b@mail.gmail.com> Feb 3 15:17:38 www postfix/qmgr[15822]: C75032A803D: from=<nick.iles@gmail.com>, size=1981, nrcpt=1 (queue active) Feb 3 15:17:39 www procmail[12285]: Error while writing to "/var/log/procmail.log" Feb 3 15:17:39 www postfix/local[12284]: C75032A803D: to=<nick.niuk.net@www.niuk.net>, orig_to=<nick@niuk.net>, relay=local, delay=2, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME) Feb 3 15:17:39 www postfix/qmgr[15822]: C75032A803D: removed

Any chance you can suggest anything else - this machine is on VMIN Pro 3.51 and Centos 4.6

Nick

Ok I have fixed the permissions on procmail.log which has allowed procmail to progress further - the error is now with lookup-domain - see below:

[code:1]procmail: Assigning "TRAP=//etc/webmin/virtual-server/procmail-logger.pl"
procmail: Executing "/etc/webmin/virtual-server/lookup-domain.pl,caroline.fundays.org.uk"
Failed to run /virtual-server/lookup-domain.pl : No such file or directory at /etc/webmin/virtual-server/lookup-domain.pl line 10.
procmail: Program failure (2) of "/etc/webmin/virtual-server/lookup-domain.pl"
[/code:1]

Any thoughts?

Nick

Nick,

What does your /etc/procmailrc file look like?

Is your virtualmin config installed in /etc/webmin/virtual-server directory? Is it elsewhere?

What does /etc/webmin/virtual-server/lookup-domain.pl look like?

What is root= set to in /etc/webmin/miniserv.conf?

Likely your procmailrc is pointing to the wrong location, or your permissions are not set correctly on your virtualmin config.

This is what mine looks like for lookup-domain.pl

[code:1]salvonexus seanwolfe # ls -la /etc/webmin/virtual-server/lookup-domain.pl
-rwxr-xr-x 1 root root 278 Jan 28 16:21 /etc/webmin/virtual-server/lookup-domain.pl
[/code:1]

Nick,

Did you try some of the tests that I posted in the previous posts?
Otherwise you may be in the same place I am. The only thing that concerns me is that you are getting errors that it can’t find /etc/webmin/virtual-server/lookup-domain.pl.

But some things that I have seen while testing this is to check a few things. For example, can you run /etc/webmin/virtual-server/lookup-domain.pl from the command line? It might be that one of the files that lookup-domain is trying to find isn’t there.

Also, have you reinstalled Webmin? Did you install Virtualmin via the installer script, or from a distro package?

Hi Sean

Vmin and Webmin installed via standard installers from the Webmin/Vmin sites. I have followed this post closely and have done all the tests so far. If I run lookup-domain from command line it works fine, producing entries in the log and returning a domain id. This is very wierd!

I can’t think of much else to try!

Nick