From 8875061bf7503b560e74c218fd06968882d6ece6 Mon Sep 17 00:00:00 2001 From: Danil Tarasov <87192879+almostinf@users.noreply.github.com> Date: Thu, 18 Jul 2024 11:43:23 +0300 Subject: [PATCH] refactor(notifier): logging related to sending events (#1056) Authored-by: Aleksandr Matsko (@AleksandrMatsko) --- datatypes.go | 18 +++++++++--------- log_fields.go | 26 +++++++++++++++----------- notifier/log_common.go | 16 +++++++++++++++- notifier/notifier.go | 25 +++++++++++++++---------- notifier/plotting.go | 21 ++++++++------------- 5 files changed, 62 insertions(+), 44 deletions(-) diff --git a/datatypes.go b/datatypes.go index 7756697a6..c9a1a234f 100644 --- a/datatypes.go +++ b/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", diff --git a/log_fields.go b/log_fields.go index b5c471542..14264933c 100644 --- a/log_fields.go +++ b/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" ) diff --git a/notifier/log_common.go b/notifier/log_common.go index 67cf4dea8..82756ef70 100644 --- a/notifier/log_common.go +++ b/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 } diff --git a/notifier/notifier.go b/notifier/notifier.go index 6a31134a0..cd81a20d6 100644 --- a/notifier/notifier.go +++ b/notifier/notifier.go @@ -197,29 +197,34 @@ func (notifier *StandardNotifier) runSender(sender moira.Sender, ch chan Notific for pkg := range ch { log := getLogWithPackageContext(¬ifier.logger, &pkg, ¬ifier.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(). diff --git a/notifier/plotting.go b/notifier/plotting.go index 44963d573..041d1d318 100644 --- a/notifier/plotting.go +++ b/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.