cmd/site: better logging

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) {
+var (
-	now := time.Now()
+	templateRenderTime = promauto.NewHistogramVec(prometheus.HistogramOpts{
-	ln.Log(context.Background(), f, ln.F{"action": "template_rendered", "dur": now.Sub(from).String(), "name": name})
+		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)
 		}
 

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
 		}

go.mod

@@ -1,6 +1,7 @@
 module christine.website
 
 require (
+	github.com/celrenheit/sandflake v0.0.0-20171226210037-92cb626f32dc
 	github.com/golang/protobuf v1.3.1 // indirect
 	github.com/gorilla/feeds v1.1.0
 	github.com/kr/pretty v0.1.0 // indirect
@@ -11,6 +12,7 @@ require (
 	github.com/prometheus/common v0.2.0 // indirect
 	github.com/prometheus/procfs v0.0.0-20190319124303-40f3c57fb198 // indirect
 	github.com/russross/blackfriday v2.0.0+incompatible
+	github.com/sebest/xff v0.0.0-20160910043805-6c115e0ffa35
 	github.com/shurcooL/sanitized_anchor_name v1.0.0 // indirect
 	github.com/snabb/sitemap v1.0.0
 	github.com/stretchr/testify v1.3.0

go.sum

@@ -2,6 +2,8 @@ github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc/go.mod h1:LOuy
 github.com/alecthomas/units v0.0.0-20151022065526-2efee857e7cf/go.mod h1:ybxpYRFXyAe+OPACYpWeL0wqObRcbAqCMya13uyzqw0=
 github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 h1:xJ4a3vCFaGF/jqvzLMYoU8P317H5OQ+Via4RmuPwCS0=
 github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
+github.com/celrenheit/sandflake v0.0.0-20171226210037-92cb626f32dc h1:JcF3zLolKwrXXeBjvczfaxd3kxwFEBmiBQ6tOdha6QQ=
+github.com/celrenheit/sandflake v0.0.0-20171226210037-92cb626f32dc/go.mod h1:7L8gY0+4GYeBc9TvqVuDUq7tXuM6Sj7llnt7HkVwWlQ=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -52,6 +54,8 @@ github.com/prometheus/procfs v0.0.0-20190319124303-40f3c57fb198 h1:gANBAZ/83d6fD
 github.com/prometheus/procfs v0.0.0-20190319124303-40f3c57fb198/go.mod h1:TjEm7ze935MbeOT/UhFTIMYKhuLP4wbCsTZCD3I8kEA=
 github.com/russross/blackfriday v2.0.0+incompatible h1:cBXrhZNUf9C+La9/YpS+UHpUT8YD6Td9ZMSU9APFcsk=
 github.com/russross/blackfriday v2.0.0+incompatible/go.mod h1:JO/DiYxRf+HjHt06OyowR9PTA263kcR/rfWxYHBV53g=
+github.com/sebest/xff v0.0.0-20160910043805-6c115e0ffa35 h1:eajwn6K3weW5cd1ZXLu2sJ4pvwlBiCWY4uDejOr73gM=
+github.com/sebest/xff v0.0.0-20160910043805-6c115e0ffa35/go.mod h1:wozgYq9WEBQBaIJe4YZ0qTSFAMxmcwBhQH0fO0R34Z0=
 github.com/shurcooL/sanitized_anchor_name v1.0.0 h1:PdmoCO6wvbs+7yrJyMORt4/BmY5IYyJwS/kOiWx8mHo=
 github.com/shurcooL/sanitized_anchor_name v1.0.0/go.mod h1:1NzhyTcUVG4SuEtjjoZeVRXNmyL/1OwPU0+IJeTBvfc=
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
@@ -70,6 +74,7 @@ github.com/tj/front v0.0.0-20170212063142-739be213b0a1/go.mod h1:deJrtusCTptAW4E
 golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/net v0.0.0-20180811021610-c39426892332/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/net v0.0.0-20181114220301-adae6a3d119a/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
+golang.org/x/net v0.0.0-20181201002055-351d144fa1fc h1:a3CU5tJYVj92DY2LaA1kUkrsqD5/3mLDhx2NcNqyW+0=
 golang.org/x/net v0.0.0-20181201002055-351d144fa1fc/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/sync v0.0.0-20181108010431-42b317875d0f/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=