frontend: use logrus structured logger

Signed-off-by: Ahmet Alp Balkan <ahmetb@google.com>

src/frontend/Dockerfile

@@ -6,6 +6,7 @@ WORKDIR /go/src/frontend
 RUN go get -d github.com/google/uuid \
     github.com/gorilla/mux \
     github.com/pkg/errors \
+    github.com/sirupsen/logrus \
     google.golang.org/grpc \
     google.golang.org/grpc/codes \
     google.golang.org/grpc/status

src/frontend/handlers.go

@@ -1,18 +1,16 @@
 package main
 
 import (
-	"context"
 	"fmt"
 	"frontend/money"
 	"html/template"
-	"log"
 	"net/http"
 	"strconv"
 	"time"
 
-	"github.com/google/uuid"
 	"github.com/gorilla/mux"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 
 	pb "frontend/genproto"
 )
@@ -24,45 +22,22 @@ var (
 		}).ParseGlob("templates/*.html"))
 )
 
-func ensureSessionID(next http.HandlerFunc) http.HandlerFunc {
-	return func(w http.ResponseWriter, r *http.Request) {
-		var sessionID string
-		c, err := r.Cookie(cookieSessionID)
-		if err == http.ErrNoCookie {
-			u, _ := uuid.NewRandom()
-			sessionID = u.String()
-			http.SetCookie(w, &http.Cookie{
-				Name:   cookieSessionID,
-				Value:  sessionID,
-				MaxAge: cookieMaxAge,
-			})
-		} else if err != nil {
-			renderHTTPError(w, errors.Wrap(err, "unrecognized cookie error"), http.StatusInternalServerError)
-			return
-		} else {
-			sessionID = c.Value
-		}
-		ctx := context.WithValue(r.Context(), ctxKeySessionID{}, sessionID)
-		r = r.WithContext(ctx)
-		next(w, r)
-	}
-}
-
 func (fe *frontendServer) homeHandler(w http.ResponseWriter, r *http.Request) {
-	log.Printf("[home] session_id=%s currency=%s", sessionID(r), currentCurrency(r))
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
+	log.WithField("currency", currentCurrency(r)).Info("home")
 	currencies, err := fe.getCurrencies(r.Context())
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve currencies"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve currencies"), http.StatusInternalServerError)
 		return
 	}
 	products, err := fe.getProducts(r.Context())
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve products"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve products"), http.StatusInternalServerError)
 		return
 	}
 	cart, err := fe.getCart(r.Context(), sessionID(r))
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve cart"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve cart"), http.StatusInternalServerError)
 		return
 	}
 
@@ -74,7 +49,7 @@ func (fe *frontendServer) homeHandler(w http.ResponseWriter, r *http.Request) {
 	for i, p := range products {
 		price, err := fe.convertCurrency(r.Context(), p.GetPriceUsd(), currentCurrency(r))
 		if err != nil {
-			renderHTTPError(w, errors.Wrapf(err, "failed to do currency conversion for product %s", p.GetId()), http.StatusInternalServerError)
+			renderHTTPError(log, w, errors.Wrapf(err, "failed to do currency conversion for product %s", p.GetId()), http.StatusInternalServerError)
 			return
 		}
 		ps[i] = productView{p, price}
@@ -87,43 +62,46 @@ func (fe *frontendServer) homeHandler(w http.ResponseWriter, r *http.Request) {
 		"session_id":    sessionID(r),
 		"cart_size":     len(cart),
 	}); err != nil {
-		log.Println(err)
+		log.Error(err)
 	}
 }
 
 func (fe *frontendServer) productHandler(w http.ResponseWriter, r *http.Request) {
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
 	id := mux.Vars(r)["id"]
 	if id == "" {
-		renderHTTPError(w, errors.New("product id not specified"), http.StatusBadRequest)
+		renderHTTPError(log, w, errors.New("product id not specified"), http.StatusBadRequest)
 		return
 	}
-	log.Printf("[productHandler] id=%s currency=%s session=%s", id, currentCurrency(r), sessionID(r))
+	log.WithField("id", id).WithField("currency", currentCurrency(r)).
+		Debug("serving product page")
+
 	p, err := fe.getProduct(r.Context(), id)
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve product"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve product"), http.StatusInternalServerError)
 		return
 	}
 	currencies, err := fe.getCurrencies(r.Context())
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve currencies"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve currencies"), http.StatusInternalServerError)
 		return
 	}
 
 	cart, err := fe.getCart(r.Context(), sessionID(r))
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve cart"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve cart"), http.StatusInternalServerError)
 		return
 	}
 
 	price, err := fe.convertCurrency(r.Context(), p.GetPriceUsd(), currentCurrency(r))
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "failed to convert currency"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "failed to convert currency"), http.StatusInternalServerError)
 		return
 	}
 
 	recommendations, err := fe.getRecommendations(r.Context(), sessionID(r), []string{id})
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "failed to get product recommendations"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "failed to get product recommendations"), http.StatusInternalServerError)
 		return
 	}
 
