courier: Improve delivery error messages

Delivery errors can be visible to the end-user via DSN responses, and
some of them are not very clear, or are missing useful debugging
information (such as the MX).

This patch improves the messages by including the MX where appropriate,
having explicit errors for cases where no servers are found/allowed, and
using less technical language for the common explanations.

There are no changes to the behaviour on errors, this change only
affects the messages.

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
 	}
 

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 {

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()

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 {