http:// qmail.jms1.net / scripts / rules / troubleshooting.shtml

Troubleshooting the qmail Rules Interface

As I write this, I'm getting ready to announce this system to the public on my web site. I've asked a few friends to test the system for me, but I haven't heard anything back from them about it, so I don't know if they have run into any problems, or if they've even looked at it. So the only problems I know about are the ones that I have personally run into, or the ones which I can guess will be common issues.

If you do run into any problems which aren't answered here, please ask on the qmail-patch mailing list instead of emailing me directly (unless you want to hire me as a consultant to take care of a specific issue, of course.)

I have tried to test the system on three different machines, using all three database engines listed above (PostgreSQL, MySQL, and SQLite.) However, most of my testing and all of my live usage has been on my own server, where I use PostgreSQL, so the other two engines honestly haven't been tested as well as PostgreSQL has.


Troubleshooting the Database

Most of the problems you will encounter will be while trying to test or use either the web interface, or the rcptcheck.pl processing script. If you are having an issue with the database itself, your best bet is to review the setup instructions for the database engine you're using.


Troubleshooting the Web Interface

The web interface sends error messages and other diagnostic information to Apache's error log file. The ErrorLog directive in your httpd.conf file will tell you where this is.


Troubleshooting the Processing Script

Most of the troubles I see people having with the rcptcheck.pl script will revolve around setting the necessary environment variables. Because the program's configuration and the data it uses for the tests will mostly be coming from environment variables, a useful debugging tool would be the ability to see all of the variables the script is receiving when it starts.

In order to help with this, I have added a block of code to the beginning of the script which will dump the entire environment out to the log file, if the file /var/qmail/control/g4dump exists. The contents and permissions don't really matter, the script checks to see if it exists and, if so, dumps its environment before starting its normal processing.

As long as qmail-smtpd is actually calling the script, you will be able to see all of the environment variables it's starting with, so that you can tell what data it's receiving, and hopefully tell if a problem is being caused by a bug in the script, or by qmail-smtpd (or some other program, such as tcpserver) not adding the variables you or I think should be added.

If you create the /var/qmail/control/g4dump file, please delete it as soon as you're finished with your testing. You may want to use two windows for this - watch the log file in one window, and in the other window create the file (using the "touch" command) and be ready to remove the file as soon as one or two messages have been processed. Leaving this file in place will make your log file grow much more quickly than it normally would.

Here's an example:

# touch /var/qmail/control/g4dump # tail -F /service/qmail-stmp/log/main/current @40000000500cd4a71ed88d94 tcpserver: end 16583 status 0 @40000000500cd4a71ed8994c tcpserver: status: 0/30 @40000000500cd4a8110ae464 tcpserver: status: 1/30 @40000000500cd4a8110b4224 tcpserver: pid 16594 from 65.55.90.34 @40000000500cd4a819e101f4 tcpserver: ok 16594 a.mx.jms1.net:69.28.72.69:25 snt0-omc1-s23.snt0.hotmail.com:65.55.90.34::38908 @40000000500cd4b2323b8904 qmail-smtpd[16594]: MFCHECK pass [65.55.90.34] hotmail.com @40000000500cd4b30b811f2c qmail-smtpd[16594]: Received-SPF: pass (a.mx.jms1.net: SPF record at spf-a.hotmail.com designates 65.55.90.34 as permitted sender) @40000000500cd4b30b812ae4 qmail-smtpd[16594]: MAIL FROM:<xxxxxx@hotmail.com> @40000000500cd4b3102f1eac qmail-smtpd[16594]: RCPT TO:<joe@xxxxxx.com> @40000000500cd4b3102f2a64 qmail-smtpd[16594]: validrcptto [65.55.90.34] trying: joe@xxxxxx.com @40000000500cd4b3102f3234 qmail-smtpd[16594]: validrcptto [65.55.90.34] found: joe@xxxxxx.com @40000000500cd4b40d2b96f4 rcptcheck.pl[16595][16594]: DUMP: ALLOW_INSECURE_AUTH="0" @40000000500cd4b40d2ba2ac rcptcheck.pl[16595][16594]: DUMP: AUTH_CDB="/var/qmail/control/auth.cdb" @40000000500cd4b40d2baa7c rcptcheck.pl[16595][16594]: DUMP: AUTH_SET_DATABYTES="0" @40000000500cd4b40d2bb24c rcptcheck.pl[16595][16594]: DUMP: AUTH_SET_SPFBEHAVIOR="1" @40000000500cd4b40d2bb634 rcptcheck.pl[16595][16594]: DUMP: DENY_TLS="0" @40000000500cd4b40d2bbe04 rcptcheck.pl[16595][16594]: DUMP: DIEMSG="421 a.mx.jms1.net Service not available, try later." @40000000500cd4b40d2c1fac rcptcheck.pl[16595][16594]: DUMP: DIEMSG_MAXCONNC="421 a.mx.jms1.net Too many connections from your network." @40000000500cd4b40d2c2b64 rcptcheck.pl[16595][16594]: DUMP: DIEMSG_MAXCONNIP="421 a.mx.jms1.net Too many connections from your IP address." @40000000500cd4b40d2c3334 rcptcheck.pl[16595][16594]: DUMP: DIEMSG_MAXLOAD="421 a.mx.jms1.net Server busy, try again later." @40000000500cd4b40d2c5e2c rcptcheck.pl[16595][16594]: DUMP: DROP_PRE_GREET="1" @40000000500cd4b40d2c6214 rcptcheck.pl[16595][16594]: DUMP: FORCE_TLS="0" @40000000500cd4b40d2c69e4 rcptcheck.pl[16595][16594]: DUMP: G4DBCONN="DBI:Pg(PrintError=>0):dbname=rules" @40000000500cd4b40d2c71b4 rcptcheck.pl[16595][16594]: DUMP: G4DBPASS="xxxxxx" @40000000500cd4b40d2c7984 rcptcheck.pl[16595][16594]: DUMP: G4DBUSER="g4mail" @40000000500cd4b40d2c9cac rcptcheck.pl[16595][16594]: DUMP: G4GREY24="0" @40000000500cd4b40d2ceeb4 rcptcheck.pl[16595][16594]: DUMP: GREETDELAY="10" @40000000500cd4b40d2cf684 rcptcheck.pl[16595][16594]: DUMP: HELO="snt0-omc1-s23.snt0.hotmail.com" @40000000500cd4b40d2cfe54 rcptcheck.pl[16595][16594]: DUMP: MAXCONNC="5" @40000000500cd4b40d2d023c rcptcheck.pl[16595][16594]: DUMP: MAXCONNIP="2" @40000000500cd4b40d2d0a0c rcptcheck.pl[16595][16594]: DUMP: MAXLOAD="800" @40000000500cd4b40d2d11dc rcptcheck.pl[16595][16594]: DUMP: MAXRCPT="100" @40000000500cd4b40d2dae1c rcptcheck.pl[16595][16594]: DUMP: MFCHECK="3" @40000000500cd4b40d2db204 rcptcheck.pl[16595][16594]: DUMP: NOP0FCHECK="1" @40000000500cd4b40d2db9d4 rcptcheck.pl[16595][16594]: DUMP: PATH="/var/qmail/bin:~vpopmail/bin:/usr/local/bin:/usr/bin:/bin" @40000000500cd4b40d2dc1a4 rcptcheck.pl[16595][16594]: DUMP: PROTO="TCP" @40000000500cd4b40d2dc974 rcptcheck.pl[16595][16594]: DUMP: PWD="/var/service/qmail-smtp" @40000000500cd4b40d2dcd5c rcptcheck.pl[16595][16594]: DUMP: QMAILQUEUE="/var/qmail/bin/simscan" @40000000500cd4b40d2df854 rcptcheck.pl[16595][16594]: DUMP: QMAILSMTPD_LOG_MAIL="1" @40000000500cd4b40d2e0024 rcptcheck.pl[16595][16594]: DUMP: QMAILSMTPD_LOG_RCPT="1" @40000000500cd4b40d2e07f4 rcptcheck.pl[16595][16594]: DUMP: RCPTCHECK="/var/qmail/bin/rcptcheck.pl" @40000000500cd4b40d2e0bdc rcptcheck.pl[16595][16594]: DUMP: RECIPIENT="joe@xxxxxx.com" @40000000500cd4b40d2e13ac rcptcheck.pl[16595][16594]: DUMP: RELAYREJ="1" @40000000500cd4b40d2e3abc rcptcheck.pl[16595][16594]: DUMP: REQUIRE_AUTH="0" @40000000500cd4b40d2e8cc4 rcptcheck.pl[16595][16594]: DUMP: SENDER="xxxxxx@hotmail.com" @40000000500cd4b40d2e90ac rcptcheck.pl[16595][16594]: DUMP: SHLVL="0" @40000000500cd4b40d2e987c rcptcheck.pl[16595][16594]: DUMP: SIMSCAN_DEBUG="0" @40000000500cd4b40d2ea04c rcptcheck.pl[16595][16594]: DUMP: SIMSCAN_DEBUG_FILES="0" @40000000500cd4b40d2ea434 rcptcheck.pl[16595][16594]: DUMP: SPFBEHAVIOR="3" @40000000500cd4b40d2eac04 rcptcheck.pl[16595][16594]: DUMP: SPFRESULT="pass" @40000000500cd4b40d2ed314 rcptcheck.pl[16595][16594]: DUMP: SPF_BLOCK_PLUS_ALL="1" @40000000500cd4b40d2edae4 rcptcheck.pl[16595][16594]: DUMP: SPF_LOG="1" @40000000500cd4b40d2ee2b4 rcptcheck.pl[16595][16594]: DUMP: SSL="0" @40000000500cd4b40d2eea84 rcptcheck.pl[16595][16594]: DUMP: TCPLOCALHOST="a.mx.jms1.net" @40000000500cd4b40d2eee6c rcptcheck.pl[16595][16594]: DUMP: TCPLOCALIP="69.28.72.69" @40000000500cd4b40d2ef63c rcptcheck.pl[16595][16594]: DUMP: TCPLOCALPORT="25" @40000000500cd4b40d2f1d4c rcptcheck.pl[16595][16594]: DUMP: TCPREMOTEHOST="snt0-omc1-s23.snt0.hotmail.com" @40000000500cd4b40d2f251c rcptcheck.pl[16595][16594]: DUMP: TCPREMOTEIP="65.55.90.34" @40000000500cd4b40d2f2cec rcptcheck.pl[16595][16594]: DUMP: TCPREMOTEPORT="38908" @40000000500cd4b40d2f30d4 rcptcheck.pl[16595][16594]: DUMP: TLS_SERVER_CERT="/var/qmail/control/servercert.pem" @40000000500cd4b40d2f38a4 rcptcheck.pl[16595][16594]: DUMP: USE_FD4="1" @40000000500cd4b40d2f5fb4 rcptcheck.pl[16595][16594]: DUMP: VALIDRCPTTO_CDB="/var/qmail/control/validrcptto.cdb" @40000000500cd4b40d2fb1bc rcptcheck.pl[16595][16594]: DUMP: VALIDRCPTTO_LIMIT="10" @40000000500cd4b40d2fb5a4 rcptcheck.pl[16595][16594]: DUMP: VALIDRCPTTO_LOG="2" @40000000500cd4b40d2fbd74 rcptcheck.pl[16595][16594]: xxxxxx@hotmail.com joe@xxxxxx.com 65.55.90.34 OK A @40000000500cd4b428a07594 tcpserver: end 16594 status 0 @40000000500cd4b428a134fc tcpserver: status: 0/30 (Hit CONTROL-C here) # rm /var/qmail/control/g4dump