@@ -145,22 +123,23 @@ func (fe *frontendServer) productHandler(w http.ResponseWriter, r *http.Request)
 }
 
 func (fe *frontendServer) addToCartHandler(w http.ResponseWriter, r *http.Request) {
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
 	quantity, _ := strconv.ParseUint(r.FormValue("quantity"), 10, 32)
 	productID := r.FormValue("product_id")
 	if productID == "" || quantity == 0 {
-		renderHTTPError(w, errors.New("invalid form input"), http.StatusBadRequest)
+		renderHTTPError(log, w, errors.New("invalid form input"), http.StatusBadRequest)
 		return
 	}
-	log.Printf("[addToCart] product_id=%s qty=%d session_id=%s", productID, quantity, sessionID(r))
+	log.WithField("product", productID).WithField("quantity", quantity).Debug("adding to cart")
 
 	p, err := fe.getProduct(r.Context(), productID)
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve product"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve product"), http.StatusInternalServerError)
 		return
 	}
 
 	if err := fe.insertCart(r.Context(), sessionID(r), p.GetId(), int32(quantity)); err != nil {
-		renderHTTPError(w, errors.Wrap(err, "failed to add to cart"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "failed to add to cart"), http.StatusInternalServerError)
 		return
 	}
 	w.Header().Set("location", "/cart")
@@ -168,10 +147,11 @@ func (fe *frontendServer) addToCartHandler(w http.ResponseWriter, r *http.Reques
 }
 
 func (fe *frontendServer) emptyCartHandler(w http.ResponseWriter, r *http.Request) {
-	log.Printf("[emptyCart] session_id=%s", sessionID(r))
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
+	log.Debug("emptying cart")
 
 	if err := fe.emptyCart(r.Context(), sessionID(r)); err != nil {
-		renderHTTPError(w, errors.Wrap(err, "failed to empty cart"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "failed to empty cart"), http.StatusInternalServerError)
 		return
 	}
 	w.Header().Set("location", "/")
@@ -179,27 +159,28 @@ func (fe *frontendServer) emptyCartHandler(w http.ResponseWriter, r *http.Reques
 }
 
 func (fe *frontendServer) viewCartHandler(w http.ResponseWriter, r *http.Request) {
-	log.Printf("[viewCart] session_id=%s", sessionID(r))
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
+	log.Debug("view user cart")
 	currencies, err := fe.getCurrencies(r.Context())
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve currencies"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve currencies"), http.StatusInternalServerError)
 		return
 	}
 	cart, err := fe.getCart(r.Context(), sessionID(r))
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "could not retrieve cart"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "could not retrieve cart"), http.StatusInternalServerError)
 		return
 	}
 
 	recommendations, err := fe.getRecommendations(r.Context(), sessionID(r), cartIDs(cart))
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "failed to get product recommendations"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "failed to get product recommendations"), http.StatusInternalServerError)
 		return
 	}
 
 	shippingCost, err := fe.getShippingQuote(r.Context(), cart, currentCurrency(r))
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "failed to get shipping quote"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "failed to get shipping quote"), http.StatusInternalServerError)
 		return
 	}
 
