Mark Martinec:
> 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:
Please file a ZFS bug reportug. As per POSIX, when the O_CREAT is
specified to open(),
The third argument does not affect whether the file is open
for reading, writing or for both.
In other words, read/write access is controlled with the O_RDWR flags,
not the read/write permissions argument.
When the above error happens, Postfix discards the file. Consequently,
Postfix performance will be reduced, because it creates one extra file
per MAIL transaction, instead of one extra file over the process
lifetime.
Wietse
>
> # 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
>
>
