From f9808345b9922f0c90bf7df00a1f6fc28b404663 Mon Sep 17 00:00:00 2001 From: Carl Jackson Date: Sun, 23 Mar 2014 02:58:24 -0700 Subject: [PATCH] Standard middlewares I've currently written three: - Request ID generation - Request logging, with color (!) - Recovery from panics --- README.md | 18 ----- default.go | 5 ++ goji.go | 2 + web/middleware/logger.go | 149 +++++++++++++++++++++++++++++++++++ web/middleware/middleware.go | 4 + web/middleware/recoverer.go | 44 +++++++++++ web/middleware/request_id.go | 70 ++++++++++++++++ web/middleware/terminal.go | 44 +++++++++++ 8 files changed, 318 insertions(+), 18 deletions(-) create mode 100644 web/middleware/logger.go create mode 100644 web/middleware/middleware.go create mode 100644 web/middleware/recoverer.go create mode 100644 web/middleware/request_id.go create mode 100644 web/middleware/terminal.go diff --git a/README.md b/README.md index b0df83e..9a1affb 100644 --- a/README.md +++ b/README.md @@ -47,21 +47,3 @@ Features [graceful]: http://godoc.org/github.com/zenazn/goji/graceful [param]: http://godoc.org/github.com/zenazn/goji/param - -Todo ----- - -Goji probably deserves a bit more love before anyone actually tries to use it. -Things that need doing include: - -* Support for omitting trailing slashes on routes which include them. -* Tests for `goji/web`. There are currently no tests. This probably means - `goji/web` is made of bugs. I'm sorry. -* Standard middleware implementations. I'm currently thinking: - * Request ID assigner: injects a request ID into the environment. - * Request logger: logs requests as they come in. Preferrably with request IDs - and maybe even with colors. - * Request timer: maybe part of the request logger. Time how long each request - takes and print it. Maybe with color. - * Error handler: recovers from panics, does something nice with the output. - * Healthcheck endpoint: Always returns OK. diff --git a/default.go b/default.go index c43cccf..fca2a27 100644 --- a/default.go +++ b/default.go @@ -2,6 +2,7 @@ package goji import ( "github.com/zenazn/goji/web" + "github.com/zenazn/goji/web/middleware" ) // The default web.Mux. @@ -9,6 +10,10 @@ var DefaultMux *web.Mux func init() { DefaultMux = web.New() + + DefaultMux.Use("RequestId", middleware.RequestId) + DefaultMux.Use("Logger", middleware.Logger) + DefaultMux.Use("Recoverer", middleware.Recoverer) } // Append the given middleware to the default Mux's middleware stack. See the diff --git a/goji.go b/goji.go index e973f7c..8f68ac3 100644 --- a/goji.go +++ b/goji.go @@ -48,6 +48,8 @@ func Serve() { flag.Parse() } + log.SetFlags(log.Flags() | log.Lmicroseconds) + // Install our handler at the root of the standard net/http default mux. // This allows packages like expvar to continue working as expected. http.Handle("/", DefaultMux) diff --git a/web/middleware/logger.go b/web/middleware/logger.go new file mode 100644 index 0000000..72c4115 --- /dev/null +++ b/web/middleware/logger.go @@ -0,0 +1,149 @@ +package middleware + +import ( + "bufio" + "bytes" + "log" + "net" + "net/http" + "time" + + "github.com/zenazn/goji/web" +) + +// Logger is a middleware that logs the start and end of each request, along +// with some useful data about what was requested, what the response status was, +// and how long it took to return. When standard output is a TTY, Logger will +// print in color, otherwise it will print in black and white. +// +// Logger prints a request ID if one is provided. +func Logger(c *web.C, h http.Handler) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + reqId := GetReqId(*c) + + printStart(reqId, r) + + lw := wrapWriter(w) + + t1 := time.Now() + h.ServeHTTP(lw, r) + lw.maybeWriteHeader() + t2 := time.Now() + + printEnd(reqId, lw, t2.Sub(t1)) + } + + return http.HandlerFunc(fn) +} + +func printStart(reqId string, r *http.Request) { + var buf bytes.Buffer + + if reqId != "" { + cW(&buf, bBlack, "[%s] ", reqId) + } + buf.WriteString("Started ") + cW(&buf, bMagenta, "%s ", r.Method) + cW(&buf, nBlue, "%q ", r.URL.String()) + buf.WriteString("from ") + buf.WriteString(r.RemoteAddr) + + log.Print(buf.String()) +} + +func printEnd(reqId string, w writerProxy, dt time.Duration) { + var buf bytes.Buffer + + if reqId != "" { + cW(&buf, bBlack, "[%s] ", reqId) + } + buf.WriteString("Returning ") + if w.status() < 200 { + cW(&buf, bBlue, "%03d", w.status()) + } else if w.status() < 300 { + cW(&buf, bGreen, "%03d", w.status()) + } else if w.status() < 400 { + cW(&buf, bCyan, "%03d", w.status()) + } else if w.status() < 500 { + cW(&buf, bYellow, "%03d", w.status()) + } else { + cW(&buf, bRed, "%03d", w.status()) + } + buf.WriteString(" in ") + if dt < 500*time.Millisecond { + cW(&buf, nGreen, "%s", dt) + } else if dt < 5*time.Second { + cW(&buf, nYellow, "%s", dt) + } else { + cW(&buf, nRed, "%s", dt) + } + + log.Print(buf.String()) +} + +func wrapWriter(w http.ResponseWriter) writerProxy { + _, cn := w.(http.CloseNotifier) + _, fl := w.(http.Flusher) + _, hj := w.(http.Hijacker) + + bw := basicWriter{ResponseWriter: w} + if cn && fl && hj { + return &fancyWriter{bw} + } else { + return &bw + } +} + +type writerProxy interface { + http.ResponseWriter + maybeWriteHeader() + status() int +} + +type basicWriter struct { + http.ResponseWriter + wroteHeader bool + code int +} + +func (b *basicWriter) WriteHeader(code int) { + b.code = code + b.wroteHeader = true + b.ResponseWriter.WriteHeader(code) +} +func (b *basicWriter) Write(buf []byte) (int, error) { + b.maybeWriteHeader() + return b.ResponseWriter.Write(buf) +} +func (b *basicWriter) maybeWriteHeader() { + if !b.wroteHeader { + b.WriteHeader(http.StatusOK) + } +} +func (b *basicWriter) status() int { + return b.code +} +func (b *basicWriter) Unwrap() http.ResponseWriter { + return b.ResponseWriter +} + +type fancyWriter struct { + basicWriter +} + +func (f *fancyWriter) CloseNotify() <-chan bool { + cn := f.basicWriter.ResponseWriter.(http.CloseNotifier) + return cn.CloseNotify() +} +func (f *fancyWriter) Flush() { + fl := f.basicWriter.ResponseWriter.(http.Flusher) + fl.Flush() +} +func (f *fancyWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) { + hj := f.basicWriter.ResponseWriter.(http.Hijacker) + return hj.Hijack() +} + +var _ http.CloseNotifier = &fancyWriter{} +var _ http.Flusher = &fancyWriter{} +var _ http.Hijacker = &fancyWriter{} diff --git a/web/middleware/middleware.go b/web/middleware/middleware.go new file mode 100644 index 0000000..23cfde2 --- /dev/null +++ b/web/middleware/middleware.go @@ -0,0 +1,4 @@ +/* +Package middleware provides several standard middleware implementations. +*/ +package middleware diff --git a/web/middleware/recoverer.go b/web/middleware/recoverer.go new file mode 100644 index 0000000..adf1ca4 --- /dev/null +++ b/web/middleware/recoverer.go @@ -0,0 +1,44 @@ +package middleware + +import ( + "bytes" + "log" + "net/http" + "runtime/debug" + + "github.com/zenazn/goji/web" +) + +// Recoverer is a middleware that recovers from panics, logs the panic (and a +// backtrace), and returns a HTTP 500 (Internal Server Error) status if +// possible. +// +// Recoverer prints a request ID if one is provided. +func Recoverer(c *web.C, h http.Handler) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + reqId := GetReqId(*c) + + defer func() { + if err := recover(); err != nil { + printPanic(reqId, err) + debug.PrintStack() + http.Error(w, http.StatusText(500), 500) + } + }() + + h.ServeHTTP(w, r) + } + + return http.HandlerFunc(fn) +} + +func printPanic(reqId string, err interface{}) { + var buf bytes.Buffer + + if reqId != "" { + cW(&buf, bBlack, "[%s] ", reqId) + } + cW(&buf, bRed, "panic: %#v", err) + + log.Print(buf.String()) +} diff --git a/web/middleware/request_id.go b/web/middleware/request_id.go new file mode 100644 index 0000000..7c8f5d7 --- /dev/null +++ b/web/middleware/request_id.go @@ -0,0 +1,70 @@ +package middleware + +import ( + "crypto/rand" + "encoding/base64" + "fmt" + "net/http" + "os" + "strings" + "sync/atomic" + + "github.com/zenazn/goji/web" +) + +// Key to use when setting the request ID. +const RequestIdKey = "reqId" + +var prefix string +var reqid uint64 + +func init() { + hostname, err := os.Hostname() + if hostname == "" || err != nil { + hostname = "localhost" + } + var buf [12]byte + rand.Read(buf[:]) + b64 := base64.StdEncoding.EncodeToString(buf[:]) + // Strip out annoying characters. We have something like a billion to + // one chance of having enough from 12 bytes of entropy + b64 = strings.NewReplacer("+", "", "/", "").Replace(b64) + + prefix = fmt.Sprintf("%s/%s", hostname, b64[0:8]) +} + +// RequestId is a middleware that injects a request ID into the context of each +// request. A request ID is a string of the form "host.example.com/random-0001", +// where "random" is a base62 random string that uniquely identifies this go +// process, and where the last number is an atomically incremented request +// counter. +func RequestId(c *web.C, h http.Handler) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + if c.Env == nil { + c.Env = make(map[string]interface{}) + } + myid := atomic.AddUint64(&reqid, 1) + c.Env[RequestIdKey] = fmt.Sprintf("%s-%06d", prefix, myid) + + h.ServeHTTP(w, r) + } + + return http.HandlerFunc(fn) +} + +// Get a request ID from the given context if one is present. Returns the empty +// string if a request ID cannot be found. +func GetReqId(c web.C) string { + if c.Env == nil { + return "" + } + v, ok := c.Env[RequestIdKey] + if !ok { + return "" + } + if reqId, ok := v.(string); ok { + return reqId + } else { + return "" + } +} diff --git a/web/middleware/terminal.go b/web/middleware/terminal.go new file mode 100644 index 0000000..813e83d --- /dev/null +++ b/web/middleware/terminal.go @@ -0,0 +1,44 @@ +package middleware + +import ( + "bytes" + "fmt" + + "code.google.com/p/go.crypto/ssh/terminal" +) + +var ( + // Normal colors + nBlack = []byte{'\033', '[', '3', '0', 'm'} + nRed = []byte{'\033', '[', '3', '1', 'm'} + nGreen = []byte{'\033', '[', '3', '2', 'm'} + nYellow = []byte{'\033', '[', '3', '3', 'm'} + nBlue = []byte{'\033', '[', '3', '4', 'm'} + nMagenta = []byte{'\033', '[', '3', '5', 'm'} + nCyan = []byte{'\033', '[', '3', '6', 'm'} + nWhite = []byte{'\033', '[', '3', '7', 'm'} + // Bright colors + bBlack = []byte{'\033', '[', '3', '0', ';', '1', 'm'} + bRed = []byte{'\033', '[', '3', '1', ';', '1', 'm'} + bGreen = []byte{'\033', '[', '3', '2', ';', '1', 'm'} + bYellow = []byte{'\033', '[', '3', '3', ';', '1', 'm'} + bBlue = []byte{'\033', '[', '3', '4', ';', '1', 'm'} + bMagenta = []byte{'\033', '[', '3', '5', ';', '1', 'm'} + bCyan = []byte{'\033', '[', '3', '6', ';', '1', 'm'} + bWhite = []byte{'\033', '[', '3', '7', ';', '1', 'm'} + + reset = []byte{'\033', '[', '0', 'm'} +) + +var isTTY = terminal.IsTerminal(1) + +// colorWrite +func cW(buf *bytes.Buffer, color []byte, s string, args ...interface{}) { + if isTTY { + buf.Write(color) + } + fmt.Fprintf(buf, s, args...) + if isTTY { + buf.Write(reset) + } +}