Standard middlewares

I've currently written three:
- Request ID generation
- Request logging, with color (!)
- Recovery from panics

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.

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

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)

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{}

web/middleware/middleware.go

@@ -0,0 +1,4 @@
+/*
+Package middleware provides several standard middleware implementations.
+*/
+package middleware

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())
+}

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 ""
+	}
+}

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)
+	}
+}