feat: Access Logging on the user server

Closes: #98

Co-authored-by: Roberto Abdelkader Martínez Pérez <robertomartinezp@gmail.com>

internal/logger/logger.go

@@ -1,12 +1,45 @@
 package logger
 
 import (
+	"fmt"
 	"log"
 	"os"
+	"time"
 )
 
+var A *log.Logger
 var L *log.Logger
 
 func init() {
+	A = log.New(os.Stdout, "", 0)
 	L = log.New(os.Stderr, "", log.LstdFlags|log.Lmicroseconds|log.LUTC)
 }
+
+// See https://en.wikipedia.org/wiki/Common_Log_Format
+// Tested with love against CLFParser https://pypi.org/project/clfparser/
+func LogAccess(clientAddr, handlerId, user, method, resource, version string, status int, bytesSent int64, referer, userAgent string) {
+	clientAddr = dashIfEmpty(clientAddr)
+	handlerId = dashIfEmpty(handlerId)
+	user = dashIfEmpty(user)
+	referer = dashIfEmpty(referer)
+	userAgent = dashIfEmpty(userAgent)
+	firstLine := fmt.Sprintf("%s %s %s", method, resource, version)
+	ts := time.Now().UTC().Format("02/Jan/2006:15:04:05 -0700") // Amazing date format layout!  Not.
+	A.Printf("%s %s %s [%s] %q %d %d %q %q\n",
+		clientAddr,
+		handlerId,
+		user,
+		ts,
+		firstLine,
+		status,
+		bytesSent,
+		referer,
+		userAgent)
+}
+
+func dashIfEmpty(value string) string {
+	if value == "" {
+		return "-"
+	}
+	return value
+}

internal/server/data/resource.go

@@ -192,7 +192,8 @@ func setResponseStatus(w http.ResponseWriter, r *http.Request, h *model.Handler)
 	} else if http.StatusText(si) == "" {
 		httperror.ErrorJSON(w, InvalidStatusCode, http.StatusBadRequest)
 	} else {
-		h.Writer.WriteHeader(int(si))
+		h.Status = si
+		h.Writer.WriteHeader(si)
 	}
 }
 
@@ -221,10 +222,12 @@ func setResponseCookies(w http.ResponseWriter, r *http.Request, h *model.Handler
 }
 
 func setResponseBody(w http.ResponseWriter, r *http.Request, h *model.Handler) {
-	if n, err := io.Copy(h.Writer, r.Body); err != nil {
+	n, err := io.Copy(h.Writer, r.Body)
+	if err != nil {
 		if n > 0 {
 			panic(http.ErrAbortHandler)
 		}
 		httperror.ErrorJSON(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
 	}
+	h.SentBytes += n
 }

internal/server/model/handler.go

@@ -41,4 +41,10 @@ type Handler struct {
 
 	// Writer is the original http.ResponseWriter of the request.
 	Writer http.ResponseWriter
+
+	// Status is the returned status code
+	Status int
+
+	// SentBytes is the number of sent bytes
+	SentBytes int64
 }

internal/server/user/mux/gorillize.go

@@ -21,6 +21,7 @@ import (
 
 	"github.com/gorilla/mux"
 
+	"github.com/BBVA/kapow/internal/logger"
 	"github.com/BBVA/kapow/internal/server/model"
 )
 
@@ -30,6 +31,35 @@ func gorillize(rs []model.Route, buildHandler func(model.Route) http.Handler) *m
 	for _, r := range rs {
 		m.Handle(r.Pattern, buildHandler(r)).Methods(r.Method)
 	}
-
+	m.NotFoundHandler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusNotFound)
+		logger.LogAccess(
+			r.RemoteAddr,
+			"-",
+			"-",
+			r.Method,
+			r.RequestURI,
+			r.Proto,
+			http.StatusNotFound,
+			0,
+			r.Header.Get("Referer"),
+			r.Header.Get("User-Agent"),
+		)
+	})
+	m.MethodNotAllowedHandler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusMethodNotAllowed)
+		logger.LogAccess(
+			r.RemoteAddr,
+			"-",
+			"-",
+			r.Method,
+			r.RequestURI,
+			r.Proto,
+			http.StatusMethodNotAllowed,
+			0,
+			r.Header.Get("Referer"),
+			r.Header.Get("User-Agent"),
+		)
+	})
 	return m
 }

internal/server/user/mux/gorillize_test.go

@@ -42,6 +42,8 @@ func handleRouteIDToBody(route model.Route) http.Handler {
 
 func TestGorillizeReturnsAnEmptyMuxWhenAnEmptyRouteList(t *testing.T) {
 	m := gorillize([]model.Route{}, handlerStatusOK)
+	m.NotFoundHandler = nil
+	m.MethodNotAllowedHandler = nil
 
 	if !reflect.DeepEqual(*m, *mux.NewRouter()) {
 		t.Error("Returned mux not empty")

internal/server/user/mux/handlerbuilder.go

@@ -45,6 +45,7 @@ func handlerBuilder(route model.Route) http.Handler {
 			Route:   route,
 			Request: r,
 			Writer:  w,
+			Status:  200,
 		}
 
 		data.Handlers.Add(h)
@@ -78,6 +79,20 @@ func handlerBuilder(route model.Route) http.Handler {
 			logger.L.Println(err)
 		}
 
+		if r != nil {
+			logger.LogAccess(
+				r.RemoteAddr,
+				h.ID,
+				"-",
+				r.Method,
+				r.RequestURI,
+				r.Proto,
+				h.Status,
+				h.SentBytes,
+				r.Header.Get("Referer"),
+				r.Header.Get("User-Agent"),
+			)
+		}
 	})
 }
 

internal/server/user/mux/mux.go

@@ -32,7 +32,7 @@ type SwappableMux struct {
 
 func New() *SwappableMux {
 	return &SwappableMux{
-		root: mux.NewRouter(),
+		root: gorillize([]model.Route{}, handlerBuilder),
 	}
 }