better tracing (#182)

* better tracing

* more logging

impl/cmd/main.go

@@ -12,6 +12,7 @@ import (
 	"github.com/sirupsen/logrus"
 
 	"github.com/TBD54566975/did-dht-method/config"
+	int "github.com/TBD54566975/did-dht-method/internal/util"
 	"github.com/TBD54566975/did-dht-method/pkg/dht"
 	"github.com/TBD54566975/did-dht-method/pkg/server"
 	"github.com/TBD54566975/did-dht-method/pkg/telemetry"
@@ -54,6 +55,8 @@ func run() error {
 
 	// set up telemetry
 	if cfg.ServerConfig.Telemetry {
+		// add trace hook to logrus
+		logrus.AddHook(&int.TraceHook{})
 		if err = telemetry.SetupTelemetry(ctx); err != nil {
 			logrus.WithContext(ctx).WithError(err).Fatal("error initializing telemetry")
 		}

impl/internal/util/logging.go

@@ -0,0 +1,33 @@
+package util
+
+import (
+	"github.com/sirupsen/logrus"
+	"go.opentelemetry.io/otel/trace"
+)
+
+// TraceHook is a logrus hook that adds trace information to log entries
+type TraceHook struct{}
+
+func (h *TraceHook) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+func (h *TraceHook) Fire(entry *logrus.Entry) error {
+	ctx := entry.Context
+	if ctx == nil {
+		return nil
+	}
+
+	span := trace.SpanFromContext(ctx)
+	if !span.SpanContext().IsValid() {
+		return nil
+	}
+
+	traceID := span.SpanContext().TraceID().String()
+	spanID := span.SpanContext().SpanID().String()
+
+	entry.Data["traceID"] = traceID
+	entry.Data["spanID"] = spanID
+
+	return nil
+}

impl/pkg/server/health.go

@@ -4,6 +4,8 @@ import (
 	"net/http"
 
 	"github.com/gin-gonic/gin"
+
+	"github.com/TBD54566975/did-dht-method/pkg/telemetry"
 )
 
 type GetHealthCheckResponse struct {
@@ -25,6 +27,9 @@ const (
 //	@Success		200	{object}	GetHealthCheckResponse
 //	@Router			/health [get]
 func Health(c *gin.Context) {
+	_, span := telemetry.GetTracer().Start(c, "HealthHTTP.Health")
+	defer span.End()
+
 	status := GetHealthCheckResponse{Status: HealthOK}
 	Respond(c, status, http.StatusOK)
 }

impl/pkg/server/pkarr.go

@@ -13,6 +13,7 @@ import (
 	"github.com/TBD54566975/did-dht-method/internal/util"
 	"github.com/TBD54566975/did-dht-method/pkg/pkarr"
 	"github.com/TBD54566975/did-dht-method/pkg/service"
+	"github.com/TBD54566975/did-dht-method/pkg/telemetry"
 )
 
 // PkarrRouter is the router for the Pkarr API
@@ -39,6 +40,9 @@ func NewPkarrRouter(service *service.PkarrService) (*PkarrRouter, error) {
 //	@Failure		500	{string}	string	"Internal server error"
 //	@Router			/{id} [get]
 func (r *PkarrRouter) GetRecord(c *gin.Context) {
+	ctx, span := telemetry.GetTracer().Start(c, "PkarrHTTP.GetRecord")
+	defer span.End()
+
 	id := GetParam(c, IDParam)
 	if id == nil || *id == "" {
 		LoggingRespondErrMsg(c, "missing id param", http.StatusBadRequest)
@@ -56,7 +60,7 @@ func (r *PkarrRouter) GetRecord(c *gin.Context) {
 		return
 	}
 
-	resp, err := r.service.GetPkarr(c, *id)
+	resp, err := r.service.GetPkarr(ctx, *id)
 	if err != nil {
 		// TODO(gabe): provide a more maintainable way to handle custom errors
 		if strings.Contains(err.Error(), "spam") {
@@ -93,6 +97,9 @@ func (r *PkarrRouter) GetRecord(c *gin.Context) {
 //	@Failure		500	{string}	string	"Internal server error"
 //	@Router			/{id} [put]
 func (r *PkarrRouter) PutRecord(c *gin.Context) {
+	ctx, span := telemetry.GetTracer().Start(c, "PkarrHTTP.PutRecord")
+	defer span.End()
+
 	id := GetParam(c, IDParam)
 	if id == nil || *id == "" {
 		LoggingRespondErrMsg(c, "missing id param", http.StatusBadRequest)
@@ -132,7 +139,7 @@ func (r *PkarrRouter) PutRecord(c *gin.Context) {
 		return
 	}
 
-	if err = r.service.PublishPkarr(c, *id, *request); err != nil {
+	if err = r.service.PublishPkarr(ctx, *id, *request); err != nil {
 		LoggingRespondErrWithMsg(c, err, "failed to publish pkarr record", http.StatusInternalServerError)
 		return
 	}

impl/pkg/service/pkarr.go

@@ -110,6 +110,7 @@ func (s *PkarrService) PublishPkarr(ctx context.Context, id string, record pkarr
 	if err = s.cache.Set(id, recordBytes); err != nil {
 		return err
 	}
+	logrus.WithContext(ctx).WithField("record", id).Debug("added pkarr record to cache and db")
 
 	// return here and put it in the DHT asynchronously
 	go func() {
@@ -119,6 +120,8 @@ func (s *PkarrService) PublishPkarr(ctx context.Context, id string, record pkarr
 
 		if _, err = s.dht.Put(putCtx, record.BEP44()); err != nil {
 			logrus.WithContext(ctx).WithError(err).Errorf("error from dht.Put for record: %s", id)
+		} else {
+			logrus.WithContext(ctx).WithField("record", id).Debug("put pkarr record to DHT")
 		}
 	}()