Logging improvements (#4113)

tjhop · web-flow · commit 1e0117285708 · 2025-11-14T07:52:11.000+01:00
* ref(webhook): return error if unable to parse group key Addresses feedback from another PR #4089 (comment) Signed-off-by: TJ Hoplock <t.hoplock@gmail.com> * fix(silence): log errors at ERROR level instead of INFO Signed-off-by: TJ Hoplock <t.hoplock@gmail.com> * chore(notify): make logging more consistent, converge on `group_key` This changes the majority of our `Notify()` implementations to set up a new logger with the group key attached under the key name `group_key`, and then to use that logger in all subsequent calls to the logger, including passing it through to further functions that accept loggers via params. A few of the notify implementations are more complicated; they either extract the key later in their `Notify()` implementation or within sub methods, or even conditionally like with sns. I left those mostly as is for now, as they seem to be more snow-flake-y. Signed-off-by: TJ Hoplock <t.hoplock@gmail.com> --------- Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
diff --git a/notify/discord/discord.go b/notify/discord/discord.go
@@ -95,10 +95,11 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 		return false, err
 	}
 
-	n.logger.Debug("extracted group key", "key", key)
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
 
 	alerts := types.Alerts(as...)
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 	tmpl := notify.TmplText(n.tmpl, data, &err)
 	if err != nil {
 		return false, err
@@ -109,22 +110,22 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 		return false, err
 	}
 	if truncated {
-		n.logger.Warn("Truncated title", "key", key, "max_runes", maxTitleLenRunes)
+		logger.Warn("Truncated title", "max_runes", maxTitleLenRunes)
 	}
 	description, truncated := notify.TruncateInRunes(tmpl(n.conf.Message), maxDescriptionLenRunes)
 	if err != nil {
 		return false, err
 	}
 	if truncated {
-		n.logger.Warn("Truncated message", "key", key, "max_runes", maxDescriptionLenRunes)
+		logger.Warn("Truncated message", "max_runes", maxDescriptionLenRunes)
 	}
 
 	content, truncated := notify.TruncateInRunes(tmpl(n.conf.Content), maxContentLenRunes)
 	if err != nil {
 		return false, err
 	}
 	if truncated {
-		n.logger.Warn("Truncated message", "key", key, "max_runes", maxContentLenRunes)
+		logger.Warn("Truncated message", "max_runes", maxContentLenRunes)
 	}
 
 	color := colorGrey
@@ -160,7 +161,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 		if _, err := netUrl.Parse(n.conf.AvatarURL); err == nil {
 			w.AvatarURL = n.conf.AvatarURL
 		} else {
-			n.logger.Warn("Bad avatar url", "key", key)
+			logger.Warn("Bad avatar url", "key", key)
 		}
 	}
 
diff --git a/notify/jira/jira.go b/notify/jira/jira.go
@@ -72,6 +72,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 	}
 
 	logger := n.logger.With("group_key", key.String())
+	logger.Debug("extracted group key")
 
 	var (
 		alerts = types.Alerts(as...)
diff --git a/notify/msteams/msteams.go b/notify/msteams/msteams.go
@@ -85,9 +85,10 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 		return false, err
 	}
 
-	n.logger.Debug("extracted group key", "key", key)
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
 
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 	tmpl := notify.TmplText(n.tmpl, data, &err)
 	if err != nil {
 		return false, err
diff --git a/notify/msteamsv2/msteamsv2.go b/notify/msteamsv2/msteamsv2.go
@@ -109,9 +109,10 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 		return false, err
 	}
 
