[milters] Archive

Lists Index Date Thread Search

Article: 2801
From: Anders Nilsson
Date: 2012-01-24 10:49:02 -0500
Subject: milter-spiff - SPF result TempError: internal error

Hi,

A strange TempError sometimes occurs for milter-spiff for certain domains.
It seems to be a permanent problem for the sending domain.

Example of sendmail log entry:
Jan 24 11:57:14 hs2 sm-acceptingconnections[7736]: q0OAvEQC007736:
Milter: to=<receiver@domain.com>, reject=451 4.4.3 sender
<sender@telefonica.net> via 213.4.138.21 SPF result TempError:
internal error

I have tried DNS lookups by dig, host, com/snert/src/lib/net/pdq and
com/snert/src/lib/mail/spf for the domains in question and all
performs without error and pass the SPF checks. So the DNS on the
server seems to be working ok. Dns requests on the server are
forwarded from 2 resolvers.

I activated the verbose logging and include an example of the error below.
The whole log for the mail is probably to long to include.
The row:
Jan 24 11:57:15 hs2 milter-spiff[3205]: exit  spfCheck(b6bb303c,
telefonica.net, '(NULL)') result=TempError error=internal error
Seems interesting. But it's unclear to me why the error occurs.
---
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=43:"milter-spiff-from:sender@telefonica.net" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=32:"milter-spiff-from:telefonica.net" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=21:"milter-spiff-from:net" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=29:"milter-spiff-from:sender@" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=18:"milter-spiff-from:" value="" rc=-2
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=30:"from:sender@telefonica.net" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=19:"from:telefonica.net" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access" key=8:"from:net"
value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=16:"from:sender@" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: enter spfCheck(b6bb303c,
telefonica.net, '(NULL)') ip=213.4.138.21 helo=telefonica.net
mail=sender@telefonica.net
Jan 24 11:57:15 hs2 milter-spiff[3205]: pdqOpen() pdq=92be770
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=40410 IN TXT   telefonica.net
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=40410 rcode=0
length=327 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=40410 an=1 ns=2 ar=2 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=40410 IN TXT   telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=40410 IN NS    telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=40410 IN NS    telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=40410 IN A     dns1.terra.es.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=40410 IN A     dns2.terra.es.
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x92bffe0 ms=3000
pending=0 errno=0 0.002189949
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x92bffe0 0.002207880
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 23676 IN TXT
"v=spf1 mx ptr:mailhost.telefonica.net mx:mx.dominios.telefonica.net
+a:spf.telefonica.net ip4:213.4.128.121 ip4:213.4.129.0/24
ip4:213.4.134.0/24 ip4:213.4.138.0/24 ip4:213.4.140.7
ip4:213.4.149.0/24 ?all" ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 16898 IN NS
dns1.terra.es. ; AUTHORITY
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 16898 IN NS
dns2.terra.es. ; AUTHORITY
Jan 24 11:57:15 hs2 milter-spiff[3205]: dns1.terra.es. 11003 IN A
213.4.132.1 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: dns2.terra.es. 11003 IN A
213.4.141.1 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: domain=telefonica.net
TXT=v=spf1 mx ptr:mailhost.telefonica.net
mx:mx.dominios.telefonica.net +a:spf.telefonica.net ip4:213.4.128.121
ip4:213.4.129.0/24 ip4:213.4.134.0/24 ip4:213.4.138.0/24
ip4:213.4.140.7 ip4:213.4.149.0/24 ?all
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=14143 IN MX    telefonica.net
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=14143 rcode=0
length=149 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=14143 an=1 ns=2 ar=3 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=14143 IN MX    telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=14143 IN NS    telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=14143 IN NS    telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=14143 IN A
tnetmx.telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=14143 IN A     dns1.terra.es.
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=14143 IN A     dns2.terra.es.
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x92c0128 ms=3000
pending=0 errno=0 0.001839208
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x92c0128 0.001856705
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=58181 IN AAAA
tnetmx.telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=58181 rcode=0
length=39 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=58181 an=0 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x0 ms=3000 pending=0
errno=0 0.001839451
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x0 0.001857985
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 22958 IN MX
100 tnetmx.telefonica.net. ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 16898 IN NS
dns1.terra.es. ; AUTHORITY
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 16898 IN NS
dns2.terra.es. ; AUTHORITY
Jan 24 11:57:15 hs2 milter-spiff[3205]: tnetmx.telefonica.net. 22958
IN A 213.4.149.227 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: dns1.terra.es. 11003 IN A
213.4.132.1 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: dns2.terra.es. 11003 IN A
213.4.141.1 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 22958 IN MX
100 tnetmx.telefonica.net. ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 16898 IN NS
dns1.terra.es. ; AUTHORITY
Jan 24 11:57:15 hs2 milter-spiff[3205]: telefonica.net. 16898 IN NS
dns2.terra.es. ; AUTHORITY
Jan 24 11:57:15 hs2 milter-spiff[3205]: tnetmx.telefonica.net. 22958
IN A 213.4.149.227 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: dns1.terra.es. 11003 IN A
213.4.132.1 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: dns2.terra.es. 11003 IN A
213.4.141.1 ; EXTRA
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=6121  IN PTR
21.138.4.213.in-addr.arpa.
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=6121 rcode=0
length=79 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=6121 an=1 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=6121  IN PTR
21.138.4.213.in-addr.arpa.
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x92c0128 ms=3000
pending=0 errno=0 0.001770395
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x92c0128 0.001788676
Jan 24 11:57:15 hs2 milter-spiff[3205]: 21.138.4.213.in-addr.arpa.
81276 IN PTR impaqm5.telefonica.net. ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=62934 IN A
impaqm5.telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=4906  IN AAAA
impaqm5.telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=62934 rcode=0
length=168 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=4906 rcode=0
length=40 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=4906 an=0 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=62934 an=8 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=62934 IN A
impaqm5.telefonica.net.
Jan 24 11:57:15 hs2 last message repeated 7 times
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x92c0350 ms=3000
pending=0 errno=0 0.002059937
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x92c0350 0.002079567
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.138.21 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.138.13 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.138.5 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.129.33 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.129.25 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.129.20 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.138.37 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: impaqm5.telefonica.net. 16898
IN A 213.4.138.29 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: ptr=impaqm5.telefonica.net.
target=mailhost.telefonica.net
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=15097 IN MX
mx.dominios.telefonica.net
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=15097 rcode=0
length=107 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=15097 an=0 ns=1 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=15097 IN SOA   telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x92c0128 ms=3000
pending=0 errno=0 0.001653951
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x92c0128 0.001672063
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=37570 IN A
mx.dominios.telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=50364 IN AAAA
mx.dominios.telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=37570 rcode=0
length=60 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=50364 rcode=0
length=44 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=50364 an=0 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=37570 an=1 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: answer id=37570 IN A
mx.dominios.telefonica.net.
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x92c0130 ms=3000
pending=0 errno=0 0.001937626
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x92c0130 0.001954827
Jan 24 11:57:15 hs2 milter-spiff[3205]: mx.dominios.telefonica.net. 0
IN MX 0 mx.dominios.telefonica.net. ; UNKNOWN
Jan 24 11:57:15 hs2 milter-spiff[3205]: mx.dominios.telefonica.net.
23676 IN A 213.4.149.229 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: mx.dominios.telefonica.net. 0
IN MX 0 mx.dominios.telefonica.net. ; UNKNOWN
Jan 24 11:57:15 hs2 milter-spiff[3205]: mx.dominios.telefonica.net.
23676 IN A 213.4.149.229 ; ANSWER
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=35318 IN A
spf.telefonica.net
Jan 24 11:57:15 hs2 milter-spiff[3205]: > query id=56634 IN AAAA
spf.telefonica.net
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=35318 rcode=0
length=36 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: < recv id=56634 rcode=0
length=36 from=192.168.1.1
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=56634 an=0 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: header id=35318 an=0 ns=0 ar=0 rcode=OK
Jan 24 11:57:15 hs2 milter-spiff[3205]: poll rc=0x0 ms=3000 pending=0
errno=0 0.001837370
Jan 24 11:57:15 hs2 milter-spiff[3205]: wait rc=0x0 0.001855440
Jan 24 11:57:15 hs2 milter-spiff[3205]: exit  spfCheck(b6bb303c,
telefonica.net, '(NULL)') result=TempError error=internal error
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=36:"milter-spiff-to:receiver@domain.com" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=29:"milter-spiff-to:domain.com" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=18:"milter-spiff-to:com" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=23:"milter-spiff-to:receiver@" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=16:"milter-spiff-to:" value="" rc=-2
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=25:"spam:receiver@domain.com" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=18:"spam:domain.com" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access" key=7:"spam:com"
value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=12:"spam:receiver@" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=23:"to:receiver@domain.com" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=16:"to:domain.com" value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access" key=5:"to:com"
value=""
Jan 24 11:57:15 hs2 milter-spiff[3205]: map="access"
key=10:"to:receiver@" value=""
Jan 24 11:57:15 hs2 sm-acceptingconnections[7736]: q0OAvEQC007736:
Milter: to=<receiver@domain.com>, reject=451 4.4.3 sender
<sender@telefonica.net> via 213.4.138.21 SPF result TempError:
internal error
Jan 24 11:57:15 hs2 sm-acceptingconnections[7736]: q0OAvEQC007736:
from=<sender@telefonica.net>, size=243334, class=0, nrcpts=0,
proto=ESMTP, daemon=MTA, relay=impaqm5.telefonica.net [213.4.138.21]

---
Software:
OS: CentOS release 5 (Final)
Sendmail 8.13.8
milter-spiff 0.15.33
libsnert 1.70.10

The socket config info from milter-spiff.mc
---
INPUT_MAIL_FILTER(
        `milter-spiff',
        `S=unix:/var/run/milter/milter-spiff.socket, T=C:10s;S:10s;R:10s;E:20s'
)dnl
---

Settings from /etc/mail/milter-spiff.cf
---
dns-max-timeout=45
-spf-temp-error-dns
---

Let me know if you need more info.

Questions.
1. Can you see why this problem occurs, and what we can do to fix it?
2. I noticed that an A query for spf.telefonica.net doesn't give an answer.
If that is the problem, can we ignore this and continue the checks
instead of giving the TempError?
3. Is there a way to make the email pass the spf checks if a TempError
occurs instead of bouncing it with a 451 error message?
I couldn't find any configuration for that.

Anders

Lists Index Date Thread Search