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

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 @40000000500cd92136b7ddac qmail-smtpd[16831]: AUTH successful [x.x.x.x] @40000000500cd922007f76dc qmail-smtpd[16831]: MFCHECK pass [x.x.x.x] @40000000500cd922007f8294 qmail-smtpd[16831]: MAIL FROM:<> @40000000500cd9220fc29d54 qmail-smtpd[16831]: RCPT TO:<> @40000000500cd922136dd2d4[16832][16831]: 1/1(5) I no @40000000500cd922136de65c[16832][16831]: 2/2(55) T "^xxxxxx" no @40000000500cd922136dee2c[16832][16831]: 3/1(47) E "" no @40000000500cd922136df5fc[16832][16831]: 3/2(12) E "" no @40000000500cd922136f97f4[16832][16831]: 5/1(50) U MATCH ( @40000000500cd922136f9fc4[16832][16831]: 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 "^" 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 "^"" 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 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, 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.)