From 799ce0b9a33cb46a2d7ef3ff5de68c7cbf004c5f Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Thu, 12 Oct 2023 14:28:03 +1100 Subject: [PATCH 1/2] Use common logger instance to reduce duplication in `Group.Eval()` Signed-off-by: Charles Korn --- rules/manager.go | 21 +++++++++++---------- 1 file changed, 11 insertions(+), 10 deletions(-) diff --git a/rules/manager.go b/rules/manager.go index ed6923cfdf..67e43b2a71 100644 --- a/rules/manager.go +++ b/rules/manager.go @@ -672,6 +672,7 @@ func (g *Group) Eval(ctx context.Context, ts time.Time) { } func(i int, rule Rule) { + logger := log.WithPrefix(g.logger, "name", rule.Name(), "index", i) ctx, sp := otel.Tracer("").Start(ctx, "rule") sp.SetAttributes(attribute.String("name", rule.Name())) defer func(t time.Time) { @@ -696,7 +697,7 @@ func (g *Group) Eval(ctx context.Context, ts time.Time) { // happens on shutdown and thus we skip logging of any errors here. var eqc promql.ErrQueryCanceled if !errors.As(err, &eqc) { - level.Warn(g.logger).Log("name", rule.Name(), "index", i, "msg", "Evaluating rule failed", "rule", rule, "err", err) + level.Warn(logger).Log("msg", "Evaluating rule failed", "rule", rule, "err", err) } return } @@ -722,7 +723,7 @@ func (g *Group) Eval(ctx context.Context, ts time.Time) { sp.SetStatus(codes.Error, err.Error()) g.metrics.EvalFailures.WithLabelValues(GroupKey(g.File(), g.Name())).Inc() - level.Warn(g.logger).Log("name", rule.Name(), "index", i, "msg", "Rule sample appending failed", "err", err) + level.Warn(logger).Log("msg", "Rule sample appending failed", "err", err) return } g.seriesInPreviousEval[i] = seriesReturned @@ -746,15 +747,15 @@ func (g *Group) Eval(ctx context.Context, ts time.Time) { switch { case errors.Is(unwrappedErr, storage.ErrOutOfOrderSample): numOutOfOrder++ - level.Debug(g.logger).Log("name", rule.Name(), "index", i, "msg", "Rule evaluation result discarded", "err", err, "sample", s) + level.Warn(logger).Log("msg", "Rule evaluation result discarded", "err", err, "sample", s) case errors.Is(unwrappedErr, storage.ErrTooOldSample): numTooOld++ - level.Debug(g.logger).Log("name", rule.Name(), "index", i, "msg", "Rule evaluation result discarded", "err", err, "sample", s) + level.Warn(logger).Log("msg", "Rule evaluation result discarded", "err", err, "sample", s) case errors.Is(unwrappedErr, storage.ErrDuplicateSampleForTimestamp): numDuplicates++ - level.Debug(g.logger).Log("name", rule.Name(), "index", i, "msg", "Rule evaluation result discarded", "err", err, "sample", s) + level.Warn(logger).Log("msg", "Rule evaluation result discarded", "err", err, "sample", s) default: - level.Warn(g.logger).Log("name", rule.Name(), "index", i, "msg", "Rule evaluation result discarded", "err", err, "sample", s) + level.Warn(logger).Log("msg", "Rule evaluation result discarded", "err", err, "sample", s) } } else { buf := [1024]byte{} @@ -762,13 +763,13 @@ func (g *Group) Eval(ctx context.Context, ts time.Time) { } } if numOutOfOrder > 0 { - level.Warn(g.logger).Log("name", rule.Name(), "index", i, "msg", "Error on ingesting out-of-order result from rule evaluation", "numDropped", numOutOfOrder) + level.Warn(logger).Log("msg", "Error on ingesting out-of-order result from rule evaluation", "numDropped", numOutOfOrder) } if numTooOld > 0 { - level.Warn(g.logger).Log("name", rule.Name(), "index", i, "msg", "Error on ingesting too old result from rule evaluation", "numDropped", numTooOld) + level.Warn(logger).Log("msg", "Error on ingesting too old result from rule evaluation", "numDropped", numTooOld) } if numDuplicates > 0 { - level.Warn(g.logger).Log("name", rule.Name(), "index", i, "msg", "Error on ingesting results from rule evaluation with different value but same timestamp", "numDropped", numDuplicates) + level.Warn(logger).Log("msg", "Error on ingesting results from rule evaluation with different value but same timestamp", "numDropped", numDuplicates) } for metric, lset := range g.seriesInPreviousEval[i] { @@ -787,7 +788,7 @@ func (g *Group) Eval(ctx context.Context, ts time.Time) { // Do not count these in logging, as this is expected if series // is exposed from a different rule. default: - level.Warn(g.logger).Log("name", rule.Name(), "index", i, "msg", "Adding stale sample failed", "sample", lset.String(), "err", err) + level.Warn(logger).Log("msg", "Adding stale sample failed", "sample", lset.String(), "err", err) } } } From 8801c44cff0cf95170d2ed4b7b541143866e7e23 Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Thu, 12 Oct 2023 14:28:29 +1100 Subject: [PATCH 2/2] Add trace ID to log lines emitted during rule evaluation Signed-off-by: Charles Korn --- rules/manager.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/rules/manager.go b/rules/manager.go index 67e43b2a71..62a47eb938 100644 --- a/rules/manager.go +++ b/rules/manager.go @@ -684,6 +684,10 @@ func (g *Group) Eval(ctx context.Context, ts time.Time) { rule.SetEvaluationTimestamp(t) }(time.Now()) + if sp.SpanContext().IsSampled() && sp.SpanContext().HasTraceID() { + logger = log.WithPrefix(g.logger, "traceID", sp.SpanContext().TraceID()) + } + g.metrics.EvalTotal.WithLabelValues(GroupKey(g.File(), g.Name())).Inc() vector, err := rule.Eval(ctx, evaluationDelay, ts, g.opts.QueryFunc, g.opts.ExternalURL, g.Limit())