diff --git a/handlers.go b/handlers.go index 75db7f8..d03f2bf 100644 --- a/handlers.go +++ b/handlers.go @@ -7,15 +7,10 @@ package handlers import ( "bufio" "fmt" - "io" "net" "net/http" - "net/url" "sort" - "strconv" "strings" - "time" - "unicode/utf8" ) // MethodHandler is an http.Handler that dispatches to a handler whose key in the @@ -48,59 +43,6 @@ func (h MethodHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { } } -// loggingHandler is the http.Handler implementation for LoggingHandlerTo and its -// friends -type loggingHandler struct { - writer io.Writer - handler http.Handler -} - -// combinedLoggingHandler is the http.Handler implementation for LoggingHandlerTo -// and its friends -type combinedLoggingHandler struct { - writer io.Writer - handler http.Handler -} - -func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { - t := time.Now() - logger := makeLogger(w) - url := *req.URL - h.handler.ServeHTTP(logger, req) - writeLog(h.writer, req, url, t, logger.Status(), logger.Size()) -} - -func (h combinedLoggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { - t := time.Now() - logger := makeLogger(w) - url := *req.URL - h.handler.ServeHTTP(logger, req) - writeCombinedLog(h.writer, req, url, t, logger.Status(), logger.Size()) -} - -func makeLogger(w http.ResponseWriter) loggingResponseWriter { - var logger loggingResponseWriter = &responseLogger{w: w, status: http.StatusOK} - if _, ok := w.(http.Hijacker); ok { - logger = &hijackLogger{responseLogger{w: w, status: http.StatusOK}} - } - h, ok1 := logger.(http.Hijacker) - c, ok2 := w.(http.CloseNotifier) - if ok1 && ok2 { - return hijackCloseNotifier{logger, h, c} - } - if ok2 { - return &closeNotifyWriter{logger, c} - } - return logger -} - -type commonLoggingResponseWriter interface { - http.ResponseWriter - http.Flusher - Status() int - Size() int -} - // responseLogger is wrapper of http.ResponseWriter that keeps track of its HTTP // status code and body size type responseLogger struct { @@ -165,173 +107,6 @@ type hijackCloseNotifier struct { http.CloseNotifier } -const lowerhex = "0123456789abcdef" - -func appendQuoted(buf []byte, s string) []byte { - var runeTmp [utf8.UTFMax]byte - for width := 0; len(s) > 0; s = s[width:] { - r := rune(s[0]) - width = 1 - if r >= utf8.RuneSelf { - r, width = utf8.DecodeRuneInString(s) - } - if width == 1 && r == utf8.RuneError { - buf = append(buf, `\x`...) - buf = append(buf, lowerhex[s[0]>>4]) - buf = append(buf, lowerhex[s[0]&0xF]) - continue - } - if r == rune('"') || r == '\\' { // always backslashed - buf = append(buf, '\\') - buf = append(buf, byte(r)) - continue - } - if strconv.IsPrint(r) { - n := utf8.EncodeRune(runeTmp[:], r) - buf = append(buf, runeTmp[:n]...) - continue - } - switch r { - case '\a': - buf = append(buf, `\a`...) - case '\b': - buf = append(buf, `\b`...) - case '\f': - buf = append(buf, `\f`...) - case '\n': - buf = append(buf, `\n`...) - case '\r': - buf = append(buf, `\r`...) - case '\t': - buf = append(buf, `\t`...) - case '\v': - buf = append(buf, `\v`...) - default: - switch { - case r < ' ': - buf = append(buf, `\x`...) - buf = append(buf, lowerhex[s[0]>>4]) - buf = append(buf, lowerhex[s[0]&0xF]) - case r > utf8.MaxRune: - r = 0xFFFD - fallthrough - case r < 0x10000: - buf = append(buf, `\u`...) - for s := 12; s >= 0; s -= 4 { - buf = append(buf, lowerhex[r>>uint(s)&0xF]) - } - default: - buf = append(buf, `\U`...) - for s := 28; s >= 0; s -= 4 { - buf = append(buf, lowerhex[r>>uint(s)&0xF]) - } - } - } - } - return buf - -} - -// buildCommonLogLine builds a log entry for req in Apache Common Log Format. -// ts is the timestamp with which the entry should be logged. -// status and size are used to provide the response HTTP status and size. -func buildCommonLogLine(req *http.Request, url url.URL, ts time.Time, status int, size int) []byte { - username := "-" - if url.User != nil { - if name := url.User.Username(); name != "" { - username = name - } - } - - host, _, err := net.SplitHostPort(req.RemoteAddr) - - if err != nil { - host = req.RemoteAddr - } - - uri := req.RequestURI - - // Requests using the CONNECT method over HTTP/2.0 must use - // the authority field (aka r.Host) to identify the target. - // Refer: https://httpwg.github.io/specs/rfc7540.html#CONNECT - if req.ProtoMajor == 2 && req.Method == "CONNECT" { - uri = req.Host - } - if uri == "" { - uri = url.RequestURI() - } - - buf := make([]byte, 0, 3*(len(host)+len(username)+len(req.Method)+len(uri)+len(req.Proto)+50)/2) - buf = append(buf, host...) - buf = append(buf, " - "...) - buf = append(buf, username...) - buf = append(buf, " ["...) - buf = append(buf, ts.Format("02/Jan/2006:15:04:05 -0700")...) - buf = append(buf, `] "`...) - buf = append(buf, req.Method...) - buf = append(buf, " "...) - buf = appendQuoted(buf, uri) - buf = append(buf, " "...) - buf = append(buf, req.Proto...) - buf = append(buf, `" `...) - buf = append(buf, strconv.Itoa(status)...) - buf = append(buf, " "...) - buf = append(buf, strconv.Itoa(size)...) - return buf -} - -// writeLog writes a log entry for req to w in Apache Common Log Format. -// ts is the timestamp with which the entry should be logged. -// status and size are used to provide the response HTTP status and size. -func writeLog(w io.Writer, req *http.Request, url url.URL, ts time.Time, status, size int) { - buf := buildCommonLogLine(req, url, ts, status, size) - buf = append(buf, '\n') - w.Write(buf) -} - -// writeCombinedLog writes a log entry for req to w in Apache Combined Log Format. -// ts is the timestamp with which the entry should be logged. -// status and size are used to provide the response HTTP status and size. -func writeCombinedLog(w io.Writer, req *http.Request, url url.URL, ts time.Time, status, size int) { - buf := buildCommonLogLine(req, url, ts, status, size) - buf = append(buf, ` "`...) - buf = appendQuoted(buf, req.Referer()) - buf = append(buf, `" "`...) - buf = appendQuoted(buf, req.UserAgent()) - buf = append(buf, '"', '\n') - w.Write(buf) -} - -// CombinedLoggingHandler return a http.Handler that wraps h and logs requests to out in -// Apache Combined Log Format. -// -// See http://httpd.apache.org/docs/2.2/logs.html#combined for a description of this format. -// -// LoggingHandler always sets the ident field of the log to - -func CombinedLoggingHandler(out io.Writer, h http.Handler) http.Handler { - return combinedLoggingHandler{out, h} -} - -// LoggingHandler return a http.Handler that wraps h and logs requests to out in -// Apache Common Log Format (CLF). -// -// See http://httpd.apache.org/docs/2.2/logs.html#common for a description of this format. -// -// LoggingHandler always sets the ident field of the log to - -// -// Example: -// -// r := mux.NewRouter() -// r.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) { -// w.Write([]byte("This is a catch-all route")) -// }) -// loggedRouter := handlers.LoggingHandler(os.Stdout, r) -// http.ListenAndServe(":1123", loggedRouter) -// -func LoggingHandler(out io.Writer, h http.Handler) http.Handler { - return loggingHandler{out, h} -} - // isContentType validates the Content-Type header matches the supplied // contentType. That is, its type and subtype match. func isContentType(h http.Header, contentType string) bool { diff --git a/handlers_test.go b/handlers_test.go index 04ee244..3f164a3 100644 --- a/handlers_test.go +++ b/handlers_test.go @@ -5,14 +5,11 @@ package handlers import ( - "bytes" - "net" "net/http" "net/http/httptest" "net/url" "strings" "testing" - "time" ) const ( @@ -73,233 +70,6 @@ func TestMethodHandler(t *testing.T) { } } -func TestMakeLogger(t *testing.T) { - rec := httptest.NewRecorder() - logger := makeLogger(rec) - // initial status - if logger.Status() != http.StatusOK { - t.Fatalf("wrong status, got %d want %d", logger.Status(), http.StatusOK) - } - // WriteHeader - logger.WriteHeader(http.StatusInternalServerError) - if logger.Status() != http.StatusInternalServerError { - t.Fatalf("wrong status, got %d want %d", logger.Status(), http.StatusInternalServerError) - } - // Write - logger.Write([]byte(ok)) - if logger.Size() != len(ok) { - t.Fatalf("wrong size, got %d want %d", logger.Size(), len(ok)) - } - // Header - logger.Header().Set("key", "value") - if val := logger.Header().Get("key"); val != "value" { - t.Fatalf("wrong header, got %s want %s", val, "value") - } -} - -func TestWriteLog(t *testing.T) { - loc, err := time.LoadLocation("Europe/Warsaw") - if err != nil { - panic(err) - } - ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) - - // A typical request with an OK response - req := newRequest("GET", "http://example.com") - req.RemoteAddr = "192.168.100.5" - - buf := new(bytes.Buffer) - writeLog(buf, req, *req.URL, ts, http.StatusOK, 100) - log := buf.String() - - expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } - - // CONNECT request over http/2.0 - req = &http.Request{ - Method: "CONNECT", - Proto: "HTTP/2.0", - ProtoMajor: 2, - ProtoMinor: 0, - URL: &url.URL{Host: "www.example.com:443"}, - Host: "www.example.com:443", - RemoteAddr: "192.168.100.5", - } - - buf = new(bytes.Buffer) - writeLog(buf, req, *req.URL, ts, http.StatusOK, 100) - log = buf.String() - - expected = "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"CONNECT www.example.com:443 HTTP/2.0\" 200 100\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } - - // Request with an unauthorized user - req = newRequest("GET", "http://example.com") - req.RemoteAddr = "192.168.100.5" - req.URL.User = url.User("kamil") - - buf.Reset() - writeLog(buf, req, *req.URL, ts, http.StatusUnauthorized, 500) - log = buf.String() - - expected = "192.168.100.5 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 401 500\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } - - // Request with url encoded parameters - req = newRequest("GET", "http://example.com/test?abc=hello%20world&a=b%3F") - req.RemoteAddr = "192.168.100.5" - - buf.Reset() - writeLog(buf, req, *req.URL, ts, http.StatusOK, 100) - log = buf.String() - - expected = "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET /test?abc=hello%20world&a=b%3F HTTP/1.1\" 200 100\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } -} - -func TestWriteCombinedLog(t *testing.T) { - loc, err := time.LoadLocation("Europe/Warsaw") - if err != nil { - panic(err) - } - ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) - - // A typical request with an OK response - req := newRequest("GET", "http://example.com") - req.RemoteAddr = "192.168.100.5" - req.Header.Set("Referer", "http://example.com") - req.Header.Set( - "User-Agent", - "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.33 "+ - "(KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33", - ) - - buf := new(bytes.Buffer) - writeCombinedLog(buf, req, *req.URL, ts, http.StatusOK, 100) - log := buf.String() - - expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100 \"http://example.com\" " + - "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + - "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } - - // CONNECT request over http/2.0 - req1 := &http.Request{ - Method: "CONNECT", - Host: "www.example.com:443", - Proto: "HTTP/2.0", - ProtoMajor: 2, - ProtoMinor: 0, - RemoteAddr: "192.168.100.5", - Header: http.Header{}, - URL: &url.URL{Host: "www.example.com:443"}, - } - req1.Header.Set("Referer", "http://example.com") - req1.Header.Set( - "User-Agent", - "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.33 "+ - "(KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33", - ) - - buf = new(bytes.Buffer) - writeCombinedLog(buf, req1, *req1.URL, ts, http.StatusOK, 100) - log = buf.String() - - expected = "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"CONNECT www.example.com:443 HTTP/2.0\" 200 100 \"http://example.com\" " + - "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + - "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } - - // Request with an unauthorized user - req.URL.User = url.User("kamil") - - buf.Reset() - writeCombinedLog(buf, req, *req.URL, ts, http.StatusUnauthorized, 500) - log = buf.String() - - expected = "192.168.100.5 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 401 500 \"http://example.com\" " + - "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + - "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } - - // Test with remote ipv6 address - req.RemoteAddr = "::1" - - buf.Reset() - writeCombinedLog(buf, req, *req.URL, ts, http.StatusOK, 100) - log = buf.String() - - expected = "::1 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100 \"http://example.com\" " + - "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + - "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } - - // Test remote ipv6 addr, with port - req.RemoteAddr = net.JoinHostPort("::1", "65000") - - buf.Reset() - writeCombinedLog(buf, req, *req.URL, ts, http.StatusOK, 100) - log = buf.String() - - expected = "::1 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100 \"http://example.com\" " + - "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + - "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" - if log != expected { - t.Fatalf("wrong log, got %q want %q", log, expected) - } -} - -func TestLogPathRewrites(t *testing.T) { - var buf bytes.Buffer - - handler := http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { - req.URL.Path = "/" // simulate http.StripPrefix and friends - w.WriteHeader(200) - }) - logger := LoggingHandler(&buf, handler) - - logger.ServeHTTP(httptest.NewRecorder(), newRequest("GET", "/subdir/asdf")) - - if !strings.Contains(buf.String(), "GET /subdir/asdf HTTP") { - t.Fatalf("Got log %#v, wanted substring %#v", buf.String(), "GET /subdir/asdf HTTP") - } -} - -func BenchmarkWriteLog(b *testing.B) { - loc, err := time.LoadLocation("Europe/Warsaw") - if err != nil { - b.Fatalf(err.Error()) - } - ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) - - req := newRequest("GET", "http://example.com") - req.RemoteAddr = "192.168.100.5" - - b.ResetTimer() - - buf := &bytes.Buffer{} - for i := 0; i < b.N; i++ { - buf.Reset() - writeLog(buf, req, *req.URL, ts, http.StatusUnauthorized, 500) - } -} - func TestContentTypeHandler(t *testing.T) { tests := []struct { Method string diff --git a/logging.go b/logging.go new file mode 100644 index 0000000..cbd182f --- /dev/null +++ b/logging.go @@ -0,0 +1,252 @@ +// Copyright 2013 The Gorilla Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package handlers + +import ( + "io" + "net" + "net/http" + "net/url" + "strconv" + "time" + "unicode/utf8" +) + +// Logging + +// FormatterParams is the structure any formatter will be handed when time to log comes +type LogFormatterParams struct { + Request *http.Request + URL url.URL + TimeStamp time.Time + StatusCode int + Size int +} + +// LogFormatter gives the signature of the formatter function passed to CustomLoggingHandler +type LogFormatter func(writer io.Writer, params LogFormatterParams) + +// loggingHandler is the http.Handler implementation for LoggingHandlerTo and its +// friends + +type loggingHandler struct { + writer io.Writer + handler http.Handler + formatter LogFormatter +} + +func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { + t := time.Now() + logger := makeLogger(w) + url := *req.URL + + h.handler.ServeHTTP(logger, req) + + params := LogFormatterParams{ + Request: req, + URL: url, + TimeStamp: t, + StatusCode: logger.Status(), + Size: logger.Size(), + } + + h.formatter(h.writer, params) +} + +func makeLogger(w http.ResponseWriter) loggingResponseWriter { + var logger loggingResponseWriter = &responseLogger{w: w, status: http.StatusOK} + if _, ok := w.(http.Hijacker); ok { + logger = &hijackLogger{responseLogger{w: w, status: http.StatusOK}} + } + h, ok1 := logger.(http.Hijacker) + c, ok2 := w.(http.CloseNotifier) + if ok1 && ok2 { + return hijackCloseNotifier{logger, h, c} + } + if ok2 { + return &closeNotifyWriter{logger, c} + } + return logger +} + +type commonLoggingResponseWriter interface { + http.ResponseWriter + http.Flusher + Status() int + Size() int +} + +const lowerhex = "0123456789abcdef" + +func appendQuoted(buf []byte, s string) []byte { + var runeTmp [utf8.UTFMax]byte + for width := 0; len(s) > 0; s = s[width:] { + r := rune(s[0]) + width = 1 + if r >= utf8.RuneSelf { + r, width = utf8.DecodeRuneInString(s) + } + if width == 1 && r == utf8.RuneError { + buf = append(buf, `\x`...) + buf = append(buf, lowerhex[s[0]>>4]) + buf = append(buf, lowerhex[s[0]&0xF]) + continue + } + if r == rune('"') || r == '\\' { // always backslashed + buf = append(buf, '\\') + buf = append(buf, byte(r)) + continue + } + if strconv.IsPrint(r) { + n := utf8.EncodeRune(runeTmp[:], r) + buf = append(buf, runeTmp[:n]...) + continue + } + switch r { + case '\a': + buf = append(buf, `\a`...) + case '\b': + buf = append(buf, `\b`...) + case '\f': + buf = append(buf, `\f`...) + case '\n': + buf = append(buf, `\n`...) + case '\r': + buf = append(buf, `\r`...) + case '\t': + buf = append(buf, `\t`...) + case '\v': + buf = append(buf, `\v`...) + default: + switch { + case r < ' ': + buf = append(buf, `\x`...) + buf = append(buf, lowerhex[s[0]>>4]) + buf = append(buf, lowerhex[s[0]&0xF]) + case r > utf8.MaxRune: + r = 0xFFFD + fallthrough + case r < 0x10000: + buf = append(buf, `\u`...) + for s := 12; s >= 0; s -= 4 { + buf = append(buf, lowerhex[r>>uint(s)&0xF]) + } + default: + buf = append(buf, `\U`...) + for s := 28; s >= 0; s -= 4 { + buf = append(buf, lowerhex[r>>uint(s)&0xF]) + } + } + } + } + return buf + +} + +// buildCommonLogLine builds a log entry for req in Apache Common Log Format. +// ts is the timestamp with which the entry should be logged. +// status and size are used to provide the response HTTP status and size. +func buildCommonLogLine(req *http.Request, url url.URL, ts time.Time, status int, size int) []byte { + username := "-" + if url.User != nil { + if name := url.User.Username(); name != "" { + username = name + } + } + + host, _, err := net.SplitHostPort(req.RemoteAddr) + + if err != nil { + host = req.RemoteAddr + } + + uri := req.RequestURI + + // Requests using the CONNECT method over HTTP/2.0 must use + // the authority field (aka r.Host) to identify the target. + // Refer: https://httpwg.github.io/specs/rfc7540.html#CONNECT + if req.ProtoMajor == 2 && req.Method == "CONNECT" { + uri = req.Host + } + if uri == "" { + uri = url.RequestURI() + } + + buf := make([]byte, 0, 3*(len(host)+len(username)+len(req.Method)+len(uri)+len(req.Proto)+50)/2) + buf = append(buf, host...) + buf = append(buf, " - "...) + buf = append(buf, username...) + buf = append(buf, " ["...) + buf = append(buf, ts.Format("02/Jan/2006:15:04:05 -0700")...) + buf = append(buf, `] "`...) + buf = append(buf, req.Method...) + buf = append(buf, " "...) + buf = appendQuoted(buf, uri) + buf = append(buf, " "...) + buf = append(buf, req.Proto...) + buf = append(buf, `" `...) + buf = append(buf, strconv.Itoa(status)...) + buf = append(buf, " "...) + buf = append(buf, strconv.Itoa(size)...) + return buf +} + +// writeLog writes a log entry for req to w in Apache Common Log Format. +// ts is the timestamp with which the entry should be logged. +// status and size are used to provide the response HTTP status and size. +func writeLog(writer io.Writer, params LogFormatterParams) { + buf := buildCommonLogLine(params.Request, params.URL, params.TimeStamp, params.StatusCode, params.Size) + buf = append(buf, '\n') + writer.Write(buf) +} + +// writeCombinedLog writes a log entry for req to w in Apache Combined Log Format. +// ts is the timestamp with which the entry should be logged. +// status and size are used to provide the response HTTP status and size. +func writeCombinedLog(writer io.Writer, params LogFormatterParams) { + buf := buildCommonLogLine(params.Request, params.URL, params.TimeStamp, params.StatusCode, params.Size) + buf = append(buf, ` "`...) + buf = appendQuoted(buf, params.Request.Referer()) + buf = append(buf, `" "`...) + buf = appendQuoted(buf, params.Request.UserAgent()) + buf = append(buf, '"', '\n') + writer.Write(buf) +} + +// CombinedLoggingHandler return a http.Handler that wraps h and logs requests to out in +// Apache Combined Log Format. +// +// See http://httpd.apache.org/docs/2.2/logs.html#combined for a description of this format. +// +// LoggingHandler always sets the ident field of the log to - +func CombinedLoggingHandler(out io.Writer, h http.Handler) http.Handler { + return loggingHandler{out, h, writeCombinedLog} +} + +// LoggingHandler return a http.Handler that wraps h and logs requests to out in +// Apache Common Log Format (CLF). +// +// See http://httpd.apache.org/docs/2.2/logs.html#common for a description of this format. +// +// LoggingHandler always sets the ident field of the log to - +// +// Example: +// +// r := mux.NewRouter() +// r.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) { +// w.Write([]byte("This is a catch-all route")) +// }) +// loggedRouter := handlers.LoggingHandler(os.Stdout, r) +// http.ListenAndServe(":1123", loggedRouter) +// +func LoggingHandler(out io.Writer, h http.Handler) http.Handler { + return loggingHandler{out, h, writeLog} +} + +// CustomLoggingHandler provides a way to supply a custom log formatter +// while taking advantage of the mechanisms in this package +func CustomLoggingHandler(out io.Writer, h http.Handler, f LogFormatter) http.Handler { + return loggingHandler{out, h, f} +} diff --git a/logging_test.go b/logging_test.go new file mode 100644 index 0000000..69f7177 --- /dev/null +++ b/logging_test.go @@ -0,0 +1,311 @@ +// Copyright 2013 The Gorilla Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package handlers + +import ( + "bytes" + "net/http" + "net/http/httptest" + "net/url" + "strings" + "testing" + "time" +) + +func TestMakeLogger(t *testing.T) { + rec := httptest.NewRecorder() + logger := makeLogger(rec) + // initial status + if logger.Status() != http.StatusOK { + t.Fatalf("wrong status, got %d want %d", logger.Status(), http.StatusOK) + } + // WriteHeader + logger.WriteHeader(http.StatusInternalServerError) + if logger.Status() != http.StatusInternalServerError { + t.Fatalf("wrong status, got %d want %d", logger.Status(), http.StatusInternalServerError) + } + // Write + logger.Write([]byte(ok)) + if logger.Size() != len(ok) { + t.Fatalf("wrong size, got %d want %d", logger.Size(), len(ok)) + } + // Header + logger.Header().Set("key", "value") + if val := logger.Header().Get("key"); val != "value" { + t.Fatalf("wrong header, got %s want %s", val, "value") + } +} + +func TestLogPathRewrites(t *testing.T) { + var buf bytes.Buffer + + handler := http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + req.URL.Path = "/" // simulate http.StripPrefix and friends + w.WriteHeader(200) + }) + logger := LoggingHandler(&buf, handler) + + logger.ServeHTTP(httptest.NewRecorder(), newRequest("GET", "/subdir/asdf")) + + if !strings.Contains(buf.String(), "GET /subdir/asdf HTTP") { + t.Fatalf("Got log %#v, wanted substring %#v", buf.String(), "GET /subdir/asdf HTTP") + } +} + +func BenchmarkWriteLog(b *testing.B) { + loc, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + b.Fatalf(err.Error()) + } + ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) + + req := newRequest("GET", "http://example.com") + req.RemoteAddr = "192.168.100.5" + + b.ResetTimer() + + params := LogFormatterParams{ + Request: req, + URL: *req.URL, + TimeStamp: ts, + StatusCode: http.StatusUnauthorized, + Size: 500, + } + + buf := &bytes.Buffer{} + + for i := 0; i < b.N; i++ { + buf.Reset() + writeLog(buf, params) + } +} + +func TestLogFormatterWriteLog_Scenario1(t *testing.T) { + formatter := writeLog + expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100\n" + LoggingScenario1(t, formatter, expected) +} + +func TestLogFormatterCombinedLog_Scenario1(t *testing.T) { + formatter := writeCombinedLog + expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100 \"http://example.com\" " + + "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + + "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" + LoggingScenario1(t, formatter, expected) +} + +func TestLogFormatterWriteLog_Scenario2(t *testing.T) { + formatter := writeLog + expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"CONNECT www.example.com:443 HTTP/2.0\" 200 100\n" + LoggingScenario2(t, formatter, expected) +} + +func TestLogFormatterCombinedLog_Scenario2(t *testing.T) { + formatter := writeCombinedLog + expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"CONNECT www.example.com:443 HTTP/2.0\" 200 100 \"http://example.com\" " + + "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + + "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" + LoggingScenario2(t, formatter, expected) +} + +func TestLogFormatterWriteLog_Scenario3(t *testing.T) { + formatter := writeLog + expected := "192.168.100.5 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 401 500\n" + LoggingScenario3(t, formatter, expected) +} + +func TestLogFormatterCombinedLog_Scenario3(t *testing.T) { + formatter := writeCombinedLog + expected := "192.168.100.5 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 401 500 \"http://example.com\" " + + "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + + "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" + LoggingScenario3(t, formatter, expected) +} + +func TestLogFormatterWriteLog_Scenario4(t *testing.T) { + formatter := writeLog + expected := "192.168.100.5 - - [26/May/1983:03:30:45 +0200] \"GET /test?abc=hello%20world&a=b%3F HTTP/1.1\" 200 100\n" + LoggingScenario4(t, formatter, expected) +} +func TestLogFormatterCombinedLog_Scenario5(t *testing.T) { + formatter := writeCombinedLog + expected := "::1 - kamil [26/May/1983:03:30:45 +0200] \"GET / HTTP/1.1\" 200 100 \"http://example.com\" " + + "\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) " + + "AppleWebKit/537.33 (KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33\"\n" + LoggingScenario5(t, formatter, expected) +} + +func LoggingScenario1(t *testing.T, formatter LogFormatter, expected string) { + loc, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + panic(err) + } + ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) + + // A typical request with an OK response + req := constructTypicalRequestOk() + + buf := new(bytes.Buffer) + params := LogFormatterParams{ + Request: req, + URL: *req.URL, + TimeStamp: ts, + StatusCode: http.StatusOK, + Size: 100, + } + + formatter(buf, params) + log := buf.String() + + if log != expected { + t.Fatalf("wrong log, got %q want %q", log, expected) + } +} + +func LoggingScenario2(t *testing.T, formatter LogFormatter, expected string) { + loc, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + panic(err) + } + ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) + + // CONNECT request over http/2.0 + req := constructConnectRequest() + + buf := new(bytes.Buffer) + params := LogFormatterParams{ + Request: req, + URL: *req.URL, + TimeStamp: ts, + StatusCode: http.StatusOK, + Size: 100, + } + formatter(buf, params) + log := buf.String() + + if log != expected { + t.Fatalf("wrong log, got %q want %q", log, expected) + } +} + +func LoggingScenario3(t *testing.T, formatter LogFormatter, expected string) { + loc, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + panic(err) + } + ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) + + // Request with an unauthorized user + req := constructTypicalRequestOk() + req.URL.User = url.User("kamil") + + buf := new(bytes.Buffer) + params := LogFormatterParams{ + Request: req, + URL: *req.URL, + TimeStamp: ts, + StatusCode: http.StatusUnauthorized, + Size: 500, + } + formatter(buf, params) + log := buf.String() + + if log != expected { + t.Fatalf("wrong log, got %q want %q", log, expected) + } +} +func LoggingScenario4(t *testing.T, formatter LogFormatter, expected string) { + loc, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + panic(err) + } + ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) + + // Request with url encoded parameters + req := constructEncodedRequest() + + buf := new(bytes.Buffer) + params := LogFormatterParams{ + Request: req, + URL: *req.URL, + TimeStamp: ts, + StatusCode: http.StatusOK, + Size: 100, + } + formatter(buf, params) + log := buf.String() + + if log != expected { + t.Fatalf("wrong log, got %q want %q", log, expected) + } +} + +func LoggingScenario5(t *testing.T, formatter LogFormatter, expected string) { + loc, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + panic(err) + } + ts := time.Date(1983, 05, 26, 3, 30, 45, 0, loc) + + req := constructTypicalRequestOk() + req.URL.User = url.User("kamil") + req.RemoteAddr = "::1" + + buf := new(bytes.Buffer) + params := LogFormatterParams{ + Request: req, + URL: *req.URL, + TimeStamp: ts, + StatusCode: http.StatusOK, + Size: 100, + } + formatter(buf, params) + log := buf.String() + + if log != expected { + t.Fatalf("wrong log, got %q want %q", log, expected) + } +} + +// A typical request with an OK response +func constructTypicalRequestOk() *http.Request { + req := newRequest("GET", "http://example.com") + req.RemoteAddr = "192.168.100.5" + req.Header.Set("Referer", "http://example.com") + req.Header.Set( + "User-Agent", + "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.33 "+ + "(KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33", + ) + return req +} + +// CONNECT request over http/2.0 +func constructConnectRequest() *http.Request { + + req := &http.Request{ + Method: "CONNECT", + Host: "www.example.com:443", + Proto: "HTTP/2.0", + ProtoMajor: 2, + ProtoMinor: 0, + RemoteAddr: "192.168.100.5", + Header: http.Header{}, + URL: &url.URL{Host: "www.example.com:443"}, + } + req.Header.Set("Referer", "http://example.com") + req.Header.Set( + "User-Agent", + "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.33 "+ + "(KHTML, like Gecko) Chrome/27.0.1430.0 Safari/537.33", + ) + return req +} + +func constructEncodedRequest() *http.Request { + req := constructTypicalRequestOk() + req.URL, _ = url.Parse("http://example.com/test?abc=hello%20world&a=b%3F") + return req +}