Initial update - manage access log

middlewares/logger.go

@@ -1,18 +1,57 @@
 package middlewares
 
+/*
+Middleware Logger writes each request and its response to the access log.
+It gets some information from the logInfoResponseWriter set up by previous middleware.
+*/
+
 import (
-	"log"
+	"fmt"
+	log "github.com/Sirupsen/logrus"
+	"github.com/streamrail/concurrent-map"
+	"io"
+	"net"
 	"net/http"
 	"os"
-
-	"github.com/gorilla/handlers"
+	"strconv"
+	"strings"
+	"sync"
+	"sync/atomic"
+	"time"
 )
 
-// Logger is a middleware handler that logs the request as it goes in and the response as it goes out.
+const (
+	loggerReqidHeader = "X-Traefik-Reqid"
+)
+
+// Logger holds the File defining the access log
 type Logger struct {
 	file *os.File
 }
 
+// Logging handler to log frontend name, backend name, and elapsed time
+type frontendBackendLoggingHandler struct {
+	reqid       string
+	writer      io.Writer
+	handlerFunc http.HandlerFunc
+}
+
+var (
+	reqidCounter        uint64       // Request ID
+	infoRwMap           = cmap.New() // Map of reqid to response writer
+	backend2FrontendMap map[string]string
+)
+
+// logInfoResponseWriter is a wrapper of type http.ResponseWriter
+// that tracks frontend and backend names and request status and size
+type logInfoResponseWriter struct {
+	rw       http.ResponseWriter
+	backend  string
+	frontend string
+	status   int
+	size     int
+}
+
 // NewLogger returns a new Logger instance.
 func NewLogger(file string) *Logger {
 	if len(file) > 0 {
@@ -25,17 +64,134 @@ func NewLogger(file string) *Logger {
 	return &Logger{nil}
 }
 
+// SetBackend2FrontendMap is called by server.go to set up frontend translation
+func SetBackend2FrontendMap(newMap *map[string]string) {
+	backend2FrontendMap = *newMap
+}
+
 func (l *Logger) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http.HandlerFunc) {
 	if l.file == nil {
 		next(rw, r)
 	} else {
-		handlers.CombinedLoggingHandler(l.file, next).ServeHTTP(rw, r)
+		reqid := strconv.FormatUint(atomic.AddUint64(&reqidCounter, 1), 10)
+		log.Debugf("Starting request %s: %s %s %s %s %s", reqid, r.Method, r.URL.RequestURI(), r.Proto, r.Referer(), r.UserAgent())
+		r.Header[loggerReqidHeader] = []string{reqid}
+		defer deleteReqid(r, reqid)
+		frontendBackendLoggingHandler{reqid, l.file, next}.ServeHTTP(rw, r)
 	}
 }
 
-// Close closes the logger (i.e. the file).
+// Delete a reqid from the map and the request's headers
+func deleteReqid(r *http.Request, reqid string) {
+	log.Debugf("Ending request %s", reqid)
+	infoRwMap.Remove(reqid)
+	delete(r.Header, loggerReqidHeader)
+}
+
+// Save the backend name for the Logger
+func saveBackendNameForLogger(r *http.Request, backendName string) {
+	if reqidHdr := r.Header[loggerReqidHeader]; len(reqidHdr) == 1 {
+		reqid := reqidHdr[0]
+		if infoRw, ok := infoRwMap.get(reqid); ok {
+			infoRw.SetBackend(backendName)
+			infoRw.SetFrontend(backend2FrontendMap[backendName])
+		}
+	}
+}
+
+// Close closes the Logger (i.e. the file).
 func (l *Logger) Close() {
 	if l.file != nil {
 		l.file.Close()
 	}
 }
+
+// Logging handler to log frontend name, backend name, and elapsed time
+func (fblh frontendBackendLoggingHandler) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
+	startTime := time.Now()
+	infoRw := &logInfoResponseWriter{rw: rw}
+	infoRwMap.Set(fblh.reqid, infoRw)
+	fblh.handlerFunc(infoRw, req)
+
+	username := "-"
+	url := *req.URL
+	if url.User != nil {
+		if name := url.User.Username(); name != "" {
+			username = name
+		}
+	}
+
+	host, _, err := net.SplitHostPort(req.RemoteAddr)
+	if err != nil {
+		host = req.RemoteAddr
+	}
+
+	ts := startTime.Format("02/Jan/2006:15:04:05 -0700")
+	method := req.Method
+	uri := url.RequestURI()
+	if qmIndex := strings.Index(uri, "?"); qmIndex > 0 {
+		uri = uri[0:qmIndex]
+	}
+	proto := req.Proto
+	referer := req.Referer()
+	agent := req.UserAgent()
+
+	frontend := strings.TrimPrefix(infoRw.GetFrontend(), "frontend-")
+	backend := infoRw.GetBackend()
+	status := infoRw.GetStatus()
+	size := infoRw.GetSize()
+
+	elapsed := time.Now().UTC().Sub(startTime.UTC())
+	fmt.Fprintf(fblh.writer, `%s - %s [%s] "%s %s %s" %d %d "%s" "%s" %s "%s" "%s" %s%s`,
+		host, username, ts, method, uri, proto, status, size, referer, agent, fblh.reqid, frontend, backend, elapsed, "\n")
+
+}
+
+func (lirw *logInfoResponseWriter) Header() http.Header {
+	return lirw.rw.Header()
+}
+
+func (lirw *logInfoResponseWriter) Write(b []byte) (int, error) {
+	if lirw.status == 0 {
+		lirw.status = http.StatusOK
+	}
+	size, err := lirw.rw.Write(b)
+	lirw.size += size
+	return size, err
+}
+
+func (lirw *logInfoResponseWriter) WriteHeader(s int) {
+	lirw.rw.WriteHeader(s)
+	lirw.status = s
+}
+
+func (lirw *logInfoResponseWriter) Flush() {
+	f, ok := lirw.rw.(http.Flusher)
+	if ok {
+		f.Flush()
+	}
+}
+
+func (lirw *logInfoResponseWriter) GetStatus() int {
+	return lirw.status
+}
+
+func (lirw *logInfoResponseWriter) GetSize() int {
+	return lirw.size
+}
+
+func (lirw *logInfoResponseWriter) GetBackend() string {
+	return lirw.backend
+}
+
+func (lirw *logInfoResponseWriter) GetFrontend() string {
+	return lirw.frontend
+}
+
+func (lirw *logInfoResponseWriter) SetBackend(backend string) {
+	lirw.backend = backend
+}
+
+func (lirw *logInfoResponseWriter) SetFrontend(frontend string) {
+	lirw.frontend = frontend
+}

