add traceid log field if tracing context if available (#35)

pkg/api/pingpong.go

@@ -22,31 +22,31 @@ func (s *server) pingpongHandler(w http.ResponseWriter, r *http.Request) {
 	peerID := mux.Vars(r)["peer-id"]
 	ctx := r.Context()
 
-	span, ctx := s.Tracer.StartSpanFromContext(ctx, "pingpong-api")
+	span, logger, ctx := s.Tracer.StartSpanFromContext(ctx, "pingpong-api", s.Logger)
 	defer span.Finish()
 
 	address, err := swarm.ParseHexAddress(peerID)
 	if err != nil {
-		s.Logger.Debugf("pingpong: parse peer address %s: %v", peerID, err)
+		logger.Debugf("pingpong: parse peer address %s: %v", peerID, err)
 		jsonhttp.BadRequest(w, "invalid peer address")
 		return
 	}
 
 	rtt, err := s.Pingpong.Ping(ctx, address, "hey", "there", ",", "how are", "you", "?")
 	if err != nil {
-		s.Logger.Debugf("pingpong: ping %s: %v", peerID, err)
+		logger.Debugf("pingpong: ping %s: %v", peerID, err)
 		if errors.Is(err, p2p.ErrPeerNotFound) {
 			jsonhttp.NotFound(w, "peer not found")
 			return
 		}
 
-		s.Logger.Errorf("pingpong failed to peer %s", peerID)
+		logger.Errorf("pingpong failed to peer %s", peerID)
 		jsonhttp.InternalServerError(w, nil)
 		return
 	}
 	s.metrics.PingRequestCount.Inc()
 
-	s.Logger.Infof("pingpong succeeded to peer %s", peerID)
+	logger.Infof("pingpong succeeded to peer %s", peerID)
 	jsonhttp.OK(w, pingpongResponse{
 		RTT: rtt.String(),
 	})

pkg/logging/logging.go

@@ -24,6 +24,7 @@ type Logger interface {
 	WithField(key string, value interface{}) *logrus.Entry
 	WithFields(fields logrus.Fields) *logrus.Entry
 	WriterLevel(logrus.Level) *io.PipeWriter
+	NewEntry() *logrus.Entry
 }
 
 type logger struct {
@@ -45,3 +46,7 @@ func New(w io.Writer, level logrus.Level) Logger {
 		metrics: metrics,
 	}
 }
+
+func (l *logger) NewEntry() *logrus.Entry {
+	return logrus.NewEntry(l.Logger)
+}

pkg/p2p/libp2p/libp2p.go

@@ -248,6 +248,10 @@ func (s *Service) AddProtocol(p p2p.ProtocolSpec) (err error) {
 				return
 			}
 
+			logger := tracing.NewLoggerWithTraceID(ctx, s.logger)
+
+			logger.Tracef("handle protocol %s/%s: stream %s: peer %s", p.Name, p.Version, ss.Name, overlay)
+
 			s.metrics.HandledStreamCount.Inc()
 			if err := ss.Handler(ctx, p2p.Peer{Address: overlay}, stream); err != nil {
 				var e *p2p.DisconnectError
@@ -256,7 +260,8 @@ func (s *Service) AddProtocol(p p2p.ProtocolSpec) (err error) {
 					_ = s.Disconnect(overlay)
 				}
 
-				s.logger.Debugf("handle protocol %s/%s: stream %s: peer %s: %v", p.Name, p.Version, ss.Name, overlay, err)
+				logger.Debugf("handle protocol %s/%s: stream %s: peer %s: %v", p.Name, p.Version, ss.Name, overlay, err)
+				return
 			}
 		})
 	}

pkg/p2p/libp2p/tracing_test.go