Obviously I have obscured a few details to protect the identities of my clients and the people sending mail to them, as well as the real password I'm using for my PostgreSQL database, but otherwise everything you see is what actually appeared on my screen when I did this just now.

You will probably notice a few things in the log entries for rcptcheck.pl:

Here's a more typical set of log entries. This is a test message that I just sent from my home test machine to myself on my server:

@40000000500cd917144aa22c tcpserver: status: 1/30 @40000000500cd9171452e374 tcpserver: pid 16831 from x.x.x.x @40000000500cd917145b4bcc tcpserver: ok 16831 a.mx.jms1.net:69.28.72.69:25 x-x-x-x.tpa.clearwire-wmx.net:x.x.x.x::36683 @40000000500cd92136b7ddac qmail-smtpd[16831]: AUTH successful [x.x.x.x] homeserver@domain.xyz @40000000500cd922007f76dc qmail-smtpd[16831]: MFCHECK pass [x.x.x.x] jms1.net @40000000500cd922007f8294 qmail-smtpd[16831]: MAIL FROM:<root@jms1.net> @40000000500cd9220fc29d54 qmail-smtpd[16831]: RCPT TO:<jms1@jms1.net> @40000000500cd922136dd2d4 rcptcheck.pl[16832][16831]: 1/1(5) I 69.28.72.64/28 no @40000000500cd922136de65c rcptcheck.pl[16832][16831]: 2/2(55) T "^xxxxxx" no @40000000500cd922136dee2c rcptcheck.pl[16832][16831]: 3/1(47) E "xxxxxx@gmail.com" no @40000000500cd922136df5fc rcptcheck.pl[16832][16831]: 3/2(12) E "@xxxxxx.com" no @40000000500cd922136f97f4 rcptcheck.pl[16832][16831]: 5/1(50) U MATCH (homeserver@domain.xyz) @40000000500cd922136f9fc4 rcptcheck.pl[16832][16831]: root@jms1.net jms1@jms1.net x.x.x.x OK U @40000000500cd9222a7a428c tcpserver: end 16831 status 0 @40000000500cd9222a7a4a5c tcpserver: status: 0/30

The lines which look like "3/1(47) E "^xxxxxx@gmail.com" no" are produced when a debug rule is present in the processing chain. The numbers "3/1(47)" are the phase, sequence, and rule ID being processed (so this one is "phase=3, seq=1, id=47".) The "E "^xxxxxx@gmail.com"" part tells that this is a "check sender email" rule, looking for the pattern shown, and the "no" at the end tells you that this message did not match that particular rule.

You may notice that phase 2 sequence 1 is missing. This is because this is the debug rule which turned on debugging for the jms1.net domain. I'm okay with using debugging on my own domain, but I don't need to enable it for the entire machine.


2012-08-20 Niamh Holding pointing out an interesting issue... If a recipient address has a "-" character in it, and qmail is also using "-" as the separator charcter for extension addresses, it can cause problems. I need to look into this.

In addition, I just noticed that when I wrote rcptcheck.pl, I have the "-" character hard-coded into the script. That needs to be fixed, but it won't happen today (I'm in the middle of packing up for a move.)