From 9b0ecaa0fe190cf3c13ace26af05c131376be9b4 Mon Sep 17 00:00:00 2001 From: Simon Pasquier Date: Wed, 10 Jul 2019 11:24:51 +0200 Subject: [PATCH] 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 * Fix typo Signed-off-by: Simon Pasquier --- .gitignore | 1 + notify/email/email.go | 116 +++++++++++-------- notify/email/email_test.go | 193 +++++++++++++++++++++++++++---- notify/email/testdata/auth.yml | 4 + notify/email/testdata/noauth.yml | 2 + notify/notify.go | 2 +- 6 files changed, 246 insertions(+), 72 deletions(-) create mode 100644 notify/email/testdata/auth.yml create mode 100644 notify/email/testdata/noauth.yml diff --git a/.gitignore b/.gitignore index cccce8e9..cb777178 100644 --- a/.gitignore +++ b/.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 diff --git a/notify/email/email.go b/notify/email/email.go index e059e48f..390189b5 100644 --- a/notify/email/email.go +++ b/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 - } - c, err = smtp.NewClient(conn, host) - if err != nil { - return true, err + return true, errors.Wrap(err, "establish TLS connection to server") } } else { - // Connect to the SMTP smarthost. - c, err = smtp.Dial(n.conf.Smarthost) + var ( + d = net.Dialer{} + err error + ) + conn, err = d.DialContext(ctx, "tcp", n.conf.Smarthost) if err != nil { - return true, err + return true, errors.Wrap(err, "establish connection to server") } } + c, err = smtp.NewClient(conn, host) + if err != nil { + conn.Close() + return true, errors.Wrap(err, "create SMTP client") + } defer func() { - if err := c.Quit(); err != nil { - level.Error(n.logger).Log("msg", "failed to close SMTP connection", "err", err) + // Try to clean up after ourselves but don't log anything if something has failed. + 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 { - return true, fmt.Errorf("sending mail from: %s", err) + if err = c.Mail(addrs[0].Address); err != nil { + 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 { - return true, fmt.Errorf("sending rcpt to: %s", err) + if err = c.Rcpt(addr.Address); err != nil { + return true, errors.Wrapf(err, "send RCPT command") } } - // Send the email body. - wc, err := c.Data() + // Send the email headers and body. + 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 } diff --git a/notify/email/email_test.go b/notify/email/email_test.go index b6e77af0..caea1f9a 100644 --- a/notify/email/email_test.go +++ b/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, diff --git a/notify/email/testdata/auth.yml b/notify/email/testdata/auth.yml new file mode 100644 index 00000000..bcdc1c28 --- /dev/null +++ b/notify/email/testdata/auth.yml @@ -0,0 +1,4 @@ +smarthost: localhost:1026 +server: http://localhost:1081/ +username: user +password: pass diff --git a/notify/email/testdata/noauth.yml b/notify/email/testdata/noauth.yml new file mode 100644 index 00000000..d20be227 --- /dev/null +++ b/notify/email/testdata/noauth.yml @@ -0,0 +1,2 @@ +smarthost: localhost:1025 +server: http://localhost:1080/ diff --git a/notify/notify.go b/notify/notify.go index 70def59a..875fb8cb 100644 --- a/notify/notify.go +++ b/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)