Logrus instrumentation hook

go.mod

@@ -12,6 +12,7 @@ require (
 	github.com/mitchellh/go-homedir v1.1.0
 	github.com/opentracing/basictracer-go v1.0.0
 	github.com/opentracing/opentracing-go v1.1.0
+	github.com/sirupsen/logrus v1.5.0
 	github.com/stretchr/testify v1.5.1
 	github.com/undefinedlabs/go-mpatch v0.0.0-20200326085307-1a86426f42a6
 	github.com/vmihailenco/msgpack v4.0.4+incompatible

go.sum

@@ -26,6 +26,8 @@ github.com/google/uuid v1.1.1 h1:Gkbcsh/GbpXz7lPftLA3P6TYMwjCLYm83jiFQZF/3gY=
 github.com/google/uuid v1.1.1/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/kisielk/errcheck v1.2.0/go.mod h1:/BMXB+zMLi60iA8Vv6Ksmxu/1UDYcXs4uQLJ+jE2L00=
 github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1 h1:mweAR1A6xJ3oS2pRaGiHgQ4OO8tzTaLawm8vnODuwDk=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/pretty v0.2.0 h1:s5hAObm+yFO5uHYt5dYjxi2rXrsnmRpJx4OYvIWUaQs=
 github.com/kr/pretty v0.2.0/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
@@ -40,7 +42,10 @@ github.com/opentracing/opentracing-go v1.1.0/go.mod h1:UkNAQd3GIcIGf0SeVgPpRdFSt
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
+github.com/sirupsen/logrus v1.5.0 h1:1N5EYkVAPEywqZRJd7cwnRtCb6xJx7NH3T3WUTF980Q=
+github.com/sirupsen/logrus v1.5.0/go.mod h1:+F7Ogzej0PZc/94MaYx/nvG9jOFMD2osvC3s+Squfpo=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.5.1 h1:nOGnQDM7FYENwehXlg/kFVnos3rEvtKTjRvOWSzb6H4=
 github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA=
 github.com/undefinedlabs/go-mpatch v0.0.0-20200122175732-0044123dbb98 h1:Z/megzdoMbuZ0H/oLmfTw92PAEfyTi1DkvAr8AUzFgw=
@@ -67,6 +72,7 @@ golang.org/x/sync v0.0.0-20181108010431-42b317875d0f/go.mod h1:RxMgew5VJxzue5/jJ
 golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sys v0.0.0-20180830151530-49385e6e1522/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200302150141-5c8b2ff67527 h1:uYVVQ9WP/Ds2ROhcaGPeIdVq0RIXVLwsHlnvJ+cT1So=
 golang.org/x/sys v0.0.0-20200302150141-5c8b2ff67527/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

instrumentation/logrus/hook.go

@@ -0,0 +1,101 @@
+package logrus
+
+import (
+	"fmt"
+	"path/filepath"
+
+	"github.com/opentracing/opentracing-go"
+	otLog "github.com/opentracing/opentracing-go/log"
+
+	log "github.com/sirupsen/logrus"
+
+	"go.undefinedlabs.com/scopeagent/tags"
+	"go.undefinedlabs.com/scopeagent/tracer"
+)
+
+type (
+	ScopeHook struct {
+		LogLevels []log.Level
+	}
+)
+
+var scopeHook = &ScopeHook{}
+
+// Adds an scope hook in the logger if is not already added.
+func AddScopeHook(logger *log.Logger) {
+	// We check first if the logger already contains a ScopeHook instance
+	for _, hooks := range logger.Hooks {
+		for _, hook := range hooks {
+			if _, ok := hook.(*ScopeHook); ok {
+				return
+			}
+		}
+	}
+	logger.AddHook(scopeHook)
+}
+
+// Fire will be called when some logging function is called with current hook
+// It will format log entry to string and write it to appropriate writer
+func (hook *ScopeHook) Fire(entry *log.Entry) error {
+	if entry.Context == nil {
+		return nil
+	}
+
+	// If context is found, we try to find the a span from the context and write the logs
+	if span := opentracing.SpanFromContext(entry.Context); span != nil {
+
+		logLevel := tags.LogLevel_VERBOSE
+		if entry.Level == log.PanicLevel || entry.Level == log.FatalLevel || entry.Level == log.ErrorLevel {
+			logLevel = tags.LogLevel_ERROR
+		} else if entry.Level == log.WarnLevel {
+			logLevel = tags.LogLevel_WARNING
+		} else if entry.Level == log.InfoLevel {
+			logLevel = tags.LogLevel_INFO
+		} else if entry.Level == log.DebugLevel {
+			logLevel = tags.LogLevel_DEBUG
+		} else if entry.Level == log.TraceLevel {
+			logLevel = tags.LogLevel_VERBOSE
+		}
+
+		fields := []otLog.Field{
+			otLog.String(tags.EventType, tags.LogEvent),
+			otLog.String(tags.LogEventLevel, logLevel),
+			otLog.String("log.logger", "logrus"),
+			otLog.String("log.level", entry.Level.String()),
+			otLog.String(tags.EventMessage, entry.Message),
+		}
+
+		if entry.Caller != nil && entry.Caller.File != "" && entry.Caller.Line != 0 {
+			fields = append(fields, otLog.String(tags.EventSource, fmt.Sprintf("%s:%d", filepath.Clean(entry.Caller.File), entry.Caller.Line)))
+		}
+
+		if entry.Data != nil {
+			for k, v := range entry.Data {
+				fields = append(fields, otLog.Object(k, v))
+			}
+		}
+
+		if ownSpan, ok := span.(tracer.Span); ok {
+			ownSpan.LogFieldsWithTimestamp(entry.Time, fields...)
+		} else {
+			span.LogFields(fields...)
+		}
+	}
+	return nil
+}
+
+// Levels define on which log levels this hook would trigger
+func (hook *ScopeHook) Levels() []log.Level {
+	if hook.LogLevels == nil {
+		hook.LogLevels = []log.Level{
+			log.PanicLevel,
+			log.FatalLevel,
+			log.ErrorLevel,
+			log.WarnLevel,
+			log.InfoLevel,
+			log.DebugLevel,
+			log.TraceLevel,
+		}
+	}
+	return hook.LogLevels
+}

instrumentation/logrus/hook_test.go

@@ -0,0 +1,35 @@
+package logrus
+
+import (
+	"github.com/sirupsen/logrus"
+	"os"
+	"testing"
+
+	"go.undefinedlabs.com/scopeagent"
+	"go.undefinedlabs.com/scopeagent/agent"
+	"go.undefinedlabs.com/scopeagent/tracer"
+)
+
+var r *tracer.InMemorySpanRecorder
+
+func TestMain(m *testing.M) {
+	// Test tracer
+	r = tracer.NewInMemoryRecorder()
+	os.Exit(scopeagent.Run(m, agent.WithRecorders(r)))
+}
+
+func TestLogrus(t *testing.T) {
+	ctx := scopeagent.GetContextFromTest(t)
+	r.Reset()
+
+	logger := logrus.New()
+	logger.SetLevel(logrus.TraceLevel)
+	logger.SetReportCaller(true)
+	AddScopeHook(logger)
+
+	logger.WithContext(ctx).WithField("Data", "Value").Error("Error message")
+	logger.WithContext(ctx).WithField("Data", "Value").Warn("Warning message")
+	logger.WithContext(ctx).WithField("Data", "Value").Info("Info message")
+	logger.WithContext(ctx).WithField("Data", "Value").Debug("Debug message")
+	logger.WithContext(ctx).WithField("Data", "Value").Trace("Trace message")
+}

tracer/span.go

@@ -25,6 +25,9 @@ type Span interface {
 
 	// Sets the start time
 	SetStart(start time.Time) opentracing.Span
+
+	// Log fields with timestamp
+	LogFieldsWithTimestamp(t time.Time, fields ...log.Field)
 }
 
 // Implements the `Span` interface. Created via tracerImpl (see
@@ -143,6 +146,23 @@ func (s *spanImpl) LogFields(fields ...log.Field) {
 	s.appendLog(lr)
 }
 
+func (s *spanImpl) LogFieldsWithTimestamp(t time.Time, fields ...log.Field) {
+	lr := opentracing.LogRecord{
+		Timestamp: t,
+		Fields:    fields,
+	}
+	defer s.onLogFields(lr)
+	s.Lock()
+	defer s.Unlock()
+	if s.trim() || s.tracer.options.DropAllLogs {
+		return
+	}
+	if lr.Timestamp.IsZero() {
+		lr.Timestamp = time.Now()
+	}
+	s.appendLog(lr)
+}
+
 func (s *spanImpl) LogEvent(event string) {
 	s.Log(opentracing.LogData{
 		Event: event,