I'd like to report a rather minor/cosmetic problem - namely a lack of
useful logging when an smtpd service tries to connect to a proxy content
filter over a Unix socket which is too heavily protected - but which took
me far longer to understand than necessary (the strong protection was on
a parent directory, not on a socket itself, which obscured the obvious).
All I got was a '451 4.3.0 Error: queue file write error' for the
client, and just a disconnect and a double bounce in the log.
Turning on verbosity on smtpd did not help to explain the issue.
(version: postfix-current-2.8.20100728 from ports @ FreeBSD 8.1)
In the end I tried a post-queue setup, and the failing lmtp service
was far more helpful, clearly reporting a 'Permission denied' and
giving the socket name. Fixing the socket permission problem
resolved the original proxy setup case too.
My test setup (proxy over a Unix socket):
10111 inet n - n - - smtpd
-o smtpd_proxy_filter=unix:/var/amavis/amavisd.sock
-o mynetworks=127.0.0.0/8,[::1]
-o smtpd_client_restrictions=permit_mynetworks,reject
# telnet 127.0.0.1 10111
220 xxx.ijs.si ESMTP Postfix
ehlo bla
250-[...]
mail from:<mark.marti...@ijs.si>
250 2.1.0 Ok
rcpt to:<mark.marti...@ijs.si>
451 4.3.0 Error: queue file write error
quit
221 2.0.0 Bye
postfix/smtpd[55739]: connect from localhost.ijs.si[127.0.0.1]
postfix/cleanup[55754]: 7E4A510E:
message-id=<20100902231515.7e4a5...@xxx.ijs.si>
postfix/smtpd[55739]: disconnect from localhost.ijs.si[127.0.0.1]
postfix/qmgr[55737]: 7E4A510E: from=<double-bou...@xxx.ijs.si>, size=841,
nrcpt=1 (queue active)
postfix/cleanup[55754]: ACD2010F:
message-id=<20100902231515.7e4a5...@xxx.ijs.si>
postfix/local[55755]: 7E4A510E: to=<postmas...@xxx.ijs.si>,
orig_to=<postmaster>,
relay=local, delay=0.21, delays=0.19/0.01/0/0.02, dsn=2.0.0, status=sent
(forwarded as ACD2010F)
postfix/qmgr[55737]: ACD2010F: from=<double-bou...@xxx.ijs.si>, size=969,
nrcpt=1 (queue active)
postfix/qmgr[55737]: 7E4A510E: removed
postfix/smtp[55756]: ACD2010F: to= [...] 250 2.0.0 Ok: queued as 2359B1D1C5B
postfix/qmgr[55737]: ACD2010F: removed
With a verbosity turned on (smtpd -v) the log is just a little bit
more specific, but still fails to report the permission problem
connecting to the unix socket:
[...]
postfix/smtpd[55877]: generic_checks: name=permit_mynetworks
postfix/smtpd[55877]: permit_mynetworks: localhost.ijs.si 127.0.0.1
postfix/smtpd[55877]: match_hostname: localhost.ijs.si ~? 127.0.0.0/8
postfix/smtpd[55877]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8
postfix/smtpd[55877]: generic_checks: name=permit_mynetworks status=1
postfix/smtpd[55877]: smtpd_check_rewrite: trying: permit_inet_interfaces
postfix/smtpd[55877]: permit_inet_interfaces: localhost.ijs.si 127.0.0.1
postfix/smtpd[55877]: smtp_get: EOF
postfix/smtpd[55877]: warning: lost connection with proxy
unix:/var/amavis/amavisd.sock
postfix/smtpd[55877]: > localhost.ijs.si[127.0.0.1]: 451 4.3.0 Error: queue
file write error
postfix/smtpd[55877]: < localhost.ijs.si[127.0.0.1]: quit
postfix/smtpd[55877]: > localhost.ijs.si[127.0.0.1]: 221 2.0.0 Bye
Now here below is the post-queue filtering setup, letting an lmtp service
talk to the same content filter's Unix socket as above. The logging is
clear and to the point in this case:
10111 inet n - n - - smtpd
-o content_filter=testfeed:unix:/var/amavis/amavisd.sock
-o mynetworks=127.0.0.0/8,[::1]
-o smtpd_client_restrictions=permit_mynetworks,reject
testfeed unix - - n - 50 lmtp
-o lmtp_send_xforward_command=yes
postfix/lmtp[55986]: 61C8A117: to=<mark.marti...@ijs.si>, relay=none,
delay=24, delays=24/0/0/0, dsn=4.4.1, status=deferred
(connect to xxx.ijs.si[/var/amavis/amavisd.sock]: Permission denied)
Perhaps an improved error logging could save somebody the effort
of troubleshooting.
Btw, for the curios: the result of my experiment is that feeding a
message to a proxy content filter over a Unix socket is sometimes
as fast (Mb/s) as over an inet socket, and sometimes about 27% slower.
The lines with two distinct slopes clearly emerge on a diagram
of elapsed time vs. message size for a DATA phase. No idea why,
but I won't bother to investigate, as the inet is clearly a winner
at times, or an exact even otherwise. Funny.
Mark
