Add open telemetry logging hook for logrus

cpuguy83 · cpuguy83 · commit 45c3453a7cd9 · 2021-09-21T21:19:28.000Z
This adds valuable logging data to the open telemetry traces.

When the trace is not recording we don't bother doing anything as it is
relatively expensive to convert logrus data to otel just due to the
nature of how logrus works.

The way this works is that we now set a context on the logrus.Entry that
gets passed around which the hook then uses to determine if there is an
active span to forward the logs to.

Signed-off-by: Brian Goff &lt;cpuguy83@gmail.com&gt;
diff --git a/cmd/containerd/command/main.go b/cmd/containerd/command/main.go
@@ -320,6 +320,8 @@ func applyFlags(context *cli.Context, config *srvconfig.Config) error {
 	if err := setLogFormat(config); err != nil {
 		return err
 	}
+	setLogHooks()
+
 	for _, v := range []struct {
 		name string
 		d    *string
@@ -385,6 +387,10 @@ func setLogFormat(config *srvconfig.Config) error {
 	return nil
 }
 
+func setLogHooks() {
+	logrus.StandardLogger().AddHook(tracing.NewLogrusHook())
+}
+
 func dumpStacks(writeToFile bool) {
 	var (
 		buf       []byte
diff --git a/log/context.go b/log/context.go
@@ -52,7 +52,8 @@ const (
 // WithLogger returns a new context with the provided logger. Use in
 // combination with logger.WithField(s) for great effect.
 func WithLogger(ctx context.Context, logger *logrus.Entry) context.Context {
-	return context.WithValue(ctx, loggerKey{}, logger)
+	e := logger.WithContext(ctx)
+	return context.WithValue(ctx, loggerKey{}, e)
 }
 
 // GetLogger retrieves the current logger from the context. If no logger is
@@ -61,7 +62,7 @@ func GetLogger(ctx context.Context) *logrus.Entry {
 	logger := ctx.Value(loggerKey{})
 
 	if logger == nil {
-		return L
+		return L.WithContext(ctx)
 	}
 
 	return logger.(*logrus.Entry)
diff --git a/log/context_test.go b/log/context_test.go
@@ -25,8 +25,6 @@ import (
 
 func TestLoggerContext(t *testing.T) {
 	ctx := context.Background()
-	assert.Equal(t, GetLogger(ctx), L)      // should be same as L variable
-	assert.Equal(t, G(ctx), GetLogger(ctx)) // these should be the same.
 
 	ctx = WithLogger(ctx, G(ctx).WithField("test", "one"))
 	assert.Equal(t, GetLogger(ctx).Data["test"], "one")
diff --git a/tracing/log.go b/tracing/log.go
@@ -0,0 +1,66 @@
+/*
+   Copyright The containerd Authors.
+
+   Licensed under the Apache License, Version 2.0 (the "License");
+   you may not use this file except in compliance with the License.
+   You may obtain a copy of the License at
+
+       http://www.apache.org/licenses/LICENSE-2.0
+
+   Unless required by applicable law or agreed to in writing, software
+   distributed under the License is distributed on an "AS IS" BASIS,
+   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+   See the License for the specific language governing permissions and
+   limitations under the License.
+*/
+
+package tracing
+
+import (
+	"github.com/sirupsen/logrus"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
+)
+
+// NewLogrusHook creates a new logrus hook
+func NewLogrusHook() *LogrusHook {
+	return &LogrusHook{}
+}
+
+// LogrusHook is a logrus hook which adds logrus events to active spans.
+// If the span is not recording or the span context is invalid, the hook is a no-op.
+type LogrusHook struct{}
+
+// Levels returns the logrus levels that this hook is interested in.
+func (h *LogrusHook) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+// Fire is called when a log event occurs.
+func (h *LogrusHook) Fire(entry *logrus.Entry) error {
+	span := trace.SpanFromContext(entry.Context)
+	if span == nil {
+		return nil
+	}
+
+	if !span.SpanContext().IsValid() || !span.IsRecording() {
+		return nil
+	}
+
+	span.AddEvent(
+		entry.Message,
+		trace.WithAttributes(logrusDataToAttrs(entry.Data)...),
+		trace.WithAttributes(attribute.String("level", entry.Level.String())),
+		trace.WithTimestamp(entry.Time),
+	)
+
+	return nil
+}
+
+func logrusDataToAttrs(data logrus.Fields) []attribute.KeyValue {
+	attrs := make([]attribute.KeyValue, 0, len(data))
+	for k, v := range data {
+		attrs = append(attrs, attribute.Any(k, v))
+	}
+	return attrs
+}
