refactor(notifier): logging related to sending events (#1056)

Authored-by: Aleksandr Matsko (@AleksandrMatsko)

datatypes.go

@@ -186,6 +186,15 @@ func (trigger TriggerData) GetTriggerURI(frontURI string) string {
 	return ""
 }
 
+// GetTags returns "[tag1][tag2]...[tagN]" string.
+func (trigger *TriggerData) GetTags() string {
+	var buffer bytes.Buffer
+	for _, tag := range trigger.Tags {
+		buffer.WriteString(fmt.Sprintf("[%s]", tag))
+	}
+	return buffer.String()
+}
+
 // Team is a structure that represents a group of users that share a subscriptions and contacts.
 type Team struct {
 	ID          string
@@ -664,15 +673,6 @@ func (events NotificationEvents) GetCurrentState(throttled bool) State {
 	return events.getSubjectState()
 }
 
-// GetTags returns "[tag1][tag2]...[tagN]" string.
-func (trigger *TriggerData) GetTags() string {
-	var buffer bytes.Buffer
-	for _, tag := range trigger.Tags {
-		buffer.WriteString(fmt.Sprintf("[%s]", tag))
-	}
-	return buffer.String()
-}
-
 // GetKey return notification key to prevent duplication to the same contact.
 func (notification *ScheduledNotification) GetKey() string {
 	return fmt.Sprintf("%s:%s:%s:%s:%s:%d:%s:%d:%t:%d",

log_fields.go

@@ -1,15 +1,19 @@
 package moira
 
 const (
-	LogFieldNameCheckpoint      = "moira.checkpoint"
-	LogFieldNameContactID       = "moira.contact.id"
-	LogFieldNameContactType     = "moira.contact.type"
-	LogFieldNameContactValue    = "moira.contact.value"
-	LogFieldNameContext         = "moira.context"
-	LogFieldNameMetricName      = "moira.metric.name"
-	LogFieldNameMetricTimestamp = "moira.metric.timestamp"
-	LogFieldNameTriggerID       = "moira.trigger.id"
-	LogFieldNameTriggerName     = "moira.trigger.name"
-	LogFieldNameSubscriptionID  = "moira.subscription.id"
-	LogFieldNameStackTrace      = "stackTrace"
+	LogFieldNameCheckpoint         = "moira.checkpoint"
+	LogFieldNameContactID          = "moira.contact.id"
+	LogFieldNameContactType        = "moira.contact.type"
+	LogFieldNameContactValue       = "moira.contact.value"
+	LogFieldNameContactUser        = "moira.contact.user"
+	LogFieldNameContactTeam        = "moira.contact.team"
+	LogFieldNamePlotsBuildDuration = "moira.plots.build_duration_ms"
+	LogFieldNameFailCount          = "moira.notification.fail_count"
+	LogFieldNameContext            = "moira.context"
+	LogFieldNameMetricName         = "moira.metric.name"
+	LogFieldNameMetricTimestamp    = "moira.metric.timestamp"
+	LogFieldNameTriggerID          = "moira.trigger.id"
+	LogFieldNameTriggerName        = "moira.trigger.name"
+	LogFieldNameSubscriptionID     = "moira.subscription.id"
+	LogFieldNameStackTrace         = "stackTrace"
 )

notifier/log_common.go

@@ -6,14 +6,28 @@ func getLogWithPackageContext(log *moira.Logger, pkg *NotificationPackage, confi
 	logger := (*log).Clone().
 		String(moira.LogFieldNameContactID, pkg.Contact.ID).
 		String(moira.LogFieldNameContactType, pkg.Contact.Type).
-		String(moira.LogFieldNameContactValue, pkg.Contact.Value)
+		String(moira.LogFieldNameContactValue, pkg.Contact.Value).
+		Int(moira.LogFieldNameFailCount, pkg.FailCount).
+		String(moira.LogFieldNameContext, "notification")
+
 	if pkg.Trigger.ID != "" { // note: test notification without trigger info
 		logger.
 			String(moira.LogFieldNameTriggerID, pkg.Trigger.ID).
 			String(moira.LogFieldNameTriggerName, pkg.Trigger.Name)
 	}
 
+	if pkg.Contact.User != "" {
+		logger.
+			String(moira.LogFieldNameContactUser, pkg.Contact.User)
+	}
+
+	if pkg.Contact.Team != "" {
+		logger.
+			String(moira.LogFieldNameContactTeam, pkg.Contact.Team)
+	}
+
 	SetLogLevelByConfig(config.LogContactsToLevel, pkg.Contact.ID, &logger)
+
 	return logger
 }
 

notifier/notifier.go

@@ -197,29 +197,34 @@ func (notifier *StandardNotifier) runSender(sender moira.Sender, ch chan Notific
 
 	for pkg := range ch {
 		log := getLogWithPackageContext(&notifier.logger, &pkg, &notifier.config)
-		plottingLog := log.Clone().String(moira.LogFieldNameContext, "plotting")
-		plots, err := notifier.buildNotificationPackagePlots(pkg, plottingLog)
-		if err != nil {
+		plots, plotsBuildDuration, plotsBuildErr := notifier.buildNotificationPackagePlots(pkg, log)
+		if plotsBuildErr != nil {
 			var event logging.EventBuilder
-			switch err.(type) { // nolint:errorlint
+			switch plotsBuildErr.(type) { // nolint:errorlint
 			case plotting.ErrNoPointsToRender:
-				event = plottingLog.Debug()
+				event = log.Debug()
 			default:
-				event = plottingLog.Error()
+				event = log.Error()
 			}
 			event.
-				String(moira.LogFieldNameTriggerID, pkg.Trigger.ID).
-				Error(err).
+				Error(plotsBuildErr).
 				Msg("Can't build notification package plot for trigger")
 		}
 
-		err = pkg.Trigger.PopulatedDescription(pkg.Events)
+		err := pkg.Trigger.PopulatedDescription(pkg.Events)
 		if err != nil {
 			log.Warning().
 				Error(err).
 				Msg("Error populate description")
 		}
 
+		logEvent := log.Info()
+		if plots == nil {
+			logEvent.Int64(moira.LogFieldNamePlotsBuildDuration, plotsBuildDuration)
+		}
+		logEvent.
+			Msg("Try to send notification package")
+
 		err = sender.SendEvents(pkg.Events, pkg.Contact, pkg.Trigger, plots, pkg.Throttled)
 		if err == nil {
 			notifier.metrics.MarkSendersOkMetrics(pkg.Contact.Type)
@@ -235,7 +240,7 @@ func (notifier *StandardNotifier) runSender(sender moira.Sender, ch chan Notific
 			if pkg.FailCount > notifier.config.MaxFailAttemptToSendAvailable {
 				log.Error().
 					Error(err).
-					Int("fail_count", pkg.FailCount).
+					Int(moira.LogFieldNameFailCount, pkg.FailCount).
 					Msg("Cannot send notification")
 			} else {
 				log.Warning().

notifier/plotting.go

@@ -52,31 +52,30 @@ func buildTriggerPlots(trigger *moira.Trigger, metricsData map[string][]metricSo
 	return result, nil
 }
 
-// buildNotificationPackagePlots returns bytes slices containing package plots.
-func (notifier *StandardNotifier) buildNotificationPackagePlots(pkg NotificationPackage, logger moira.Logger) ([][]byte, error) {
+// buildNotificationPackagePlots returns bytes slices containing package plots and plots build duration (in ms).
+func (notifier *StandardNotifier) buildNotificationPackagePlots(pkg NotificationPackage, logger moira.Logger) ([][]byte, int64, error) {
 	if !pkg.Plotting.Enabled {
-		return nil, nil
+		return nil, 0, nil
 	}
 	if pkg.Trigger.ID == "" {
-		return nil, nil
+		return nil, 0, nil
 	}
 
-	logger.Info().Msg("Start build plots for package")
 	startTime := time.Now()
 	metricsToShow := pkg.GetMetricNames()
 	if len(metricsToShow) == 0 {
-		return nil, nil
+		return nil, 0, nil
 	}
 	plotTemplate, err := plotting.GetPlotTemplate(pkg.Plotting.Theme, notifier.config.Location)
 	if err != nil {
-		return nil, err
+		return nil, 0, err
 	}
 
 	from, to := resolveMetricsWindow(logger, pkg.Trigger, pkg)
 	evaluateTriggerStartTime := time.Now()
 	metricsData, trigger, err := notifier.evaluateTriggerMetrics(from, to, pkg.Trigger.ID)
 	if err != nil {
-		return nil, err
+		return nil, 0, err
 	}
 	notifier.metrics.PlotsEvaluateTriggerDurationMs.Update(time.Since(evaluateTriggerStartTime).Milliseconds())
 
@@ -89,11 +88,7 @@ func (notifier *StandardNotifier) buildNotificationPackagePlots(pkg Notification
 	result, err := buildTriggerPlots(trigger, metricsData, plotTemplate)
 	notifier.metrics.PlotsBuildDurationMs.Update(time.Since(buildPlotStartTime).Milliseconds())
 
-	logger.Info().
-		Int64("moira.plots.build_duration_ms", time.Since(startTime).Milliseconds()).
-		Msg("Finished build plots for package")
-
-	return result, err
+	return result, time.Since(startTime).Milliseconds(), err
 }
 
 // resolveMetricsWindow returns from, to parameters depending on trigger type.