I'm working on a website (as a volunteer - www.vvfh.org), and I have a
problem sending mail from a web form. Unfortunately, this is on one of
those cloud server deals where I have very little access for
troubleshooting purposes.
I put the files (the script and the contact page) on another server that I
control so I could see what the error messages were, but the form worked
fine there.
Here's what's happening. When I fill out the form and click on Submit, the
script returns a success message but I never receive the mail. I'm sending
the mail to an account on the server I control.
The cloud hosting setup is saying the mail is delivered successfully, but
it's not.
Looking at the logs on the receiving server (postfix 2.10.2 on FreeBSD
8.3), the mail is being bounced, but the bounce makes no sense to me at all.
Here's a snippet from the mail log:
Jan 9 02:49:24 mail postfix/policyd-weight[29824]: child: spawned
Jan 9 02:49:26 mail postfix/policyd-weight[29824]: weighted check:
NOT_IN_SBL_XBL_SPAMHAUS=-1.5 NOT_IN_SPAMCOP=-1.5 NOT_IN_BL_NJABL=-1.5
HELO_IP_IN_CL16_SUBNET=-0.41 (check from: .hostzilla. - helo:
.a.free.hostzilla. - helo-domain: .hostzilla.)
FROM/MX_MATCHES_UNVR_HELO(DOMAIN)_OR_CL_NAME(DOMAIN)=-1.5
RESOLVED_IP_IS_NOT_HELO=1.5 FROM_MULTIPARTED=1.09;
<client=unknown[67.227.164.146]> <helo=a.free.hostzilla.ws>
<from=vvfh...@a.free.hostzilla.ws> <to=g...@stovebolt.com>; rate: -3.82
Jan 9 02:49:26 mail postfix/policyd-weight[29824]: decided action=PREPEND
X-policyd-weight: NOT_IN_SBL_XBL_SPAMHAUS=-1.5 NOT_IN_SPAMCOP=-1.5
NOT_IN_BL_NJABL=-1.5 HELO_IP_IN_CL16_SUBNET=-0.41 (check from: .hostzilla.
- helo: .a.free.hostzilla. - helo-domain: .hostzilla.)
FROM/MX_MATCHES_UNVR_HELO(DOMAIN)_OR_CL_NAME(DOMAIN)=-1.5
RESOLVED_IP_IS_NOT_HELO=1.5 FROM_MULTIPARTED=1.09; rate: -3.82;
<client=unknown[67.227.164.146]> <helo=a.free.hostzilla.ws>
<from=vvfh...@a.free.hostzilla.ws> <to=g...@stovebolt.com>; delay: 2s
Jan 9 02:49:26 mail postfix/smtpd[29823]: 3D42D2F173C:
client=unknown[67.227.164.146]
Jan 9 02:49:26 mail postfix/cleanup[29825]: 3D42D2F173C:
message-id=<e1w15gr-0005p2...@a.free.hostzilla.ws>
Jan 9 02:49:26 mail postfix/qmgr[5989]: 3D42D2F173C:
from=<vvfh...@a.free.hostzilla.ws>, size=1633, nrcpt=1 (queue active)
Jan 9 02:49:26 mail postfix/smtpd[29823]: disconnect from
unknown[67.227.164.146]
Jan 9 02:49:32 mail postfix/pipe[29826]: 3D42D2F173C:
to=<g...@stovebolt.com>, relay=filter, delay=7.8, delays=1.8/0.01/0/5.9,
dsn=5.3.0, status=bounced (Command died with status 1:
"/usr/local/bin/filter.sh". Command output: Jan 9 02:49:28.913 [29829]
warn: netset: cannot include 127.0.0.0/32 as it has already been included
Jan 9 02:49:28.913 [29829] warn: netset: illegal network address given:
'216.58.158.271' rm: out.29827: No such file or directory )
Jan 9 02:49:32 mail postfix/cleanup[29825]: 3B3E82F176C:
message-id=<20140109024932.3b3e82f1...@mail.stovebolt.com>
Jan 9 02:49:32 mail postfix/qmgr[5989]: 3B3E82F176C: from=<>, size=3973,
nrcpt=1 (queue active)
Jan 9 02:49:32 mail postfix/bounce[29835]: 3D42D2F173C: sender
non-delivery notification: 3B3E82F176C
Jan 9 02:49:32 mail postfix/qmgr[5989]: 3D42D2F173C: removed
Jan 9 02:49:32 mail postfix/smtp[29795]: 3B3E82F176C:
to=<vvfh...@a.free.hostzilla.ws>,
relay=a.free.hostzilla.ws[67.227.165.253]:25, delay=0.24,
delays=0.04/0/0.16/0.04, dsn=5.0.0, status=bounced (host
a.free.hostzilla.ws[67.227.165.253] said: 550-You do not have sufficient
privileges to send mail to this address. Please 550 authenticate and try
again. (in reply to RCPT TO command))
Jan 9 02:49:32 mail postfix/qmgr[5989]: 3B3E82F176C: removed
So the mail is accepted by postfix and handed off to filter.sh where it's
bounced back with the message "550-You do not have sufficient privileges to
send mail to this address. Please 550 authenticate and try again. (in
reply to RCPT TO command))"
Huh? The mail is being sent TO a legitimate address from a "foreign"
server. Unless it's rejected as spam, it should be delivered. I don't get
it. What am I missing?
If needed I can post the postconf -n results.
Other mail from "foreign" hosts is being delivered properly.
For example:
Jan 9 04:05:30 mail postfix/postscreen[35241]: CONNECT from
[129.110.180.40]:23138 to [216.58.158.171]:25
Jan 9 04:05:36 mail postfix/postscreen[35241]: PASS NEW
[129.110.180.40]:23138
Jan 9 04:05:36 mail postfix/smtpd[35245]: warning: database
/usr/local/mailman/data/aliases.db is older than source file
/usr/local/mailman/data/aliases
Jan 9 04:05:36 mail postfix/smtpd[35245]: connect from
ip-001.utdallas.edu[129.110.180.40]
Jan 9 04:05:36 mail postfix/smtpd[35245]: Anonymous TLS connection
established from ip-001.utdallas.edu[129.110.180.40]: TLSv1 with cipher
RC4-SHA (128/128 bits)
Jan 9 04:05:37 mail postfix/policyd-weight[29824]: weighted check:
NOT_IN_SBL_XBL_SPAMHAUS=-1.5 NOT_IN_SPAMCOP=-1.5 NOT_IN_BL_NJABL=-1.5
CL_IP_EQ_FROM_MX=-3.1; <client=ip-001.utdallas.edu[129.110.180.40]>
<helo=ip-001.utdallas.edu> <from=prvs=0799048bf=pa...@utdallas.edu>
<to=g...@stovebolt.com>; rate: -7.6
Jan 9 04:05:37 mail postfix/policyd-weight[29824]: decided action=PREPEND
X-policyd-weight: NOT_IN_SBL_XBL_SPAMHAUS=-1.5 NOT_IN_SPAMCOP=-1.5
NOT_IN_BL_NJABL=-1.5 CL_IP_EQ_FROM_MX=-3.1; rate: -7.6;
<client=ip-001.utdallas.edu[129.110.180.40]> <helo=ip-001.utdallas.edu>
<from=prvs=0799048bf=pa...@utdallas.edu> <to=g...@stovebolt.com>; delay: 1s
Jan 9 04:05:37 mail postfix/smtpd[35245]: C27AB2F1513:
client=ip-001.utdallas.edu[129.110.180.40]
Jan 9 04:05:37 mail postfix/cleanup[35248]: C27AB2F1513:
message-id=<43F88331AA2D150AEFE9BB60@Pauls-MacBook-Pro.local>
Jan 9 04:05:37 mail postfix/qmgr[5989]: C27AB2F1513:
from=<prvs=0799048bf=pa...@utdallas.edu>, size=1467, nrcpt=1 (queue active)
Jan 9 04:05:42 mail postfix/smtpd[35245]: disconnect from
ip-001.utdallas.edu[129.110.180.40]
Jan 9 04:05:44 mail postfix/pickup[30226]: CBE712F157D: uid=1004
from=<prvs=0799048bf=pa...@utdallas.edu>
Jan 9 04:05:44 mail postfix/cleanup[35248]: CBE712F157D:
message-id=<43F88331AA2D150AEFE9BB60@Pauls-MacBook-Pro.local>
Jan 9 04:05:44 mail postfix/pipe[35249]: C27AB2F1513:
to=<g...@stovebolt.com>, relay=filter, delay=8, delays=1.1/0.01/0/6.9,
dsn=2.0.0, status=sent (delivered via filter service)
Jan 9 04:05:44 mail postfix/qmgr[5989]: C27AB2F1513: removed
Jan 9 04:05:44 mail postfix/qmgr[5989]: CBE712F157D:
from=<prvs=0799048bf=pa...@utdallas.edu>, size=1810, nrcpt=1 (queue active)
Jan 9 04:05:44 mail postfix/local[35259]: warning: database
/usr/local/mailman/data/aliases.db is older than source file
/usr/local/mailman/data/aliases
Jan 9 04:05:44 mail postfix/local[35259]: CBE712F157D:
to=<g...@stovebolt.com>, relay=local, delay=0.07, delays=0.04/0.01/0/0.02,
dsn=2.0.0, status=sent (delivered to maildir)
Jan 9 04:05:44 mail postfix/qmgr[5989]: CBE712F157D: removed
I am stumped. The filter.sh script is verbatim the one scraped from
Weitse's pages.
Paul Schmehl, Senior Infosec Analyst
As if it wasn't already obvious, my opinions
are my own and not those of my employer.
*******************************************
"It is as useless to argue with those who have
renounced the use of reason as to administer
medication to the dead." Thomas Jefferson
"There are some ideas so wrong that only a very
intelligent person could believe in them." George Orwell
