diff --git a/examples/accessLog/.gitignore b/examples/accessLog/.gitignore new file mode 100644 index 000000000..47939b405 --- /dev/null +++ b/examples/accessLog/.gitignore @@ -0,0 +1,2 @@ +exampleHandler +exampleHandler.exe diff --git a/examples/accessLog/exampleHandler.go b/examples/accessLog/exampleHandler.go new file mode 100644 index 000000000..2a8fb3d61 --- /dev/null +++ b/examples/accessLog/exampleHandler.go @@ -0,0 +1,46 @@ +/* +Simple program to start a web server on a specified port +*/ +package main + +import ( + "flag" + "fmt" + "net/http" + "os" +) + +var ( + name string + port int + help *bool +) + +func init() { + flag.StringVar(&name, "n", "", "Name of handler for messages") + flag.IntVar(&port, "p", 0, "Port number to listen") + help = flag.Bool("h", false, "Displays help message") +} + +func usage() { + fmt.Printf("Usage: example -n name -p port \n") + os.Exit(2) +} + +func handler(w http.ResponseWriter, r *http.Request) { + fmt.Fprintf(w, "%s: Received query %s!\n", name, r.URL.Path[1:]) +} + +func main() { + flag.Parse() + if *help || len(name) == 0 || port <= 0 { + usage() + } + http.HandleFunc("/", handler) + fmt.Printf("%s: Listening on :%d...\n", name, port) + if er := http.ListenAndServe(fmt.Sprintf(":%d", port), nil); er != nil { + fmt.Printf("%s: Error from ListenAndServe: %s", name, er.Error()) + os.Exit(1) + } + fmt.Printf("%s: How'd we get past listen and serve???\n", name) +} diff --git a/examples/accessLog/runAb.sh b/examples/accessLog/runAb.sh new file mode 100644 index 000000000..db7d9366c --- /dev/null +++ b/examples/accessLog/runAb.sh @@ -0,0 +1,122 @@ +#!/bin/bash +usage() +{ + echo 'runAb.sh - Run Apache Benchmark to test access log' + echo ' Usage: runAb.sh [--conn nnn] [--log xxx] [--num nnn] [--time nnn] [--wait nn]' + echo ' -c|--conn - number of simultaneous connections (default 100)' + echo ' -l|--log - name of logfile (default benchmark.log)' + echo ' -n|--num - number of requests (default 50000); ignored when -t specified' + echo ' -t|--time - time in seconds for benchmark (default no limit)' + echo ' -w|--wait - number of seconds to wait for Traefik to initialize (default 15)' + echo ' ' + exit +} + +# Parse options + +conn=100 +num=50000 +wait=15 +time=0 +logfile="" +while [[ $1 =~ ^- ]] +do + case $1 in + -c|--conn) + conn=$2 + shift + ;; + -h|--help) + usage + ;; + -l|--log|--logfile) + logfile=$2 + shift + ;; + -n|--num) + num=$2 + shift + ;; + -t|--time) + time=$2 + shift + ;; + -w|--wait) + wait=$2 + shift + ;; + *) + echo Unknown option "$1" + usage + esac + shift +done +if [ -z "$logfile" ] ; then + logfile="benchmark.log" +fi + +# Change to accessLog examples directory + +[ -d examples/accessLog ] && cd examples/accessLog +if [ ! -r exampleHandler.go ] ; then + echo Please run this script either from the traefik repo root or from the examples/accessLog directory + exit +fi + +# Kill traefik and any running example processes + +sudo pkill -f traefik +pkill -f exampleHandler +[ ! -d log ] && mkdir log + +# Start new example processes + +go build exampleHandler.go +[ $? -ne 0 ] && exit $? +./exampleHandler -n Handler1 -p 8081 & +[ $? -ne 0 ] && exit $? +./exampleHandler -n Handler2 -p 8082 & +[ $? -ne 0 ] && exit $? +./exampleHandler -n Handler3 -p 8083 & +[ $? -ne 0 ] && exit $? + +# Wait a couple of seconds for handlers to initialize and start Traefik + +cd ../.. +sleep 2s +echo Starting Traefik... +sudo ./traefik -c examples/accessLog/traefik.ab.toml & +[ $? -ne 0 ] && exit $? + +# Wait for Traefik to initialize and run ab + +echo Waiting $wait seconds before starting ab benchmark +sleep ${wait}s +echo +stime=`date '+%s'` +if [ $time -eq 0 ] ; then + echo Benchmark starting `date` with $conn connections until $num requests processed | tee $logfile + echo | tee -a $logfile + echo ab -k -c $conn -n $num http://127.0.0.1/test | tee -a $logfile + echo | tee -a $logfile + ab -k -c $conn -n $num http://127.0.0.1/test 2>&1 | tee -a $logfile +else + if [ $num -ne 50000 ] ; then + echo Request count ignored when --time specified + fi + echo Benchmark starting `date` with $conn connections for $time seconds | tee $logfile + echo | tee -a $logfile + echo ab -k -c $conn -t $time -n 100000000 http://127.0.0.1/test | tee -a $logfile + echo | tee -a $logfile + ab -k -c $conn -t $time -n 100000000 http://127.0.0.1/test 2>&1 | tee -a $logfile +fi + +etime=`date '+%s'` +let "dt=$etime - $stime" +let "ds=$dt % 60" +let "dm=($dt / 60) % 60" +let "dh=$dt / 3600" +echo | tee -a $logfile +printf "Benchmark ended `date` after %d:%02d:%02d\n" $dh $dm $ds | tee -a $logfile +echo Results available in $logfile + diff --git a/examples/accessLog/runExample.sh b/examples/accessLog/runExample.sh new file mode 100644 index 000000000..69186b4df --- /dev/null +++ b/examples/accessLog/runExample.sh @@ -0,0 +1,40 @@ +#!/bin/bash +# Script to run a three-server example. This script runs the three servers and restarts Traefik +# Once it is running, use the command: +# +# curl http://127.0.0.1:80/test{1,2,2} +# +# to send requests to send test requests to the servers. You should see a response like: +# +# Handler1: received query test1! +# Handler2: received query test2! +# Handler3: received query test2! +# +# and can then inspect log/access.log to see frontend, backend, and timing + +# Kill traefik and any running example processes +sudo pkill -f traefik +pkill -f exampleHandler +[ ! -d log ] && mkdir log + +# Start new example processes +cd examples/accessLog +go build exampleHandler.go +[ $? -ne 0 ] && exit $? +./exampleHandler -n Handler1 -p 8081 & +[ $? -ne 0 ] && exit $? +./exampleHandler -n Handler2 -p 8082 & +[ $? -ne 0 ] && exit $? +./exampleHandler -n Handler3 -p 8083 & +[ $? -ne 0 ] && exit $? + +# Wait a couple of seconds for handlers to initialize and start Traefik +cd ../.. +sleep 2s +echo Starting Traefik... +sudo ./traefik -c examples/accessLog/traefik.example.toml & +[ $? -ne 0 ] && exit $? + +echo Sample handlers and traefik started successfully! +echo 'Use command curl http://127.0.0.1:80/test{1,2,2} to drive test' +echo Then inspect log/access.log to verify it contains frontend, backend, and timing diff --git a/examples/accessLog/traefik.ab.toml b/examples/accessLog/traefik.ab.toml new file mode 100644 index 000000000..28fa15bbb --- /dev/null +++ b/examples/accessLog/traefik.ab.toml @@ -0,0 +1,37 @@ +################################################################ +# Global configuration +################################################################ +traefikLogsFile = "log/traefik.log" +accessLogsFile = "log/access.log" +logLevel = "DEBUG" + +################################################################ +# Web configuration backend +################################################################ +[web] +address = ":7888" + +################################################################ +# File configuration backend +################################################################ +[file] + +################################################################ +# rules +################################################################ + [backends] + [backends.backend] + [backends.backend.LoadBalancer] + method = "drr" + [backends.backend.servers.server1] + url = "http://127.0.0.1:8081" + [backends.backend.servers.server2] + url = "http://127.0.0.1:8082" + [backends.backend.servers.server3] + url = "http://127.0.0.1:8083" + [frontends] + [frontends.frontend] + backend = "backend" + passHostHeader = true + [frontends.frontend.routes.test] + rule = "Path: /test" diff --git a/examples/accessLog/traefik.example.toml b/examples/accessLog/traefik.example.toml new file mode 100644 index 000000000..0e425210d --- /dev/null +++ b/examples/accessLog/traefik.example.toml @@ -0,0 +1,42 @@ +################################################################ +# Global configuration +################################################################ +traefikLogsFile = "log/traefik.log" +accessLogsFile = "log/access.log" +logLevel = "DEBUG" + +################################################################ +# Web configuration backend +################################################################ +[web] +address = ":7888" + +################################################################ +# File configuration backend +################################################################ +[file] + +################################################################ +# rules +################################################################ + [backends] + [backends.backend1] + [backends.backend1.servers.server1] + url = "http://127.0.0.1:8081" + [backends.backend2] + [backends.backend2.LoadBalancer] + method = "drr" + [backends.backend2.servers.server1] + url = "http://127.0.0.1:8082" + [backends.backend2.servers.server2] + url = "http://127.0.0.1:8083" + [frontends] + [frontends.frontend1] + backend = "backend1" + [frontends.frontend1.routes.test_1] + rule = "Path: /test1" + [frontends.frontend2] + backend = "backend2" + passHostHeader = true + [frontends.frontend2.routes.test_2] + rule = "Path: /test2" \ No newline at end of file diff --git a/middlewares/logger.go b/middlewares/logger.go index 34baf6f9f..236e27ac3 100644 --- a/middlewares/logger.go +++ b/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 +} diff --git a/middlewares/logger_test.go b/middlewares/logger_test.go new file mode 100644 index 000000000..72ea4704e --- /dev/null +++ b/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) { +} diff --git a/middlewares/saveBackend.go b/middlewares/saveBackend.go new file mode 100644 index 000000000..459c8d184 --- /dev/null +++ b/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) +} diff --git a/server.go b/server.go index fc948c462..4a29df5fd 100644 --- a/server.go +++ b/server.go @@ -35,7 +35,10 @@ import ( "github.com/streamrail/concurrent-map" ) -var oxyLogger = &OxyLogger{} +var ( + oxyLogger = &OxyLogger{} + backend2FrontendMap map[string]string +) // Server is the reverse-proxy/load-balancer engine type Server struct { @@ -180,9 +183,9 @@ func (server *Server) listenConfigurations(stop chan bool) { } currentConfigurations := server.currentConfigurations.Get().(configs) if configMsg.Configuration == nil { - log.Info("Skipping empty Configuration") - } else if reflect.DeepEqual(currentConfigurations[configMsg.ProviderName], configMsg.Configuration) { - log.Info("Skipping same configuration") + log.Infof("Skipping empty Configuration for provider %s", configMsg.ProviderName) + } else if reflect.DeepEqual(server.currentConfigurations[configMsg.ProviderName], configMsg.Configuration) { + log.Infof("Skipping same configuration for provider %s", configMsg.ProviderName) } else { // Copy configurations to new map so we don't change current if LoadConfig fails newConfigurations := make(configs) @@ -369,6 +372,7 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo redirectHandlers := make(map[string]http.Handler) backends := map[string]http.Handler{} + backend2FrontendMap := map[string]string{} for _, configuration := range configurations { frontendNames := sortedFrontendNamesForConfig(configuration) for _, frontendName := range frontendNames { @@ -376,6 +380,7 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo log.Debugf("Creating frontend %s", frontendName) fwd, _ := forward.New(forward.Logger(oxyLogger), forward.PassHostHeader(frontend.PassHostHeader)) + saveBackend := middlewares.NewSaveBackend(fwd) // default endpoints if not defined in frontends if len(frontend.EntryPoints) == 0 { frontend.EntryPoints = globalConfiguration.DefaultEntryPoints @@ -411,7 +416,7 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo if backends[frontend.Backend] == nil { log.Debugf("Creating backend %s", frontend.Backend) var lb http.Handler - rr, _ := roundrobin.New(fwd) + rr, _ := roundrobin.New(saveBackend) if configuration.Backends[frontend.Backend] == nil { return nil, errors.New("Undefined backend: " + frontend.Backend) } @@ -429,6 +434,7 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo if err != nil { return nil, err } + backend2FrontendMap[url.String()] = frontendName log.Debugf("Creating server %s at %s with weight %d", serverName, url.String(), server.Weight) if err := rebalancer.UpsertServer(url, roundrobin.Weight(server.Weight)); err != nil { return nil, err @@ -442,6 +448,7 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo if err != nil { return nil, err } + backend2FrontendMap[url.String()] = frontendName log.Debugf("Creating server %s at %s with weight %d", serverName, url.String(), server.Weight) if err := rr.UpsertServer(url, roundrobin.Weight(server.Weight)); err != nil { return nil, err @@ -503,6 +510,7 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo } } } + middlewares.SetBackend2FrontendMap(&backend2FrontendMap) return serverEntryPoints, nil }