Use custom logger for sql debug logging

Author: mraerino

api/api.go

@@ -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/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/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

api/payments.go

@@ -45,7 +45,7 @@ func (a *API) PaymentListForUser(w http.ResponseWriter, r *http.Request) error {
 		return notFoundError("Couldn't find a record for " + userID)
 	}
 
-	trans, httpErr := queryForTransactions(a.db, log, "user_id = ?", userID)
+	trans, httpErr := queryForTransactions(a.DB(r), log, "user_id = ?", userID)
 	if httpErr != nil {
 		return httpErr
 	}
@@ -60,7 +60,7 @@ func (a *API) PaymentListForOrder(w http.ResponseWriter, r *http.Request) error
 	orderID := gcontext.GetOrderID(ctx)
 	claims := gcontext.GetClaims(ctx)
 
-	order, httpErr := queryForOrder(a.db, orderID, log)
+	order, httpErr := queryForOrder(a.DB(r), orderID, log)
 	if httpErr != nil {
 		return httpErr
 	}
@@ -138,7 +138,7 @@ func (a *API) PaymentCreate(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	orderID := gcontext.GetOrderID(ctx)
-	tx := a.db.Begin()
+	tx := a.DB(r).Begin()
 	order := &models.Order{}
 	loader := tx.
 		Preload("LineItems").
@@ -237,9 +237,10 @@ func (a *API) PaymentCreate(w http.ResponseWriter, r *http.Request) error {
 func (a *API) PaymentConfirm(w http.ResponseWriter, r *http.Request) error {
 	ctx := r.Context()
 	log := getLogEntry(r)
+	db := a.DB(r)
 
 	payID := chi.URLParam(r, "payment_id")
-	trans, httpErr := a.getTransaction(payID)
+	trans, httpErr := getTransaction(db, payID)
 	if httpErr != nil {
 		return httpErr
 	}
@@ -260,7 +261,7 @@ func (a *API) PaymentConfirm(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	order := &models.Order{}
-	if rsp := a.db.Find(order, "id = ?", trans.OrderID); rsp.Error != nil {
+	if rsp := db.Find(order, "id = ?", trans.OrderID); rsp.Error != nil {
 		if rsp.RecordNotFound() {
 			return notFoundError("Order not found")
 		}
@@ -286,7 +287,7 @@ func (a *API) PaymentConfirm(w http.ResponseWriter, r *http.Request) error {
 		return internalServerError("Error on provider while trying to confirm: %v. Try again later.", err)
 	}
 
-	tx := a.db.Begin()
+	tx := db.Begin()
 
 	if trans.InvoiceNumber == 0 {
 		invoiceNumber, err := models.NextInvoiceNumber(tx, order.InstanceID)
@@ -311,7 +312,7 @@ func (a *API) PaymentConfirm(w http.ResponseWriter, r *http.Request) error {
 func (a *API) PaymentList(w http.ResponseWriter, r *http.Request) error {
 	log := getLogEntry(r)
 	instanceID := gcontext.GetInstanceID(r.Context())
-	query := a.db.Where("instance_id = ?", instanceID)
+	query := a.DB(r).Where("instance_id = ?", instanceID)
 
 	query, err := parsePaymentQueryParams(query, r.URL.Query())
 	if err != nil {
@@ -328,7 +329,7 @@ func (a *API) PaymentList(w http.ResponseWriter, r *http.Request) error {
 // PaymentView returns information about a single payment. It is only available to admins.
 func (a *API) PaymentView(w http.ResponseWriter, r *http.Request) error {
 	payID := chi.URLParam(r, "payment_id")
-	trans, httpErr := a.getTransaction(payID)
+	trans, httpErr := getTransaction(a.DB(r), payID)
 	if httpErr != nil {
 		return httpErr
 	}
@@ -339,6 +340,7 @@ func (a *API) PaymentView(w http.ResponseWriter, r *http.Request) error {
 // refunds if desired. It is only available to admins.
 func (a *API) PaymentRefund(w http.ResponseWriter, r *http.Request) error {
 	ctx := r.Context()
+	db := a.DB(r)
 	config := gcontext.GetConfig(ctx)
 	params := PaymentParams{Currency: "USD"}
 	err := json.NewDecoder(r.Body).Decode(&params)
@@ -347,7 +349,7 @@ func (a *API) PaymentRefund(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	payID := chi.URLParam(r, "payment_id")
-	trans, httpErr := a.getTransaction(payID)
+	trans, httpErr := getTransaction(db, payID)
 	if httpErr != nil {
 		return httpErr
 	}
@@ -369,7 +371,7 @@ func (a *API) PaymentRefund(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	log := getLogEntry(r)
-	order, httpErr := queryForOrder(a.db, trans.OrderID, log)
+	order, httpErr := queryForOrder(db, trans.OrderID, log)
 	if httpErr != nil {
 		return httpErr
 	}
@@ -398,7 +400,7 @@ func (a *API) PaymentRefund(w http.ResponseWriter, r *http.Request) error {
 		Status:     models.PendingState,
 	}
 
-	tx := a.db.Begin()
+	tx := db.Begin()
 	tx.Create(m)
 	provID := provider.Name()
 	log.Debugf("Starting refund to %s", provID)
@@ -480,8 +482,8 @@ func (a *API) PreauthorizePayment(w http.ResponseWriter, r *http.Request) error
 // ------------------------------------------------------------------------------------------------
 // Helpers
 // ------------------------------------------------------------------------------------------------
-func (a *API) getTransaction(payID string) (*models.Transaction, *HTTPError) {
-	trans, err := models.GetTransaction(a.db, payID)
+func getTransaction(db *gorm.DB, payID string) (*models.Transaction, *HTTPError) {
+	trans, err := models.GetTransaction(db, payID)
 	if err != nil {
 		return nil, internalServerError("Error while querying for transactions").WithInternalError(err)
 	}