contextual logging

impl/cmd/main.go

@@ -31,10 +31,7 @@ import (
 //	@license.name	Apache 2.0
 //	@license.url	http://www.apache.org/licenses/LICENSE-2.0.html
 func main() {
-	logrus.SetFormatter(&logrus.JSONFormatter{
-		DisableTimestamp: false,
-		PrettyPrint:      true,
-	})
+	logrus.SetFormatter(&logrus.JSONFormatter{})
 	logrus.SetReportCaller(true)
 
 	log := logrus.NewEntry(logrus.StandardLogger()).WithField("version", config.Version)
@@ -59,10 +56,10 @@ func run() error {
 		configPath = envConfigPath
 	}
 
-	logrus.WithField("path", configPath).Info("loading config from file")
+	logrus.WithContext(ctx).WithField("path", configPath).Info("loading config from file")
 	cfg, err := config.LoadConfig(configPath)
 	if err != nil {
-		logrus.Fatalf("could not instantiate config: %s", err.Error())
+		logrus.WithContext(ctx).Fatalf("could not instantiate config: %s", err.Error())
 	}
 
 	// set up logger
@@ -91,15 +88,15 @@ func run() error {
 
 	serverErrors := make(chan error, 1)
 	go func() {
-		logrus.WithField("listen_address", s.Addr).Info("starting listener")
+		logrus.WithContext(ctx).WithField("listen_address", s.Addr).Info("starting listener")
 		serverErrors <- s.ListenAndServe()
 	}()
 
 	select {
 	case err = <-serverErrors:
 		return errors.Wrap(err, "server error")
 	case sig := <-shutdown:
-		logrus.WithField("signal", sig.String()).Info("shutdown signal received")
+		logrus.WithContext(ctx).WithField("signal", sig.String()).Info("shutdown signal received")
 
 		ctx, cancel := context.WithTimeout(context.Background(), time.Second*5)
 		defer cancel()

impl/pkg/dht/dht.go

@@ -88,7 +88,7 @@ func (d *DHT) Put(ctx context.Context, request bep44.Put) (string, error) {
 
 	// Check if there are any nodes in the DHT
 	if len(d.Server.Nodes()) == 0 {
-		logrus.Warn("no nodes available in the DHT for publishing")
+		logrus.WithContext(ctx).Warn("no nodes available in the DHT for publishing")
 	}
 
 	key := util.Z32Encode(request.K[:])
@@ -101,7 +101,7 @@ func (d *DHT) Put(ctx context.Context, request bep44.Put) (string, error) {
 		}
 		return "", errutil.LoggingNewErrorf("failed to put key[%s] into dht, tried %d nodes, got %d responses", key, t.NumAddrsTried, t.NumResponses)
 	} else {
-		logrus.WithField("key", key).Debug("successfully put key into dht")
+		logrus.WithContext(ctx).WithField("key", key).Debug("successfully put key into dht")
 	}
 	return util.Z32Encode(request.K[:]), nil
 }

impl/pkg/server/util.go

@@ -46,7 +46,7 @@ func RespondBytes(c *gin.Context, data []byte, statusCode int) {
 
 // LoggingRespondError sends an error response back to the client as a safe error
 func LoggingRespondError(c *gin.Context, err error, statusCode int) {
-	logrus.WithError(err).Error()
+	logrus.WithContext(c).WithError(err).Error()
 	Respond(c, err, statusCode)
 }
 

impl/pkg/service/pkarr.go

@@ -76,7 +76,7 @@ func (s *PkarrService) PublishPkarr(ctx context.Context, id string, record pkarr
 	if got, err := s.cache.Get(id); err == nil {
 		var resp pkarr.Response
 		if err = json.Unmarshal(got, &resp); err == nil && record.Response().Equals(resp) {
-			logrus.WithField("record_id", id).Debug("resolved pkarr record from cache with matching response")
+			logrus.WithContext(ctx).WithField("record_id", id).Debug("resolved pkarr record from cache with matching response")
 			return nil
 		}
 	}
@@ -101,7 +101,7 @@ func (s *PkarrService) PublishPkarr(ctx context.Context, id string, record pkarr
 		defer cancel()
 
 		if _, err = s.dht.Put(putCtx, record.BEP44()); err != nil {
-			logrus.WithError(err).Errorf("error from dht.Put for record: %s", id)
+			logrus.WithContext(ctx).WithError(err).Errorf("error from dht.Put for record: %s", id)
 		}
 	}()
 
@@ -117,17 +117,17 @@ func (s *PkarrService) GetPkarr(ctx context.Context, id string) (*pkarr.Response
 	if got, err := s.cache.Get(id); err == nil {
 		var resp pkarr.Response
 		if err = json.Unmarshal(got, &resp); err == nil {
-			logrus.WithField("record_id", id).Debug("resolved pkarr record from cache")
+			logrus.WithContext(ctx).WithField("record_id", id).Debug("resolved pkarr record from cache")
 			return &resp, nil
 		}
-		logrus.WithError(err).WithField("record", id).Warn("failed to get pkarr record from cache, falling back to dht")
+		logrus.WithContext(ctx).WithError(err).WithField("record", id).Warn("failed to get pkarr record from cache, falling back to dht")
 	}
 
 	// next do a dht lookup
 	got, err := s.dht.GetFull(ctx, id)
 	if err != nil {
 		// try to resolve from storage before returning and error
-		logrus.WithError(err).WithField("record", id).Warn("failed to get pkarr record from dht, attempting to resolve from storage")
+		logrus.WithContext(ctx).WithError(err).WithField("record", id).Warn("failed to get pkarr record from dht, attempting to resolve from storage")
 
 		rawID, err := util.Z32Decode(id)
 		if err != nil {
@@ -136,11 +136,11 @@ func (s *PkarrService) GetPkarr(ctx context.Context, id string) (*pkarr.Response
 
 		record, err := s.db.ReadRecord(ctx, rawID)
 		if err != nil || record == nil {
-			logrus.WithError(err).WithField("record", id).Error("failed to resolve pkarr record from storage")
+			logrus.WithContext(ctx).WithError(err).WithField("record", id).Error("failed to resolve pkarr record from storage")
 			return nil, err
 		}
 
-		logrus.WithField("record", id).Debug("resolved pkarr record from storage")
+		logrus.WithContext(ctx).WithField("record", id).Debug("resolved pkarr record from storage")
 		resp := record.Response()
 		if err = s.addRecordToCache(id, record.Response()); err != nil {
 			logrus.WithError(err).WithField("record", id).Error("failed to set pkarr record in cache")
@@ -166,7 +166,7 @@ func (s *PkarrService) GetPkarr(ctx context.Context, id string) (*pkarr.Response
 
 	// add the record to cache, do it here to avoid duplicate calculations
 	if err = s.addRecordToCache(id, resp); err != nil {
-		logrus.WithError(err).Errorf("failed to set pkarr record[%s] in cache", id)
+		logrus.WithContext(ctx).WithError(err).Errorf("failed to set pkarr record[%s] in cache", id)
 	}
 
 	return &resp, nil
@@ -206,7 +206,7 @@ func (s *PkarrService) republish() {
 		}
 
 		if len(allRecords) == 0 {
-			logrus.Info("No records to republish")
+			logrus.Info("no records to republish")
 			return
 		}
 

impl/pkg/storage/db/bolt/bolt.go

@@ -141,7 +141,7 @@ func (b *Bolt) read(ctx context.Context, namespace, key string) ([]byte, error)
 	err := b.db.View(func(tx *bolt.Tx) error {
 		bucket := tx.Bucket([]byte(namespace))
 		if bucket == nil {
-			logrus.WithField("namespace", namespace).Info("namespace does not exist")
+			logrus.WithContext(ctx).WithField("namespace", namespace).Info("namespace does not exist")
 			return nil
 		}
 		result = bucket.Get([]byte(key))
@@ -175,7 +175,7 @@ func (b *Bolt) readSeveral(ctx context.Context, namespace string, after []byte,
 	err := b.db.View(func(tx *bolt.Tx) error {
 		bucket := tx.Bucket([]byte(namespace))
 		if bucket == nil {
-			logrus.WithField("namespace", namespace).Warn("namespace does not exist")
+			logrus.WithContext(ctx).WithField("namespace", namespace).Warn("namespace does not exist")
 			return nil
 		}
 
@@ -210,7 +210,7 @@ func (b *Bolt) RecordCount(ctx context.Context) (int, error) {
 	err := b.db.View(func(tx *bolt.Tx) error {
 		bucket := tx.Bucket([]byte(pkarrNamespace))
 		if bucket == nil {
-			logrus.WithField("namespace", pkarrNamespace).Warn("namespace does not exist")
+			logrus.WithContext(ctx).WithField("namespace", pkarrNamespace).Warn("namespace does not exist")
 			return nil
 		}
 		count = bucket.Stats().KeyN

impl/pkg/storage/db/postgres/postgres.go

@@ -135,7 +135,7 @@ func (p Postgres) ListRecords(ctx context.Context, nextPageToken []byte, limit i
 		record, err := pkarr.NewRecord(row.Key, row.Value, row.Sig, row.Seq)
 		if err != nil {
 			// TODO: do something useful if this happens
-			logrus.WithError(err).WithField("record_id", row.ID).Warn("error loading record from database, skipping")
+			logrus.WithContext(ctx).WithError(err).WithField("record_id", row.ID).Warn("error loading record from database, skipping")
 			continue
 		}