Switch to logrus

2024-05-11 05:55:04 +00:00 · 2018-12-02 13:58:41 -08:00
parent 9d5fbf2f79
commit 9e5fa38dcf
6 changed files with 166 additions and 55 deletions
--- a/cmd/app/main.go
+++ b/cmd/app/main.go
@@ -3,7 +3,6 @@ package main
 import (
 	"context"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 	"os/signal"
@@ -17,6 +16,8 @@ import (
 	"github.com/mxpv/podsync/pkg/stats"
 	"github.com/mxpv/podsync/pkg/storage"
 	"github.com/mxpv/podsync/pkg/support"
+
+	log "github.com/sirupsen/logrus"
 )

 func main() {
@@ -30,17 +31,17 @@ func main() {

 	cfg, err := config.ReadConfiguration()
 	if err != nil {
-		panic(err)
+		log.WithError(err).Fatal("failed to read configuration")
 	}

 	database, err := storage.NewPG(cfg.PostgresConnectionURL, true)
 	if err != nil {
-		panic(err)
+		log.WithError(err).Fatal("failed to create pg")
 	}

 	statistics, err := stats.NewRedisStats(cfg.RedisURL)
 	if err != nil {
-		panic(err)
+		log.WithError(err).Fatal("failed to create redis")
 	}

 	patreon := support.NewPatreon(database)
@@ -49,12 +50,12 @@ func main() {

 	youtube, err := builders.NewYouTubeBuilder(cfg.YouTubeApiKey)
 	if err != nil {
-		panic(err)
+		log.WithError(err).Fatal("failed to create YouTube builder")
 	}

 	vimeo, err := builders.NewVimeoBuilder(ctx, cfg.VimeoApiKey)
 	if err != nil {
-		panic(err)
+		log.WithError(err).Fatal("failed to create Vimeo builder")
 	}

 	feed, err := feeds.NewFeedService(
@@ -74,19 +75,27 @@ func main() {
 	}

 	go func() {
-		log.Println("running listener")
+		log.Infof("running listener at %s", srv.Addr)
 		if err := srv.ListenAndServe(); err != nil {
-			log.Fatal(err)
+			log.WithError(err).Error("failed to listen")
 		}
 	}()

 	<-stop

-	log.Printf("shutting down server")
+	log.Info("shutting down server")

-	_ = srv.Shutdown(ctx)
-	_ = database.Close()
-	_ = statistics.Close()
+	if err := srv.Shutdown(ctx); err != nil {
+		log.WithError(err).Error("server shutdown failed")
+	}

-	log.Printf("server gracefully stopped")
+	if err := database.Close(); err != nil {
+		log.WithError(err).Error("failed to close database")
+	}
+
+	if err := statistics.Close(); err != nil {
+		log.WithError(err).Error("failed to close stats storage")
+	}
+
+	log.Info("server gracefully stopped")
 }
--- a/go.mod
+++ b/go.mod
@@ -9,7 +9,6 @@ require (
 	github.com/boj/redistore v0.0.0-20160128113310-fc113767cd6b // indirect
 	github.com/bradfitz/gomemcache v0.0.0-20180710155616-bc664df96737 // indirect
 	github.com/bradleypeabody/gorilla-sessions-memcache v0.0.0-20180621172731-4e5d6d543851 // indirect
-	github.com/davecgh/go-spew v1.1.0 // indirect
 	github.com/eduncan911/podcast v1.3.0 // indirect
 	github.com/garyburd/redigo v1.6.0 // indirect
 	github.com/gin-contrib/sessions v0.0.0-20170731012558-a71ea9167c61
@@ -33,8 +32,8 @@ require (
 	github.com/onsi/gomega v1.4.3 // indirect
 	github.com/pelletier/go-toml v1.2.0 // indirect
 	github.com/pkg/errors v0.8.0
-	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/silentsokolov/go-vimeo v1.2.0
+	github.com/sirupsen/logrus v1.2.0
 	github.com/spf13/afero v1.1.1 // indirect
 	github.com/spf13/cast v1.2.0 // indirect
 	github.com/spf13/jwalterweatherman v0.0.0-20180109140146-7c0cea34c8ec // indirect
--- a/go.sum
+++ b/go.sum
@@ -14,8 +14,8 @@ github.com/bradfitz/gomemcache v0.0.0-20180710155616-bc664df96737 h1:rRISKWyXfVx
 github.com/bradfitz/gomemcache v0.0.0-20180710155616-bc664df96737/go.mod h1:PmM6Mmwb0LSuEubjR8N7PtNe1KxZLtOUHtbeikc5h60=
 github.com/bradleypeabody/gorilla-sessions-memcache v0.0.0-20180621172731-4e5d6d543851 h1:kvC96NV3jN3viax6pJqsa8R4aQSapayHdDpNsBF/EN8=
 github.com/bradleypeabody/gorilla-sessions-memcache v0.0.0-20180621172731-4e5d6d543851/go.mod h1:dkChI7Tbtx7H1Tj7TqGSZMOeGpMP5gLHtjroHd4agiI=
-github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8=
-github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/eduncan911/podcast v1.3.0 h1:lVCar1J39mMNWR2SbGzPjeUbCKEkQ6/pt/7beQqK6fk=
 github.com/eduncan911/podcast v1.3.0/go.mod h1:C7Q04QZtv7LW/1X67mc1zwsktpZ68kbxsUS3CYWniJg=
 github.com/fsnotify/fsnotify v1.4.7 h1:IXs+QLmnXW2CcXuY+8Mzv/fWEsPGWxqefPtCP5CnV9I=
@@ -54,6 +54,8 @@ github.com/jmespath/go-jmespath v0.0.0-20160202185014-0b12d6b521d8 h1:12VvqtR6Ao
 github.com/jmespath/go-jmespath v0.0.0-20160202185014-0b12d6b521d8/go.mod h1:Nht3zPeWKUH0NzdCt2Blrr5ys8VGpn0CEB0cQHVjt7k=
 github.com/kidstuff/mongostore v0.0.0-20180412085134-db2a8b4fac1f h1:84d0qxD9AiuBNpeK5TkYwTKKNezsYxIVn8nWh0pq51E=
 github.com/kidstuff/mongostore v0.0.0-20180412085134-db2a8b4fac1f/go.mod h1:g2nVr8KZVXJSS97Jo8pJ0jgq29P6H7dG0oplUA86MQw=
+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/magiconair/properties v1.8.0 h1:LLgXmsheXeRoUOBOjtwPQCWIYqM/LU1ayDtDePerRcY=
 github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czPbwD3XqdrwzmxQ=
 github.com/mattn/go-isatty v0.0.3 h1:ns/ykhmWi7G9O+8a448SecJU3nSMBXJfqQkl0upE1jI=
@@ -79,6 +81,8 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/silentsokolov/go-vimeo v1.2.0 h1:Xp3Vn8ekcE+b5ExJOrwEytkDd5h6AdfH31NPERAuTGI=
 github.com/silentsokolov/go-vimeo v1.2.0/go.mod h1:10FeaKUMy5t3KLsYfy54dFrq0rpwcfyKkKcF7vRGIRY=
+github.com/sirupsen/logrus v1.2.0 h1:juTguoYk5qI21pwyTXY3B3Y5cOTH3ZUyZCg1v/mihuo=
+github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
 github.com/spf13/afero v1.1.1 h1:Lt3ihYMlE+lreX1GS4Qw4ZsNpYQLxIXKBTEOXm3nt6I=
 github.com/spf13/afero v1.1.1/go.mod h1:j4pytiNVoe2o6bmDsKpLACNPDBIoEAkihy7loJ1B0CQ=
 github.com/spf13/cast v1.2.0 h1:HHl1DSRbEQN2i8tJmtS6ViPyHx35+p51amrdsiTCrkg=
@@ -89,6 +93,7 @@ github.com/spf13/pflag v1.0.1 h1:aCvUg6QPl3ibpQUxyLkrEkCHtPqYJL4x9AuhqVqFis4=
 github.com/spf13/pflag v1.0.1/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
 github.com/spf13/viper v1.0.2 h1:Ncr3ZIuJn322w2k1qmzXDnkLAdQMlJqBa9kfAH+irso=
 github.com/spf13/viper v1.0.2/go.mod h1:A8kyI5cUJhb8N+3pkfONlcEcZbueH6nhAm0Fq7SrnBM=
+github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/teris-io/shortid v0.0.0-20171029131806-771a37caa5cf h1:Z2X3Os7oRzpdJ75iPqWZc0HeJWFYNCvKsfpQwFpRNTA=
@@ -97,6 +102,8 @@ github.com/ugorji/go v1.1.1 h1:gmervu+jDMvXTbcHQ0pd2wee85nEoE0BsVyEuzkfK8w=
 github.com/ugorji/go v1.1.1/go.mod h1:hnLbHMwcvSihnDhEfx2/BzKp2xb0Y+ErdfYcrs9tkJQ=
 github.com/ventu-io/go-shortid v0.0.0-20171029131806-771a37caa5cf h1:cgAKVljim9RJRcJNGjnBUajXj1FupBSdWwW4JaQG7vk=
 github.com/ventu-io/go-shortid v0.0.0-20171029131806-771a37caa5cf/go.mod h1:6rZqAOk/eYX5FJyjQJ6Z3RBSN389IXX2ijwW4FcggaM=
+golang.org/x/crypto v0.0.0-20180904163835-0709b304e793 h1:u+LnwYTOOW7Ukr/fppxEb1Nwz0AtPflrblfvUudpo+I=
+golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/net v0.0.0-20180906233101-161cd47e91fd h1:nTDtHvHSdCn1m6ITfMRqtOd/9+7a3s8RBNOZ3eYZzJA=
 golang.org/x/net v0.0.0-20180906233101-161cd47e91fd/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/oauth2 v0.0.0-20180620175406-ef147856a6dd h1:QQhib242ErYDSMitlBm8V7wYCm/1a25hV8qMadIKLPA=
@@ -104,6 +111,7 @@ golang.org/x/oauth2 v0.0.0-20180620175406-ef147856a6dd/go.mod h1:N/0e6XlmueqKjAG
 golang.org/x/sync v0.0.0-20180314180146-1d60e4601c6f/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.0.0-20181108010431-42b317875d0f h1:Bl/8QSvNqXvPGPGXa2z5xUTmV7VDcZyvRZ+QQXkXTZQ=
 golang.org/x/sync v0.0.0-20181108010431-42b317875d0f/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e h1:o3PsSEY8E4eXWkXrIP9YJALUkVZqzHJT5DOasTyn8Vs=
 golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
--- a/pkg/handler/handler.go
+++ b/pkg/handler/handler.go
@@ -3,7 +3,6 @@ package handler
 import (
 	"encoding/json"
 	"io/ioutil"
-	"log"
 	"net/http"
 	"path"
 	"strings"
@@ -12,10 +11,13 @@ import (
 	"github.com/gin-gonic/gin"
 	patreon "github.com/mxpv/patreon-go"
 	itunes "github.com/mxpv/podcast"
+	"golang.org/x/oauth2"
+
 	"github.com/mxpv/podsync/pkg/api"
 	"github.com/mxpv/podsync/pkg/config"
 	"github.com/mxpv/podsync/pkg/session"
-	"golang.org/x/oauth2"
+
+	log "github.com/sirupsen/logrus"
 )

 const (
@@ -146,25 +148,25 @@ func (h handler) create(c *gin.Context) {
 }

 func (h handler) getFeed(c *gin.Context) {
-	hashId := c.Request.URL.Path[1:]
-	if hashId == "" || len(hashId) > maxHashIDLength {
+	hashID := c.Request.URL.Path[1:]
+	if hashID == "" || len(hashID) > maxHashIDLength {
 		c.String(http.StatusBadRequest, "invalid feed id")
 		return
 	}

-	if strings.HasSuffix(hashId, ".xml") {
-		hashId = strings.TrimSuffix(hashId, ".xml")
+	if strings.HasSuffix(hashID, ".xml") {
+		hashID = strings.TrimSuffix(hashID, ".xml")
 	}

-	podcast, err := h.feed.BuildFeed(hashId)
+	podcast, err := h.feed.BuildFeed(hashID)
 	if err != nil {
+		log.WithError(err).WithField("hash_id", hashID).Error("failed to build feed")
+
 		code := http.StatusInternalServerError
 		if err == api.ErrNotFound {
 			code = http.StatusNotFound
 		} else if err == api.ErrQuotaExceeded {
 			code = http.StatusTooManyRequests
-		} else {
-			log.Printf("server error (hash id: %s): %v", hashId, err)
 		}

 		c.String(code, err.Error())
@@ -194,7 +196,7 @@ func (h handler) webhook(c *gin.Context) {
 	// Read body to byte array in order to verify signature first
 	body, err := ioutil.ReadAll(c.Request.Body)
 	if err != nil {
-		log.Printf("failed to read webhook body: %v", err)
+		log.WithError(err).Error("failed to read webhook request")
 		c.Status(http.StatusBadRequest)
 		return
 	}
@@ -203,13 +205,13 @@ func (h handler) webhook(c *gin.Context) {
 	signature := c.GetHeader(patreon.HeaderSignature)
 	valid, err := patreon.VerifySignature(body, h.cfg.PatreonWebhooksSecret, signature)
 	if err != nil {
-		log.Printf("failed to verify signature: %v", err)
+		log.WithError(err).Error("failed to verify signature")
 		c.Status(http.StatusBadRequest)
 		return
 	}

 	if !valid {
-		log.Printf("! webhooks signatures are not equal (header: %s)", signature)
+		log.Errorf("webhooks signatures are not equal (header: %s)", signature)
 		c.Status(http.StatusUnauthorized)
 		return
 	}
@@ -217,24 +219,24 @@ func (h handler) webhook(c *gin.Context) {
 	// Get event name
 	eventName := c.GetHeader(patreon.HeaderEventType)
 	if eventName == "" {
-		log.Print("event name header is empty")
+		log.Error("event name header is empty")
 		c.Status(http.StatusBadRequest)
 		return
 	}

 	pledge := &patreon.WebhookPledge{}
 	if err := json.Unmarshal(body, pledge); err != nil {
+		log.WithError(err).Error("failed to unmarshal pledge")
 		c.JSON(badRequest(err))
 		return
 	}

 	if err := h.patreon.Hook(&pledge.Data, eventName); err != nil {
-		log.Printf(
-			"failed to process patreon event %s (event: %s, user: %s): %v",
-			pledge.Data.ID,
-			eventName,
-			pledge.Data.Relationships.Patron.Data.ID,
-			err)
+		log.WithError(err).WithFields(log.Fields{
+			"user_id":      pledge.Data.Relationships.Patron.Data.ID,
+			"pledge_id":    pledge.Data.ID,
+			"pledge_event": eventName,
+		}).Error("failed to process patreon event")

 		// Don't return any errors to Patreon, otherwise subsequent notifications will be blocked.
 		return
@@ -245,17 +247,15 @@ func (h handler) webhook(c *gin.Context) {
 	if eventName == patreon.EventUpdatePledge {
 		newLevel := h.patreon.GetFeatureLevelFromAmount(pledge.Data.Attributes.AmountCents)
 		if err := h.feed.Downgrade(patronID, newLevel); err != nil {
-			log.Printf("downgrade failed: %v", err)
 			return
 		}
 	} else if eventName == patreon.EventDeletePledge {
 		if err := h.feed.Downgrade(patronID, api.DefaultFeatures); err != nil {
-			log.Printf("downgrade failed: %v", err)
 			return
 		}
 	}

-	log.Printf("sucessfully processed patreon event %s (%s)", pledge.Data.ID, eventName)
+	log.Infof("sucessfully processed patreon event %s (%s)", pledge.Data.ID, eventName)
 }

 func New(feed feedService, support patreonService, cfg *config.AppConfig) http.Handler {
--- a/pkg/storage/dynamo.go
+++ b/pkg/storage/dynamo.go
@@ -14,6 +14,8 @@ import (

 	"github.com/mxpv/podsync/pkg/api"
 	"github.com/mxpv/podsync/pkg/model"
+
+	log "github.com/sirupsen/logrus"
 )

 const (
@@ -88,6 +90,11 @@ func NewDynamo(region, endpoint string) (Dynamo, error) {
 }

 func (d Dynamo) SaveFeed(feed *model.Feed) error {
+	logger := log.WithFields(log.Fields{
+		"hash_id": feed.HashID,
+		"user_id": feed.UserID,
+	})
+
 	now := time.Now().UTC()

 	feed.LastAccess = now
@@ -95,6 +102,7 @@ func (d Dynamo) SaveFeed(feed *model.Feed) error {

 	item, err := attr.MarshalMap(feed)
 	if err != nil {
+		logger.WithError(err).Error("failed to marshal feed model")
 		return err
 	}

@@ -104,11 +112,19 @@ func (d Dynamo) SaveFeed(feed *model.Feed) error {
 		ConditionExpression: aws.String("attribute_not_exists(HashID)"),
 	}

-	_, err = d.dynamo.PutItem(input)
-	return err
+	if _, err := d.dynamo.PutItem(input); err != nil {
+		logger.WithError(err).Error("failed to save feed item")
+		return err
+	}
+
+	return nil
 }

 func (d Dynamo) GetFeed(hashID string) (*model.Feed, error) {
+	logger := log.WithField("hash_id", hashID)
+
+	logger.Debug("getting feed")
+
 	getInput := &dynamodb.GetItemInput{
 		TableName: feedsTableName,
 		Key: map[string]*dynamodb.AttributeValue{
@@ -118,6 +134,7 @@ func (d Dynamo) GetFeed(hashID string) (*model.Feed, error) {

 	getOutput, err := d.dynamo.GetItem(getInput)
 	if err != nil {
+		logger.WithError(err).Error("failed to get feed item")
 		return nil, err
 	}

@@ -127,20 +144,26 @@ func (d Dynamo) GetFeed(hashID string) (*model.Feed, error) {

 	var feed model.Feed
 	if err := attr.UnmarshalMap(getOutput.Item, &feed); err != nil {
+		logger.WithError(err).Error("failed to unmarshal feed item")
 		return nil, err
 	}

 	// Check if we need to update LastAccess field (no more than once per hour)
 	now := time.Now().UTC()
 	if feed.LastAccess.Add(feedLastAccessUpdatePeriod).Before(now) {
+		logger.Debugf("updating feed's last access timestamp")
+
 		// Set LastAccess field to now
 		// Set ExpirationTime field to now + feedTimeToLive
-		builder := expr.
-			Set(expr.Name("LastAccess"), expr.Value(now)).
-			Set(expr.Name("ExpirationTime"), expr.Value(now.Add(feedTimeToLive)))
+		updateExpression, err := expr.
+			NewBuilder().
+			WithUpdate(expr.
+				Set(expr.Name("LastAccess"), expr.Value(now)).
+				Set(expr.Name("ExpirationTime"), expr.Value(now.Add(feedTimeToLive)))).
+			Build()

-		updateExpression, err := expr.NewBuilder().WithUpdate(builder).Build()
 		if err != nil {
+			logger.WithError(err).Error("failed to build update expression")
 			return nil, err
 		}

@@ -152,6 +175,7 @@ func (d Dynamo) GetFeed(hashID string) (*model.Feed, error) {

 		_, err = d.dynamo.UpdateItem(updateInput)
 		if err != nil {
+			logger.WithError(err).Error("failed to update feed item")
 			return nil, err
 		}

@@ -162,6 +186,10 @@ func (d Dynamo) GetFeed(hashID string) (*model.Feed, error) {
 }

 func (d Dynamo) GetMetadata(hashID string) (*model.Feed, error) {
+	logger := log.WithField("hash_id", hashID)
+
+	logger.Debug("getting metadata")
+
 	projectionExpression, err := expr.
 		NewBuilder().
 		WithProjection(
@@ -174,18 +202,23 @@ func (d Dynamo) GetMetadata(hashID string) (*model.Feed, error) {
 				expr.Name("Quality"))).
 		Build()

+	if err != nil {
+		logger.WithError(err).Error("failed to build projection expression")
+		return nil, err
+	}

 	input := &dynamodb.GetItemInput{
 		TableName: feedsTableName,
 		Key: map[string]*dynamodb.AttributeValue{
 			"HashID": {S: aws.String(hashID)},
 		},
-		ProjectionExpression: projectionExpression.Projection(),
+		ProjectionExpression:     projectionExpression.Projection(),
 		ExpressionAttributeNames: projectionExpression.Names(),
 	}

 	output, err := d.dynamo.GetItem(input)
 	if err != nil {
+		logger.WithError(err).Error("failed to get metadata item")
 		return nil, err
 	}

@@ -195,6 +228,7 @@ func (d Dynamo) GetMetadata(hashID string) (*model.Feed, error) {

 	var feed model.Feed
 	if err := attr.UnmarshalMap(output.Item, &feed); err != nil {
+		logger.WithError(err).Error("failed to unmarshal metadata item")
 		return nil, err
 	}

@@ -202,6 +236,13 @@ func (d Dynamo) GetMetadata(hashID string) (*model.Feed, error) {
 }

 func (d Dynamo) Downgrade(userID string, featureLevel int) error {
+	logger := log.WithFields(log.Fields{
+		"user_id":       userID,
+		"feature_level": featureLevel,
+	})
+
+	logger.Debug("downgrading user's feeds")
+
 	if featureLevel > api.ExtendedFeatures {
 		// Max page size: 600
 		// Format: any
@@ -215,11 +256,14 @@ func (d Dynamo) Downgrade(userID string, featureLevel int) error {
 		Build()

 	if err != nil {
+		logger.WithError(err).Error("failed to build key condition")
 		return err
 	}

 	// Query all feed's hash ids for specified

+	logger.Debug("querying hash ids")
+
 	queryInput := &dynamodb.QueryInput{
 		TableName:                 feedsTableName,
 		IndexName:                 feedDowngradeIndexName,
@@ -241,9 +285,15 @@ func (d Dynamo) Downgrade(userID string, featureLevel int) error {
 	})

 	if err != nil {
+		logger.WithError(err).Error("query failed")
 		return err
 	}

+	logger.Debugf("got %d key(s)", len(keys))
+	if len(keys) == 0 {
+		return nil
+	}
+
 	if featureLevel == api.ExtendedFeatures {
 		// Max page size: 150
 		// Format: any
@@ -258,6 +308,7 @@ func (d Dynamo) Downgrade(userID string, featureLevel int) error {
 			Build()

 		if err != nil {
+			logger.WithError(err).Error("failed to build update expression")
 			return err
 		}

@@ -273,6 +324,7 @@ func (d Dynamo) Downgrade(userID string, featureLevel int) error {

 			_, err := d.dynamo.UpdateItem(input)
 			if err != nil {
+				logger.WithError(err).Error("failed to update item")
 				return err
 			}
 		}
@@ -305,17 +357,25 @@ func (d Dynamo) Downgrade(userID string, featureLevel int) error {

 			_, err := d.dynamo.UpdateItem(input)
 			if err != nil {
+				logger.WithError(err).Error("failed to update item")
 				return err
 			}
 		}
 	}

+	logger.Info("successfully downgraded user's feeds")
 	return nil
 }

 func (d Dynamo) AddPledge(pledge *model.Pledge) error {
+	logger := log.WithFields(log.Fields{
+		"pledge_id": pledge.PledgeID,
+		"user_id":   pledge.PatronID,
+	})
+
 	item, err := attr.MarshalMap(pledge)
 	if err != nil {
+		logger.WithError(err).Error("failed to marshal pledge")
 		return err
 	}

@@ -325,11 +385,22 @@ func (d Dynamo) AddPledge(pledge *model.Pledge) error {
 		ConditionExpression: aws.String("attribute_not_exists(PatronID)"),
 	}

-	_, err = d.dynamo.PutItem(input)
-	return err
+	if _, err := d.dynamo.PutItem(input); err != nil {
+		logger.WithError(err).Error("failed to put item")
+		return err
+	}
+
+	return nil
 }

 func (d Dynamo) UpdatePledge(patronID string, pledge *model.Pledge) error {
+	logger := log.WithFields(log.Fields{
+		"pledge_id": pledge.PledgeID,
+		"user_id":   patronID,
+	})
+
+	logger.Infof("updating pledge (new amount: %d)", pledge.AmountCents)
+
 	builder := expr.
 		Set(expr.Name("DeclinedSince"), expr.Value(pledge.DeclinedSince)).
 		Set(expr.Name("AmountCents"), expr.Value(pledge.AmountCents)).
@@ -339,6 +410,7 @@ func (d Dynamo) UpdatePledge(patronID string, pledge *model.Pledge) error {

 	updateExpression, err := expr.NewBuilder().WithUpdate(builder).Build()
 	if err != nil {
+		logger.WithError(err).Error("failed to build update expression")
 		return err
 	}

@@ -352,8 +424,8 @@ func (d Dynamo) UpdatePledge(patronID string, pledge *model.Pledge) error {
 		ExpressionAttributeValues: updateExpression.Values(),
 	}

-	_, err = d.dynamo.UpdateItem(input)
-	if err != nil {
+	if _, err := d.dynamo.UpdateItem(input); err != nil {
+		logger.WithError(err).Error("failed to update pledge")
 		return err
 	}

@@ -361,7 +433,13 @@ func (d Dynamo) UpdatePledge(patronID string, pledge *model.Pledge) error {
 }

 func (d Dynamo) DeletePledge(pledge *model.Pledge) error {
+	logger := log.WithFields(log.Fields{
+		"pledge_id": pledge.PledgeID,
+		"user_id":   pledge.PatronID,
+	})
+
 	pk := strconv.FormatInt(pledge.PatronID, 10)
+	logger.Infof("deleting pledge %s", pk)

 	input := &dynamodb.DeleteItemInput{
 		TableName: pledgesTableName,
@@ -370,11 +448,19 @@ func (d Dynamo) DeletePledge(pledge *model.Pledge) error {
 		},
 	}

-	_, err := d.dynamo.DeleteItem(input)
-	return err
+	if _, err := d.dynamo.DeleteItem(input); err != nil {
+		logger.WithError(err).Error("failed to delete pledge")
+		return err
+	}
+
+	return nil
 }

 func (d Dynamo) GetPledge(patronID string) (*model.Pledge, error) {
+	logger := log.WithField("user_id", patronID)
+
+	logger.Debug("getting pledge")
+
 	input := &dynamodb.GetItemInput{
 		TableName: pledgesTableName,
 		Key: map[string]*dynamodb.AttributeValue{
@@ -384,6 +470,7 @@ func (d Dynamo) GetPledge(patronID string) (*model.Pledge, error) {

 	output, err := d.dynamo.GetItem(input)
 	if err != nil {
+		logger.WithError(err).Error("failed to get pledge item")
 		return nil, err
 	}

@@ -393,6 +480,7 @@ func (d Dynamo) GetPledge(patronID string) (*model.Pledge, error) {

 	var pledge model.Pledge
 	if err := attr.UnmarshalMap(output.Item, &pledge); err != nil {
+		logger.WithError(err).Error("failed to unmarshal pledge item")
 		return nil, err
 	}

--- a/pkg/support/patreon.go
+++ b/pkg/support/patreon.go
@@ -2,7 +2,6 @@ package support

 import (
 	"fmt"
-	"log"
 	"strconv"

 	"github.com/mxpv/patreon-go"
@@ -10,6 +9,8 @@ import (

 	"github.com/mxpv/podsync/pkg/api"
 	"github.com/mxpv/podsync/pkg/model"
+
+	log "github.com/sirupsen/logrus"
 )

 const (
@@ -70,8 +71,15 @@ func ToModel(pledge *patreon.Pledge) (*model.Pledge, error) {
 }

 func (h Patreon) Hook(pledge *patreon.Pledge, event string) error {
+	logger := log.WithFields(log.Fields{
+		"module":       "hook",
+		"pledge_id":    pledge.ID,
+		"pledge_event": event,
+	})
+
 	obj, err := ToModel(pledge)
 	if err != nil {
+		logger.WithError(err).Error("failed to convert pledge to model")
 		return err
 	}

@@ -81,7 +89,6 @@ func (h Patreon) Hook(pledge *patreon.Pledge, event string) error {
 	case patreon.EventUpdatePledge:
 		// Update comes with different PledgeID from Patreon, so do update by user ID
 		patronID := pledge.Relationships.Patron.Data.ID
-
 		if err := h.db.UpdatePledge(patronID, obj); err != nil {
 			return err
 		}
@@ -112,7 +119,7 @@ func (h Patreon) GetFeatureLevelByID(patronID string) (level int) {

 	pledge, err := h.FindPledge(patronID)
 	if err != nil {
-		log.Printf("! can't find pledge for user %s: %v", patronID, err)
+		log.WithError(err).WithField("user_id", patronID).Error("can't find pledge for user")
 		return
 	}