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

Author: piksel

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
-		}
-
-		notifs := "Using no notifications"
-		notifierNames := notifier.GetNames()
-		if len(notifierNames) > 0 {
-			notifs = "Using notifications: " + strings.Join(notifierNames, ", ")
-		}
-
-		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")
-		}
+	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()
+	}
+
+	startupLog.Info("Watchtower ", meta.Version)
+
+	notifierNames := notifier.GetNames()
+	if len(notifierNames) > 0 {
+		startupLog.Info("Using notifications: " + strings.Join(notifierNames, ", "))
+	} else {
+		startupLog.Info("Using no notifications")
+	}
+
+	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,67 +114,87 @@ 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")
 			}
 		}
 	}
 
 	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 {