git » chasquid » commit d74e6e3

diff --git a/internal/courier/mda.go b/internal/courier/mda.go
index 6898469..b94bbbb 100644
--- a/internal/courier/mda.go
+++ b/internal/courier/mda.go
@@ -71,7 +71,8 @@ func (p *MDA) Deliver(from string, to string, data []byte) (error, bool) {
 
 	output, err := cmd.CombinedOutput()
 	if ctx.Err() == context.DeadlineExceeded {
-		return tr.Error(errTimeout), false
+		return tr.Errorf("local delivery failed: %w after %v",
+			errTimeout, p.Timeout), false
 	}
 
 	if err != nil {
@@ -84,7 +85,10 @@ func (p *MDA) Deliver(from string, to string, data []byte) (error, bool) {
 				permanent = status.ExitStatus() != 75
 			}
 		}
-		err = tr.Errorf("MDA delivery failed: %w - %q", err, string(output))
+		// Include the output, as it usually contains the reason for the
+		// failure. Quote it, as it can contain arbitrary characters.
+		err = tr.Errorf("local delivery failed: %w (output: %q)",
+			err, strings.TrimSpace(string(output)))
 		return err, permanent
 	}
 
diff --git a/internal/courier/mda_test.go b/internal/courier/mda_test.go
index 7b21c64..fba9cb3 100644
--- a/internal/courier/mda_test.go
+++ b/internal/courier/mda_test.go
@@ -33,7 +33,7 @@ func TestMDATimeout(t *testing.T) {
 	p := MDA{"sleep", []string{"1"}, 100 * time.Millisecond}
 
 	err, permanent := p.Deliver("from", "to@local", []byte("data"))
-	if err != errTimeout {
+	if !errors.Is(err, errTimeout) {
 		t.Errorf("Unexpected error: %v", err)
 	}
 	if permanent {
diff --git a/internal/courier/smtp.go b/internal/courier/smtp.go
index 0af630a..9886ba1 100644
--- a/internal/courier/smtp.go
+++ b/internal/courier/smtp.go
@@ -74,19 +74,23 @@ func (s *SMTP) Deliver(from string, to string, data []byte) (error, bool) {
 	}
 
 	mxs, err, perm := lookupMXs(a.tr, a.toDomain)
-	if err != nil || len(mxs) == 0 {
+	if err != nil {
+		return a.tr.Errorf("error looking up mail servers for %q: %w",
+			a.toDomain, err), perm
+	}
+	if len(mxs) == 0 {
 		// Note this is considered a permanent error.
 		// This is in line with what other servers (Exim) do. However, the
 		// downside is that temporary DNS issues can affect delivery, so we
 		// have to make sure we try hard enough on the lookup above.
-		return a.tr.Errorf("Could not find mail server: %v", err), perm
+		return a.tr.Errorf("no mail servers found for %q", a.toDomain), true
 	}
 
 	a.stsPolicy = s.fetchSTSPolicy(a.tr, a.toDomain)
 
 	for _, mx := range mxs {
 		if a.stsPolicy != nil && !a.stsPolicy.MXIsAllowed(mx) {
-			a.tr.Printf("%q skipped as per MTA-STA policy", mx)
+			a.tr.Printf("%q skipped as per MTA-STS policy", mx)
 			continue
 		}
 
@@ -101,8 +105,17 @@ func (s *SMTP) Deliver(from string, to string, data []byte) (error, bool) {
 		a.tr.Errorf("%q returned transient error: %v", mx, err)
 	}
 
+	if err == nil {
+		// We did not attempt delivery to any of the MXs, because the MTA-STS
+		// policy did not allow any of them.
+		return a.tr.Errorf(
+			"none of the mail servers for %q are allowed by its MTA-STS policy",
+			a.toDomain), false
+	}
+
 	// We exhausted all MXs failed to deliver, try again later.
-	return a.tr.Errorf("all MXs returned transient failures (last: %v)", err), false
+	return a.tr.Errorf(
+		"all mail servers failed temporarily, last error: %w", err), false
 }
 
 // Forward an email. On failures, returns an error, and whether or not it is
@@ -137,8 +150,14 @@ func (s *SMTP) Forward(from string, to string, data []byte, servers []string) (e
 		a.tr.Errorf("%q returned transient error: %v", server, err)
 	}
 
+	if err == nil {
+		// Should not happen, as the alias parser requires at least one server.
+		return a.tr.Errorf("no servers to forward to"), false
+	}
+
 	// We exhausted all servers, try again later.
-	return a.tr.Errorf("all servers returned transient failures (last: %v)", err), false
+	return a.tr.Errorf(
+		"all servers failed temporarily, last error: %w", err), false
 }
 
 type attempt struct {
@@ -160,18 +179,18 @@ func (a *attempt) deliver(mx string) (error, bool) {
 retry:
 	conn, err := net.DialTimeout("tcp", mx+":"+*smtpPort, smtpDialTimeout)
 	if err != nil {
-		return a.tr.Errorf("Could not dial: %w", err), false
+		return a.tr.Errorf("%s: connection failed: %w", mx, err), false
 	}
 	defer conn.Close()
 	conn.SetDeadline(time.Now().Add(smtpTotalTimeout))
 
 	c, err := smtp.NewClient(conn, mx)
 	if err != nil {
-		return a.tr.Errorf("Error creating client: %w", err), false
+		return a.tr.Errorf("%s: greeting failed: %w", mx, err), false
 	}
 
 	if err = c.Hello(a.courier.HelloDomain); err != nil {
-		return a.tr.Errorf("Error saying hello: %w", err), false
+		return a.tr.Errorf("%s: EHLO failed: %w", mx, err), false
 	}
 
 	secLevel := domaininfo.SecLevel_PLAIN
@@ -218,7 +237,9 @@ retry:
 		// We consider the failure transient, so transient misconfigurations
 		// do not affect deliveries.
 		slcResults.Add("fail", 1)
-		return a.tr.Errorf("Security level check failed (level:%s)", secLevel), false
+		return a.tr.Errorf("%s: security level check failed: "+
+			"connection is %s, but we have previously seen a higher "+
+			"security level for %q", mx, secLevel, a.toDomain), false
 	}
 	slcResults.Add("pass", 1)
 
@@ -227,29 +248,34 @@ retry:
 		// https://tools.ietf.org/html/rfc8461#section-4.2
 		if secLevel != domaininfo.SecLevel_TLS_SECURE {
 			stsSecurityResults.Add("fail", 1)
-			return a.tr.Errorf("invalid security level (%v) for STS policy",
-				secLevel), false
+			return a.tr.Errorf("%s: connection is %s, but the MTA-STS "+
+				"policy for %q requires TLS with a valid certificate",
+				mx, secLevel, a.toDomain), false
 		}
 		stsSecurityResults.Add("pass", 1)
 		a.tr.Debugf("STS policy: connection is using valid TLS")
 	}
 
 	if err = c.MailAndRcpt(a.from, a.to); err != nil {
-		return a.tr.Errorf("MAIL+RCPT %w", err), smtp.IsPermanent(err)
+		return a.tr.Errorf("%s: MAIL/RCPT failed: %w", mx, err),
+			smtp.IsPermanent(err)
 	}
 
 	w, err := c.Data()
 	if err != nil {
-		return a.tr.Errorf("DATA %w", err), smtp.IsPermanent(err)
+		return a.tr.Errorf("%s: DATA failed: %w", mx, err),
+			smtp.IsPermanent(err)
 	}
 	_, err = w.Write(a.data)
 	if err != nil {
-		return a.tr.Errorf("DATA writing: %w", err), smtp.IsPermanent(err)
+		return a.tr.Errorf("%s: sending message data failed: %w", mx, err),
+			smtp.IsPermanent(err)
 	}
 
 	err = w.Close()
 	if err != nil {
-		return a.tr.Errorf("DATA closing %w", err), smtp.IsPermanent(err)
+		return a.tr.Errorf("%s: message not accepted: %w", mx, err),
+			smtp.IsPermanent(err)
 	}
 
 	_ = c.Quit()
diff --git a/internal/courier/smtp_test.go b/internal/courier/smtp_test.go
index fc4cb52..80048b6 100644
--- a/internal/courier/smtp_test.go
+++ b/internal/courier/smtp_test.go
@@ -1,8 +1,11 @@
 package courier
 
 import (
+	"encoding/json"
+	"errors"
 	"fmt"
 	"net"
+	"os"
 	"strings"
 	"testing"
 	"time"
@@ -78,49 +81,59 @@ func TestSMTPErrors(t *testing.T) {
 	// gets stuck.
 	smtpTotalTimeout = 1 * time.Second
 
-	responses := []map[string]string{
+	cases := []struct {
+		responses map[string]string
+		wantErr   string
+	}{
 		// First test: hang response, should fail due to timeout.
-		{
+		// Which step times out depends on timing, so just check that the
+		// error mentions the server.
+		{map[string]string{
 			"_welcome": "220 no newline",
-		},
+		}, ""},
+
+		// Server rejects us in the greeting.
+		{map[string]string{
+			"_welcome": "554 go away\n",
+		}, "greeting failed: 554 "},
 
 		// MAIL FROM not allowed.
-		{
+		{map[string]string{
 			"_welcome":          "220 mail from not allowed\n",
 			"EHLO hello":        "250 ehlo ok\n",
 			"MAIL FROM:<me@me>": "501 mail error\n",
-		},
+		}, "MAIL/RCPT failed: 501 "},
 
 		// RCPT TO not allowed.
-		{
+		{map[string]string{
 			"_welcome":          "220 rcpt to not allowed\n",
 			"EHLO hello":        "250 ehlo ok\n",
 			"MAIL FROM:<me@me>": "250 mail ok\n",
 			"RCPT TO:<to@to>":   "501 rcpt error\n",
-		},
+		}, "MAIL/RCPT failed: 501 "},
 
 		// DATA error.
-		{
+		{map[string]string{
 			"_welcome":          "220 data error\n",
 			"EHLO hello":        "250 ehlo ok\n",
 			"MAIL FROM:<me@me>": "250 mail ok\n",
 			"RCPT TO:<to@to>":   "250 rcpt ok\n",
 			"DATA":              "554 data error\n",
-		},
+		}, "DATA failed: 554 "},
 
 		// DATA response error.
-		{
+		{map[string]string{
 			"_welcome":          "220 data response error\n",
 			"EHLO hello":        "250 ehlo ok\n",
 			"MAIL FROM:<me@me>": "250 mail ok\n",
 			"RCPT TO:<to@to>":   "250 rcpt ok\n",
 			"DATA":              "354 send data\n",
 			"_DATA":             "551 data response error\n",
-		},
+		}, "message not accepted: 551 "},
 	}
 
-	for _, rs := range responses {
-		srv := newFakeServer(t, rs, 1)
+	for _, c := range cases {
+		srv := newFakeServer(t, c.responses, 1)
 		host, port := srv.HostPort()
 
 		testMX["to"] = []*net.MX{{Host: host, Pref: 10}}
@@ -128,8 +141,10 @@ func TestSMTPErrors(t *testing.T) {
 
 		s := newSMTP(t)
 		err, _ := s.Deliver("me@me", "to@to", []byte("data"))
-		if err == nil {
-			t.Errorf("deliver not failed in case %q: %v", rs["_welcome"], err)
+		want := host + ": " + c.wantErr
+		if err == nil || !strings.Contains(err.Error(), want) {
+			t.Errorf("case %q: expected error containing %q, got %v",
+				c.responses["_welcome"], want, err)
 		}
 		t.Logf("failed as expected: %v", err)
 
@@ -137,6 +152,116 @@ func TestSMTPErrors(t *testing.T) {
 	}
 }
 
+func TestSMTPForward(t *testing.T) {
+	// Shorten the total timeout, so the test fails quickly if the protocol
+	// gets stuck.
+	smtpTotalTimeout = 5 * time.Second
+
+	responses := map[string]string{
+		"_welcome":          "220 welcome\n",
+		"EHLO hello":        "250 ehlo ok\n",
+		"MAIL FROM:<me@me>": "250 mail ok\n",
+		"RCPT TO:<to@to>":   "250 rcpt ok\n",
+		"DATA":              "354 send data\n",
+		"_DATA":             "250 data ok\n",
+		"QUIT":              "250 quit ok\n",
+	}
+	srv := newFakeServer(t, responses, 1)
+	host, port := srv.HostPort()
+	*smtpPort = port
+
+	s := newSMTP(t)
+
+	// Successful forward. The first server is invalid (see TestSMTP), so we
+	// also check that we try the next one.
+	err, _ := s.Forward("me@me", "to@to", []byte("data"),
+		[]string{":::", host})
+	if err != nil {
+		t.Errorf("forward failed: %v", err)
+	}
+	srv.Wait()
+
+	// All servers fail with transient errors.
+	err, permanent := s.Forward("me@me", "to@to", []byte("data"),
+		[]string{":::"})
+	want := "all servers failed temporarily, last error: :::: "
+	if err == nil || !strings.HasPrefix(err.Error(), want) || permanent {
+		t.Errorf("expected transient error starting with %q, got %v (%v)",
+			want, err, permanent)
+	}
+
+	// Permanent failure: we return right away.
+	responses["RCPT TO:<to@to>"] = "550 rcpt error\n"
+	srv = newFakeServer(t, responses, 1)
+	host, port = srv.HostPort()
+	*smtpPort = port
+	err, permanent = s.Forward("me@me", "to@to", []byte("data"),
+		[]string{host})
+	want = host + ": MAIL/RCPT failed: 550 "
+	if err == nil || !strings.HasPrefix(err.Error(), want) || !permanent {
+		t.Errorf("expected permanent error starting with %q, got %v (%v)",
+			want, err, permanent)
+	}
+	srv.Wait()
+
+	// No servers to forward to.
+	err, permanent = s.Forward("me@me", "to@to", []byte("data"), nil)
+	if err == nil || err.Error() != "no servers to forward to" || permanent {
+		t.Errorf("expected transient 'no servers' error, got %v (%v)",
+			err, permanent)
+	}
+}
+
+// Test delivery to a domain whose MTA-STS policy doesn't allow any of its
+// MXs.
+func TestSTSNoMXAllowed(t *testing.T) {
+	testMX["sts-none"] = []*net.MX{
+		{Host: "mx1", Pref: 10},
+		{Host: "mx2", Pref: 20},
+	}
+	t.Cleanup(func() { delete(testMX, "sts-none") })
+
+	// Put the policy in the cache directly, so we don't need to fetch it.
+	// This mimics the cache's on-disk format: the policy as JSON in a
+	// "pol:<domain>" file, with the expiration time as its modification time.
+	dir := t.ArtifactDir()
+	policy := &sts.Policy{
+		Version: "STSv1",
+		Mode:    sts.Enforce,
+		MXs:     []string{"other-mx"},
+		MaxAge:  1 * time.Hour,
+	}
+	data, err := json.Marshal(policy)
+	if err != nil {
+		t.Fatal(err)
+	}
+	fname := dir + "/pol:sts-none"
+	if err := os.WriteFile(fname, data, 0640); err != nil {
+		t.Fatal(err)
+	}
+	expires := time.Now().Add(policy.MaxAge)
+	if err := os.Chtimes(fname, expires, expires); err != nil {
+		t.Fatal(err)
+	}
+
+	stsCache, err := sts.NewCache(dir)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	s := newSMTP(t)
+	s.STSCache = stsCache
+	err, permanent := s.Deliver("me@me", "to@sts-none", []byte("data"))
+	want := `none of the mail servers for "sts-none" are allowed by its ` +
+		`MTA-STS policy`
+	if err == nil || err.Error() != want {
+		t.Errorf("expected error %q, got %v", want, err)
+	}
+	if permanent {
+		t.Errorf("expected transient failure, got permanent")
+	}
+}
+
 func TestNoMXServer(t *testing.T) {
 	testMX["to"] = []*net.MX{}
 
@@ -148,7 +273,33 @@ func TestNoMXServer(t *testing.T) {
 	if !permanent {
 		t.Errorf("expected permanent failure, got transient (%v)", err)
 	}
-	t.Logf("got permanent failure, as expected: %v", err)
+	if want := `no mail servers found for "to"`; err.Error() != want {
+		t.Errorf("expected error %q, got %q", want, err)
+	}
+}
+
+func TestDeliverMXLookupError(t *testing.T) {
+	dnsErr := &net.DNSError{
+		Err:         "temp error (test)",
+		Name:        "lookuperr",
+		IsTemporary: true,
+	}
+	testMXErr["lookuperr"] = dnsErr
+	t.Cleanup(func() { delete(testMXErr, "lookuperr") })
+
+	s := newSMTP(t)
+	err, permanent := s.Deliver("me@me", "to@lookuperr", []byte("data"))
+	want := `error looking up mail servers for "lookuperr": ` +
+		`lookup lookuperr: temp error (test)`
+	if err == nil || err.Error() != want {
+		t.Errorf("expected error %q, got %v", want, err)
+	}
+	if !errors.Is(err, dnsErr) {
+		t.Errorf("expected error to wrap the DNS error, got %v", err)
+	}
+	if permanent {
+		t.Errorf("expected transient failure, got permanent")
+	}
 }
 
 func TestTooManyMX(t *testing.T) {
@@ -281,7 +432,7 @@ func TestTLS(t *testing.T) {
 
 	err, permanent := s.Deliver("me@me", "to@to", []byte("data"))
 	if !strings.Contains(err.Error(),
-		"Security level check failed (level:PLAIN)") {
+		"security level check failed: connection is PLAIN") {
 		t.Errorf("expected sec level check failed, got: %v", err)
 	}
 	if permanent != false {
@@ -365,7 +516,7 @@ func TestSTSPolicyEnforcement(t *testing.T) {
 	// policy, so we expect it to fail.
 	err, permanent := a.deliver("localhost")
 	if !strings.Contains(err.Error(),
-		"invalid security level (TLS_INSECURE) for STS policy") {
+		"connection is TLS_INSECURE, but the MTA-STS policy") {
 		t.Errorf("expected invalid sec level error, got %v", err)
 	}
 	if permanent != false {
diff --git a/test/t-16-spf/expected_dsn b/test/t-16-spf/expected_dsn
index 07d07c2..5ffcf8a 100644
--- a/test/t-16-spf/expected_dsn
+++ b/test/t-16-spf/expected_dsn
@@ -26,7 +26,7 @@ Delivery of your message to the following recipient(s) failed permanently:
 
 Technical details:
 - "userB@srv-b" (EMAIL) failed permanently with error:
-    MAIL+RCPT 550 "5.7.23 SPF check failed: matched all"
+    srv-b.: MAIL/RCPT failed: 550 "5.7.23 SPF check failed: matched all"
 
 
 --???????????
@@ -40,7 +40,7 @@ Original-Recipient: utf-8; userB@srv-b
 Final-Recipient: utf-8; userB@srv-b
 Action: failed
 Status: 5.0.0
-Diagnostic-Code: smtp; MAIL+RCPT 550 "5.7.23 SPF check failed: matched all"
+Diagnostic-Code: smtp; srv-b.: MAIL/RCPT failed: 550 "5.7.23 SPF check failed: matched all"