cmd/site: better logging

2 files changed, 54 insertions, 11 deletions

diff --git a/cmd/site/html.go b/cmd/site/html.go
index 468a149..a645551 100644
--- a/cmd/site/html.go
+++ b/cmd/site/html.go
@@ -11,26 +11,36 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 	"within.website/ln"
+	"within.website/ln/opname"
 )
 
-func logTemplateTime(name string, f ln.F, from time.Time) {
-	now := time.Now()
-	ln.Log(context.Background(), f, ln.F{"action": "template_rendered", "dur": now.Sub(from).String(), "name": name})
+var (
+	templateRenderTime = promauto.NewHistogramVec(prometheus.HistogramOpts{
+		Name: "template_render_time",
+		Help: "Template render time in nanoseconds",
+	}, []string{"name"})
+)
+
+func logTemplateTime(ctx context.Context, name string, f ln.F, from time.Time) {
+	dur := time.Since(from)
+	templateRenderTime.With(prometheus.Labels{"name": name}).Observe(float64(dur))
+	ln.Log(ctx, f, ln.F{"dur": dur, "name": name})
 }
 
 func (s *Site) renderTemplatePage(templateFname string, data interface{}) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		ctx := opname.With(r.Context(), "renderTemplatePage")
 		fetag := "W/" + Hash(templateFname, etag) + "-1"
 
 		f := ln.F{"etag": fetag, "if_none_match": r.Header.Get("If-None-Match")}
 
 		if r.Header.Get("If-None-Match") == fetag {
 			http.Error(w, "Cached data OK", http.StatusNotModified)
-			ln.Log(r.Context(), f, ln.Info("Cache hit"))
+			ln.Log(ctx, f, ln.Info("Cache hit"))
 			return
 		}
 
-		defer logTemplateTime(templateFname, f, time.Now())
+		defer logTemplateTime(ctx, templateFname, f, time.Now())
 
 		var t *template.Template
 		var err error
@@ -38,7 +48,7 @@ func (s *Site) renderTemplatePage(templateFname string, data interface{}) http.H
 		t, err = template.ParseFiles("templates/base.html", "templates/"+templateFname)
 		if err != nil {
 			w.WriteHeader(http.StatusInternalServerError)
-			ln.Error(context.Background(), err, ln.F{"action": "renderTemplatePage", "page": templateFname})
+			ln.Error(ctx, err, ln.F{"action": "renderTemplatePage", "page": templateFname})
 			fmt.Fprintf(w, "error: %v", err)
 		}
 
diff --git a/cmd/site/main.go b/cmd/site/main.go
index 4ea6fe8..ec9648b 100644
--- a/cmd/site/main.go
+++ b/cmd/site/main.go
@@ -14,13 +14,17 @@ import (
 
 	"christine.website/internal/front"
 	"christine.website/internal/jsonfeed"
+	"github.com/celrenheit/sandflake"
 	"github.com/gorilla/feeds"
 	"github.com/povilasv/prommod"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	blackfriday "github.com/russross/blackfriday"
+	"github.com/sebest/xff"
 	"github.com/snabb/sitemap"
 	"within.website/ln"
+	"within.website/ln/ex"
+	"within.website/ln/opname"
 )
 
 var port = os.Getenv("PORT")
@@ -74,6 +78,27 @@ func main() {
 	http.ListenAndServe(":"+port, s)
 }
 
+func requestIDMiddleware(next http.Handler) http.Handler {
+	var g sandflake.Generator
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		id := g.Next().String()
+
+		if rid := r.Header.Get("X-Request-Id"); rid != "" {
+			id = rid + "," + id
+		}
+
+		ctx := ln.WithF(r.Context(), ln.F{
+			"request_id": id,
+		})
+		r = r.WithContext(ctx)
+
+		w.Header().Set("X-Request-Id", id)
+		r.Header.Set("X-Request-Id", id)
+
+		next.ServeHTTP(w, r)
+	})
+}
+
 // Site is the parent object for https://christine.website's backend.
 type Site struct {
 	Posts  Posts
@@ -84,15 +109,17 @@ type Site struct {
 
 	mux     *http.ServeMux
 	sitemap []byte
+	xffmw *xff.XFF
 
 	templates map[string]*template.Template
 	tlock     sync.RWMutex
 }
 
 func (s *Site) ServeHTTP(w http.ResponseWriter, r *http.Request) {
-	ln.Log(r.Context(), ln.F{"action": "Site.ServeHTTP", "user_ip_address": r.RemoteAddr, "path": r.RequestURI})
+	ctx := opname.With(r.Context(), "site.ServeHTTP")
+	r = r.WithContext(ctx)
 
-	s.mux.ServeHTTP(w, r)
+	requestIDMiddleware(s.xffmw.Handler(ex.HTTPLog(s.mux))).ServeHTTP(w, r)
 }
 
 var arbDate = time.Date(2019, time.March, 21, 18, 0, 0, 0, time.UTC)
@@ -129,6 +156,12 @@ func Build() (*Site, error) {
 		ChangeFreq: sitemap.Weekly,
 	})
 
+
+	xffmw, err := xff.Default()
+	if err != nil {
+		return nil, err
+	}
+
 	s := &Site{
 		rssFeed: &feeds.Feed{
 			Title:       "Christine Dodrill's Blog",
@@ -153,10 +186,10 @@ func Build() (*Site, error) {
 			},
 		},
 		mux:       http.NewServeMux(),
-		templates: map[string]*template.Template{},
+		xffmw: xffmw,
 	}
 
-	err := filepath.Walk("./blog/", func(path string, info os.FileInfo, err error) error {
+	err = filepath.Walk("./blog/", func(path string, info os.FileInfo, err error) error {
 		if err != nil {
 			return err
 		}
@@ -164,7 +197,7 @@ func Build() (*Site, error) {
 		if info.IsDir() {
 			return nil
 		}
-		
+
 		fin, err := os.Open(path)
 		if err != nil {
 			return err