postfix-policyd-spf-perl

DUNNO when it should be pass, tested against spfquery and manual SPF reading

Asked by PoundTeam Incorporated

root@mail:/usr/sbin# /usr/sbin/postfix-policyd-spf-perl
request=smtpd_access_policy
protocol_state=RCPT
protocol_name=SMTP
helo_name=mail.etsy.com
queue_id=85798375987
instance=71b0.45e2f5f1.d4da1.0
<email address hidden>
<email address hidden>
client_address=38.106.64.78

action=PREPEND Received-SPF: pass (mail.etsy.com: 38.106.64.78 is authorized to use '<email address hidden>' in 'mfrom' identity (mechanism 'ip4:38.106.64.64/28' matched)) receiver=mail.skpro.com; identity=mailfrom; <email address hidden>"; helo=mail.etsy.com; client-ip=38.106.64.78

request=smtpd_access_policy
protocol_state=RCPT
protocol_name=SMTP
helo_name=mail.etsy.com
queue_id=85798375987
instance=71b0.45e2f5f1.d4da1.0
<email address hidden>
<email address hidden>
client_address=38.106.64.78

action=DUNNO

===========
two in a row, different results.
===========

/var/mail/log with verbose=1:

Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: client_address=38.106.64.78
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: helo_name=mail.etsy.com
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: instance=71b0.45e2f5f1.d4da1.0
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: protocol_name=SMTP
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: protocol_state=RCPT
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: queue_id=85798375987
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: <email address hidden>
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: request=smtpd_access_policy
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Attribute: <email address hidden>
Mar 6 21:13:49 mail postfix/policy-spf[14115]: handler exempt_localhost: DUNNO
Mar 6 21:13:49 mail postfix/policy-spf[14115]: handler exempt_relay: DUNNO
Mar 6 21:13:49 mail postfix/policy-spf[14115]: SPF pass (Mechanism 'ip4:38.106.64.64/28' matched): HELO/EHLO: mail.etsy.com, IP Address: 38.106.64.78, Recipient: <email address hidden>
Mar 6 21:13:49 mail postfix/policy-spf[14115]: SPF pass (Mechanism 'ip4:38.106.64.64/28' matched): Envelope-from: <email address hidden>, IP Address: 38.106.64.78, Recipient: <email address hidden>
Mar 6 21:13:49 mail postfix/policy-spf[14115]: SPF pass (Mechanism 'ip4:38.106.64.64/28' matched): Envelope-from: <email address hidden>
Mar 6 21:13:49 mail postfix/policy-spf[14115]: handler sender_policy_framework: PREPEND Received-SPF: pass (mail.etsy.com: 38.106.64.78 is authorized to use '<email address hidden>' in 'mfrom' identity (mechanism 'ip4:38.106.64.64/28' matched)) receiver=mail.skpro.com; identity=mailfrom; <email address hidden>"; helo=mail.etsy.com; client-ip=38.106.64.78
Mar 6 21:13:49 mail postfix/policy-spf[14115]: handler sender_policy_framework: is decisive.
Mar 6 21:13:49 mail postfix/policy-spf[14115]: Policy action=PREPEND Received-SPF: pass (mail.etsy.com: 38.106.64.78 is authorized to use '<email address hidden>' in 'mfrom' identity (mechanism 'ip4:38.106.64.64/28' matched)) receiver=mail.skpro.com; identity=mailfrom; <email address hidden>"; helo=mail.etsy.com; client-ip=38.106.64.78

Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: client_address=38.106.64.78
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: helo_name=mail.etsy.com
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: instance=71b0.45e2f5f1.d4da1.0
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: protocol_name=SMTP
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: protocol_state=RCPT
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: queue_id=85798375987
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: <email address hidden>
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: request=smtpd_access_policy
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Attribute: <email address hidden>
Mar 6 21:13:53 mail postfix/policy-spf[14115]: handler exempt_localhost: DUNNO
Mar 6 21:13:53 mail postfix/policy-spf[14115]: handler exempt_relay: DUNNO
Mar 6 21:13:53 mail postfix/policy-spf[14115]: SPF pass (Mechanism 'ip4:38.106.64.64/28' matched): HELO/EHLO: mail.etsy.com, IP Address: 38.106.64.78, Recipient: <email address hidden>
Mar 6 21:13:53 mail postfix/policy-spf[14115]: SPF pass (Mechanism 'ip4:38.106.64.64/28' matched): Envelope-from: <email address hidden>, IP Address: 38.106.64.78, Recipient: <email address hidden>
Mar 6 21:13:53 mail postfix/policy-spf[14115]: SPF pass (Mechanism 'ip4:38.106.64.64/28' matched): Envelope-from: <email address hidden>
Mar 6 21:13:53 mail postfix/policy-spf[14115]: handler sender_policy_framework: <UNKNOWN>
Mar 6 21:13:53 mail postfix/policy-spf[14115]: Policy action=DUNNO

========
Terminating and restarting the app seems to fix the problem. No record of failed lookup which would explain the DUNNO response. Plus: How is there a "Mechanism" to check against if the SPF lookup failed. If the SPF pass is true .. where's that DUNNO coming from?

Ordinarily, I'd say that it's just not expected to continue to run ... BUT there was a rejection for an email from mail.etsy.com that brought me here, and according to this tool (and the spfquery tool also available) it should have passed.
========
root@mail:/usr/sbin# spfquery -i 38.106.64.78 -s <email address hidden>
pass
spfquery: domain of etsy.com designates 38.106.64.78 as permitted sender
Received-SPF: pass (spfquery: domain of etsy.com designates 38.106.64.78 as permitted sender) client-ip=38.106.64.78; <email address hidden>;

root@mail:/usr/sbin# spfquery -i 38.106.64.78 -s <email address hidden>
pass
spfquery: domain of mail.etsy.com designates 38.106.64.78 as permitted sender
Received-SPF: pass (spfquery: domain of mail.etsy.com designates 38.106.64.78 as permitted sender) client-ip=38.106.64.78; <email address hidden>;

Question information

Language:
English Edit question
Status:
Solved
For:
postfix-policyd-spf-perl Edit question
Assignee:
No assignee Edit question
Solved by:
PoundTeam Incorporated
Solved:
Last query:
Last reply:
Revision history for this message
Scott Kitterman (kitterman) said : 		#1

Postfix, by default, does the policy checks at recpt to. It runs once per recipient.

What's supposed to be happening is that for the first recipient the header is prepended and for subsequent recipients the result is dunno (which is the equivalent of passing) so that multiple copies of the header aren't included for multi-recipient mail. Since in your example the queue ID and instance are identical it's treated as part of the same message.

If you're running this by hand, which I think you are, change the instance value and I believe it'll prepend again since it thinks it's a different message.

Revision history for this message
PoundTeam Incorporated (6o-ubuntu) said : 		#2

Bummer. That means I have NO idea why it failed during the receipt of the mail that brought me to that troubleshooting run in the first place.

Guess I'll wait for another one (now that I have VERBOSE logging in place.

Thank you for the very thorough explanation!

I'll come back when I have a problem I can prove. LOL