middlewares/logger_test.go

@@ -0,0 +1,116 @@
+package middlewares
+
+import (
+	"fmt"
+	shellwords "github.com/mattn/go-shellwords"
+	"github.com/stretchr/testify/assert"
+	"io/ioutil"
+	"net/http"
+	"net/url"
+	"os"
+	"path/filepath"
+	"runtime"
+	"testing"
+)
+
+type logtestResponseWriter struct{}
+
+var (
+	logger                  *Logger
+	logfileName             = "traefikTestLogger.log"
+	logfilePath             string
+	helloWorld              = "Hello, World"
+	testBackendName         = "http://127.0.0.1/testBackend"
+	testFrontendName        = "testFrontend"
+	testStatus              = 123
+	testHostname            = "TestHost"
+	testUsername            = "TestUser"
+	testPath                = "http://testpath"
+	testPort                = 8181
+	testProto               = "HTTP/0.0"
+	testMethod              = "POST"
+	testReferer             = "testReferer"
+	testUserAgent           = "testUserAgent"
+	testBackend2FrontendMap = map[string]string{
+		testBackendName: testFrontendName,
+	}
+	printedLogdata bool
+)
+
+func TestLogger(t *testing.T) {
+	if runtime.GOOS == "windows" {
+		logfilePath = filepath.Join(os.Getenv("TEMP"), logfileName)
+	} else {
+		logfilePath = filepath.Join("/tmp", logfileName)
+	}
+
+	logger = NewLogger(logfilePath)
+	defer cleanup()
+	SetBackend2FrontendMap(&testBackend2FrontendMap)
+
+	r := &http.Request{
+		Header: map[string][]string{
+			"User-Agent": {testUserAgent},
+			"Referer":    {testReferer},
+		},
+		Proto:      testProto,
+		Host:       testHostname,
+		Method:     testMethod,
+		RemoteAddr: fmt.Sprintf("%s:%d", testHostname, testPort),
+		URL: &url.URL{
+			User: url.UserPassword(testUsername, ""),
+			Path: testPath,
+		},
+	}
+
+	logger.ServeHTTP(&logtestResponseWriter{}, r, LogWriterTestHandlerFunc)
+
+	if logdata, err := ioutil.ReadFile(logfilePath); err != nil {
+		fmt.Printf("%s\n%s\n", string(logdata), err.Error())
+		assert.Nil(t, err)
+	} else if tokens, err := shellwords.Parse(string(logdata)); err != nil {
+		fmt.Printf("%s\n", err.Error())
+		assert.Nil(t, err)
+	} else if assert.Equal(t, 14, len(tokens), printLogdata(logdata)) {
+		assert.Equal(t, testHostname, tokens[0], printLogdata(logdata))
+		assert.Equal(t, testUsername, tokens[2], printLogdata(logdata))
+		assert.Equal(t, fmt.Sprintf("%s %s %s", testMethod, testPath, testProto), tokens[5], printLogdata(logdata))
+		assert.Equal(t, fmt.Sprintf("%d", testStatus), tokens[6], printLogdata(logdata))
+		assert.Equal(t, fmt.Sprintf("%d", len(helloWorld)), tokens[7], printLogdata(logdata))
+		assert.Equal(t, testReferer, tokens[8], printLogdata(logdata))
+		assert.Equal(t, testUserAgent, tokens[9], printLogdata(logdata))
+		assert.Equal(t, "1", tokens[10], printLogdata(logdata))
+		assert.Equal(t, testFrontendName, tokens[11], printLogdata(logdata))
+		assert.Equal(t, testBackendName, tokens[12], printLogdata(logdata))
+	}
+}
+
+func cleanup() {
+	logger.Close()
+	os.Remove(logfilePath)
+}
+
+func printLogdata(logdata []byte) string {
+	return fmt.Sprintf(
+		"\nExpected: %s\n"+
+			"Actual:   %s",
+		"TestHost - TestUser [13/Apr/2016:07:14:19 -0700] \"POST http://testpath HTTP/0.0\" 123 12 \"testReferer\" \"testUserAgent\" 1 \"testFrontend\" \"http://127.0.0.1/testBackend\" 1ms",
+		string(logdata))
+}
+
+func LogWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) {
+	rw.Write([]byte(helloWorld))
+	rw.WriteHeader(testStatus)
+	saveBackendNameForLogger(r, testBackendName)
+}
+
+func (lrw *logtestResponseWriter) Header() http.Header {
+	return map[string][]string{}
+}
+
+func (lrw *logtestResponseWriter) Write(b []byte) (int, error) {
+	return len(b), nil
+}
+
+func (lrw *logtestResponseWriter) WriteHeader(s int) {
+}

middlewares/saveBackend.go

@@ -0,0 +1,24 @@
+package middlewares
+
+/*
+Middleware saveBackend sends the backend name to the logger.
+*/
+
+import (
+	"net/http"
+)
+
+// SaveBackend holds the next handler
+type SaveBackend struct {
+	next http.Handler
+}
+
+// NewSaveBackend creates a SaveBackend
+func NewSaveBackend(next http.Handler) *SaveBackend {
+	return &SaveBackend{next}
+}
+
+func (sb *SaveBackend) ServeHTTP(rw http.ResponseWriter, r *http.Request) {
+	saveBackendNameForLogger(r, (*r.URL).String())
+	sb.next.ServeHTTP(rw, r)
+}