fix(notifications): default templates and logic (#1010)

* fix(notifications): default templates and logic
* fix multi-entry report notifs and add test
* add tests for log queueing

cmd/root.go

@@ -3,6 +3,7 @@ package cmd
 import (
 	"github.com/containrrr/watchtower/internal/meta"
 	"math"
+	"net/http"
 	"os"
 	"os/signal"
 	"strconv"
@@ -197,7 +198,7 @@ func Run(c *cobra.Command, names []string) {
 		httpAPI.RegisterHandler(metricsHandler.Path, metricsHandler.Handle)
 	}
 
-	if err := httpAPI.Start(enableUpdateAPI && !unblockHTTPAPI); err != nil {
+	if err := httpAPI.Start(enableUpdateAPI && !unblockHTTPAPI); err != nil && err != http.ErrServerClosed {
 		log.Error("failed to start API", err)
 	}
 
@@ -259,24 +260,43 @@ func formatDuration(d time.Duration) string {
 }
 
 func writeStartupMessage(c *cobra.Command, sched time.Time, filtering string) {
-	if noStartupMessage, _ := c.PersistentFlags().GetBool("no-startup-message"); !noStartupMessage {
-		schedMessage := "Running a one time update."
-		if !sched.IsZero() {
-			until := formatDuration(time.Until(sched))
-			schedMessage = "Scheduling first run: " + sched.Format("2006-01-02 15:04:05 -0700 MST") +
-				"\nNote that the first check will be performed in " + until
+	noStartupMessage, _ := c.PersistentFlags().GetBool("no-startup-message")
+
+	var startupLog *log.Entry
+	if noStartupMessage {
+		startupLog = notifications.LocalLog
+	} else {
+		startupLog = log.NewEntry(log.StandardLogger())
+		// Batch up startup messages to send them as a single notification
+		notifier.StartNotification()
 	}
 
-		notifs := "Using no notifications"
+	startupLog.Info("Watchtower ", meta.Version)
+
 	notifierNames := notifier.GetNames()
 	if len(notifierNames) > 0 {
-			notifs = "Using notifications: " + strings.Join(notifierNames, ", ")
+		startupLog.Info("Using notifications: " + strings.Join(notifierNames, ", "))
+	} else {
+		startupLog.Info("Using no notifications")
 	}
 
-		log.Info("Watchtower ", meta.Version, "\n", notifs, "\n", filtering, "\n", schedMessage)
-		if log.IsLevelEnabled(log.TraceLevel) {
-			log.Warn("trace level enabled: log will include sensitive information as credentials and tokens")
+	startupLog.Info(filtering)
+
+	if !sched.IsZero() {
+		until := formatDuration(time.Until(sched))
+		startupLog.Info("Scheduling first run: " + sched.Format("2006-01-02 15:04:05 -0700 MST"))
+		startupLog.Info("Note that the first check will be performed in " + until)
+	} else {
+		startupLog.Info("Running a one time update.")
 	}
+
+	if !noStartupMessage {
+		// Send the queued up startup messages, not including the trace warning below (to make sure it's noticed)
+		notifier.SendNotification(nil)
+	}
+
+	if log.IsLevelEnabled(log.TraceLevel) {
+		startupLog.Warn("Trace level enabled: log will include sensitive information as credentials and tokens")
 	}
 }
 

pkg/notifications/notifications_suite_test.go

@@ -1,6 +1,7 @@
 package notifications_test
 
 import (
+	"github.com/onsi/gomega/format"
 	"testing"
 
 	. "github.com/onsi/ginkgo"
@@ -9,5 +10,6 @@ import (
 
 func TestNotifications(t *testing.T) {
 	RegisterFailHandler(Fail)
+	format.CharactersAroundMismatchToInclude = 20
 	RunSpecs(t, "Notifications Suite")
 }

pkg/notifications/notifier.go

@@ -30,7 +30,8 @@ func NewNotifier(c *cobra.Command) ty.Notifier {
 
 	urls = AppendLegacyUrls(urls, c)
 
-	return newShoutrrrNotifier(tplString, acceptedLogLevels, !reportTemplate, urls...)
+	title := GetTitle(c)
+	return newShoutrrrNotifier(tplString, acceptedLogLevels, !reportTemplate, title, urls...)
 }
 
 // AppendLegacyUrls creates shoutrrr equivalent URLs from legacy notification flags

pkg/notifications/shoutrrr.go

@@ -2,7 +2,6 @@ package notifications
 
 import (
 	"bytes"
-	"fmt"
 	stdlog "log"
 	"strings"
 	"text/template"
@@ -13,23 +12,33 @@ import (
 	log "github.com/sirupsen/logrus"
 )
 
+// LocalLog is a logrus logger that does not send entries as notifications
+var LocalLog = log.WithField("notify", "no")
+
 const (
 	shoutrrrDefaultLegacyTemplate = "{{range .}}{{.Message}}{{println}}{{end}}"
-	shoutrrrDefaultTemplate       = `{{- with .Report -}}
+	shoutrrrDefaultTemplate       = `
+{{- if .Report -}}
+  {{- with .Report -}}
+    {{- if ( or .Updated .Failed ) -}}
 {{len .Scanned}} Scanned, {{len .Updated}} Updated, {{len .Failed}} Failed
-{{range .Updated -}}
+      {{- range .Updated}}
 - {{.Name}} ({{.ImageName}}): {{.CurrentImageID.ShortID}} updated to {{.LatestImageID.ShortID}}
-{{end -}}
-{{range .Fresh -}}
+      {{- end -}}
+      {{- range .Fresh}}
 - {{.Name}} ({{.ImageName}}): {{.State}}
-{{end -}}
-{{range .Skipped -}}
+	  {{- end -}}
+	  {{- range .Skipped}}
 - {{.Name}} ({{.ImageName}}): {{.State}}: {{.Error}}
-{{end -}}
-{{range .Failed -}}
+	  {{- end -}}
+	  {{- range .Failed}}
 - {{.Name}} ({{.ImageName}}): {{.State}}: {{.Error}}
-{{end -}}
-{{end -}}`
+	  {{- end -}}
+    {{- end -}}
+  {{- end -}}
+{{- else -}}
+  {{range .Entries -}}{{.Message}}{{"\n"}}{{- end -}}
+{{- end -}}`
 	shoutrrrType = "shoutrrr"
 )
 
@@ -47,6 +56,7 @@ type shoutrrrTypeNotifier struct {
 	messages       chan string
 	done           chan bool
 	legacyTemplate bool
+	params         *types.Params
 }
 
 // GetScheme returns the scheme part of a Shoutrrr URL
@@ -58,6 +68,7 @@ func GetScheme(url string) string {
 	return url[:schemeEnd]
 }
 
+// GetNames returns a list of notification services that has been added
 func (n *shoutrrrTypeNotifier) GetNames() []string {
 	names := make([]string, len(n.Urls))
 	for i, u := range n.Urls {
@@ -66,9 +77,10 @@ func (n *shoutrrrTypeNotifier) GetNames() []string {
 	return names
 }
 
-func newShoutrrrNotifier(tplString string, acceptedLogLevels []log.Level, legacy bool, urls ...string) t.Notifier {
+func newShoutrrrNotifier(tplString string, acceptedLogLevels []log.Level, legacy bool, title string, urls ...string) t.Notifier {
 
 	notifier := createNotifier(urls, acceptedLogLevels, tplString, legacy)
+	notifier.params = &types.Params{"title": title}
 	log.AddHook(notifier)
 
 	// Do the sending in a separate goroutine so we don't block the main process.
@@ -102,13 +114,16 @@ func createNotifier(urls []string, levels []log.Level, tplString string, legacy
 
 func sendNotifications(n *shoutrrrTypeNotifier) {
 	for msg := range n.messages {
-		errs := n.Router.Send(msg, nil)
+		errs := n.Router.Send(msg, n.params)
 
 		for i, err := range errs {
 			if err != nil {
 				scheme := GetScheme(n.Urls[i])
 				// Use fmt so it doesn't trigger another notification.
-				fmt.Printf("Failed to send shoutrrr notification (#%d, %s): %v\n", i, scheme, err)
+				LocalLog.WithFields(log.Fields{
+					"service": scheme,
+					"index":   i,
+				}).WithError(err).Error("Failed to send shoutrrr notification")
 			}
 		}
 	}
@@ -116,53 +131,70 @@ func sendNotifications(n *shoutrrrTypeNotifier) {
 	n.done <- true
 }
 
-func (n *shoutrrrTypeNotifier) buildMessage(data Data) string {
+func (n *shoutrrrTypeNotifier) buildMessage(data Data) (string, error) {
 	var body bytes.Buffer
 	var templateData interface{} = data
 	if n.legacyTemplate {
 		templateData = data.Entries
 	}
 	if err := n.template.Execute(&body, templateData); err != nil {
-		fmt.Printf("Failed to execute Shoutrrrr template: %s\n", err.Error())
+		return "", err
 	}
 
-	return body.String()
+	return body.String(), nil
 }
 
 func (n *shoutrrrTypeNotifier) sendEntries(entries []*log.Entry, report t.Report) {
-	msg := n.buildMessage(Data{entries, report})
+	msg, err := n.buildMessage(Data{entries, report})
+
+	if msg == "" {
+		// Log in go func in case we entered from Fire to avoid stalling
+		go func() {
+			if err != nil {
+				LocalLog.WithError(err).Fatal("Notification template error")
+			} else {
+				LocalLog.Info("Skipping notification due to empty message")
+			}
+		}()
+		return
+	}
 	n.messages <- msg
 }
 
+// StartNotification begins queueing up messages to send them as a batch
 func (n *shoutrrrTypeNotifier) StartNotification() {
 	if n.entries == nil {
 		n.entries = make([]*log.Entry, 0, 10)
 	}
 }
 
+// SendNotification sends the queued up messages as a notification
 func (n *shoutrrrTypeNotifier) SendNotification(report t.Report) {
-	//if n.entries == nil || len(n.entries) <= 0 {
-	//	return
-	//}
-
 	n.sendEntries(n.entries, report)
 	n.entries = nil
 }
 
+// Close prevents further messages from being queued and waits until all the currently queued up messages have been sent
 func (n *shoutrrrTypeNotifier) Close() {
 	close(n.messages)
 
 	// Use fmt so it doesn't trigger another notification.
-	fmt.Println("Waiting for the notification goroutine to finish")
+	LocalLog.Info("Waiting for the notification goroutine to finish")
 
 	_ = <-n.done
 }
 
+// Levels return what log levels trigger notifications
 func (n *shoutrrrTypeNotifier) Levels() []log.Level {
 	return n.logLevels
 }
 
+// Fire is the hook that logrus calls on a new log message
 func (n *shoutrrrTypeNotifier) Fire(entry *log.Entry) error {
+	if entry.Data["notify"] == "no" {
+		// Skip logging if explicitly tagged as non-notify
+		return nil
+	}
 	if n.entries != nil {
 		n.entries = append(n.entries, entry)
 	} else {

pkg/notifications/shoutrrr_test.go

@@ -8,11 +8,12 @@ import (
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
 	"github.com/onsi/gomega/gbytes"
-
 	"github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 )
 
+var allButTrace = logrus.AllLevels[0:logrus.TraceLevel]
+
 var legacyMockData = Data{
 	Entries: []*logrus.Entry{
 		{
@@ -22,6 +23,28 @@ var legacyMockData = Data{
 	},
 }
 
+var mockDataMultipleEntries = Data{
+	Entries: []*logrus.Entry{
+		{
+			Level:   logrus.InfoLevel,
+			Message: "The situation is under control",
+		},
+		{
+			Level:   logrus.WarnLevel,
+			Message: "All the smoke might be covering up some problems",
+		},
+		{
+			Level:   logrus.ErrorLevel,
+			Message: "Turns out everything is on fire",
+		},
+	},
+}
+
+var mockDataAllFresh = Data{
+	Entries: []*logrus.Entry{},
+	Report:  mocks.CreateMockProgressReport(s.FreshState),
+}
+
 func mockDataFromStates(states ...s.State) Data {
 	return Data{
 		Entries: legacyMockData.Entries,
@@ -35,6 +58,7 @@ var _ = Describe("Shoutrrr", func() {
 	BeforeEach(func() {
 		logBuffer = gbytes.NewBuffer()
 		logrus.SetOutput(logBuffer)
+		logrus.SetLevel(logrus.TraceLevel)
 		logrus.SetFormatter(&logrus.TextFormatter{
 			DisableColors:    true,
 			DisableTimestamp: true,
@@ -56,7 +80,8 @@ var _ = Describe("Shoutrrr", func() {
 					},
 				}
 
-				s := shoutrrr.buildMessage(Data{Entries: entries})
+				s, err := shoutrrr.buildMessage(Data{Entries: entries})
+				Expect(err).NotTo(HaveOccurred())
 
 				Expect(s).To(Equal("foo bar\n"))
 			})
@@ -80,21 +105,34 @@ var _ = Describe("Shoutrrr", func() {
 					},
 				}
 
-				s := shoutrrr.buildMessage(Data{Entries: entries})
+				s, err := shoutrrr.buildMessage(Data{Entries: entries})
+				Expect(err).NotTo(HaveOccurred())
 
 				Expect(s).To(Equal("info: foo bar\n"))
 			})
 		})
 
+		Describe("the default template", func() {
+			When("all containers are fresh", func() {
+				It("should return an empty string", func() {
+					Expect(getTemplatedResult(``, true, mockDataAllFresh)).To(Equal(""))
+				})
+			})
+		})
+
 		When("given an invalid custom template", func() {
 			It("should format the messages using the default template", func() {
 				invNotif, err := createNotifierWithTemplate(`{{ intentionalSyntaxError`, true)
 				Expect(err).To(HaveOccurred())
+				invMsg, err := invNotif.buildMessage(legacyMockData)
+				Expect(err).NotTo(HaveOccurred())
 
 				defNotif, err := createNotifierWithTemplate(``, true)
 				Expect(err).ToNot(HaveOccurred())
+				defMsg, err := defNotif.buildMessage(legacyMockData)
+				Expect(err).ToNot(HaveOccurred())
 
-				Expect(invNotif.buildMessage(legacyMockData)).To(Equal(defNotif.buildMessage(legacyMockData)))
+				Expect(invMsg).To(Equal(defMsg))
 			})
 		})
 
@@ -130,20 +168,65 @@ var _ = Describe("Shoutrrr", func() {
 - updt2 (mock/updt2:latest): 01d120000000 updated to d0a120000000
 - frsh1 (mock/frsh1:latest): Fresh
 - skip1 (mock/skip1:latest): Skipped: unpossible
-- fail1 (mock/fail1:latest): Failed: accidentally the whole container
-`
+- fail1 (mock/fail1:latest): Failed: accidentally the whole container`
 				data := mockDataFromStates(s.UpdatedState, s.FreshState, s.FailedState, s.SkippedState, s.UpdatedState)
 				Expect(getTemplatedResult(``, false, data)).To(Equal(expected))
 			})
 
-			It("should format the messages using the default template", func() {
-				expected := `1 Scanned, 0 Updated, 0 Failed
-- frsh1 (mock/frsh1:latest): Fresh
-`
-				data := mockDataFromStates(s.FreshState)
+		})
+
+		Describe("the default template", func() {
+			When("all containers are fresh", func() {
+				It("should return an empty string", func() {
+					Expect(getTemplatedResult(``, false, mockDataAllFresh)).To(Equal(""))
+				})
+			})
+			When("at least one container was updated", func() {
+				It("should send a report", func() {
+					expected := `1 Scanned, 1 Updated, 0 Failed
+- updt1 (mock/updt1:latest): 01d110000000 updated to d0a110000000`
+					data := mockDataFromStates(s.UpdatedState)
 					Expect(getTemplatedResult(``, false, data)).To(Equal(expected))
 				})
 			})
+			When("at least one container failed to update", func() {
+				It("should send a report", func() {
+					expected := `1 Scanned, 0 Updated, 1 Failed
+- fail1 (mock/fail1:latest): Failed: accidentally the whole container`
+					data := mockDataFromStates(s.FailedState)
+					Expect(getTemplatedResult(``, false, data)).To(Equal(expected))
+				})
+			})
+			When("the report is nil", func() {
+				It("should return the logged entries", func() {
+					expected := `The situation is under control
+All the smoke might be covering up some problems
+Turns out everything is on fire
+`
+					Expect(getTemplatedResult(``, false, mockDataMultipleEntries)).To(Equal(expected))
+				})
+			})
+		})
+	})
+
+	When("batching notifications", func() {
+		When("no messages are queued", func() {
+			It("should not send any notification", func() {
+				shoutrrr := newShoutrrrNotifier("", allButTrace, true, "", "logger://")
+				shoutrrr.StartNotification()
+				shoutrrr.SendNotification(nil)
+				Consistently(logBuffer).ShouldNot(gbytes.Say(`Shoutrrr:`))
+			})
+		})
+		When("at least one message is queued", func() {
+			It("should send a notification", func() {
+				shoutrrr := newShoutrrrNotifier("", allButTrace, true, "", "logger://")
+				shoutrrr.StartNotification()
+				logrus.Info("This log message is sponsored by ContainrrrVPN")
+				shoutrrr.SendNotification(nil)
+				Eventually(logBuffer).Should(gbytes.Say(`Shoutrrr: This log message is sponsored by ContainrrrVPN`))
+			})
+		})
 	})
 
 	When("sending notifications", func() {
@@ -218,10 +301,10 @@ func createNotifierWithTemplate(tplString string, legacy bool) (*shoutrrrTypeNot
 	}, err
 }
 
-func getTemplatedResult(tplString string, legacy bool, data Data) (string, error) {
+func getTemplatedResult(tplString string, legacy bool, data Data) (msg string) {
 	notifier, err := createNotifierWithTemplate(tplString, legacy)
-	if err != nil {
-		return "", err
-	}
-	return notifier.buildMessage(data), err
+	ExpectWithOffset(1, err).NotTo(HaveOccurred())
+	msg, err = notifier.buildMessage(data)
+	ExpectWithOffset(1, err).NotTo(HaveOccurred())
+	return msg
 }