add logging, requestid middleware

This commit is contained in:
Mike Bloy 2019-09-07 22:40:11 -05:00
parent 992ccd98b3
commit 5df8d5f7ae
5 changed files with 175 additions and 4 deletions

View File

@ -5,6 +5,7 @@ import (
"os"
"github.com/kyoh86/xdg"
log "github.com/sirupsen/logrus"
"github.com/spf13/cobra"
"github.com/spf13/viper"
)
@ -37,6 +38,12 @@ func initConfig() {
viper.SetConfigName("gotest")
}
viper.ReadInConfig()
if viper.GetString("env") == "production" {
log.SetFormatter(&log.JSONFormatter{})
log.SetOutput(os.Stdout)
} else {
log.SetFormatter(&log.TextFormatter{})
}
}
// Execute the root command

2
go.mod
View File

@ -3,9 +3,11 @@ module git.bloy.org/mike/gotest
go 1.12
require (
github.com/google/uuid v1.1.1
github.com/gorilla/mux v1.7.3
github.com/joho/godotenv v1.3.0
github.com/kyoh86/xdg v1.0.0
github.com/sirupsen/logrus v1.4.2
github.com/spf13/cobra v0.0.5
github.com/spf13/viper v1.3.2
)

8
go.sum
View File

@ -8,6 +8,8 @@ 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=
github.com/fsnotify/fsnotify v1.4.7 h1:IXs+QLmnXW2CcXuY+8Mzv/fWEsPGWxqefPtCP5CnV9I=
github.com/fsnotify/fsnotify v1.4.7/go.mod h1:jwhsz4b93w/PPRr/qN1Yymfu8t87LnFCMoQvtojpjFo=
github.com/google/uuid v1.1.1 h1:Gkbcsh/GbpXz7lPftLA3P6TYMwjCLYm83jiFQZF/3gY=
github.com/google/uuid v1.1.1/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
github.com/gorilla/mux v1.7.3 h1:gnP5JzjVOuiZD07fKKToCAOjS0yOpj/qPETTXCCS6hw=
github.com/gorilla/mux v1.7.3/go.mod h1:1lud6UwP+6orDFRuTfBEV8e9/aOM/c4fVVCaMa2zaAs=
github.com/hashicorp/hcl v1.0.0 h1:0Anlzjpi4vEasTeNFn2mLJgTSwt0+6sfsiTG8qcWGx4=
@ -15,6 +17,7 @@ github.com/hashicorp/hcl v1.0.0/go.mod h1:E5yfLk+7swimpb2L/Alb/PJmXilQ/rhwaUYs4T
github.com/inconshreveable/mousetrap v1.0.0/go.mod h1:PxqpIevigyE2G7u3NXJIT2ANytuPF1OarO4DADm73n8=
github.com/joho/godotenv v1.3.0 h1:Zjp+RcGpHhGlrMbJzXTrZZPrWj+1vfm90La1wgB6Bhc=
github.com/joho/godotenv v1.3.0/go.mod h1:7hK45KPybAkOC6peb+G5yklZfMxEjkZhHbwpqxOKXbg=
github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
github.com/kyoh86/xdg v1.0.0 h1:TD1layQ0epNApNwGRblnQnT3S/2UH/gCQN1cmXWotvE=
github.com/kyoh86/xdg v1.0.0/go.mod h1:Z5mDqe0fxyxn3W2yTxsBAOQqIrXADQIh02wrTnaRM38=
github.com/magiconair/properties v1.8.0 h1:LLgXmsheXeRoUOBOjtwPQCWIYqM/LU1ayDtDePerRcY=
@ -27,6 +30,8 @@ github.com/pelletier/go-toml v1.2.0/go.mod h1:5z9KED0ma1S8pY6P1sdut58dfprrGBbd/9
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
github.com/russross/blackfriday v1.5.2/go.mod h1:JO/DiYxRf+HjHt06OyowR9PTA263kcR/rfWxYHBV53g=
github.com/sirupsen/logrus v1.4.2 h1:SPIRibHv4MatM3XXNO2BJeFLZwZ2LvZgfQ5+UNI2im4=
github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
github.com/spf13/afero v1.1.2 h1:m8/z1t7/fwjysjQRYbP0RD+bUIF/8tJwPdEZsI83ACI=
github.com/spf13/afero v1.1.2/go.mod h1:j4pytiNVoe2o6bmDsKpLACNPDBIoEAkihy7loJ1B0CQ=
github.com/spf13/cast v1.3.0 h1:oget//CVOEoFewqQxwr0Ej5yjygnqGkvggSE/gB35Q8=
@ -39,6 +44,7 @@ github.com/spf13/pflag v1.0.3 h1:zPAT6CGy6wXeQ7NtTnaTerfKOsV6V6F8agHXFiazDkg=
github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
github.com/spf13/viper v1.3.2 h1:VUFqw5KcqRf7i70GOzW7N+Q7+gxVBkSSqiXB12+JQ4M=
github.com/spf13/viper v1.3.2/go.mod h1:ZiWeW+zYFKm7srdB9IoDzzZXaJaI5eL9QjNiN/DMA2s=
github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w=
github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
github.com/ugorji/go/codec v0.0.0-20181204163529-d75b2dcb6bc8/go.mod h1:VFNgLljTbGfSG7qAOspJ7OScBnGdDN/yBr0sguwnwf0=
@ -46,6 +52,8 @@ github.com/xordataexchange/crypt v0.0.3-0.20170626215501-b2862e3d0a77/go.mod h1:
golang.org/x/crypto v0.0.0-20181203042331-505ab145d0a9/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
golang.org/x/sys v0.0.0-20181205085412-a5c9d58dba9a h1:1n5lsVfiQW3yfsRGu98756EH1YthsFqr/5mxHduZW2A=
golang.org/x/sys v0.0.0-20181205085412-a5c9d58dba9a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
golang.org/x/sys v0.0.0-20190422165155-953cdadca894 h1:Cz4ceDQGXuKRnVBDTS23GTn/pU5OE2C0WrNTOYK1Uuc=
golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=

