A freshly installed postfix 2.8.0 from FreeBSD ports on FreeBSD 8.2-RC3,
with a file system on ZFS (zpool v15, zfs v4) shows an interesting warning
when smtpd_proxy_options=speed_adjust is enabled on a smtpd service
which uses a proxy filter:
Feb 18 20:25:39 xxx postfix/smtpd[3620]:
warning: truncate before-queue filter speed-adjust log: Permission denied
Other than that, everything looks normal. There are no leftover files
in the spool area, and mail is delivered normally.
I took a liberty to let smtpd_proxy.c log a path of the log stream,
added a printout of the path just after a file creation, and commented out
the unlink, so that the temporary file remains in place for observation.
Seems to me like the problem might be a temporary file
created with *no* permission bits, and perhaps ftruncate chokes on that
even though the file has been unlinked by now:
# ll -d /var/spool/postfix/incoming/243E8171
---------- 1 postfix wheel 596 Feb 18 20:46
/var/spool/postfix/incoming/243E8171
# ll -d /var/spool/postfix/incoming
drwx------ 2 postfix wheel 4 Feb 18 20:46 /var/spool/postfix/incoming
# ll -d /var/spool/postfix
drwxr-xr-x 16 root wheel 16 Feb 10 12:18 /var/spool/postfix
# ll -d /var/spool
drwxr-xr-x 9 root wheel 9 Feb 10 12:18 /var/spool
# ll -d /var
drwxr-xr-x 28 root wheel 28 Feb 11 03:37 /var
# ll -d /
drwxr-xr-x 47 root wheel 55 Feb 13 18:41 /
Feb 18 20:46:16 xxx postfix/smtpd[12704]:
connect from localhost[127.0.0.1]
Feb 18 20:46:16 xxx postfix/smtpd[12704]:
warning: CREATED before-queue filter speed-adjust log:
incoming/243E8171
=================
Feb 18 20:46:16 xxx postfix/smtpd[12704]:
NOQUEUE: client=localhost[127.0.0.1]
Feb 18 20:46:23 xxx postfix/smtpd[12709]:
connect from localhost[127.0.0.1]
Feb 18 20:46:23 xxx postfix/smtpd[12709]:
D7A31172: client=localhost[127.0.0.1], orig_client=localhost[127.0.0.1]
Feb 18 20:46:23 xxx postfix/cleanup[12711]:
D7A31172: message-id=<201102181946.p1ijkgaw012...@xxx.ijs.si>
Feb 18 20:46:23 xxx postfix/qmgr[12698]:
D7A31172: from=<t...@xxx.ijs.si>, size=968, nrcpt=1 (queue active)
Feb 18 20:46:23 xxx postfix/smtpd[12704]:
proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025):
250 2.0.0 Ok: queued as D7A31172; from=<t...@xxx.ijs.si> to=<t...@ijs.si>
proto=ESMTP helo=<xxx.ijs.si>
Feb 18 20:46:23 xxx postfix/smtpd[12704]:
warning: truncate before-queue filter speed-adjust
log incoming/243E8171: Permission denied
=================
Feb 18 20:46:23 xxx sendmail[12703]:
p1IJkGaW012703: to=t...@ijs.si, ctladdr=test (401/401), delay=00:00:07,
xdelay=00:00:07, mailer=relay, pri=30049, relay=[127.0.0.1] [127.0.0.1],
dsn=2.0.0, stat=Sent (from MTA(smtp:[127.0.0.1]:10025):
250 2.0.0 Ok: queued as D7A31172)
Feb 18 20:46:23 xxx postfix/smtpd[12704]:
disconnect from localhost[127.0.0.1]
Feb 18 20:46:25 xxx postfix/smtp[12712]:
D7A31172: to=<t...@ijs.si>, relay=mail.ijs.si[193.2.4.66]:25,
delay=1.4, delays=0.02/0/0.03/1.3, dsn=2.0.0, status=sent
(250 2.0.0 from MTA(smtp:[::0001]:10011):
250 2.0.0 Ok: queued as 0A4611D1E4E)
Feb 18 20:46:25 xxx postfix/qmgr[12698]:
D7A31172: removed
Feb 18 20:47:17 xxx postfix/smtpd[12709]:
disconnect from localhost[127.0.0.1]
Mark
