Merge pull request #185 from netlify/chore/logging-cleanup

Logging cleanup

api/api.go

@@ -73,12 +73,12 @@ func waitForTermination(log logrus.FieldLogger, done <-chan struct{}) {
 }
 
 // NewAPI instantiates a new REST API using the default version.
-func NewAPI(globalConfig *conf.GlobalConfiguration, db *gorm.DB) *API {
-	return NewAPIWithVersion(context.Background(), globalConfig, db, defaultVersion)
+func NewAPI(globalConfig *conf.GlobalConfiguration, log logrus.FieldLogger, db *gorm.DB) *API {
+	return NewAPIWithVersion(context.Background(), globalConfig, log, db, defaultVersion)
 }
 
 // NewAPIWithVersion instantiates a new REST API.
-func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfiguration, db *gorm.DB, version string) *API {
+func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfiguration, log logrus.FieldLogger, db *gorm.DB, version string) *API {
 	api := &API{
 		config:     globalConfig,
 		db:         db,
@@ -87,7 +87,7 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 	}
 
 	xffmw, _ := xff.Default()
-	logger := newStructuredLogger(logrus.StandardLogger())
+	logger := newStructuredLogger(log)
 
 	r := newRouter()
 	r.UseBypass(xffmw.Handler)
@@ -98,6 +98,7 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 
 	r.Route("/", func(r *router) {
 		r.UseBypass(logger)
+		r.Use(api.loggingDB)
 		if globalConfig.MultiInstanceMode {
 			r.Use(api.loadInstanceConfig)
 		}
@@ -147,9 +148,10 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 
 	if globalConfig.MultiInstanceMode {
 		// Operator microservice API
-		r.WithBypass(logger).With(api.verifyOperatorRequest).Get("/", api.GetAppManifest)
+		r.WithBypass(logger).With(api.loggingDB).With(api.verifyOperatorRequest).Get("/", api.GetAppManifest)
 		r.Route("/instances", func(r *router) {
 			r.UseBypass(logger)
+			r.Use(api.loggingDB)
 			r.Use(api.verifyOperatorRequest)
 
 			r.Post("/", api.CreateInstance)

api/api_test.go

@@ -6,6 +6,7 @@ import (
 	"net/http/httptest"
 	"testing"
 
+	"github.com/sirupsen/logrus"
 	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -25,7 +26,7 @@ func TestTraceWrapper(t *testing.T) {
 
 	ctx, err := WithInstanceConfig(context.Background(), globalConfig.SMTP, config, "")
 	require.NoError(t, err)
-	api := NewAPIWithVersion(ctx, globalConfig, nil, "")
+	api := NewAPIWithVersion(ctx, globalConfig, logrus.StandardLogger(), nil, "")
 
 	server := httptest.NewServer(api.handler)
 	defer server.Close()

api/db_logger.go

@@ -0,0 +1,28 @@
+package api
+
+import (
+	"context"
+	"net/http"
+
+	"github.com/jinzhu/gorm"
+	gcontext "github.com/netlify/gocommerce/context"
+	"github.com/netlify/gocommerce/models"
+)
+
+func (a *API) loggingDB(w http.ResponseWriter, r *http.Request) (context.Context, error) {
+	if a.db == nil {
+		return r.Context(), nil
+	}
+
+	log := getLogEntry(r)
+	db := a.db.New()
+	db.SetLogger(models.NewDBLogger(log))
+
+	return gcontext.WithDB(r.Context(), db), nil
+}
+
+// DB provides callers with a database instance configured for request logging
+func (a *API) DB(r *http.Request) *gorm.DB {
+	ctx := r.Context()
+	return gcontext.GetDB(ctx)
+}

api/download.go

@@ -15,21 +15,22 @@ const maxIPsPerDay = 50
 // DownloadURL returns a signed URL to download a purchased asset.
 func (a *API) DownloadURL(w http.ResponseWriter, r *http.Request) error {
 	ctx := r.Context()
+	db := a.DB(r)
 	downloadID := chi.URLParam(r, "download_id")
 	logEntrySetField(r, "download_id", downloadID)
 	claims := gcontext.GetClaims(ctx)
 	assets := gcontext.GetAssetStore(ctx)
 
 	download := &models.Download{}
-	if result := a.db.Where("id = ?", downloadID).First(download); result.Error != nil {
+	if result := db.Where("id = ?", downloadID).First(download); result.Error != nil {
 		if result.RecordNotFound() {
 			return notFoundError("Download not found")
 		}
 		return internalServerError("Error during database query").WithInternalError(result.Error)
 	}
 
 	order := &models.Order{}
-	if result := a.db.Where("id = ?", download.OrderID).First(order); result.Error != nil {
+	if result := db.Where("id = ?", download.OrderID).First(order); result.Error != nil {
 		if result.RecordNotFound() {
 			return notFoundError("Download order not found")
 		}
@@ -44,7 +45,7 @@ func (a *API) DownloadURL(w http.ResponseWriter, r *http.Request) error {
 		return unauthorizedError("This download has not been paid yet")
 	}
 
-	rows, err := a.db.Model(&models.Event{}).
+	rows, err := db.Model(&models.Event{}).
 		Select("count(distinct(ip))").
 		Where("order_id = ? and created_at > ? and changes = 'download'", order.ID, time.Now().Add(-24*time.Hour)).
 		Rows()
@@ -66,7 +67,7 @@ func (a *API) DownloadURL(w http.ResponseWriter, r *http.Request) error {
 		return internalServerError("Error signing download").WithInternalError(err)
 	}
 
-	tx := a.db.Begin()
+	tx := db.Begin()
 	tx.Model(download).Updates(map[string]interface{}{"download_count": gorm.Expr("download_count + 1")})
 	var subject string
 	if claims != nil {
@@ -81,12 +82,13 @@ func (a *API) DownloadURL(w http.ResponseWriter, r *http.Request) error {
 // DownloadList lists all purchased downloads for an order or a user.
 func (a *API) DownloadList(w http.ResponseWriter, r *http.Request) error {
 	ctx := r.Context()
+	db := a.DB(r)
 	orderID := gcontext.GetOrderID(ctx)
 	log := getLogEntry(r)
 
 	order := &models.Order{}
 	if orderID != "" {
-		if result := a.db.Where("id = ?", orderID).First(order); result.Error != nil {
+		if result := db.Where("id = ?", orderID).First(order); result.Error != nil {
 			if result.RecordNotFound() {
 				return notFoundError("Download order not found")
 			}
@@ -106,10 +108,10 @@ func (a *API) DownloadList(w http.ResponseWriter, r *http.Request) error {
 		}
 	}
 
-	orderTable := a.db.NewScope(models.Order{}).QuotedTableName()
-	downloadsTable := a.db.NewScope(models.Download{}).QuotedTableName()
+	orderTable := db.NewScope(models.Order{}).QuotedTableName()
+	downloadsTable := db.NewScope(models.Download{}).QuotedTableName()
 
-	query := a.db.Joins("join " + orderTable + " ON " + downloadsTable + ".order_id = " + orderTable + ".id and " + orderTable + ".payment_state = 'paid'")
+	query := db.Joins("join " + orderTable + " ON " + downloadsTable + ".order_id = " + orderTable + ".id and " + orderTable + ".payment_state = 'paid'")
 	if order != nil {
 		query = query.Where(orderTable+".id = ?", order.ID)
 	} else {

api/instance.go

@@ -16,7 +16,7 @@ func (a *API) loadInstance(w http.ResponseWriter, r *http.Request) (context.Cont
 	instanceID := chi.URLParam(r, "instance_id")
 	logEntrySetField(r, "instance_id", instanceID)
 
-	i, err := models.GetInstance(a.db, instanceID)
+	i, err := models.GetInstance(a.DB(r), instanceID)
 	if err != nil {
 		if models.IsNotFoundError(err) {
 			return nil, notFoundError("Instance not found")
@@ -47,12 +47,14 @@ type InstanceResponse struct {
 }
 
 func (a *API) CreateInstance(w http.ResponseWriter, r *http.Request) error {
+	db := a.DB(r)
+
 	params := InstanceRequestParams{}
 	if err := json.NewDecoder(r.Body).Decode(&params); err != nil {
 		return badRequestError("Error decoding params: %v", err)
 	}
 
-	_, err := models.GetInstanceByUUID(a.db, params.UUID)
+	_, err := models.GetInstanceByUUID(db, params.UUID)
 	if err != nil {
 		if !models.IsNotFoundError(err) {
 			return internalServerError("Database error looking up instance").WithInternalError(err)
@@ -66,7 +68,7 @@ func (a *API) CreateInstance(w http.ResponseWriter, r *http.Request) error {
 		UUID:       params.UUID,
 		BaseConfig: params.BaseConfig,
 	}
-	if err = models.CreateInstance(a.db, &i); err != nil {
+	if err = models.CreateInstance(db, &i); err != nil {
 		return internalServerError("Database error creating instance").WithInternalError(err)
 	}
 
@@ -95,15 +97,15 @@ func (a *API) UpdateInstance(w http.ResponseWriter, r *http.Request) error {
 		i.BaseConfig = params.BaseConfig
 	}
 
-	if err := models.UpdateInstance(a.db, i); err != nil {
+	if err := models.UpdateInstance(a.DB(r), i); err != nil {
 		return internalServerError("Database error updating instance").WithInternalError(err)
 	}
 	return sendJSON(w, http.StatusOK, i)
 }
 
 func (a *API) DeleteInstance(w http.ResponseWriter, r *http.Request) error {
 	i := gcontext.GetInstance(r.Context())
-	if err := models.DeleteInstance(a.db, i); err != nil {
+	if err := models.DeleteInstance(a.DB(r), i); err != nil {
 		return internalServerError("Database error deleting instance").WithInternalError(err)
 	}
 

api/instance_test.go

@@ -25,14 +25,14 @@ type InstanceTestSuite struct {
 }
 
 func (ts *InstanceTestSuite) SetupTest() {
-	globalConfig, err := conf.LoadGlobal("test.env")
+	globalConfig, log, err := conf.LoadGlobal("test.env")
 	require.NoError(ts.T(), err)
 	globalConfig.OperatorToken = operatorToken
 	globalConfig.MultiInstanceMode = true
-	db, err := models.Connect(globalConfig)
+	db, err := models.Connect(globalConfig, log)
 	require.NoError(ts.T(), err)
 
-	api := NewAPI(globalConfig, db)
+	api := NewAPI(globalConfig, log, db)
 	ts.API = api
 
 	// Cleanup existing instance

api/log.go

@@ -10,16 +10,16 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
-func newStructuredLogger(logger *logrus.Logger) func(next http.Handler) http.Handler {
+func newStructuredLogger(logger logrus.FieldLogger) func(next http.Handler) http.Handler {
 	return chimiddleware.RequestLogger(&structuredLogger{logger})
 }
 
 type structuredLogger struct {
-	Logger *logrus.Logger
+	Logger logrus.FieldLogger
 }
 
 func (l *structuredLogger) NewLogEntry(r *http.Request) chimiddleware.LogEntry {
-	entry := &structuredLoggerEntry{Logger: logrus.NewEntry(l.Logger)}
+	entry := &structuredLoggerEntry{Logger: l.Logger}
 	logFields := logrus.Fields{
 		"component":   "api",
 		"method":      r.Method,

api/middleware_test.go

@@ -21,13 +21,13 @@ type MiddlewareTestSuite struct {
 }
 
 func (ts *MiddlewareTestSuite) SetupTest() {
-	globalConfig, err := conf.LoadGlobal("test.env")
+	globalConfig, log, err := conf.LoadGlobal("test.env")
 	require.NoError(ts.T(), err)
 	globalConfig.MultiInstanceMode = true
-	db, err := models.Connect(globalConfig)
+	db, err := models.Connect(globalConfig, log)
 	require.NoError(ts.T(), err)
 
-	api := NewAPI(globalConfig, db)
+	api := NewAPI(globalConfig, log, db)
 	ts.API = api
 }
 

api/order.go

@@ -85,6 +85,7 @@ func (a *API) withOrderID(w http.ResponseWriter, r *http.Request) (context.Conte
 // ClaimOrders will look for any orders with no user id belonging to an email and claim them
 func (a *API) ClaimOrders(w http.ResponseWriter, r *http.Request) error {
 	ctx := r.Context()
+	db := a.DB(r)
 	log := getLogEntry(r)
 	instanceID := gcontext.GetInstanceID(ctx)
 
@@ -103,7 +104,7 @@ func (a *API) ClaimOrders(w http.ResponseWriter, r *http.Request) error {
 	})
 
 	// now find all the order associated with that email
-	query := orderQuery(a.db)
+	query := orderQuery(db)
 	query = query.Where(&models.Order{
 		InstanceID: instanceID,
 		UserID:     "",
@@ -115,7 +116,7 @@ func (a *API) ClaimOrders(w http.ResponseWriter, r *http.Request) error {
 		return internalServerError("Failed to query for orders with email: %s", claims.Email).WithInternalError(res.Error)
 	}
 
-	tx := a.db.Begin()
+	tx := db.Begin()
 
 	// create the user
 	user := models.User{
@@ -154,7 +155,7 @@ func (a *API) ReceiptView(w http.ResponseWriter, r *http.Request) error {
 	logEntrySetField(r, "order_id", id)
 
 	order := &models.Order{}
-	if result := orderQuery(a.db).Preload("Transactions").First(order, "id = ?", id); result.Error != nil {
+	if result := orderQuery(a.DB(r)).Preload("Transactions").First(order, "id = ?", id); result.Error != nil {
 		if result.RecordNotFound() {
 			return notFoundError("Order not found")
 		}
@@ -198,7 +199,7 @@ func (a *API) ResendOrderReceipt(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	order := &models.Order{}
-	if result := orderQuery(a.db).Preload("Transactions").First(order, "id = ?", id); result.Error != nil {
+	if result := orderQuery(a.DB(r)).Preload("Transactions").First(order, "id = ?", id); result.Error != nil {
 		if result.RecordNotFound() {
 			return notFoundError("Order not found")
 		}
@@ -246,7 +247,7 @@ func (a *API) OrderList(w http.ResponseWriter, r *http.Request) error {
 
 	var err error
 	params := r.URL.Query()
-	query := orderQuery(a.db)
+	query := orderQuery(a.DB(r))
 	query, err = parseOrderParams(query, params)
 	if err != nil {
 		return badRequestError("Bad parameters in query: %v", err)
@@ -286,7 +287,7 @@ func (a *API) OrderView(w http.ResponseWriter, r *http.Request) error {
 	log := getLogEntry(r)
 
 	order := &models.Order{}
-	if result := orderQuery(a.db).First(order, "id = ?", id); result.Error != nil {
+	if result := orderQuery(a.DB(r)).First(order, "id = ?", id); result.Error != nil {
 		if result.RecordNotFound() {
 			return notFoundError("Order not found")
 		}
@@ -338,7 +339,7 @@ func (a *API) OrderCreate(w http.ResponseWriter, r *http.Request) error {
 		"email":    params.Email,
 		"currency": params.Currency,
 	}).Debug("Created order, starting to process request")
-	tx := a.db.Begin()
+	tx := a.DB(r).Begin()
 
 	order.IP = r.RemoteAddr
 	order.MetaData = params.MetaData
@@ -425,6 +426,7 @@ func (a *API) OrderCreate(w http.ResponseWriter, r *http.Request) error {
 // There are also blocks to changing certain fields after the state has been locked
 func (a *API) OrderUpdate(w http.ResponseWriter, r *http.Request) error {
 	ctx := r.Context()
+	db := a.DB(r)
 	orderID := gcontext.GetOrderID(ctx)
 	log := getLogEntry(r)
 	claims := gcontext.GetClaims(ctx)
@@ -440,7 +442,7 @@ func (a *API) OrderUpdate(w http.ResponseWriter, r *http.Request) error {
 	// verify that the order exists
 	existingOrder := new(models.Order)
 
-	rsp := orderQuery(a.db).First(existingOrder, "id = ?", orderID)
+	rsp := orderQuery(db).First(existingOrder, "id = ?", orderID)
 	if rsp.RecordNotFound() {
 		return notFoundError("Failed to find order with id '%s'", orderID)
 	}
@@ -486,7 +488,7 @@ func (a *API) OrderUpdate(w http.ResponseWriter, r *http.Request) error {
 		changes = append(changes, "vatnumber")
 	}
 
-	tx := a.db.Begin()
+	tx := db.Begin()
 
 	//
 	// handle the addresses