SMFIC errors in logs

[Nick Winn]

I am experiencing a high number of postfix SMFIC errors for every
milter I have installed (DKIM,DMARC,SPF). This problem persists with
postfix versions 2.6.6 and 3.0.1 on CentOS6. Has anyone else seen
these errors before and solved them?

Jun 15 18:47:36 mail-cluster1 postfix/cleanup[16080]: warning: milter
inet:localhost:8892: can't read SMFIC_HEADER reply packet header:
Success
Jun 15 20:58:31 mail-cluster1 postfix/smtpd[12242]: warning: milter
inet:localhost:8892: can't read SMFIC_MAIL reply packet header:
Success
Jun 15 20:58:32 mail-cluster1 postfix/smtpd[19545]: warning: milter
inet:localhost:8891: can't read SMFIC_RCPT reply packet header:
Success
Jun 15 20:58:32 mail-cluster1 postfix/smtpd[17699]: warning: milter
inet:localhost:8891: can't read SMFIC_RCPT reply packet header:
Success
Jun 15 20:58:32 mail-cluster1 postfix/cleanup[20340]: warning: milter
inet:localhost:8893: can't read SMFIC_HEADER reply packet header:
Broken pipe
Jun 15 20:58:32 mail-cluster1 postfix/smtpd[18181]: warning: milter
inet:localhost:8891: can't read SMFIC_MAIL reply packet header:
Success
Jun 15 20:58:32 mail-cluster1 postfix/cleanup[19600]: warning: milter
inet:localhost:8891: can't read SMFIC_HEADER reply packet header:
Success
Jun 15 20:58:32 mail-cluster1 postfix/cleanup[20062]: warning: milter
inet:localhost:8892: can't read SMFIC_HEADER reply packet header:
Broken pipe

I have tried the following items without success.

- Tried milter protocol 2 thru 6
- Changed milter timeouts to the following values
milter_connect_timeout = 600s
milter_command_timeout = 600s
milter_content_timeout = 1200s
- Upgraded postfix from version 2.6.6 to 3.0.1
- Was concerned it could be related to a high number of DNS request so
I installed unbound caching.
- Built from source latest libmilter and installed (8.15.1)

I am not sure what else I can try to resolve this problem. Any
suggestions or help is much appreciated.

Thanks!

-Nick

[Wietse Venema]

Nick Winn:

> I am experiencing a high number of postfix SMFIC errors for every
> milter I have installed (DKIM,DMARC,SPF). This problem persists with
> postfix versions 2.6.6 and 3.0.1 on CentOS6. Has anyone else seen
> these errors before and solved them?
>
> Jun 15 18:47:36 mail-cluster1 postfix/cleanup[16080]: warning: milter
> inet:localhost:8892: can't read SMFIC_HEADER reply packet header:
> Success

Does the problem go away with Selinux turned off?

Wietse

[Nick Winn]

SELinux is disabled and I am still seeing these errors.

This problem is driving me to drink...

--
---

Nick Winn

[A. Schulze]

Nick Winn:

> SELinux is disabled and I am still seeing these errors.

Nick,

such errors I saw years ago but not in current postfix releases.
Could you please send
- which milters do you use
- postconf -n and postconf -M

Andreas

[Nick Winn]

Hi Andreas

This is a list of all the milters and their version.

opendkim-2.10.3-1.el6.i686 (inet port 8891)
opendmarc-1.3.1-4.el6.i686 (inet port 8893)
pyspf (2.0.11) (inet port 8892)
and a home grown c binary that samples our mail stream (inet port 21718)

I've tried running postfix with just one and two milters running and
the errors still appear. The errors are sporatic and happen for every
milter installed.

The output of postconf -n is here:
http://paste.fedoraproject.org/232835/49232314/

The output of postconf -m is here:
http://paste.fedoraproject.org/232836/14344924/

Thank you for taking a look =)

-Nick

p/s I accidentally sent this direct to Andreas but wanted the list to
see this as well.

--
---

Nick Winn

[A. Schulze]

Nick Winn:

please keep on list...

> opendkim-2.10.3-1.el6.i686 (inet port 8891)
> opendmarc-1.3.1-4.el6.i686 (inet port 8893)
> pyspf (2.0.11) (inet port 8892)
> and a home grown c binary that samples our mail stream (inet port 21718)
>
> I've tried running postfix with just one and two milters running and
> the errors still appear. The errors are sporatic and happen for every
> milter installed.
>
> The output of postconf -n is here:
> http://paste.fedoraproject.org/232835/49232314/

you set many parameter to there defaults. I suggest to check every
single parameter
with "postconf -d $para". If you set explicit a default value,
consider removing the lines.

I guess your problem is "non_smtpd_milters".
read http://www.postfix.org/MILTER_README.html#limitations

Andreas

[Nick Winn]

I've removed all of the extras possible from my main.cf and am running
the most basic postfix config now.

Here is the output of postconf -n

https://paste.fedoraproject.org/234332/26834143/

I am still seeing the errors in the log files. =(

What should my next troubleshooting steps be?

Thanks in advance

-Nick

--
---

Nick Winn

[Viktor Dukhovni]

On Fri, Jun 19, 2015 at 09:15:51AM -0600, Nick Winn wrote:

> I've removed all of the extras possible from my main.cf and am running
> the most basic postfix config now.
>
> Here is the output of postconf -n
>
> https://paste.fedoraproject.org/234332/26834143/
>
> I am still seeing the errors in the log files. =(
>
> What should my next troubleshooting steps be?

If the milters use TCP and tcpdump works on the loopback interface,
or you have an O/S where tcpdump can capture traffic on unix-domain
sockets, get a capture of all the traffic between the Postfix client
and milter(s). Then try to determine what interaction leads to the
error messages.

--
Viktor.

[Wietse Venema]

Nick Winn:

> I've removed all of the extras possible from my main.cf and am running
> the most basic postfix config now.
>
> Here is the output of postconf -n
>
> https://paste.fedoraproject.org/234332/26834143/
>
> I am still seeing the errors in the log files. =(
>
> What should my next troubleshooting steps be?

As Viktor wrote, full packet recordings.

# tcpdump -s 0 -w /file/name -i interface port xxx

Where xxx is the port of the failing milter. I need to examine the
resulting file itself, not a printable "user friendly" version of
that file. Use direct email instead of the Postfix mailing list.

My money is on a buggy Milter program.

Wietse

[Nick Winn]

Wieste,

I appreciate your offer to take a look at a pcap but must decline due
to the sensitivity of the contents. I did take a look at some pcaps
and noticed tcp rst's were almost randomly being sent from different
milters to postfix causing the incomplete conversation leading to the
errors. I didn't spend much time digging around trying to find the
reason for the tcp rcts before I jumped ship and changed my mail
cluster to using unix sockets. Since the change i've not observed any
SMFIC errors in the maillog. This leads me to believe that the problem
is some where in the OS, possible something that could be ironed out
with tuning. I wish I had more to offer in terms of a cause /
solution, but for now my problems have been solved.

Thank you all for your time and advice =)

-Nick

--
---

Nick Winn