feats: log all requests with structured fields

5 files changed, 49 insertions, 26 deletions

diff --git a/pkg/web/configuration.go b/pkg/web/configuration.go
new file mode 100644
index 0000000..3fcd000
--- /dev/null
+++ b/pkg/web/configuration.go
@@ -0,0 +1,6 @@
+package web
+
+type Configuration struct {
+	issuer  string
+	keyData []byte
+}
diff --git a/pkg/web/http_context.go b/pkg/web/http_context.go
index ceabc70..ccbc7c9 100644
--- a/pkg/web/http_context.go
+++ b/pkg/web/http_context.go
@@ -1,6 +1,7 @@
 package web
 
 import (
+	"fmt"
 	"net/http"
 	"time"
 
@@ -8,37 +9,54 @@ import (
 )
 
 type HttpContext struct {
-	issuer  string
-	keyData []byte
-	log     *logrus.Logger
+	cfg *Configuration
+	log *logrus.Logger
 }
 
 func NewHttpContext(issuer string, keyData []byte) *HttpContext {
 	logger := logrus.New()
+	logger.SetFormatter(&logrus.TextFormatter{
+		DisableColors:          true,
+		DisableLevelTruncation: true,
+		ForceQuote:             true,
+		FullTimestamp:          true,
+		FieldMap: logrus.FieldMap{
+			logrus.FieldKeyTime:  "@timestamp",
+			logrus.FieldKeyLevel: "@level",
+			logrus.FieldKeyMsg:   "@message",
+		},
+	})
+
 	return &HttpContext{
-		issuer:  issuer,
-		keyData: keyData,
-		log:     logger,
+		cfg: &Configuration{
+			issuer:  issuer,
+			keyData: keyData,
+		},
+		log: logger,
 	}
 }
 
 func (h *HttpContext) Router() *http.ServeMux {
 	mux := http.NewServeMux()
 
-	mux.Handle("/", h.withLogging(http.HandlerFunc(h.Default)))
+	mux.Handle("/", h.buildHandlerFor(h.Default))
 	mux.Handle("/.well-known/", h.wellKnownMux())
-	mux.Handle("/authorize", http.HandlerFunc(h.Authorize))
-	mux.Handle("/register", http.HandlerFunc(h.Register))
-	mux.Handle("/revoke", http.HandlerFunc(http.NotFound))
-	mux.Handle("/token", http.HandlerFunc(h.Token))
-	mux.Handle("/userinfo", http.HandlerFunc(http.NotFound))
+	mux.Handle("/authorize", h.buildHandlerFor(h.Authorize))
+	mux.Handle("/register", h.buildHandlerFor(h.Register))
+	mux.Handle("/revoke", h.buildHandlerFor(http.NotFound))
+	mux.Handle("/token", h.buildHandlerFor(h.Token))
+	mux.Handle("/userinfo", h.buildHandlerFor(http.NotFound))
 	return mux
 }
 
+func (h *HttpContext) buildHandlerFor(handler http.HandlerFunc) http.Handler {
+	return h.withLogging(http.HandlerFunc(handler))
+}
+
 func (h *HttpContext) wellKnownMux() *http.ServeMux {
 	mux := http.NewServeMux()
-	mux.Handle("/.well-known/jwks.json", http.HandlerFunc(h.JsonWebKeySets))
-	mux.Handle("/.well-known/openid-configuration", http.HandlerFunc(h.OpenIdConfiguration))
+	mux.Handle("/.well-known/jwks.json", h.buildHandlerFor(h.JsonWebKeySets))
+	mux.Handle("/.well-known/openid-configuration", h.buildHandlerFor(h.OpenIdConfiguration))
 	return mux
 }
 
@@ -48,14 +66,13 @@ func (h *HttpContext) withLogging(next http.Handler) http.Handler {
 		next.ServeHTTP(w, r)
 		end := time.Now()
 
+		duration := end.Sub(start)
 		h.log.WithFields(logrus.Fields{
-			"content_type": r.Header.Get("Content-Type"),
-			"finished_at":  end.Unix(),
-			"method":       r.Method,
-			"path":         r.URL.Path,
-			"remote_addr":  r.RemoteAddr,
-			"started_at":   start.Unix(),
-			"user_agent":   r.UserAgent,
-		}).Info("Done")
+			"method":      r.Method,
+			"path":        r.URL.Path,
+			"remote_addr": r.RemoteAddr,
+			"user_agent":  r.UserAgent(),
+			"µs":          duration.Microseconds(),
+		}).Info(fmt.Sprintf("%v %v", r.Method, r.URL.Path))
 	})
 }
diff --git a/pkg/web/json_web_key_sets.go b/pkg/web/json_web_key_sets.go
index 2d32845..c3dafcb 100644
--- a/pkg/web/json_web_key_sets.go
+++ b/pkg/web/json_web_key_sets.go
@@ -11,7 +11,7 @@ import (
 
 func (h *HttpContext) JsonWebKeySets(w http.ResponseWriter, r *http.Request) {
 	w.Header().Set("Content-Type", "application/json")
-	privatePem, _ := pem.Decode(h.keyData)
+	privatePem, _ := pem.Decode(h.cfg.keyData)
 	parsedKey, _ := x509.ParsePKCS1PrivateKey(privatePem.Bytes)
 	key, _ := jwk.FromRaw(parsedKey)
 	pubKey, _ := jwk.PublicKeyOf(key)
diff --git a/pkg/web/open_id_configuration.go b/pkg/web/open_id_configuration.go
index 7e2149a..2c71c32 100644
--- a/pkg/web/open_id_configuration.go
+++ b/pkg/web/open_id_configuration.go
@@ -15,5 +15,5 @@ var (
 
 func (h *HttpContext) OpenIdConfiguration(w http.ResponseWriter, r *http.Request) {
 	w.Header().Set("Content-Type", "application/json")
-	tmpl.Execute(w, struct{ Issuer string }{Issuer: h.issuer})
+	tmpl.Execute(w, struct{ Issuer string }{Issuer: h.cfg.issuer})
 }
diff --git a/pkg/web/token.go b/pkg/web/token.go
index 41b6c37..1604246 100644
--- a/pkg/web/token.go
+++ b/pkg/web/token.go
@@ -62,7 +62,7 @@ func (h *HttpContext) createIdToken(clientId string) string {
 	}
 	expiresAt := now.Add(time.Hour * time.Duration(1))
 	idToken := jwt.NewWithClaims(jwt.SigningMethodRS256, &jwt.StandardClaims{
-		Issuer:    h.issuer,
+		Issuer:    h.cfg.issuer,
 		Subject:   "1",
 		Audience:  clientId,
 		ExpiresAt: expiresAt.Unix(),
@@ -71,7 +71,7 @@ func (h *HttpContext) createIdToken(clientId string) string {
 		Id:        uuid.GenerateUUID(),
 	})
 
-	key, _ := jwt.ParseRSAPrivateKeyFromPEM(h.keyData)
+	key, _ := jwt.ParseRSAPrivateKeyFromPEM(h.cfg.keyData)
 	signedIdToken, _ := idToken.SignedString(key)
 	return signedIdToken
 }