150
web/middleware.go Normal file
View File

@ -0,0 +1,150 @@
package web
import (
"context"
"net/http"
"time"
"github.com/google/uuid"
"github.com/gorilla/mux"
log "github.com/sirupsen/logrus"
)
type contextKey int
// context keys to be used when inspecting request contexts
const (
requestIDKey contextKey = iota
correlationIDKey
loggerKey
)
// Header names for middleware to use
const (
RequestIDHeader string = "X-Request-Id"
CorrelationIDHeader = "X-Correlation-Id"
)
// CorrelationIDFromRequest gets a correlation id from the request, if it
// exists.
func CorrelationIDFromRequest(req *http.Request) string {
var id string
if str := req.Header.Get(CorrelationIDHeader); str != "" {
id = str
}
return id
}
func getFromContext(ctx context.Context, key contextKey) (value string, ok bool) {
if v := ctx.Value(key); v != nil {
value = v.(string)
ok = true
return
}
value, ok = "", false
return
}
func CorrelationIDFromContext(ctx context.Context) (value string, ok bool) {
return getFromContext(ctx, correlationIDKey)
}
func RequestIDFromContext(ctx context.Context) (value string, ok bool) {
return getFromContext(ctx, requestIDKey)
}
func LoggerFromContext(ctx context.Context) *log.Entry {
if v := ctx.Value(loggerKey); v != nil {
return v.(*log.Entry)
}
return log.WithFields(log.Fields{})
}
type loggingResponseWriter struct {
http.ResponseWriter
size, status int
start time.Time
}
// This idea is taken from the violetear responsewriter
// https://github.com/nbari/violetear/blob/master/responsewriter.go
func newLoggingResponseWriter(w http.ResponseWriter) *loggingResponseWriter {
return &loggingResponseWriter{
ResponseWriter: w,
start: time.Now(),
status: http.StatusOK,
}
}
func (w *loggingResponseWriter) Status() int {
return w.status
}
func (w *loggingResponseWriter) Size() int {
return w.size
}
func (w *loggingResponseWriter) ElapsedTime() string {
return time.Since(w.start).String()
}
func (w *loggingResponseWriter) Write(data []byte) (int, error) {
size, err := w.ResponseWriter.Write(data)
w.size += size
return size, err
}
func (w *loggingResponseWriter) WriteHeader(statusCode int) {
w.status = statusCode
w.ResponseWriter.WriteHeader(statusCode)
}
func middleware(r *mux.Router) *mux.Router {
r.Use(loggingMw)
r.Use(discworldMw)
log.Info("using")
return r
}
func discworldMw(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
w.Header().Set("X-Clacks-Overhead", "GNU Terry Pratchett")
next.ServeHTTP(w, r)
})
}
func loggingMw(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
newW := newLoggingResponseWriter(w)
correlationID := CorrelationIDFromRequest(r)
if correlationID == "" {
correlationID = uuid.New().String()
}
requestID := uuid.New().String()
contextLogger := log.WithFields(log.Fields{
"requestID": requestID,
"correlationID": correlationID,
})
ctx := r.Context()
ctx = context.WithValue(ctx, requestIDKey, requestID)
ctx = context.WithValue(ctx, correlationIDKey, correlationID)
ctx = context.WithValue(ctx, loggerKey, contextLogger)
r = r.WithContext(ctx)
w.Header().Set(CorrelationIDHeader, correlationID)
w.Header().Set(RequestIDHeader, requestID)
requestLogger := contextLogger.WithFields(
log.Fields{
"path": r.URL.Path,
"query_string": r.URL.RawQuery,
"method": r.Method,
})
requestLogger.Info("Start web request")
next.ServeHTTP(newW, r)
requestLogger.WithFields(
log.Fields{
"status": newW.Status(),
"size": newW.Size(),
"duration": newW.ElapsedTime()}).
Info("End web request")
})
}

View File

@ -2,30 +2,34 @@ package web
import (
"fmt"
"log"
"net/http"
"github.com/gorilla/mux"
log "github.com/sirupsen/logrus"
"github.com/spf13/viper"
)
// Router creates the default http router
func Router() *mux.Router {
func router() *mux.Router {
r := mux.NewRouter()
r.HandleFunc("/", root)
return r
}
func root(resp http.ResponseWriter, req *http.Request) {
logger := LoggerFromContext(req.Context())
if req.URL.Path != "/" {
http.NotFound(resp, req)
logger.Warning("404 Not found")
return
}
fmt.Fprintf(resp, "Hello World!")
logger.Info("root page")
}
// RunServer runs the webserver with the router and middleware
func RunServer() {
router := Router()
router := middleware(router())
addr := viper.GetString("addr")
log.WithFields(log.Fields{"addr": addr}).Info("Webserver starting")
log.Fatal(http.ListenAndServe(viper.GetString("addr"), router))
}