@@ -44,7 +44,7 @@ func TestTracing(t *testing.T) {
 	handled := make(chan struct{})
 	if err := s1.AddProtocol(newTestProtocol(func(ctx context.Context, _ p2p.Peer, _ p2p.Stream) error {
 
-		span, _ := tracer1.StartSpanFromContext(ctx, "test-p2p-handler")
+		span, _, _ := tracer1.StartSpanFromContext(ctx, "test-p2p-handler", nil)
 		defer span.Finish()
 
 		handledTracingSpan = fmt.Sprint(span.Context())
@@ -66,7 +66,7 @@ func TestTracing(t *testing.T) {
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 
-	span, ctx := tracer2.StartSpanFromContext(ctx, "test-p2p-client")
+	span, _, ctx := tracer2.StartSpanFromContext(ctx, "test-p2p-client", nil)
 	defer span.Finish()
 
 	if fmt.Sprint(span.Context()) == "" {

pkg/pingpong/pingpong.go

@@ -64,7 +64,7 @@ func (s *Service) Protocol() p2p.ProtocolSpec {
 }
 
 func (s *Service) Ping(ctx context.Context, address swarm.Address, msgs ...string) (rtt time.Duration, err error) {
-	span, ctx := s.tracer.StartSpanFromContext(ctx, "pingpong-p2p-ping")
+	span, logger, ctx := s.tracer.StartSpanFromContext(ctx, "pingpong-p2p-ping", s.logger)
 	defer span.Finish()
 
 	start := time.Now()
@@ -92,7 +92,7 @@ func (s *Service) Ping(ctx context.Context, address swarm.Address, msgs ...strin
 			return 0, fmt.Errorf("read message: %w", err)
 		}
 
-		s.logger.Tracef("got pong: %q", pong.Response)
+		logger.Tracef("got pong: %q", pong.Response)
 		s.metrics.PongReceivedCount.Inc()
 	}
 	return time.Since(start), nil
@@ -102,7 +102,7 @@ func (s *Service) handler(ctx context.Context, p p2p.Peer, stream p2p.Stream) er
 	w, r := protobuf.NewWriterAndReader(stream)
 	defer stream.Close()
 
-	span, ctx := s.tracer.StartSpanFromContext(ctx, "pingpong-p2p-handler")
+	span, logger, ctx := s.tracer.StartSpanFromContext(ctx, "pingpong-p2p-handler", s.logger)
 	defer span.Finish()
 
 	var ping pb.Ping
@@ -113,7 +113,7 @@ func (s *Service) handler(ctx context.Context, p p2p.Peer, stream p2p.Stream) er
 			}
 			return fmt.Errorf("read message: %w", err)
 		}
-		s.logger.Tracef("got ping: %q", ping.Greeting)
+		logger.Tracef("got ping: %q", ping.Greeting)
 		s.metrics.PingReceivedCount.Inc()
 
 		if err := w.WriteMsgWithContext(ctx, &pb.Pong{

pkg/tracing/tracing.go

@@ -12,8 +12,10 @@ import (
 	"io"
 	"time"
 
+	"github.com/ethersphere/bee/pkg/logging"
 	"github.com/ethersphere/bee/pkg/p2p"
 	"github.com/opentracing/opentracing-go"
+	"github.com/sirupsen/logrus"
 	"github.com/uber/jaeger-client-go"
 	"github.com/uber/jaeger-client-go/config"
 )
@@ -29,6 +31,9 @@ var (
 	noopTracer = &Tracer{tracer: new(opentracing.NoopTracer)}
 )
 
+// LogField is the key in log message field that holds tracing id value.
+const LogField = "traceid"
+
 // Tracer connect to a tracing server and handles tracing spans and contexts
 // by using opentracing Tracer.
 type Tracer struct {
@@ -71,8 +76,9 @@ func NewTracer(o *Options) (*Tracer, io.Closer, error) {
 }
 
 // StartSpanFromContext starts a new tracing span that is either a root one or a
-// child of existing one from the provided Context.
-func (t *Tracer) StartSpanFromContext(ctx context.Context, operationName string, opts ...opentracing.StartSpanOption) (opentracing.Span, context.Context) {
+// child of existing one from the provided Context. If logger is provided, a new
+// log Entry will be returned with "traceid" log field.
+func (t *Tracer) StartSpanFromContext(ctx context.Context, operationName string, l logging.Logger, opts ...opentracing.StartSpanOption) (opentracing.Span, *logrus.Entry, context.Context) {
 	if t == nil {
 		t = noopTracer
 	}
@@ -84,7 +90,8 @@ func (t *Tracer) StartSpanFromContext(ctx context.Context, operationName string,
 	} else {
 		span = t.tracer.StartSpan(operationName, opts...)
 	}
-	return span, WithContext(ctx, span.Context())
+	sc := span.Context()
+	return span, loggerWithTraceID(sc, l), WithContext(ctx, sc)
 }
 
 // AddContextHeader adds a tracing span context to provided p2p Headers from
@@ -165,3 +172,24 @@ func FromContext(ctx context.Context) opentracing.SpanContext {
 	}
 	return c
 }
+
+// NewLoggerWithTraceID creates a new log Entry with "traceid" field added if it
+// exists in tracing span context stored from go context.
+func NewLoggerWithTraceID(ctx context.Context, l logging.Logger) *logrus.Entry {
+	return loggerWithTraceID(FromContext(ctx), l)
+}
+
+func loggerWithTraceID(sc opentracing.SpanContext, l logging.Logger) *logrus.Entry {
+	if l == nil {
+		return nil
+	}
+	jsc, ok := sc.(jaeger.SpanContext)
+	if !ok {
+		return l.NewEntry()
+	}
+	traceID := jsc.TraceID()
+	if !traceID.IsValid() {
+		return l.NewEntry()
+	}
+	return l.WithField(LogField, traceID.String())
+}

pkg/tracing/tracing_test.go

@@ -8,17 +8,20 @@ import (
 	"context"
 	"fmt"
 	"io"
+	"os"
 	"testing"
 
+	"github.com/ethersphere/bee/pkg/logging"
 	"github.com/ethersphere/bee/pkg/p2p"
 	"github.com/ethersphere/bee/pkg/tracing"
+	"github.com/uber/jaeger-client-go"
 )
 
 func TestSpanFromHeaders(t *testing.T) {
 	tracer, closer := newTracer(t)
 	defer closer.Close()
 
-	span, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation")
+	span, _, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation", nil)
 	defer span.Finish()
 
 	headers := make(p2p.Headers)
@@ -49,7 +52,7 @@ func TestSpanWithContextFromHeaders(t *testing.T) {
 	tracer, closer := newTracer(t)
 	defer closer.Close()
 
-	span, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation")
+	span, _, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation", nil)
 	defer span.Finish()
 
 	headers := make(p2p.Headers)
@@ -81,7 +84,7 @@ func TestFromContext(t *testing.T) {
 	tracer, closer := newTracer(t)
 	defer closer.Close()
 
-	span, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation")
+	span, _, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation", nil)
 	defer span.Finish()
 
 	wantSpanContext := span.Context()
@@ -103,7 +106,7 @@ func TestWithContext(t *testing.T) {
 	tracer, closer := newTracer(t)
 	defer closer.Close()
 
-	span, _ := tracer.StartSpanFromContext(context.Background(), "some-operation")
+	span, _, _ := tracer.StartSpanFromContext(context.Background(), "some-operation", nil)
 	defer span.Finish()
 
 	wantSpanContext := span.Context()
@@ -123,6 +126,82 @@ func TestWithContext(t *testing.T) {
 	}
 }
 
+func TestStartSpanFromContext_logger(t *testing.T) {
+	tracer, closer := newTracer(t)
+	defer closer.Close()
+
+	span, logger, _ := tracer.StartSpanFromContext(context.Background(), "some-operation", logging.New(os.Stdout, 5))
+	defer span.Finish()
+
+	wantTraceID := span.Context().(jaeger.SpanContext).TraceID()
+
+	v, ok := logger.Data[tracing.LogField]
+	if !ok {
+		t.Fatalf("log field %q not found", tracing.LogField)
+	}
+
+	gotTraceID, ok := v.(string)
+	if !ok {
+		t.Fatalf("log field %q is not string", tracing.LogField)
+	}
+
+	if gotTraceID != wantTraceID.String() {
+		t.Errorf("got trace id %q, want %q", gotTraceID, wantTraceID.String())
+	}
+}
+
+func TestStartSpanFromContext_nilLogger(t *testing.T) {
+	tracer, closer := newTracer(t)
+	defer closer.Close()
+
+	span, logger, _ := tracer.StartSpanFromContext(context.Background(), "some-operation", nil)
+	defer span.Finish()
+
+	if logger != nil {
+		t.Error("logger is not nil")
+	}
+}
+
+func TestNewLoggerWithTraceID(t *testing.T) {
+	tracer, closer := newTracer(t)
+	defer closer.Close()
+
+	span, _, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation", nil)
+	defer span.Finish()
+
+	logger := tracing.NewLoggerWithTraceID(ctx, logging.New(os.Stdout, 5))
+
+	wantTraceID := span.Context().(jaeger.SpanContext).TraceID()
+
+	v, ok := logger.Data[tracing.LogField]
+	if !ok {
+		t.Fatalf("log field %q not found", tracing.LogField)
+	}
+
+	gotTraceID, ok := v.(string)
+	if !ok {
+		t.Fatalf("log field %q is not string", tracing.LogField)
+	}
+
+	if gotTraceID != wantTraceID.String() {
+		t.Errorf("got trace id %q, want %q", gotTraceID, wantTraceID.String())
+	}
+}
+
+func TestNewLoggerWithTraceID_nilLogger(t *testing.T) {
+	tracer, closer := newTracer(t)
+	defer closer.Close()
+
+	span, _, ctx := tracer.StartSpanFromContext(context.Background(), "some-operation", nil)
+	defer span.Finish()
+
+	logger := tracing.NewLoggerWithTraceID(ctx, nil)
+
+	if logger != nil {
+		t.Error("logger is not nil")
+	}
+}
+
 func newTracer(t *testing.T) (*tracing.Tracer, io.Closer) {
 	t.Helper()