can't read SMFIC_BODY reply packet header: Success

From: Rolf E. Sonneveld <R.E.Sonneveld_at_sonnection.nl>
Date: Fri, 25 Nov 2011 00:32:34 +0100

Hi, all,

for a customer I'm trying to debug a problem, where Postfix interfaces
with opendkim (tcp socket 9999 on localhost), but signing fails.

uname -a:
Linux vds.example.com 2.6.32-71.el6.x86_64 #1 SMP Fri May 20 03:51:51
BST 2011 x86_64 x86_64 x86_64 GNU/Linux

opendkim.conf settings:

AllowSHA1Only yes
AutoRestart Yes
Canonicalization relaxed/simple
Domain example.com,vds.example.com
InternalHosts /var/db/dkim/internal_hosts
KeyFile /var/db/dkim/vds.example.com.key.pem
LogWhy yes
Mode s
Selector mailout
SignatureAlgorithm rsa-sha256
Socket inet:9999_at_localhost
Syslog Yes
SyslogSuccess Yes
UserID dkim

Postfix settings:

smtpd_milters = inet:localhost:9999
non_smtpd_milters = inet:localhost:9999
milter_protocol = 2
milter_default_action = accept

I tried first without the milter_protocol in main.cf (so default is I
believe version 6), however with the same result.

In the maillog I see:

Nov 25 00:00:52 vds postfix/cleanup[19573]: 353FA18140D:
message-id=<201111242300.pAON0qli019568_at_vds.example.com>
Nov 25 00:00:52 vds postfix/cleanup[19573]: warning: milter
inet:localhost:9999: can't read SMFIC_BODY reply packet header: Success
Nov 25 00:00:52 vds opendkim[18165]: terminated with signal 6, restarting
Nov 25 00:00:52 vds opendkim[19574]: OpenDKIM Filter v2.4.2 starting
(args: -x /etc/opendkim.conf)
Nov 25 00:00:52 vds postfix/qmgr[18635]: 353FA18140D:
from=<root_at_vds.example.com>, size=709, nrcpt=1 (queue active)
Nov 25 00:00:52 vds postfix/smtpd[19569]: vstream_buf_get_ready: fd 17
got 18
Nov 25 00:00:52 vds postfix/smtpd[19569]: public/cleanup socket: wanted
attribute: status
Nov 25 00:00:52 vds postfix/smtpd[19569]: input attribute name: status
Nov 25 00:00:52 vds postfix/smtpd[19569]: input attribute value: 0
Nov 25 00:00:52 vds postfix/smtpd[19569]: public/cleanup socket: wanted
attribute: reason
Nov 25 00:00:52 vds postfix/smtpd[19569]: input attribute name: reason
Nov 25 00:00:52 vds postfix/smtpd[19569]: input attribute value: (end)
Nov 25 00:00:52 vds postfix/smtpd[19569]: public/cleanup socket: wanted
attribute: (list terminator)
Nov 25 00:00:52 vds postfix/smtpd[19569]: input attribute name: (end)
Nov 25 00:00:52 vds postfix/smtpd[19569]: > localhost[127.0.0.1]: 250
2.0.0 Ok: queued as 353FA18140D
Nov 25 00:00:52 vds postfix/smtpd[19569]: abort all milters
Nov 25 00:00:52 vds postfix/smtpd[19569]: milter8_abort: abort milter
inet:localhost:9999
Nov 25 00:00:52 vds postfix/smtpd[19569]: watchdog_pat: 0x7ff560f6b3a0
Nov 25 00:00:52 vds postfix/smtpd[19569]: vstream_fflush_some: fd 12
flush 37
Nov 25 00:00:52 vds sendmail[19568]: pAON0qli019568:
to=info_at_destinationaddress.com, ctladdr=root (0/0), delay=00:00:00,
xdelay=00:00:00, mailer=relay, pri=30217, relay=[127.0.0.1] [127.0.0.1],
dsn=2.0.0, stat=Sent (Ok: queued as 353FA18140D)
Nov 25 00:00:52 vds postfix/smtpd[19569]: vstream_buf_get_ready: fd 12 got 6
Nov 25 00:00:52 vds postfix/smtpd[19569]: < localhost[127.0.0.1]: QUIT
Nov 25 00:00:52 vds postfix/smtpd[19569]: > localhost[127.0.0.1]: 221
2.0.0 Bye
Nov 25 00:00:52 vds postfix/smtpd[19569]: match_hostname: localhost ~?
93.186.181.0/24
Nov 25 00:00:52 vds postfix/smtpd[19569]: match_hostaddr: 127.0.0.1 ~?
93.186.181.0/24
Nov 25 00:00:52 vds postfix/smtpd[19569]: match_hostname: localhost ~?
127.0.0.0/8
Nov 25 00:00:52 vds postfix/smtpd[19569]: match_hostaddr: 127.0.0.1 ~?
127.0.0.0/8
Nov 25 00:00:52 vds postfix/smtpd[19569]: abort all milters
Nov 25 00:00:52 vds postfix/smtpd[19569]: milter8_abort: abort milter
inet:localhost:9999
Nov 25 00:00:52 vds postfix/smtpd[19569]: disconnect event to all milters
Nov 25 00:00:52 vds postfix/smtpd[19569]: milter8_disc_event: quit
milter inet:localhost:9999
Nov 25 00:00:52 vds postfix/smtpd[19569]: vstream_fflush_some: fd 15
flush 15
Nov 25 00:00:52 vds postfix/smtpd[19569]: disconnect from
localhost[127.0.0.1]
Nov 25 00:00:52 vds postfix/smtpd[19569]: master_notify: status 1
Nov 25 00:00:52 vds postfix/smtpd[19569]: connection closed
Nov 25 00:00:53 vds postfix/smtp[19577]: 353FA18140D:
to=<info_at_destinationaddress.com>,
relay=mx2.somedomain.com[10.20.30.40]:25, delay=1,
delays=0.08/0.01/0.05/0.87, dsn=2.5.0, status=sent (250 2.5.0 Ok,
envelope id 0LV600560TAHJF00_at_mailhost2.somedomain.com)
Nov 25 00:00:53 vds postfix/qmgr[18635]: 353FA18140D: removed

What does:

warning: milter inet:localhost:9999: can't read SMFIC_BODY reply packet
header: Success

mean? Oh, BTW, 127.0.0.1 is in the internal_hosts file.

And does OpenDKIM crash and restart during this session? (it seems it does?)
A complete log can be sent on request, off-list.

/rolf
Received on Thu Nov 24 2011 - 23:27:55 PST

This archive was generated by hypermail 2.3.0 : Mon Oct 29 2012 - 23:20:21 PST