notify/email: wrap all errors for easier debugging (#1953)

* notify/email: wrap all errors for easier debugging

In addition, this commit passes the current context to the TCP dialer
and it doesn't log any QUIT errors if the email delivery wasn't
successful.

Signed-off-by: Simon Pasquier <spasquie@redhat.com>

* Fix typo

Signed-off-by: Simon Pasquier <spasquie@redhat.com>

.gitignore

@@ -11,6 +11,7 @@
 !/cli/testdata/*.yml
 !/cli/config/testdata/*.yml
 !/config/testdata/*.yml
+!/notify/email/testdata/*.yml
 !/doc/examples/simple.yml
 !/circle.yml
 !/.travis.yml

notify/email/email.go

@@ -17,7 +17,6 @@ import (
 	"bytes"
 	"context"
 	"crypto/tls"
-	"errors"
 	"fmt"
 	"mime"
 	"mime/multipart"
@@ -31,6 +30,7 @@ import (
 
 	"github.com/go-kit/kit/log"
 	"github.com/go-kit/kit/log/level"
+	"github.com/pkg/errors"
 	commoncfg "github.com/prometheus/common/config"
 
 	"github.com/prometheus/alertmanager/config"
@@ -92,7 +92,7 @@ func (n *Email) auth(mechs string) (smtp.Auth, error) {
 			// We need to know the hostname for both auth and TLS.
 			host, _, err := net.SplitHostPort(n.conf.Smarthost)
 			if err != nil {
-				return nil, fmt.Errorf("invalid address: %s", err)
+				return nil, errors.Wrap(err, "split address")
 			}
 			return smtp.PlainAuth(identity, username, password, host), nil
 		case "LOGIN":
@@ -112,77 +112,87 @@ func (n *Email) auth(mechs string) (smtp.Auth, error) {
 
 // Notify implements the Notifier interface.
 func (n *Email) Notify(ctx context.Context, as ...*types.Alert) (bool, error) {
+	// TODO: move the check to the config package.
 	// We need to know the hostname for both auth and TLS.
-	var c *smtp.Client
 	host, port, err := net.SplitHostPort(n.conf.Smarthost)
 	if err != nil {
-		return false, fmt.Errorf("invalid address: %s", err)
+		return false, errors.Wrap(err, "split address")
 	}
 
+	var (
+		c       *smtp.Client
+		conn    net.Conn
+		success = false
+	)
 	if port == "465" {
 		tlsConfig, err := commoncfg.NewTLSConfig(&n.conf.TLSConfig)
 		if err != nil {
-			return false, err
+			return false, errors.Wrap(err, "parse TLS configuration")
 		}
 		if tlsConfig.ServerName == "" {
 			tlsConfig.ServerName = host
 		}
 
-		conn, err := tls.Dial("tcp", n.conf.Smarthost, tlsConfig)
+		conn, err = tls.Dial("tcp", n.conf.Smarthost, tlsConfig)
 		if err != nil {
-			return true, err
+			return true, errors.Wrap(err, "establish TLS connection to server")
+		}
+	} else {
+		var (
+			d   = net.Dialer{}
+			err error
+		)
+		conn, err = d.DialContext(ctx, "tcp", n.conf.Smarthost)
+		if err != nil {
+			return true, errors.Wrap(err, "establish connection to server")
+		}
 	}
 	c, err = smtp.NewClient(conn, host)
 	if err != nil {
-			return true, err
+		conn.Close()
-		}
+		return true, errors.Wrap(err, "create SMTP client")
-	} else {
-		// Connect to the SMTP smarthost.
-		c, err = smtp.Dial(n.conf.Smarthost)
-		if err != nil {
-			return true, err
-		}
 	}
 	defer func() {
-		if err := c.Quit(); err != nil {
+		// Try to clean up after ourselves but don't log anything if something has failed.
-			level.Error(n.logger).Log("msg", "failed to close SMTP connection", "err", err)
+		if err := c.Quit(); success && err != nil {
+			level.Warn(n.logger).Log("msg", "failed to close SMTP connection", "err", err)
 		}
 	}()
 
 	if n.conf.Hello != "" {
-		err := c.Hello(n.conf.Hello)
+		err = c.Hello(n.conf.Hello)
 		if err != nil {
-			return true, err
+			return true, errors.Wrap(err, "send EHLO command")
 		}
 	}
 
 	// Global Config guarantees RequireTLS is not nil.
 	if *n.conf.RequireTLS {
 		if ok, _ := c.Extension("STARTTLS"); !ok {
-			return true, fmt.Errorf("require_tls: true (default), but %q does not advertise the STARTTLS extension", n.conf.Smarthost)
+			return true, errors.Errorf("'require_tls' is true (default) but %q does not advertise the STARTTLS extension", n.conf.Smarthost)
 		}
 
 		tlsConf, err := commoncfg.NewTLSConfig(&n.conf.TLSConfig)
 		if err != nil {
-			return false, err
+			return false, errors.Wrap(err, "parse TLS configuration")
 		}
 		if tlsConf.ServerName == "" {
 			tlsConf.ServerName = host
 		}
 
 		if err := c.StartTLS(tlsConf); err != nil {
-			return true, fmt.Errorf("starttls failed: %s", err)
+			return true, errors.Wrap(err, "send STARTTLS command")
 		}
 	}
 
 	if ok, mech := c.Extension("AUTH"); ok {
 		auth, err := n.auth(mech)
 		if err != nil {
-			return true, err
+			return true, errors.Wrap(err, "find auth mechanism")
 		}
 		if auth != nil {
 			if err := c.Auth(auth); err != nil {
-				return true, fmt.Errorf("%T failed: %s", auth, err)
+				return true, errors.Wrapf(err, "%T auth", auth)
 			}
 		}
 	}
@@ -191,45 +201,48 @@ func (n *Email) Notify(ctx context.Context, as ...*types.Alert) (bool, error) {
 		tmplErr error
 		data    = notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
 		tmpl    = notify.TmplText(n.tmpl, data, &tmplErr)
-		from    = tmpl(n.conf.From)
-		to      = tmpl(n.conf.To)
 	)
+	from := tmpl(n.conf.From)
 	if tmplErr != nil {
-		return false, fmt.Errorf("failed to template 'from' or 'to': %v", tmplErr)
+		return false, errors.Wrap(tmplErr, "execute 'from' template")
+	}
+	to := tmpl(n.conf.To)
+	if tmplErr != nil {
+		return false, errors.Wrap(tmplErr, "execute 'to' template")
 	}
 
 	addrs, err := mail.ParseAddressList(from)
 	if err != nil {
-		return false, fmt.Errorf("parsing from addresses: %s", err)
+		return false, errors.Wrap(err, "parse 'from' addresses")
 	}
 	if len(addrs) != 1 {
-		return false, fmt.Errorf("must be exactly one from address")
+		return false, errors.Errorf("must be exactly one 'from' address (got: %d)", len(addrs))
 	}
-	if err := c.Mail(addrs[0].Address); err != nil {
+	if err = c.Mail(addrs[0].Address); err != nil {
-		return true, fmt.Errorf("sending mail from: %s", err)
+		return true, errors.Wrap(err, "send MAIL command")
 	}
 	addrs, err = mail.ParseAddressList(to)
 	if err != nil {
-		return false, fmt.Errorf("parsing to addresses: %s", err)
+		return false, errors.Wrapf(err, "parse 'to' addresses")
 	}
 	for _, addr := range addrs {
-		if err := c.Rcpt(addr.Address); err != nil {
+		if err = c.Rcpt(addr.Address); err != nil {
-			return true, fmt.Errorf("sending rcpt to: %s", err)
+			return true, errors.Wrapf(err, "send RCPT command")
 		}
 	}
 
-	// Send the email body.
+	// Send the email headers and body.
-	wc, err := c.Data()
+	message, err := c.Data()
 	if err != nil {
-		return true, err
+		return true, errors.Wrapf(err, "send DATA command")
 	}
-	defer wc.Close()
+	defer message.Close()
 
 	buffer := &bytes.Buffer{}
 	for header, t := range n.conf.Headers {
 		value, err := n.tmpl.ExecuteTextString(t, data)
 		if err != nil {
-			return false, fmt.Errorf("executing %q header template: %s", header, err)
+			return false, errors.Wrapf(err, "execute %q header template", header)
 		}
 		fmt.Fprintf(buffer, "%s: %s\r\n", header, mime.QEncoding.Encode("utf-8", value))
 	}
@@ -243,9 +256,9 @@ func (n *Email) Notify(ctx context.Context, as ...*types.Alert) (bool, error) {
 
 	// TODO: Add some useful headers here, such as URL of the alertmanager
 	// and active/resolved.
-	_, err = wc.Write(buffer.Bytes())
+	_, err = message.Write(buffer.Bytes())
 	if err != nil {
-		return false, fmt.Errorf("failed to write header buffer: %v", err)
+		return false, errors.Wrap(err, "write headers")
 	}
 
 	if len(n.conf.Text) > 0 {
@@ -255,20 +268,20 @@ func (n *Email) Notify(ctx context.Context, as ...*types.Alert) (bool, error) {
 			"Content-Type":              {"text/plain; charset=UTF-8"},
 		})
 		if err != nil {
-			return false, fmt.Errorf("creating part for text template: %s", err)
+			return false, errors.Wrap(err, "create part for text template")
 		}
 		body, err := n.tmpl.ExecuteTextString(n.conf.Text, data)
 		if err != nil {
-			return false, fmt.Errorf("executing email text template: %s", err)
+			return false, errors.Wrap(err, "execute text template")
 		}
 		qw := quotedprintable.NewWriter(w)
 		_, err = qw.Write([]byte(body))
 		if err != nil {
-			return true, err
+			return true, errors.Wrap(err, "write text part")
 		}
 		err = qw.Close()
 		if err != nil {
-			return true, err
+			return true, errors.Wrap(err, "close text part")
 		}
 	}
 
@@ -281,33 +294,34 @@ func (n *Email) Notify(ctx context.Context, as ...*types.Alert) (bool, error) {
 			"Content-Type":              {"text/html; charset=UTF-8"},
 		})
 		if err != nil {
-			return false, fmt.Errorf("creating part for html template: %s", err)
+			return false, errors.Wrap(err, "create part for html template")
 		}
 		body, err := n.tmpl.ExecuteHTMLString(n.conf.HTML, data)
 		if err != nil {
-			return false, fmt.Errorf("executing email html template: %s", err)
+			return false, errors.Wrap(err, "execute html template")
 		}
 		qw := quotedprintable.NewWriter(w)
 		_, err = qw.Write([]byte(body))
 		if err != nil {
-			return true, err
+			return true, errors.Wrap(err, "write HTML part")
 		}
 		err = qw.Close()
 		if err != nil {
-			return true, err
+			return true, errors.Wrap(err, "close HTML part")
 		}
 	}
 
 	err = multipartWriter.Close()
 	if err != nil {
-		return false, fmt.Errorf("failed to close multipartWriter: %v", err)
+		return false, errors.Wrap(err, "close multipartWriter")
 	}
 
-	_, err = wc.Write(multipartBuffer.Bytes())
+	_, err = message.Write(multipartBuffer.Bytes())
 	if err != nil {
-		return false, fmt.Errorf("failed to write body buffer: %v", err)
+		return false, errors.Wrap(err, "write body buffer")
 	}
 
+	success = true
 	return false, nil
 }
 

notify/email/email_test.go

@@ -23,7 +23,7 @@
 // $ docker run --rm -p 1080:1080 -p 1025:1025 --entrypoint bin/maildev djfarrelly/maildev@sha256:624e0ec781e11c3531da83d9448f5861f258ee008c1b2da63b3248bfd680acfa -v
 // $ docker run --rm -p 1081:1080 -p 1026:1025 --entrypoint bin/maildev djfarrelly/maildev@sha256:624e0ec781e11c3531da83d9448f5861f258ee008c1b2da63b3248bfd680acfa --incoming-user user --incoming-pass pass -v
 //
-// $ EMAIL_NO_AUTH_CONFIG=testdata/email_noauth.yml EMAIL_AUTH_CONFIG=testdata/email_auth.yml make
+// $ EMAIL_NO_AUTH_CONFIG=testdata/noauth.yml EMAIL_AUTH_CONFIG=testdata/auth.yml make
 //
 // See also https://github.com/djfarrelly/MailDev for more details.
 package email
@@ -103,7 +103,7 @@ func (m *mailDev) getLastEmail() (*email, error) {
 		return nil, err
 	}
 	if len(emails) == 0 {
-		return nil, fmt.Errorf("expected non-empty list of emails")
+		return nil, nil
 	}
 	return &emails[len(emails)-1], nil
 }
@@ -158,9 +158,13 @@ func loadEmailTestConfiguration(f string) (emailTestConfig, error) {
 	return c, nil
 }
 
-// notifyEmail sends a notification with one firing alert and retrieves the
-// email from the SMTP server.
 func notifyEmail(cfg *config.EmailConfig, server *mailDev) (*email, bool, error) {
+	return notifyEmailWithContext(context.Background(), cfg, server)
+}
+
+// notifyEmailWithContext sends a notification with one firing alert and retrieves the
+// email from the SMTP server if the notification has been successfully delivered.
+func notifyEmailWithContext(ctx context.Context, cfg *config.EmailConfig, server *mailDev) (*email, bool, error) {
 	if cfg.RequireTLS == nil {
 		cfg.RequireTLS = new(bool)
 	}
@@ -186,14 +190,163 @@ func notifyEmail(cfg *config.EmailConfig, server *mailDev) (*email, bool, error)
 	tmpl.ExternalURL, _ = url.Parse("http://am")
 	email := New(cfg, tmpl, log.NewNopLogger())
 
-	ctx := context.Background()
 	retry, err := email.Notify(ctx, firingAlert)
 	if err != nil {
 		return nil, retry, err
 	}
 
 	e, err := server.getLastEmail()
-	return e, retry, err
+	if err != nil {
+		return nil, retry, err
+	} else if e == nil {
+		return nil, retry, fmt.Errorf("email not found")
+	}
+	return e, retry, nil
+}
+
+// TestEmailNotifyWithErrors tries to send emails with buggy inputs.
+func TestEmailNotifyWithErrors(t *testing.T) {
+	cfgFile := os.Getenv(emailNoAuthConfigVar)
+	if len(cfgFile) == 0 {
+		t.Skipf("%s not set", emailNoAuthConfigVar)
+	}
+
+	c, err := loadEmailTestConfiguration(cfgFile)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	for _, tc := range []struct {
+		title     string
+		updateCfg func(*config.EmailConfig)
+
+		errMsg   string
+		hasEmail bool
+	}{
+		{
+			title: "invalid address",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.Smarthost = "example.com"
+			},
+			errMsg: "split address:",
+		},
+		{
+			title: "invalid 'from' template",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.From = `{{ template "invalid" }}`
+			},
+			errMsg: "execute 'from' template:",
+		},
+		{
+			title: "invalid 'from' address",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.From = `xxx`
+			},
+			errMsg: "parse 'from' addresses:",
+		},
+		{
+			title: "invalid 'to' template",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.To = `{{ template "invalid" }}`
+			},
+			errMsg: "execute 'to' template:",
+		},
+		{
+			title: "invalid 'to' address",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.To = `xxx`
+			},
+			errMsg: "parse 'to' addresses:",
+		},
+		{
+			title: "invalid 'subject' template",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.Headers["subject"] = `{{ template "invalid" }}`
+			},
+			errMsg:   `execute "subject" header template:`,
+			hasEmail: true,
+		},
+		{
+			title: "invalid 'text' template",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.Text = `{{ template "invalid" }}`
+			},
+			errMsg:   `execute text template:`,
+			hasEmail: true,
+		},
+		{
+			title: "invalid 'html' template",
+			updateCfg: func(cfg *config.EmailConfig) {
+				cfg.HTML = `{{ template "invalid" }}`
+			},
+			errMsg:   `execute html template:`,
+			hasEmail: true,
+		},
+	} {
+		tc := tc
+		t.Run(tc.title, func(t *testing.T) {
+			if len(tc.errMsg) == 0 {
+				t.Fatal("please define the expected error message")
+				return
+			}
+
+			emailCfg := &config.EmailConfig{
+				Smarthost: c.Smarthost,
+				To:        emailTo,
+				From:      emailFrom,
+				HTML:      "HTML body",
+				Text:      "Text body",
+				Headers: map[string]string{
+					"Subject": "{{ len .Alerts }} {{ .Status }} alert(s)",
+				},
+			}
+			if tc.updateCfg != nil {
+				tc.updateCfg(emailCfg)
+			}
+
+			_, retry, err := notifyEmail(emailCfg, c.Server)
+			require.Error(t, err)
+			require.Contains(t, err.Error(), tc.errMsg)
+			require.Equal(t, false, retry)
+
+			e, err := c.Server.getLastEmail()
+			require.NoError(t, err)
+			if tc.hasEmail {
+				require.NotNil(t, e)
+			} else {
+				require.Nil(t, e)
+			}
+		})
+	}
+}
+
+// TestEmailNotifyWithDoneContext tries to send an email with a context that is done.
+func TestEmailNotifyWithDoneContext(t *testing.T) {
+	cfgFile := os.Getenv(emailNoAuthConfigVar)
+	if len(cfgFile) == 0 {
+		t.Skipf("%s not set", emailNoAuthConfigVar)
+	}
+
+	c, err := loadEmailTestConfiguration(cfgFile)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	ctx, cancel := context.WithCancel(context.Background())
+	cancel()
+	_, _, err = notifyEmailWithContext(
+		ctx,
+		&config.EmailConfig{
+			Smarthost: c.Smarthost,
+			To:        emailTo,
+			From:      emailFrom,
+			HTML:      "HTML body",
+			Text:      "Text body",
+		},
+		c.Server,
+	)
+	require.Error(t, err)
+	require.Contains(t, err.Error(), "establish connection to server")
 }
 
 // TestEmailNotifyWithoutAuthentication sends an email to an instance of
@@ -269,20 +422,22 @@ func TestEmailNotifyWithAuthentication(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	testCases := []struct {
+	for _, tc := range []struct {
+		title     string
 		updateCfg func(*config.EmailConfig)
 
 		errMsg string
 		retry  bool
 	}{
 		{
+			title: "email with authentication",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.AuthUsername = c.Username
 				cfg.AuthPassword = config.Secret(c.Password)
 			},
 		},
 		{
-			// HTML-only email.
+			title: "HTML-only email",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.AuthUsername = c.Username
 				cfg.AuthPassword = config.Secret(c.Password)
@@ -290,7 +445,7 @@ func TestEmailNotifyWithAuthentication(t *testing.T) {
 			},
 		},
 		{
-			// text-only email.
+			title: "text-only email",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.AuthUsername = c.Username
 				cfg.AuthPassword = config.Secret(c.Password)
@@ -298,7 +453,7 @@ func TestEmailNotifyWithAuthentication(t *testing.T) {
 			},
 		},
 		{
-			// Multiple To addresses.
+			title: "multiple To addresses",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.AuthUsername = c.Username
 				cfg.AuthPassword = config.Secret(c.Password)
@@ -306,18 +461,18 @@ func TestEmailNotifyWithAuthentication(t *testing.T) {
 			},
 		},
 		{
-			// No more than one From address.
+			title: "no more than one From address",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.AuthUsername = c.Username
 				cfg.AuthPassword = config.Secret(c.Password)
 				cfg.From = strings.Join([]string{emailFrom, emailTo}, ",")
 			},
 
-			errMsg: "must be exactly one from address",
+			errMsg: "must be exactly one 'from' address",
 			retry:  false,
 		},
 		{
-			// Wrong credentials.
+			title: "wrong credentials",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.AuthUsername = c.Username
 				cfg.AuthPassword = config.Secret(c.Password + "wrong")
@@ -327,12 +482,12 @@ func TestEmailNotifyWithAuthentication(t *testing.T) {
 			retry:  true,
 		},
 		{
-			// No credentials.
+			title:  "no credentials",
 			errMsg: "authentication Required",
 			retry:  true,
 		},
 		{
-			// Fail to enable STARTTLS.
+			title: "try to enable STARTTLS",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.RequireTLS = new(bool)
 				*cfg.RequireTLS = true
@@ -342,7 +497,7 @@ func TestEmailNotifyWithAuthentication(t *testing.T) {
 			retry:  true,
 		},
 		{
-			// Invalid Hello string.
+			title: "invalid Hello string",
 			updateCfg: func(cfg *config.EmailConfig) {
 				cfg.AuthUsername = c.Username
 				cfg.AuthPassword = config.Secret(c.Password)
@@ -352,11 +507,9 @@ func TestEmailNotifyWithAuthentication(t *testing.T) {
 			errMsg: "501 Error",
 			retry:  true,
 		},
-	}
+	} {
-
-	for _, tc := range testCases {
 		tc := tc
-		t.Run("", func(t *testing.T) {
+		t.Run(tc.title, func(t *testing.T) {
 			emailCfg := &config.EmailConfig{
 				Smarthost: c.Smarthost,
 				To:        emailTo,

notify/email/testdata/auth.yml

@@ -0,0 +1,4 @@
+smarthost: localhost:1026
+server: http://localhost:1081/
+username: user
+password: pass

notify/email/testdata/noauth.yml

@@ -0,0 +1,2 @@
+smarthost: localhost:1025
+server: http://localhost:1080/

notify/notify.go

@@ -364,7 +364,7 @@ func (fs FanoutStage) Exec(ctx context.Context, l log.Logger, alerts ...*types.A
 					// message should only be logged at the debug level.
 					lvl = level.Debug(l)
 				}
-				lvl.Log("msg", "Error on notify", "err", err)
+				lvl.Log("msg", "Error on notify", "err", err, "context_err", ctx.Err())
 			}
 			wg.Done()
 		}(s)