Path: ...!eternal-september.org!feeder2.eternal-september.org!news.eternal-september.org!.POSTED!not-for-mail
From: Wolfgang Agnes <wagnes@example.com>
Newsgroups: comp.mail.sendmail
Subject: dmarc=fail: sendmail, spf, dkim and opendmarc
Date: Tue, 12 Nov 2024 14:56:12 -0300
Organization: A noiseless patient Spider
Lines: 280
Message-ID: <8734jwnxoj.fsf@jemoni.to>
MIME-Version: 1.0
Content-Type: text/plain
Injection-Date: Tue, 12 Nov 2024 18:56:19 +0100 (CET)
Injection-Info: dont-email.me; posting-host="7220822d78a2549ef4cf4018bba013ff";
	logging-data="1811012"; mail-complaints-to="abuse@eternal-september.org";	posting-account="U2FsdGVkX19Y82PjCTxrmkOJNHAkehwSa6q5Kw9gWdU="
Cancel-Lock: sha1:ccFo5LgV/3A6nmJMPPaVgfM6oY4=
	sha1:7YSOtojXNSPsYstq2OUN6CxzWWs=
Bytes: 16827

I've been able to see my spf, dkim and opendmarc policy working with
SMTPs that are not my own.  My problem has been with the filters on my
own system.  Even though my SMTP seems to add the SPF header and the
DKIM headers, it seems that opendmarc on my system never seems satisfied
and so it seems to always fail every message I send out.  I describe my
entire system further below, but I think I should begin with the
symptoms first.  I appreciate any help on this.  Thanks!

(*) A test message sent to a remote site

%swaks --to someone@remote.site --from me@antartida.xyz \
  --auth CRAM-MD5 --auth-user me \
  --header-X-Test "test email" \
  --server antartida.xyz
Password: <secret>
=== Trying antartida.xyz:25...
=== Connected to antartida.xyz.
<-  220 antartida.xyz ESMTP Sendmail 8.18.1/8.18.1; Tue, 12 Nov 2024 14:34:50 -0300 (-03)
 -> EHLO antartida.xyz
<-  250-antartida.xyz Hello mx.antartida.xyz [195.88.57.140], pleased to meet you
<-  250-ENHANCEDSTATUSCODES
<-  250-PIPELINING
<-  250-8BITMIME
<-  250-SIZE
<-  250-DSN
<-  250-ETRN
<-  250-AUTH DIGEST-MD5 CRAM-MD5
<-  250-STARTTLS
<-  250-DELIVERBY
<-  250 HELP
 -> AUTH CRAM-MD5
<-  334 PDIxNTE2NjU4MTUuMzM3OTc0NUBhbnRhcnRpZGEueHl6Pg==
 -> ZGJhc3RvcyAyOGMzNzcyN2IzZWYxNDgzNDc1MzhmYTM4MjI1MjQyNQ==
<-  235 2.0.0 OK Authenticated
 -> MAIL FROM:<me@antartida.xyz>
<-  250 2.1.0 <me@antartida.xyz>... Sender ok
 -> RCPT TO:<someone@remote.site>
<-  250 2.1.5 <someone@.remote.site>... Recipient ok
 -> DATA
<-  354 End data with <CR><LF>.<CR><LF>
 -> Date: Tue, 12 Nov 2024 14:34:47 -0300
 -> To: someone@remote.site
 -> From: me@antartida.xyz
 -> Subject: test Tue, 12 Nov 2024 14:34:47 -0300
 -> Message-Id: <20241112143447.077593@antartida.xyz>
 -> X-Mailer: swaks v20240103.0 jetmore.org/john/code/swaks/
 -> X-Test: test email
 ->
 -> This is a test mailing
 ->
 ->
 -> .
<-  250 2.0.0 4ACHYoGx077594 Message accepted for delivery
 -> QUIT
<-  221 2.0.0 antartida.xyz closing connection
=== Connection closed with remote host.

(*) The local maillog 

This is long because I had LogLevel=15.  You'll see below that opendmarc
adds the authentication-results header with a failure, but the spf and
dkim headers appear to be correct.  I show these two relevant log lines
first and then I show the entire set of log lines in case it's useful.

--8<-------------------------------------------------------->8---
Nov 12 14:34:51 antartida opendmarc[53126]: 4ACHYoGx077594:
antartida.xyz fail

Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: Milter
(opendmarc) insert (1): header: Authentication-Results: antartida.xyz;
dmarc=fail (p=reject dis=none) header.from=antartida.xyz
--8<-------------------------------------------------------->8---

Now the entire SMTP session:

