From 20c08e68d1218475d6c6f3ca8ae718e1f508c696 Mon Sep 17 00:00:00 2001 From: Christine Dodrill Date: Fri, 22 Mar 2019 18:42:25 -0700 Subject: [PATCH] cmd/site: better logging --- cmd/site/html.go | 22 ++++++++++++++++------ cmd/site/main.go | 43 ++++++++++++++++++++++++++++++++++++++----- go.mod | 2 ++ go.sum | 5 +++++ 4 files changed, 61 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 diff --git a/go.mod b/go.mod index ddee490..387df9d 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 92d79d1..de5831d 100644 --- a/go.sum +++ b/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=