skipped, still being delivered
Eric McClelland
emcc-mailscanner at CTCNET.COM
Fri Oct 3 21:15:50 IST 2003
On Wed, Oct 01, 2003 at 03:22:40PM +0100, Julian Field wrote:
> Great :(
> In this case, I really don't know what is going on. Postfix generates the
> error when it tries to open a message to find it is already locked by
> something else. I have been *extremely* careful and paranoid about the
> locking and have made sure the file is unlocked before it is put in the
> queue. So how this is still happening beats me.
Within the past couple days I started seeing this problem as well, and there is one thing I have noticed, yet not seen discussed, namely that MailScanner appears to be opening files in a directory - /var/spool/postfix.in/incoming/ - where AFAICT it should not:
====================
[root at Gabriel log]# lsof | grep /var/spool/postfix.in/incoming
nqmgr 15792 root 8r DIR 72,2 4096 1954564 /var/spool/postfix.in/incoming
nqmgr 15792 root 12r DIR 72,2 4096 521221 /var/spool/postfix.in/incoming/6
nqmgr 15792 root 13r DIR 72,2 4096 895861 /var/spool/postfix.in/incoming/6/3
MailScann 15897 root 5u REG 72,2 3226 1956954 /var/spool/postfix.in/incoming/1/8/18C9A1DDC5A
MailScann 15897 root 19u REG 72,2 8602 1957133 /var/spool/postfix.in/incoming/4/3/43B771DDD0D
MailScann 15897 root 20u REG 72,2 8713 1957134 /var/spool/postfix.in/incoming/4/7/473F31DDD0E
MailScann 15897 root 21u REG 72,2 8256 1956916 /var/spool/postfix.in/incoming/4/1/411D11DDC34
<snip>
MailScann 15963 root 28u REG 72,2 2687 1956812 /var/spool/postfix.in/incoming/1/8/18A571DDBCC
cleanup 16029 root 12u REG 72,2 0 1957467 /var/spool/postfix.in/incoming/C/A/CADDD1DDE5B
cleanup 16276 root 12u REG 72,2 0 1957469 /var/spool/postfix.in/incoming/A/8/A85B71DDE5D
cleanup 16308 root 12u REG 72,2 0 1957464 /var/spool/postfix.in/incoming/9/D/9D1D51DDE58
cleanup 16366 root 12u REG 72,2 0 1957466 /var/spool/postfix.in/incoming/7/D/7D3C21DDE5A
cleanup 16372 root 12u REG 72,2 0 1957468 /var/spool/postfix.in/incoming/8/6/86CB71DDE5C
MailScann 16375 root 14u REG 72,2 2131 1957194 /var/spool/postfix.in/incoming/4/1/41AD51DDD4A
<snip>
====================
...For brevity's sake I don't feel it necessary to include the rest of the output, as they're all various queue files being accessed by MailScanner or cleanup, but I certainly can if folks want (I omitted maybe two dozen lines or so).
Similarly, I can post my full configs, but I think this is sufficient for now:
Incoming Queue Dir = /var/spool/postfix.in/deferred
Incoming Work Dir = /var/spool/MailScanner/incoming
Outgoing Queue Dir = /var/spool/postfix/incoming
While it's obvious that MailScanner should read queue files in /var/spool/postfix.in/DEFERRED/ [my caps] and write them to /var/spool/postfix/incoming/ , I don't think it should be touching anything in /var/spool/postfix.IN/INCOMING/ . Am I wrong in this?
Below are some other pieces of information which may or may not be helpful:
1) I'm running RedHat 7.3 on a Compaq DL360 with two 1GHz processors and 1GB RAM; I've seen no problems with system load.
2) MailScanner version is 4.22-5; Postfix version 1.1.12; SpamAssassin version 2.55.
3) I thought I had turned off all defunct DNS-based spam checks, but MS seemed (sorry, no hard numbers) to be taking a long time to scan messages, especially late last night (between roughly midnight and 2am GMT-04, but I was also actively changing configurations and restarting MS & Co., which seemed to cause bursts of duplicate/blank emails and "skipped, still being delivered" messages). I was unable to get MS to complain of any RBL timeouts (including with Debug = yes in MailScanner.conf), but to make a long story shorter, I turned off all of the following DNS-based spam checks on a hunch (some, again, had already been offf):
====================
Fri Oct 3 15:56:36 /etc/MailScanner
root at Gabriel# ls -l /etc/mail/spamassassin/local.cf
-r--r--r-- 1 root root 780 Oct 3 02:13 /etc/mail/spamassassin/local.cf
Fri Oct 3 15:56:39 /etc/MailScanner
root at Gabriel# grep score /etc/mail/spamassassin/local.cf
score RCVD_IN_RELAYS_ORDB_ORG 0.0
score RCVD_IN_OSIRUSOFT_COM 0.0
score X_OSIRU_DUL 0.0
score X_OSIRU_DUL_FH 0.0
score X_OSIRU_OPEN_RELAY 0.0
score X_OSIRU_SPAMWARE_SITE 0.0
score X_OSIRU_SPAM_SRC 0.0
score RCVD_IN_RFCI 0.0
score RCVD_IN_ORBS 0.0
score RCVD_IN_DSBL 0.0
score RCVD_IN_MULTIHOP_DSBL 0.0
score RCVD_IN_SBL 0.0
score RCVD_IN_UNCONFIRMED_DSBL 0.0
score RCVD_IN_BONDEDSENDER 0.0
score RCVD_IN_OPM 0.0
score RCVD_IN_NJABL 0.0
score X_NJABL_OPEN_PROXY 0.0
score X_NJABL_DIALUP 0.0
====================
4) Very quickly after that, my inbound queue from from 6,000 to "zero" and my "skipped, still being delivered" messages stopped - from this I hypothesize that some DNS-based spam check was timing out (I tested some, but not all), causing MailScanner (and I'm going well beyond my expertise here) to start losing a race condition of some sort with the inbound Postfix process.
====================
Fri Oct 3 02:16:16 /etc/mail/spamassassin
---------->Checking inbound, pre-MS/SA queue<----------
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
-- 74771 Kbytes in 6368 Requests.
Fri Oct 3 02:16:32 /etc/mail/spamassassin
---------->Checking outbound, post-MS/SA queue<----------
root at Gabriel# postqueue -p | tail -1
-- 511 Kbytes in 257 Requests.
Fri Oct 3 02:16:35 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
-- 74904 Kbytes in 6384 Requests.
Fri Oct 3 02:18:38 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 644 Kbytes in 360 Requests.
Fri Oct 3 02:18:42 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
-- 75055 Kbytes in 6402 Requests.
Fri Oct 3 02:21:19 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 1168 Kbytes in 628 Requests.
Fri Oct 3 02:21:25 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
-- 74947 Kbytes in 6394 Requests.
Fri Oct 3 02:22:54 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 889 Kbytes in 465 Requests.
Fri Oct 3 02:22:56 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
-- 73887 Kbytes in 6245 Requests.
Fri Oct 3 02:26:04 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 2131 Kbytes in 665 Requests.
Fri Oct 3 02:26:07 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
-- 71968 Kbytes in 5934 Requests.
Fri Oct 3 02:27:12 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 3866 Kbytes in 851 Requests.
Fri Oct 3 02:27:18 /etc/mail/spamassassin
root at Gabriel#
Fri Oct 3 02:30:28 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
-- 68222 Kbytes in 5465 Requests.
Fri Oct 3 02:30:37 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 7310 Kbytes in 1032 Requests.
Fri Oct 3 02:30:43 /etc/mail/spamassassin
root at Gabriel#
Fri Oct 3 03:46:02 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
Mail queue is empty
Fri Oct 3 03:46:03 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 2032 Kbytes in 310 Requests.
Fri Oct 3 03:46:06 /etc/mail/spamassassin
root at Gabriel#
Fri Oct 3 09:26:59 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
Mail queue is empty
Fri Oct 3 09:27:00 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 35 Kbytes in 6 Requests.
Fri Oct 3 09:27:02 /etc/mail/spamassassin
root at Gabriel#
Fri Oct 3 11:13:48 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
Mail queue is empty
Fri Oct 3 11:13:49 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 35 Kbytes in 6 Requests.
Fri Oct 3 11:58:53 /etc/mail/spamassassin
root at Gabriel# postqueue -c /etc/postfix.in -p | tail -1
Mail queue is empty
Fri Oct 3 11:58:54 /etc/mail/spamassassin
root at Gabriel# postqueue -p | tail -1
-- 39 Kbytes in 7 Requests.
Fri Oct 3 11:58:57 /etc/mail/spamassassin
Fri Oct 3 16:05:27 /etc/MailScanner
root at Gabriel# grep "skipped, still being delivered" /var/log/maillog | tail -2
Oct 3 02:51:24 Gabriel postfix/nqmgr[13729]: 095461DE774: skipped, still being delivered
Oct 3 02:51:24 Gabriel postfix/nqmgr[13729]: 09AE61DEBC9: skipped, still being delivered
====================
I still need to finish testing the DNS-based spam checks to find which one(s) were timing out. My testing and documentation weren't the best on this one, but I apparently did something which coincided with the remission of my immediate problem. :)
--Eric
More information about the MailScanner
mailing list