From 665ffe8bd1f44b4cba88eac1eccd62ce3ef2a3cc Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Ferdinand=20M=C3=BCtsch?= <ferdinand@muetsch.io>
Date: Sun, 31 Jan 2021 16:46:39 +0100
Subject: [PATCH] chore: log request durations (resolve #102)

---
 main.go                |   7 ++-
 middlewares/logging.go | 123 ++++++++++++++++++++++++++++++++++++++---
 2 files changed, 121 insertions(+), 9 deletions(-)

diff --git a/main.go b/main.go
index 9d8941a..6f95a66 100644
--- a/main.go
+++ b/main.go
@@ -9,7 +9,9 @@ import (
 	conf "github.com/muety/wakapi/config"
 	"github.com/muety/wakapi/migrations/common"
 	"github.com/muety/wakapi/repositories"
+	"log"
 	"net/http"
+	"os"
 	"strconv"
 	"time"
 
@@ -140,7 +142,10 @@ func main() {
 
 	// Middlewares
 	recoveryMiddleware := handlers.RecoveryHandler()
-	loggingMiddleware := middlewares.NewLoggingMiddleware().Handler
+	loggingMiddleware := middlewares.NewLoggingMiddleware(
+		// Use logbuch here once https://github.com/emvi/logbuch/issues/4 is realized
+		log.New(os.Stdout, "", 0),
+	)
 	corsMiddleware := handlers.CORS()
 	authenticateMiddleware := middlewares.NewAuthenticateMiddleware(
 		userService,
diff --git a/middlewares/logging.go b/middlewares/logging.go
index 2170d67..dc614d1 100644
--- a/middlewares/logging.go
+++ b/middlewares/logging.go
@@ -1,17 +1,124 @@
 package middlewares
 
+// Borrowed from https://gist.github.com/elithrar/887d162dfd0c539b700ab4049c76e22b
+
 import (
-	"github.com/gorilla/handlers"
+	"io"
+	"log"
 	"net/http"
-	"os"
+	"time"
 )
 
-type LoggingMiddleware struct{}
-
-func NewLoggingMiddleware() *LoggingMiddleware {
-	return &LoggingMiddleware{}
+type LoggingMiddleware struct {
+	handler http.Handler
+	output  *log.Logger
 }
 
-func (m *LoggingMiddleware) Handler(h http.Handler) http.Handler {
-	return handlers.LoggingHandler(os.Stdout, h)
+func NewLoggingMiddleware(output *log.Logger) func(http.Handler) http.Handler {
+	return func(h http.Handler) http.Handler {
+		return &LoggingMiddleware{
+			handler: h,
+			output:  output,
+		}
+	}
+}
+
+func (lg *LoggingMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	ww := wrapWriter(w)
+
+	start := time.Now()
+	lg.handler.ServeHTTP(ww, r)
+	end := time.Now()
+	duration := end.Sub(start)
+
+	lg.output.Printf(
+		"%v status=%d, method=%s, uri=%s, duration=%v, bytes=%d, addr=%s\n",
+		time.Now().Format(time.RFC3339Nano),
+		ww.Status(),
+		r.Method,
+		r.URL.String(),
+		duration,
+		ww.BytesWritten(),
+		r.RemoteAddr,
+	)
+}
+
+// The below writer-wrapping code has been lifted from
+// https://github.com/zenazn/goji/blob/master/web/middleware/logger.go - because
+// it does exactly what is needed, and it's unlikely to change in any
+// significant way that makes copying worse-off than importing. MIT licensed
+// and (c) Carl Jackson.
+
+// writerProxy is a proxy around an http.ResponseWriter that allows you to hook
+// into various parts of the response process.
+type writerProxy interface {
+	http.ResponseWriter
+	// Status returns the HTTP status of the request, or 0 if one has not
+	// yet been sent.
+	Status() int
+	// BytesWritten returns the total number of bytes sent to the client.
+	BytesWritten() int
+	// Tee causes the response body to be written to the given io.Writer in
+	// addition to proxying the writes through. Only one io.Writer can be
+	// tee'd to at once: setting a second one will overwrite the first.
+	// Writes will be sent to the proxy before being written to this
+	// io.Writer. It is illegal for the tee'd writer to be modified
+	// concurrently with writes.
+	Tee(io.Writer)
+	// Unwrap returns the original proxied target.
+	Unwrap() http.ResponseWriter
+}
+
+// wrapWriter wraps an http.ResponseWriter, returning a proxy that allows you to
+// hook into various parts of the response process.
+func wrapWriter(w http.ResponseWriter) writerProxy {
+	return &basicWriter{ResponseWriter: w}
+}
+
+// basicWriter wraps a http.ResponseWriter that implements the minimal
+// http.ResponseWriter interface.
+type basicWriter struct {
+	http.ResponseWriter
+	wroteHeader bool
+	code        int
+	bytes       int
+	tee         io.Writer
+}
+
+func (b *basicWriter) WriteHeader(code int) {
+	if !b.wroteHeader {
+		b.code = code
+		b.wroteHeader = true
+		b.ResponseWriter.WriteHeader(code)
+	}
+}
+func (b *basicWriter) Write(buf []byte) (int, error) {
+	b.WriteHeader(http.StatusOK)
+	n, err := b.ResponseWriter.Write(buf)
+	if b.tee != nil {
+		_, err2 := b.tee.Write(buf[:n])
+		// Prefer errors generated by the proxied writer.
+		if err == nil {
+			err = err2
+		}
+	}
+	b.bytes += n
+	return n, err
+}
+func (b *basicWriter) maybeWriteHeader() {
+	if !b.wroteHeader {
+		b.WriteHeader(http.StatusOK)
+	}
+}
+func (b *basicWriter) Status() int {
+	return b.code
+}
+func (b *basicWriter) BytesWritten() int {
+	return b.bytes
+}
+func (b *basicWriter) Tee(w io.Writer) {
+	b.tee = w
+}
+func (b *basicWriter) Unwrap() http.ResponseWriter {
+	return b.ResponseWriter
 }