Hello,
Murray S. Kucherawy --> dkim-milter-discuss (2008-04-10 16:27:17 -0700):
> Make the attached patch to libmilter, rebuild your library and then
> relink dkim-filter, and let 'er rip. This will log a message for every
> piece of I/O between the filter and the MTA so the increase in your mail
> log could be substantial, and will also log a message if a milter
> callback returns a non-standard value (which skips the reply, which may
> be the problem). Unfortunately it looks like this is the best next step
> to isolating the problem.
>
> Talk to you in about a week, right? :-)
a week and a day later the (probably same) problem happened on my
secondary MX (mx2); previously it only happened on my primary MX (mx1).
The first attachment (maillog.mx2) contains the relevant part of mx2's
mail log. The message in question failed to be delivered, and 20 minutes
later the sending MTA tried again and successfully delivered the message
to mx1. The relevant part of that communication is what's in the second
attachment (mx1).
Both times dkim-milter fails to parse an Authentication-Results header.
The message finally delivered to mx1 had the following headers:
X-DomainKeys: Sendmail DomainKeys Filter v1.0.0 mx1.salmi.ch 0BCA624C7E
Authentication-Results: mx1.salmi.ch; domainkeys=pass (testing) [EMAIL
PROTECTED]
I'm running dk-milter just before running dkim-milter on both system...
Please tell if I should provide more information.
Regards, Jukka
--
bashian roulette:
$ ((RANDOM%6)) || rm -rf ~
Apr 17 21:41:30 urchin postfix/smtpd[26876]: warning: 64.207.133.135: address
not listed for hostname mail1.darfurgenocide.org
Apr 17 21:41:30 urchin postfix/smtpd[26876]: connect from
unknown[64.207.133.135]
Apr 17 21:41:30 urchin dkim-milter[120]: mi_rd_cmd(79) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: mi_wr_cmd(79) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status 20 in state 1
Apr 17 21:41:30 urchin dkim-milter[120]: mi_rd_cmd(67) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 2
Apr 17 21:41:30 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 2
Apr 17 21:41:30 urchin dkim-milter[120]: mi_rd_cmd(77) on fd 8
Apr 17 21:41:30 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:30 urchin postfix/smtpd[26876]: A9B52AA2B:
client=unknown[64.207.133.135]
Apr 17 21:41:31 urchin postfix/cleanup[26947]: A9B52AA2B: message-id=<[EMAIL
PROTECTED]>
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 4
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(76) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status 20 in state 7
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status -1 in state 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(66) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(99) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: mi_rd_cmd(68) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: Sendmail DKIM Filter: milter returned
bogus status 20 in state 9
Apr 17 21:41:32 urchin dkim-milter[120]: A9B52AA2B failed to parse
Authentication-Results: header
Apr 17 21:41:32 urchin postfix/cleanup[26947]: warning: milter
inet:localhost:1026: can't read SMFIC_BODYEOB reply packet header: Undefined
error: 0
Apr 17 21:41:32 urchin postfix/cleanup[26947]: A9B52AA2B: milter-reject:
END-OF-MESSAGE from unknown[64.207.133.135]: 4.7.1 Service unavailable - try
again later; from=<[...]> to=<[...]> proto=ESMTP helo=<mail4.avaaz.org>
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(105) on fd 8
Apr 17 21:41:32 urchin dkim-milter[120]: A9B52AA2B "X-DKIM" header add failed
Apr 17 21:41:32 urchin dkim-milter[120]: mi_wr_cmd(116) on fd 8
Apr 17 21:41:37 urchin postfix/smtpd[26876]: disconnect from
unknown[64.207.133.135]
Apr 17 22:01:33 grouper postfix/smtpd[11113]: warning: 64.207.133.135: address
not listed for hostname mail1.darfurgenocide.org
Apr 17 22:01:33 grouper postfix/smtpd[11113]: connect from
unknown[64.207.133.135]
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_rd_cmd(79) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_wr_cmd(79) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status 20 in state 1
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_rd_cmd(67) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 2
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 2
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_rd_cmd(77) on fd 4
Apr 17 22:01:33 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:34 grouper postfix/smtpd[11113]: 0BCA624C7E:
client=unknown[64.207.133.135]
Apr 17 22:01:34 grouper postfix/cleanup[1602]: 0BCA624C7E: message-id=<[EMAIL
PROTECTED]>
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(76) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status 20 in state 7
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 8
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(66) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(99) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status 20 in state 9
Apr 17 22:01:35 grouper dkim-milter[11973]: 0BCA624C7E failed to parse
Authentication-Results: header
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(105) on fd 4
Apr 17 22:01:35 grouper dkim-milter[11973]: mi_wr_cmd(97) on fd 4
Apr 17 22:01:35 grouper postfix/qmgr[28820]: 0BCA624C7E: from=<[...]>,
size=7740, nrcpt=1 (queue active)
Apr 17 22:01:35 grouper postfix/lmtp[26198]: 0BCA624C7E: to=<[...]>,
orig_to=<[...]>, relay=mx1.salmi.ch[/sockets/lmtp/sock], delay=1.9,
delays=1.9/0/0/0.01, dsn=2.1.5, status=sent (250 2.1.5 Ok)
Apr 17 22:01:35 grouper postfix/qmgr[28820]: 0BCA624C7E: removed
Apr 17 22:01:40 grouper dkim-milter[11973]: mi_rd_cmd(68) on fd 4
Apr 17 22:01:40 grouper postfix/smtpd[11113]: disconnect from
unknown[64.207.133.135]
Apr 17 22:01:40 grouper dkim-milter[11973]: Sendmail DKIM Filter: milter
returned bogus status -1 in state 10
-------------------------------------------------------------------------
This SF.net email is sponsored by the 2008 JavaOne(SM) Conference
Don't miss this year's exciting event. There's still time to save $100.
Use priority code J8TL2D2.
http://ad.doubleclick.net/clk;198757673;13503038;p?http://java.sun.com/javaone
_______________________________________________
dkim-milter-discuss mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/dkim-milter-discuss