Nov 12 14:34:50 antartida sm-mta[77594]: NOQUEUE: connect from mx.antartida.xyz [195.88.57.140]
Nov 12 14:34:50 antartida sm-mta[77594]: AUTH: available mech=SCRAM-SHA-512 SCRAM-SHA-384 SCRAM-SHA-256 SCRAM-SHA-224 SCRAM-SHA-1 DIGEST-MD5 OTP CRAM-MD5 NTLM ANONYMOUS, allowed mech=GSSAPI DIGEST-MD5 CRAM-MD5 LOGIN PLAIN
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: Milter (spfmilter): init success to negotiate
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: Milter (dkim-filter): init success to negotiate
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: Milter (opendmarc): init success to negotiate
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: Milter: connect to filters
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=spfmilter, action=connect, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=dkim-filter, action=connect, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=opendmarc, action=connect, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 220 antartida.xyz ESMTP Sendmail 8.18.1/8.18.1; Tue, 12 Nov 2024 14:34:50 -0300 (-03)
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: <-- EHLO antartida.xyz
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=spfmilter, action=helo, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=opendmarc, action=helo, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-antartida.xyz Hello mx.antartida.xyz [195.88.57.140], pleased to meet you
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-ENHANCEDSTATUSCODES
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-PIPELINING
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-8BITMIME
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-SIZE
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-DSN
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-ETRN
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-AUTH DIGEST-MD5 CRAM-MD5
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-STARTTLS
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250-DELIVERBY
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250 HELP
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: <-- AUTH CRAM-MD5
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 334 PDIxNTE2NjU4MTUuMzM3OTc0NUBhbnRhcnRpZGEueHl6Pg==
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 235 2.0.0 OK Authenticated
Nov 12 14:34:50 antartida sm-mta[77594]: AUTH=server, relay=mx.antartida.xyz [195.88.57.140], authid=me, mech=CRAM-MD5, bits=0
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: <-- MAIL FROM:<me@antartida.xyz>
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: Milter: sender: <me@antartida.xyz>
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=spfmilter, action=mail, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=dkim-filter, action=mail, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: milter=opendmarc, action=mail, continue
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250 2.1.0 <me@antartida.xyz>... Sender ok
Nov 12 14:34:50 antartida sm-mta[77594]: 4ACHYoGx077594: <-- RCPT TO:<someone@remote.site>
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: Milter: rcpts: <someone@remote.site>
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=spfmilter, action=rcpt, continue
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=dkim-filter, action=rcpt, continue
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=opendmarc, action=rcpt, continue
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250 2.1.5 <someone@remote.site>... Recipient ok
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: <-- DATA
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: --- 354 End data with <CR><LF>.<CR><LF>
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: from=<me@antartida.xyz>, size=287, class=0, nrcpts=1, msgid=<20241112143447.077593@antartida.xyz>, proto=ESMTPA, daemon=IPv4, relay=mx.antartida.xyz [195.88.57.140]
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=spfmilter, action=header, continue
Nov 12 14:34:51 antartida syslogd: last message repeated 6 times
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=spfmilter, action=eoh, continue
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: Milter (spfmilter) insert (0): header: Received-SPF: pass (antartida.xyz: authenticated connection) receiver=antartida.xyz; client-ip=195.88.57.140; helo=antartida.xyz; envelope-from=me@antartida.xyz; x-software=spfmilter 2.001 http://www.acme.com/software/spfmilter/ with libspf2-1.2.11;
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=dkim-filter, action=header, continue
Nov 12 14:34:51 antartida syslogd: last message repeated 7 times
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=dkim-filter, action=eoh, continue
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=dkim-filter, action=body, continue
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: Milter (dkim-filter) insert (1): header: DKIM-Signature:  v=1; a=rsa-sha256; c=relaxed/simple; d=antartida.xyz;\n\ts=default; t=1731432891;\n\tbh=ecGWgWCJeWxJFeM0urOVWP+KOlqqvsQYKOpYUP8nk7I=;\n\th=Date:To:From:Subject;\n\tb=IDOMq8KnwMb7bgpeMGJOuiW/i9PbmFi9UE4df2u07P6agEeuGAbzepdq9tUmYc5w8\n\t gv5J9u2x8iALPN/6TEzVuDLBhhLfO8XCpWcuK+i5fLKKajo5cpGNVkoMI0cB36zCO3\n\t AwH/wK5f2K8YOgUbQbHYZQBLDdneC1Cp45wYmK0o=
Nov 12 14:34:51 antartida opendkim[35443]: 4ACHYoGx077594: DKIM-Signature field added (s=default, d=antartida.xyz)
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=opendmarc, action=header, continue
Nov 12 14:34:51 antartida syslogd: last message repeated 8 times
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: milter=opendmarc, action=eoh, continue
Nov 12 14:34:51 antartida opendmarc[53126]: 4ACHYoGx077594: antartida.xyz fail
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: Milter (opendmarc) insert (1): header: Authentication-Results: antartida.xyz; dmarc=fail (p=reject dis=none) header.from=antartida.xyz
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: Milter accept: message
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoGx077594: --- 250 2.0.0 4ACHYoGx077594 Message accepted for delivery
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoH0077594: <-- QUIT
Nov 12 14:34:51 antartida sm-mta[77594]: 4ACHYoH0077594: --- 221 2.0.0 antartida.xyz closing connection
Nov 12 14:34:51 antartida sm-mta[77596]: 4ACHYoGx077594: --- 050 <someone@remote.site>... Connecting to aspmx.l.google.com. via esmtp...
Nov 12 14:34:51 antartida sm-mta[77596]: 4ACHYoGx077594: makeconnection (aspmx.l.google.com. [IPv6:2607:f8b0:400c:c36:0:0:0:1b].25 (28)) failed: No route to host
Nov 12 14:34:51 antartida sm-mta[77596]: 4ACHYoGx077594: SMTP outgoing connect on mx.antartida.xyz
Nov 12 14:34:51 antartida sm-mta[77596]: STARTTLS: CRLFile missing
Nov 12 14:34:51 antartida sm-mta[77596]: STARTTLS=client, init=1
Nov 12 14:34:51 antartida sm-mta[77596]: tls_clt_features=(null), relay=aspmx.l.google.com [74.125.139.26]
Nov 12 14:34:51 antartida sm-mta[77596]: tls_clt_features=empty, stat=0, relay=aspmx.l.google.com [74.125.139.26]
Nov 12 14:34:51 antartida sm-mta[77596]: STARTTLS=client, start=ok
Nov 12 14:34:51 antartida sm-mta[77596]: STARTTLS=client, info: fds=8/5, err=2
Nov 12 14:34:51 antartida sm-mta[77596]: STARTTLS: TLS cert verify: depth=2 /C=US/O=Google Trust Services LLC/CN=GTS Root R1, state=0, reason=unable to get issuer certificate
Nov 12 14:34:52 antartida sm-mta[77596]: STARTTLS=client, get_verify: 2 get_peer: 0x37afc4c39780
Nov 12 14:34:52 antartida sm-mta[77596]: STARTTLS=client, relay=aspmx.l.google.com., version=TLSv1.3, verify=FAIL, cipher=TLS_AES_256_GCM_SHA384, bits=256/256
Nov 12 14:34:52 antartida sm-mta[77596]: STARTTLS=client, cert-subject=/CN=mx.google.com, cert-issuer=/C=US/O=Google+20Trust+20Services/CN=WR2, verifymsg=unable to get issuer certificate
Nov 12 14:34:52 antartida sm-mta[77596]: STARTTLS=read, info: fds=8/5, err=2
Nov 12 14:34:52 antartida syslogd: last message repeated 4 times
Nov 12 14:34:52 antartida sm-mta[77596]: 4ACHYoGx077594: --- 050 <someone@remote.site>... Sent (OK  1731432897 ada2fe7eead31-4aaa7bac85asi3247497137.420 - gsmtp)
Nov 12 14:34:52 antartida sm-mta[77596]: 4ACHYoGx077594: to=<someone@remote.site>, ctladdr=<me@antartida.xyz> (1003/0), delay=00:00:01, xdelay=00:00:01, mailer=esmtp, pri=30287, relay=aspmx.l.google.com. [74.125.139.26], dsn=2.0.0, stat=Sent (OK  1731432897 ada2fe7eead31-4aaa7bac85asi3247497137.420 - gsmtp)
Nov 12 14:34:52 antartida sm-mta[77596]: 4ACHYoGx077594: done; delay=00:00:01, ntries=1
Nov 12 14:34:52 antartida sm-mta[77596]: NOQUEUE: --- 050 Closing connection to aspmx.l.google.com.
Nov 12 14:34:52 antartida sm-mta[77596]: STARTTLS=read, info: fds=8/5, err=2
Nov 12 14:34:52 antartida sm-mta[77596]: STARTTLS=client, SSL_shutdown failed: -1

(*) What opendmarc notices

You'll see in my opendmarc configuration below that I'm using a
history.txt file for debugging purposes.  In history.txt, relative to
the test message above, I find in history.txt:

job 4ACHYoGx077594
reporter antartida.xyz
received 1731432891
ipaddr 195.88.57.140
from antartida.xyz
mfrom antartida.xyz
spf 3
pdomain antartida.xyz
policy 16
rua mailto:postmaster@antartida.xyz
pct 100
adkim 115
aspf 115
p 114
sp 0
align_dkim 5
align_spf 5
arc 7
========== REMAINDER OF ARTICLE TRUNCATED ==========