diff --git a/cmd/root.go b/cmd/root.go index fb7c29b..47f7133 100644 --- a/cmd/root.go +++ b/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") } } diff --git a/pkg/notifications/notifications_suite_test.go b/pkg/notifications/notifications_suite_test.go index 1b77c2a..19d286e 100644 --- a/pkg/notifications/notifications_suite_test.go +++ b/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") } diff --git a/pkg/notifications/notifier.go b/pkg/notifications/notifier.go index b54630c..7c999d0 100644 --- a/pkg/notifications/notifier.go +++ b/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 diff --git a/pkg/notifications/shoutrrr.go b/pkg/notifications/shoutrrr.go index 41ef126..ac293fb 100644 --- a/pkg/notifications/shoutrrr.go +++ b/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 { diff --git a/pkg/notifications/shoutrrr_test.go b/pkg/notifications/shoutrrr_test.go index e92655c..1b4ebab 100644 --- a/pkg/notifications/shoutrrr_test.go +++ b/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,18 +168,63 @@ 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 + }) + + 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 ` - data := mockDataFromStates(s.FreshState) - Expect(getTemplatedResult(``, false, data)).To(Equal(expected)) + 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`)) }) }) }) @@ -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 }