Hello,
Am 2014-01-09 05:26, schrieb Seann:
Paul,
First thing that caught my eye, is it looks like the reason for the
bounce was the filter shell script died:
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
That is based on this line in your logs:
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 )
Does the email send with that filter removed for testing, if possible?
It really looks like it is dying in the Filter.sh script, based on the
logs you are showing.
Since I don't know what that shell script is doing, I can't say much
on it, but an educated guess is there is something being injected into
the headers of the email message that your filter script doesn't like.
Regards,
Seann
On 1/8/2014 10:11 PM, Paul Schmehl wrote:
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
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
I am not a network Pro, but 127.0.0.0 is the first available address,
and is reserved , also the last one 127.0.0.255 is reserved. (broadcast)
so, for me it has to be 127.0.0.1/32 for the first usable address and
172.0.0.0/8 if you plan to use a wider range.
warn: netset: illegal network <---- ! i think its bcause u used
127.0.0.0/32.
can u give it a try with 127.0.0.1/32 ?
marko
