From 4d05223224b087ce338b1d27ad8521e4df4e855e Mon Sep 17 00:00:00 2001 From: pancho horrillo Date: Wed, 16 Dec 2020 17:51:22 +0100 Subject: [PATCH] feat: Access Logging on the user server MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes: #98 Co-authored-by: Roberto Abdelkader Martínez Pérez --- internal/logger/logger.go | 33 ++++++++++++++++++++++ internal/server/data/resource.go | 7 +++-- internal/server/model/handler.go | 6 ++++ internal/server/user/mux/gorillize.go | 32 ++++++++++++++++++++- internal/server/user/mux/gorillize_test.go | 2 ++ internal/server/user/mux/handlerbuilder.go | 15 ++++++++++ internal/server/user/mux/mux.go | 2 +- 7 files changed, 93 insertions(+), 4 deletions(-) diff --git a/internal/logger/logger.go b/internal/logger/logger.go index 91442af..19418de 100644 --- a/internal/logger/logger.go +++ b/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 +} diff --git a/internal/server/data/resource.go b/internal/server/data/resource.go index 61894d6..3c1ac90 100644 --- a/internal/server/data/resource.go +++ b/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 } diff --git a/internal/server/model/handler.go b/internal/server/model/handler.go index 8d79b35..851c459 100644 --- a/internal/server/model/handler.go +++ b/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 } diff --git a/internal/server/user/mux/gorillize.go b/internal/server/user/mux/gorillize.go index 9ebcc2d..900ab48 100644 --- a/internal/server/user/mux/gorillize.go +++ b/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 } diff --git a/internal/server/user/mux/gorillize_test.go b/internal/server/user/mux/gorillize_test.go index f531f2d..570a823 100644 --- a/internal/server/user/mux/gorillize_test.go +++ b/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") diff --git a/internal/server/user/mux/handlerbuilder.go b/internal/server/user/mux/handlerbuilder.go index 1865860..c0ec1c7 100644 --- a/internal/server/user/mux/handlerbuilder.go +++ b/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"), + ) + } }) } diff --git a/internal/server/user/mux/mux.go b/internal/server/user/mux/mux.go index 508cbcb..7b1dfba 100644 --- a/internal/server/user/mux/mux.go +++ b/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), } }