@@ -213,12 +194,12 @@ func (fe *frontendServer) viewCartHandler(w http.ResponseWriter, r *http.Request
 	for i, item := range cart {
 		p, err := fe.getProduct(r.Context(), item.GetProductId())
 		if err != nil {
-			renderHTTPError(w, errors.Wrapf(err, "could not retrieve product #%s", item.GetProductId()), http.StatusInternalServerError)
+			renderHTTPError(log, w, errors.Wrapf(err, "could not retrieve product #%s", item.GetProductId()), http.StatusInternalServerError)
 			return
 		}
 		price, err := fe.convertCurrency(r.Context(), p.GetPriceUsd(), currentCurrency(r))
 		if err != nil {
-			renderHTTPError(w, errors.Wrapf(err, "could not convert currency for product #%s", item.GetProductId()), http.StatusInternalServerError)
+			renderHTTPError(log, w, errors.Wrapf(err, "could not convert currency for product #%s", item.GetProductId()), http.StatusInternalServerError)
 			return
 		}
 
@@ -248,7 +229,8 @@ func (fe *frontendServer) viewCartHandler(w http.ResponseWriter, r *http.Request
 }
 
 func (fe *frontendServer) placeOrderHandler(w http.ResponseWriter, r *http.Request) {
-	log.Printf("[checkout] session_id=%s", sessionID(r))
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
+	log.Debug("placing order")
 
 	var (
 		email         = r.FormValue("email")
@@ -281,10 +263,10 @@ func (fe *frontendServer) placeOrderHandler(w http.ResponseWriter, r *http.Reque
 				Country:       country},
 		})
 	if err != nil {
-		renderHTTPError(w, errors.Wrap(err, "failed to complete the order"), http.StatusInternalServerError)
+		renderHTTPError(log, w, errors.Wrap(err, "failed to complete the order"), http.StatusInternalServerError)
 		return
 	}
-	log.Printf("order #%s completed", order.GetOrder().GetOrderId())
+	log.WithField("order", order.GetOrder().GetOrderId()).Info("order placed")
 
 	order.GetOrder().GetItems()
 	recommendations, _ := fe.getRecommendations(r.Context(), sessionID(r), nil)
@@ -306,7 +288,8 @@ func (fe *frontendServer) placeOrderHandler(w http.ResponseWriter, r *http.Reque
 }
 
 func (fe *frontendServer) logoutHandler(w http.ResponseWriter, r *http.Request) {
-	log.Printf("[logout] session_id=%s", sessionID(r))
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
+	log.Debug("logging out")
 	for _, c := range r.Cookies() {
 		c.Expires = time.Now().Add(-time.Hour * 24 * 365)
 		c.MaxAge = -1
@@ -317,8 +300,11 @@ func (fe *frontendServer) logoutHandler(w http.ResponseWriter, r *http.Request)
 }
 
 func (fe *frontendServer) setCurrencyHandler(w http.ResponseWriter, r *http.Request) {
+	log := r.Context().Value(ctxKeyLog{}).(logrus.FieldLogger)
 	cur := r.FormValue("currency_code")
-	log.Printf("[setCurrency] session_id=%s code=%s", sessionID(r), cur)
+	log.WithField("curr.new", cur).WithField("curr.old", currentCurrency(r)).
+		Debug("setting currency")
+
 	if cur != "" {
 		http.SetCookie(w, &http.Cookie{
 			Name:   cookieCurrency,
@@ -334,8 +320,8 @@ func (fe *frontendServer) setCurrencyHandler(w http.ResponseWriter, r *http.Requ
 	w.WriteHeader(http.StatusFound)
 }
 
-func renderHTTPError(w http.ResponseWriter, err error, code int) {
+func renderHTTPError(log logrus.FieldLogger, w http.ResponseWriter, err error, code int) {
-	log.Printf("[error](code=%d) %+v ", code, err)
+	log.WithField("error", err).Error("request error")
 	errMsg := fmt.Sprintf("%+v", err)
 
 	w.WriteHeader(code)

src/frontend/main.go

@@ -3,14 +3,13 @@ package main
 import (
 	"context"
 	"fmt"
-	"log"
 	"net/http"
 	"os"
 	"time"
 
-	"github.com/pkg/errors"
-
 	"github.com/gorilla/mux"
+	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 	"google.golang.org/grpc"
 )
 
@@ -53,7 +52,9 @@ type frontendServer struct {
 
 func main() {
 	ctx := context.Background()
-	log.SetFlags(log.Lshortfile | log.Ltime)
+	log := logrus.New()
+	log.Level = logrus.DebugLevel
+	log.Formatter = &logrus.TextFormatter{}
 
 	srvPort := port
 	if os.Getenv("PORT") != "" {
@@ -85,8 +86,10 @@ func main() {
 	r.HandleFunc("/logout", svc.logoutHandler).Methods(http.MethodGet)
 	r.HandleFunc("/cart/checkout", ensureSessionID(svc.placeOrderHandler)).Methods(http.MethodPost)
 	r.PathPrefix("/static/").Handler(http.StripPrefix("/static/", http.FileServer(http.Dir("./static/"))))
-	log.Printf("starting server on " + addr + ":" + srvPort)
+
-	log.Fatal(http.ListenAndServe(addr+":"+srvPort, r))
+	log.Infof("starting server on " + addr + ":" + srvPort)
+	loggedHandler := &logHandler{log: log, next: r}
+	log.Fatal(http.ListenAndServe(addr+":"+srvPort, loggedHandler))
 }
 
 func mustMapEnv(target *string, envKey string) {

src/frontend/middleware.go

@@ -0,0 +1,85 @@
+package main
+
+import (
+	"context"
+	"net/http"
+	"time"
+
+	"github.com/google/uuid"
+	"github.com/sirupsen/logrus"
+)
+
+type ctxKeyLog struct{}
+
+type logHandler struct {
+	log  *logrus.Logger
+	next http.Handler
+}
+
+type responseRecorder struct {
+	b      int
+	status int
+	w      http.ResponseWriter
+}
+
+func (r *responseRecorder) Header() http.Header { return r.w.Header() }
+
+func (r *responseRecorder) Write(p []byte) (int, error) {
+	if r.status == 0 {
+		r.status = http.StatusOK
+	}
+	n, err := r.w.Write(p)
+	r.b += n
+	return n, err
+}
+
+func (r *responseRecorder) WriteHeader(statusCode int) {
+	r.status = statusCode
+	r.w.WriteHeader(statusCode)
+}
+
+func (lh *logHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	start := time.Now()
+	rr := &responseRecorder{w: w}
+	log := lh.log.WithFields(logrus.Fields{
+		"http.req.path":   r.URL.Path,
+		"http.req.method": r.Method,
+	})
+	if v, ok := r.Context().Value(ctxKeySessionID{}).(string); ok {
+		log = log.WithField("session_id", v)
+	}
+	log.Debug("request started")
+	defer func() {
+		log.WithFields(logrus.Fields{
+			"http.resp.took_ms": int64(time.Since(start) / time.Millisecond),
+			"http.resp.status":  rr.status,
+			"http.resp.bytes":   rr.b}).Debugf("request complete")
+	}()
+
+	ctx := context.WithValue(r.Context(), ctxKeyLog{}, log)
+	r = r.WithContext(ctx)
+	lh.next.ServeHTTP(rr, r)
+}
+
+func ensureSessionID(next http.HandlerFunc) http.HandlerFunc {
+	return func(w http.ResponseWriter, r *http.Request) {
+		var sessionID string
+		c, err := r.Cookie(cookieSessionID)
+		if err == http.ErrNoCookie {
+			u, _ := uuid.NewRandom()
+			sessionID = u.String()
+			http.SetCookie(w, &http.Cookie{
+				Name:   cookieSessionID,
+				Value:  sessionID,
+				MaxAge: cookieMaxAge,
+			})
+		} else if err != nil {
+			return
+		} else {
+			sessionID = c.Value
+		}
+		ctx := context.WithValue(r.Context(), ctxKeySessionID{}, sessionID)
+		r = r.WithContext(ctx)
+		next(w, r)
+	}
+}

src/frontend/port-forward-dependencies.sh

@@ -1,7 +1,7 @@
 #!/bin/bash
 set -ex
 
-kubectl port-forward $(kubectl get pods -l app=currencyservice -o=name | head -n 1) 7000:31337 &
+kubectl port-forward $(kubectl get pods -l app=currencyservice -o=name | head -n 1) 7000:7000 &
 kubectl port-forward $(kubectl get pods -l app=recommendationservice -o=name | head -n 1) 8081:8080 &
 kubectl port-forward $(kubectl get pods -l app=cartservice -o=name | head -n 1) 7070:7070 &
 kubectl port-forward $(kubectl get pods -l app=productcatalogservice -o=name | head -n 1) 3550:3550 &