Re: Puzzling problem
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
Re: Puzzling problem
Thursday, January 9, 2014, 10:31:30 AM, you wrote: 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 ? That is a warning from SpamAssassin stating 127.0.0.0/32 is already included as an internal network. Therefore, the OP should remove the internal network configuration option from the SpamAssassin config. -- Best regards, Duanemailto:duih...@gmail.com
Re: Puzzling problem
--On January 9, 2014 at 11:31:30 AM +0100 Marko Weber | ZBF we...@zackbummfertig.de wrote: 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 a bug in the NetAddr::IP Perl module that's affecting spamassassin. Cf. https://issues.apache.org/SpamAssassin/show_bug.cgi?id=6681 In reviewing my mail logs, it appears that every time that bug manifests itself, the mail is rejected, so that looks like the path I need to go down. Not sure why it's being triggered every time the form mail arrives, but I'm going to try constructing proper email headers for the message before sending it to see if that resolves the issue. -- 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
Re: Puzzling problem
--On January 9, 2014 at 11:00:30 AM + Duane Hill duih...@gmail.com wrote: Thursday, January 9, 2014, 10:31:30 AM, you wrote: 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 ? That is a warning from SpamAssassin stating 127.0.0.0/32 is already included as an internal network. Therefore, the OP should remove the internal network configuration option from the SpamAssassin config. Thanks. That solved the problem. -- 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
Re: Puzzling problem
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
