Add better logging around republishing and rate limiting (#267)

* update:

* better logging

impl/pkg/server/dht.go

@@ -6,9 +6,9 @@ import (
 	"fmt"
 	"io"
 	"net/http"
-	"strings"
 
 	"github.com/gin-gonic/gin"
+	"github.com/pkg/errors"
 
 	"github.com/TBD54566975/did-dht/internal/util"
 	"github.com/TBD54566975/did-dht/pkg/dht"
@@ -62,11 +62,11 @@ func (r *DHTRouter) GetRecord(c *gin.Context) {
 
 	resp, err := r.service.GetDHT(ctx, *id)
 	if err != nil {
-		// TODO(gabe): provide a more maintainable way to handle custom errors
-		if strings.Contains(err.Error(), "spam") {
+		if errors.Is(err, service.SpamError) {
 			LoggingRespondErrMsg(c, fmt.Sprintf("too many requests for bad key %s", *id), http.StatusTooManyRequests)
 			return
 		}
+
 		LoggingRespondErrWithMsg(c, err, fmt.Sprintf("failed to get dht record: %s", *id), http.StatusInternalServerError)
 		return
 	}

impl/pkg/service/dht.go

@@ -126,19 +126,23 @@ func (s *DHTService) PublishDHT(ctx context.Context, id string, record dht.BEP44
 	return nil
 }
 
+var SpamError = errors.New("rate limited to prevent spam")
+
 // GetDHT returns the full DNS record (including sig data) for the given z-base-32 encoded ID
 func (s *DHTService) GetDHT(ctx context.Context, id string) (*dht.BEP44Response, error) {
 	ctx, span := telemetry.GetTracer().Start(ctx, "DHTService.GetDHT")
 	defer span.End()
 
 	// make sure the key is valid
 	if _, err := util.Z32Decode(id); err != nil {
-		return nil, ssiutil.LoggingCtxErrorMsgf(ctx, err, "failed to decode z-base-32 encoded ID: %s", id)
+		logrus.WithContext(ctx).WithField("record_id", id).Error("failed to decode z-base-32 encoded ID")
+		return nil, errors.Wrapf(err, "failed to decode z-base-32 encoded ID: %s", id)
 	}
 
 	// if the key is in the badGetCache, return an error
 	if _, err := s.badGetCache.Get(id); err == nil {
-		return nil, ssiutil.LoggingCtxErrorMsgf(ctx, err, "bad key [%s] rate limited to prevent spam", id)
+		logrus.WithContext(ctx).WithField("record_id", id).Error("bad key rate limited to prevent spam")
+		return nil, SpamError
 	}
 
 	// first do a cache lookup
@@ -258,6 +262,8 @@ func (s *DHTService) republishRecords(ctx context.Context) []failedRecord {
 
 	var wg sync.WaitGroup
 
+	republishStart := time.Now()
+
 	for {
 		recordsBatch, nextPageToken, err = s.db.ListRecords(ctx, nextPageToken, 1000)
 		if err != nil {
@@ -289,12 +295,18 @@ func (s *DHTService) republishRecords(ctx context.Context) []failedRecord {
 
 	wg.Wait()
 
+	republishEnd := time.Since(republishStart)
+	hours := int(republishEnd.Hours())
+	minutes := int(republishEnd.Minutes()) % 60
+	seconds := int(republishEnd.Seconds()) % 60
+	logrus.WithContext(ctx).Infof("Republishing completed in: %d hours, %d minutes, %d seconds", hours, minutes, seconds)
+
 	successRate := float64(seenRecords-int32(len(failedRecords))) / float64(seenRecords) * 100
 	logrus.WithContext(ctx).WithFields(logrus.Fields{
 		"success": seenRecords - int32(len(failedRecords)),
 		"errors":  len(failedRecords),
 		"total":   seenRecords,
-	}).Debugf("republishing complete with [%d] batches of [%d] total records with a [%.2f] percent success rate", batchCnt, seenRecords, successRate)
+	}).Infof("republishing complete with [%d] batches of [%d] total records with a [%.2f] percent success rate", batchCnt, seenRecords, successRate)
 
 	return failedRecords
 }