-	n.logger.Debug("extracted group key", "key", key)
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
 
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 	tmpl := notify.TmplText(n.tmpl, data, &err)
 	if err != nil {
 		return false, err
diff --git a/notify/opsgenie/opsgenie.go b/notify/opsgenie/opsgenie.go
@@ -132,9 +132,10 @@ func (n *Notifier) createRequests(ctx context.Context, as ...*types.Alert) ([]*h
 	if err != nil {
 		return nil, false, err
 	}
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
 
-	n.logger.Debug("extracted group key", "key", key)
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 
 	tmpl := notify.TmplText(n.tmpl, data, &err)
 
@@ -174,7 +175,7 @@ func (n *Notifier) createRequests(ctx context.Context, as ...*types.Alert) ([]*h
 	default:
 		message, truncated := notify.TruncateInRunes(tmpl(n.conf.Message), maxMessageLenRunes)
 		if truncated {
-			n.logger.Warn("Truncated message", "alert", key, "max_runes", maxMessageLenRunes)
+			logger.Warn("Truncated message", "alert", key, "max_runes", maxMessageLenRunes)
 		}
 
 		createEndpointURL := n.conf.APIURL.Copy()
diff --git a/notify/pagerduty/pagerduty.go b/notify/pagerduty/pagerduty.go
@@ -308,17 +308,18 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 	if err != nil {
 		return false, err
 	}
+	logger := n.logger.With("group_key", key)
 
 	var (
 		alerts    = types.Alerts(as...)
-		data      = notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+		data      = notify.GetTemplateData(ctx, n.tmpl, as, logger)
 		eventType = pagerDutyEventTrigger
 	)
 	if alerts.Status() == model.AlertResolved {
 		eventType = pagerDutyEventResolve
 	}
 
-	n.logger.Debug("extracted group key", "key", key, "eventType", eventType)
+	logger.Debug("extracted group key", "eventType", eventType)
 
 	details := make(map[string]string, len(n.conf.Details))
 	for k, v := range n.conf.Details {
diff --git a/notify/pushover/pushover.go b/notify/pushover/pushover.go
@@ -72,10 +72,10 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 	if !ok {
 		return false, fmt.Errorf("group key missing")
 	}
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
 
-	// @tjhop: should this use `group` for the keyval like most other notify implementations?
-	n.logger.Debug("extracted group key", "incident", key)
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 
 	var (
 		err     error
@@ -113,7 +113,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 
 	title, truncated := notify.TruncateInRunes(tmpl(n.conf.Title), maxTitleLenRunes)
 	if truncated {
-		n.logger.Warn("Truncated title", "incident", key, "max_runes", maxTitleLenRunes)
+		logger.Warn("Truncated title", "incident", key, "max_runes", maxTitleLenRunes)
 	}
 	parameters.Add("title", title)
 
@@ -130,7 +130,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 
 	message, truncated = notify.TruncateInRunes(message, maxMessageLenRunes)
 	if truncated {
-		n.logger.Warn("Truncated message", "incident", key, "max_runes", maxMessageLenRunes)
+		logger.Warn("Truncated message", "incident", key, "max_runes", maxMessageLenRunes)
 	}
 	message = strings.TrimSpace(message)
 	if message == "" {
@@ -141,7 +141,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 
 	supplementaryURL, truncated := notify.TruncateInRunes(tmpl(n.conf.URL), maxURLLenRunes)
 	if truncated {
-		n.logger.Warn("Truncated URL", "incident", key, "max_runes", maxURLLenRunes)
+		logger.Warn("Truncated URL", "incident", key, "max_runes", maxURLLenRunes)
 	}
 	parameters.Add("url", supplementaryURL)
 	parameters.Add("url_title", tmpl(n.conf.URLTitle))
@@ -167,7 +167,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 	}
 	u.RawQuery = parameters.Encode()
 	// Don't log the URL as it contains secret data (see #1825).
-	n.logger.Debug("Sending message", "incident", key)
+	logger.Debug("Sending message", "incident", key)
 	resp, err := notify.PostText(ctx, n.client, u.String(), nil)
 	if err != nil {
 		return true, notify.RedactURL(err)
diff --git a/notify/rocketchat/rocketchat.go b/notify/rocketchat/rocketchat.go
@@ -140,7 +140,14 @@ func getToken(c *config.RocketchatConfig) (string, error) {
 func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error) {
 	var err error
 
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	key, err := notify.ExtractGroupKey(ctx)
+	if err != nil {
+		return false, err
+	}
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
+
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 	tmplText := notify.TmplText(n.tmpl, data, &err)
 	if err != nil {
 		return false, err
@@ -152,11 +159,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 
 	title, truncated := notify.TruncateInRunes(title, maxTitleLenRunes)
 	if truncated {
-		key, err := notify.ExtractGroupKey(ctx)
-		if err != nil {
-			return false, err
-		}
-		n.logger.Warn("Truncated title", "key", key, "max_runes", maxTitleLenRunes)
+		logger.Warn("Truncated title", "max_runes", maxTitleLenRunes)
 	}
 	att := &Attachment{
 		Title:     title,
diff --git a/notify/slack/slack.go b/notify/slack/slack.go
@@ -93,8 +93,16 @@ type attachment struct {
 // Notify implements the Notifier interface.
 func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error) {
 	var err error
+
+	key, err := notify.ExtractGroupKey(ctx)
+	if err != nil {
+		return false, err
+	}
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
+
 	var (
-		data     = notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+		data     = notify.GetTemplateData(ctx, n.tmpl, as, logger)
 		tmplText = notify.TmplText(n.tmpl, data, &err)
 	)
 	var markdownIn []string
@@ -107,11 +115,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 
 	title, truncated := notify.TruncateInRunes(tmplText(n.conf.Title), maxTitleLenRunes)
 	if truncated {
-		key, err := notify.ExtractGroupKey(ctx)
-		if err != nil {
-			return false, err
-		}
-		n.logger.Warn("Truncated title", "key", key, "max_runes", maxTitleLenRunes)
+		logger.Warn("Truncated title", "max_runes", maxTitleLenRunes)
 	}
 	att := &attachment{
 		Title:      title,
diff --git a/notify/telegram/telegram.go b/notify/telegram/telegram.go
@@ -64,27 +64,30 @@ func New(conf *config.TelegramConfig, t *template.Template, l *slog.Logger, http
 }
 
 func (n *Notifier) Notify(ctx context.Context, alert ...*types.Alert) (bool, error) {
+	key, ok := notify.GroupKey(ctx)
+	if !ok {
+		return false, fmt.Errorf("group key missing")
+	}
+
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
+
 	var (
 		err  error
-		data = notify.GetTemplateData(ctx, n.tmpl, alert, n.logger)
+		data = notify.GetTemplateData(ctx, n.tmpl, alert, logger)
 		tmpl = notify.TmplText(n.tmpl, data, &err)
 	)
 
 	if n.conf.ParseMode == "HTML" {
 		tmpl = notify.TmplHTML(n.tmpl, data, &err)
 	}
 
-	key, ok := notify.GroupKey(ctx)
-	if !ok {
-		return false, fmt.Errorf("group key missing")
-	}
-
 	messageText, truncated := notify.TruncateInRunes(tmpl(n.conf.Message), maxMessageLenRunes)
 	if err != nil {
 		return false, err
 	}
 	if truncated {
-		n.logger.Warn("Truncated message", "alert", key, "max_runes", maxMessageLenRunes)
+		logger.Warn("Truncated message", "max_runes", maxMessageLenRunes)
 	}
 
 	n.client.Token, err = n.getBotToken()
@@ -101,7 +104,7 @@ func (n *Notifier) Notify(ctx context.Context, alert ...*types.Alert) (bool, err
 	if err != nil {
 		return true, err
 	}
-	n.logger.Debug("Telegram message successfully published", "message_id", message.ID, "chat_id", message.Chat.ID)
+	logger.Debug("Telegram message successfully published", "message_id", message.ID, "chat_id", message.Chat.ID)
 
 	return false, nil
 }
diff --git a/notify/victorops/victorops.go b/notify/victorops/victorops.go
@@ -141,7 +141,7 @@ func (n *Notifier) createVictorOpsPayload(ctx context.Context, as ...*types.Aler
 
 	stateMessage, truncated := notify.TruncateInRunes(stateMessage, maxMessageLenRunes)
 	if truncated {
-		n.logger.Warn("Truncated state_message", "incident", key, "max_runes", maxMessageLenRunes)
+		n.logger.Warn("Truncated state_message", "group_key", key, "max_runes", maxMessageLenRunes)
 	}
 
 	msg := map[string]string{
diff --git a/notify/webex/webex.go b/notify/webex/webex.go
@@ -72,9 +72,10 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 		return false, err
 	}
 
-	n.logger.Debug("extracted group key", "key", key)
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
 
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 	tmpl := notify.TmplText(n.tmpl, data, &err)
 	if err != nil {
 		return false, err
@@ -87,7 +88,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 
 	message, truncated := notify.TruncateInBytes(message, maxMessageSize)
 	if truncated {
-		n.logger.Debug("message truncated due to exceeding maximum allowed length by webex", "truncated_message", message)
+		logger.Debug("message truncated due to exceeding maximum allowed length by webex", "truncated_message", message)
 	}
 
 	w := webhook{
diff --git a/notify/webhook/webhook.go b/notify/webhook/webhook.go
@@ -82,12 +82,11 @@ func (n *Notifier) Notify(ctx context.Context, alerts ...*types.Alert) (bool, er
 
 	groupKey, err := notify.ExtractGroupKey(ctx)
 	if err != nil {
-		// @tjhop: should we `return false, err` here as we do in most
-		// other Notify() implementations?
-		n.logger.Error("error extracting group key", "err", err)
+		return false, err
 	}
 
-	n.logger.Debug("extracted group key", "key", groupKey.String())
+	logger := n.logger.With("group_key", groupKey)
+	logger.Debug("extracted group key")
 
 	msg := &Message{
 		Version:         "4",
diff --git a/notify/wechat/wechat.go b/notify/wechat/wechat.go
@@ -86,8 +86,10 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 		return false, err
 	}
 
-	n.logger.Debug("extracted group key", "key", key)
-	data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)
+	logger := n.logger.With("group_key", key)
+	logger.Debug("extracted group key")
+
+	data := notify.GetTemplateData(ctx, n.tmpl, as, logger)
 
 	tmpl := notify.TmplText(n.tmpl, data, &err)
 	if err != nil {
@@ -174,7 +176,7 @@ func (n *Notifier) Notify(ctx context.Context, as ...*types.Alert) (bool, error)
 	if err != nil {
 		return true, err
 	}
-	n.logger.Debug(string(body), "incident", key)
+	logger.Debug(string(body))
 
 	var weResp weChatResponse
 	if err := json.Unmarshal(body, &weResp); err != nil {
diff --git a/silence/silence.go b/silence/silence.go
@@ -555,8 +555,7 @@ Loop:
 		return
 	}
 	if err := runMaintenance(doMaintenance); err != nil {
-		// @tjhop: this should probably log at error level
-		s.logger.Info("Creating shutdown snapshot failed", "err", err)
+		s.logger.Error("Creating shutdown snapshot failed", "err", err)
 	}
 }
 

Original file line number	Diff line number	Diff line change
`@@ -95,10 +95,11 @@ func (n Notifier) Notify(ctx context.Context, as ...types.Alert) (bool, error)`
`95`	`95`	`return false, err`
`96`	`96`	`}`
`97`	`97`
`98`		`- n.logger.Debug("extracted group key", "key", key)`
	`98`	`+ logger := n.logger.With("group_key", key)`
	`99`	`+ logger.Debug("extracted group key")`
`99`	`100`
`100`	`101`	`alerts := types.Alerts(as...)`
`101`		`- data := notify.GetTemplateData(ctx, n.tmpl, as, n.logger)`
	`102`	`+ data := notify.GetTemplateData(ctx, n.tmpl, as, logger)`
`102`	`103`	`tmpl := notify.TmplText(n.tmpl, data, &err)`
`103`	`104`	`if err != nil {`
`104`	`105`	`return false, err`
`@@ -109,22 +110,22 @@ func (n Notifier) Notify(ctx context.Context, as ...types.Alert) (bool, error)`
`109`	`110`	`return false, err`
`110`	`111`	`}`
`111`	`112`	`if truncated {`
`112`		`- n.logger.Warn("Truncated title", "key", key, "max_runes", maxTitleLenRunes)`
	`113`	`+ logger.Warn("Truncated title", "max_runes", maxTitleLenRunes)`
`113`	`114`	`}`
`114`	`115`	`description, truncated := notify.TruncateInRunes(tmpl(n.conf.Message), maxDescriptionLenRunes)`
`115`	`116`	`if err != nil {`
`116`	`117`	`return false, err`
`117`	`118`	`}`
`118`	`119`	`if truncated {`
`119`		`- n.logger.Warn("Truncated message", "key", key, "max_runes", maxDescriptionLenRunes)`
	`120`	`+ logger.Warn("Truncated message", "max_runes", maxDescriptionLenRunes)`
`120`	`121`	`}`
`121`	`122`
`122`	`123`	`content, truncated := notify.TruncateInRunes(tmpl(n.conf.Content), maxContentLenRunes)`
`123`	`124`	`if err != nil {`
`124`	`125`	`return false, err`
`125`	`126`	`}`
`126`	`127`	`if truncated {`
`127`		`- n.logger.Warn("Truncated message", "key", key, "max_runes", maxContentLenRunes)`
	`128`	`+ logger.Warn("Truncated message", "max_runes", maxContentLenRunes)`
`128`	`129`	`}`
`129`	`130`
`130`	`131`	`color := colorGrey`
`@@ -160,7 +161,7 @@ func (n Notifier) Notify(ctx context.Context, as ...types.Alert) (bool, error)`
`160`	`161`	`if _, err := netUrl.Parse(n.conf.AvatarURL); err == nil {`
`161`	`162`	`w.AvatarURL = n.conf.AvatarURL`
`162`	`163`	`} else {`
`163`		`- n.logger.Warn("Bad avatar url", "key", key)`
	`164`	`+ logger.Warn("Bad avatar url", "key", key)`
`164`	`165`	`}`
`165`	`166`	`}`
`166`	`167`
Original file line number	Diff line number	Diff line change
`@@ -72,6 +72,7 @@ func (n Notifier) Notify(ctx context.Context, as ...types.Alert) (bool, error)`
`72`	`72`	`}`
`73`	`73`
`74`	`74`	`logger := n.logger.With("group_key", key.String())`
	`75`	`+ logger.Debug("extracted group key")`
`75`	`76`
`76`	`77`	`var (`
`77`	`78`	`alerts = types.Alerts(as...)`
Original file line number	Diff line number	Diff line change
`@@ -308,17 +308,18 @@ func (n Notifier) Notify(ctx context.Context, as ...types.Alert) (bool, error)`
`308`	`308`	`if err != nil {`
`309`	`309`	`return false, err`
`310`	`310`	`}`
	`311`	`+ logger := n.logger.With("group_key", key)`
`311`	`312`
`312`	`313`	`var (`
`313`	`314`	`alerts = types.Alerts(as...)`
`314`		`- data = notify.GetTemplateData(ctx, n.tmpl, as, n.logger)`
	`315`	`+ data = notify.GetTemplateData(ctx, n.tmpl, as, logger)`
`315`	`316`	`eventType = pagerDutyEventTrigger`
`316`	`317`	`)`
`317`	`318`	`if alerts.Status() == model.AlertResolved {`
`318`	`319`	`eventType = pagerDutyEventResolve`
`319`	`320`	`}`
`320`	`321`
`321`		`- n.logger.Debug("extracted group key", "key", key, "eventType", eventType)`
	`322`	`+ logger.Debug("extracted group key", "eventType", eventType)`
`322`	`323`
`323`	`324`	`details := make(map[string]string, len(n.conf.Details))`
`324`	`325`	`for k, v := range n.conf.Details {`