diff --git a/.gitignore b/.gitignore index 866aca26c..a63c731ec 100644 --- a/.gitignore +++ b/.gitignore @@ -10,4 +10,6 @@ traefik.toml vendor/ static/ .vscode/ -site/ \ No newline at end of file +site/ +*.log +*.exe 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 100755 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 100755 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/examples/k8s.namespace.sh b/examples/k8s.namespace.sh old mode 100755 new mode 100644 diff --git a/glide.lock b/glide.lock index a847744aa..02fbf138d 100644 --- a/glide.lock +++ b/glide.lock @@ -1,5 +1,5 @@ -hash: e92948ce12f546d39a02c2e58668f7d12d7b1f3dd56eb046e01b527df756f734 -updated: 2016-04-26T23:18:15.861898862+02:00 +hash: a9f41b9fe89ac3028da27ac9cbe31db9a79ae89082f42507d4d0c58290517ee2 +updated: 2016-04-27T17:14:45.61228359Z imports: - name: github.com/alecthomas/template version: b867cc6ab45cece8143cfcc6fc9c77cf3f2c23c0 @@ -100,7 +100,7 @@ imports: - types/time - types/blkiodev - name: github.com/docker/go-connections - version: 5b7154ba2efe13ff86ae8830a9e7cb120b080d6e + version: f549a9393d05688dff0992ef3efd8bbe6c628aeb subpackages: - nat - sockets @@ -121,6 +121,12 @@ imports: version: 9cbd2a1374f46905c68a4eb3694a130610adc62a - name: github.com/donovanhide/eventsource version: d8a3071799b98cacd30b6da92f536050ccfe6da4 +- name: github.com/eapache/go-resiliency + version: b86b1ec0dd4209a588dc1285cdd471e73525c0b3 + subpackages: + - breaker +- name: github.com/eapache/queue + version: ded5959c0d4e360646dc9e9908cff48666781367 - name: github.com/elazarl/go-bindata-assetfs version: d5cac425555ca5cf00694df246e04f05e6a55150 - name: github.com/flynn/go-shlex @@ -131,6 +137,8 @@ imports: version: 11d3bc7aa68e238947792f30573146a3231fc0f1 - name: github.com/golang/glog version: fca8c8854093a154ff1eb580aae10276ad6b1b5f +- name: github.com/golang/snappy + version: ec642410cd033af63620b66a91ccbd3c69c2c59a - name: github.com/google/go-querystring version: 9235644dd9e52eeae6fa48efd539fdc351a0af53 subpackages: @@ -148,7 +156,7 @@ imports: subpackages: - api - name: github.com/hashicorp/hcl - version: 27a57f2605e04995c111273c263d51cee60d9bc4 + version: 2604f3bda7e8960c1be1063709e7d7f0765048d0 subpackages: - hcl/ast - hcl/parser @@ -160,6 +168,8 @@ imports: - json/token - name: github.com/inconshreveable/mousetrap version: 76626ae9c91c4f2a10f34cad8ce83ea42c93bb75 +- name: github.com/klauspost/crc32 + version: 19b0b332c9e4516a6370a0456e6182c3b5036720 - name: github.com/kr/pretty version: add1dbc86daf0f983cd4a48ceb39deb95c729b67 - name: github.com/kr/text @@ -174,10 +184,12 @@ imports: version: 565402cd71fbd9c12aa7e295324ea357e970a61e - name: github.com/mailgun/timetools version: fd192d755b00c968d312d23f521eb0cdc6f66bd0 +- name: github.com/mattn/go-shellwords + version: 525bedee691b5a8df547cb5cf9f86b7fb1883e24 - name: github.com/Microsoft/go-winio version: 862b6557927a5c5c81e411c12aa6de7e566cbb7a - name: github.com/miekg/dns - version: a5cc44dc6b2eee8eddfd6581e1c6bb753ff0d176 + version: dd83d5cbcfd986f334b2747feeb907e281318fdf - name: github.com/mitchellh/mapstructure version: d2dd0262208475919e1a362f675cfc0e7c10e905 - name: github.com/moul/http2curl @@ -196,6 +208,8 @@ imports: version: fa6674abf3f4580b946a01bf7a1ce4ba8766205b subpackages: - zk +- name: github.com/Shopify/sarama + version: 92a286e4dde1688175cff3d2ec9b49a02838b447 - name: github.com/Sirupsen/logrus version: 418b41d23a1bf978c06faea5313ba194650ac088 - name: github.com/spf13/cast @@ -207,7 +221,7 @@ imports: - name: github.com/spf13/jwalterweatherman version: 33c24e77fb80341fe7130ee7c594256ff08ccc46 - name: github.com/spf13/pflag - version: 8f6a28b0916586e7f22fe931ae2fcfc380b1c0e6 + version: 1f296710f879815ad9e6d39d947c828c3e4b4c3d - name: github.com/spf13/viper version: a212099cbe6fbe8d07476bfda8d2d39b6ff8f325 - name: github.com/streamrail/concurrent-map @@ -228,7 +242,7 @@ imports: - name: github.com/unrolled/render version: 26b4e3aac686940fe29521545afad9966ddfc80c - name: github.com/vdemeester/docker-events - version: 1ecaca5890ef1ffd266fcbfdbe43073ef105704b + version: 6ea3f28df37f29a47498bc8b32b36ad8491dbd37 - name: github.com/vdemeester/libkermit version: 7e4e689a6fa9281e0fb9b7b9c297e22d5342a5ec - name: github.com/vdemeester/shakers @@ -251,11 +265,11 @@ imports: - name: github.com/wendal/errors version: f66c77a7882b399795a8987ebf87ef64a427417e - name: github.com/xenolf/lego - version: 684400fe76a813e78d87803a62bc04d977c501d2 + version: 23e88185c255e95a106835d80e76e5a3a66d7c54 subpackages: - acme - name: golang.org/x/crypto - version: 1777f3ba8c1fed80fcaec3317e3aaa4f627764d2 + version: d68c3ecb62c850b645dc072a8d78006286bf81ca subpackages: - ocsp - name: golang.org/x/net diff --git a/glide.yaml b/glide.yaml index 0115ec46f..fbaa1e75d 100644 --- a/glide.yaml +++ b/glide.yaml @@ -183,3 +183,5 @@ import: - package: github.com/mailgun/multibuf - package: github.com/streamrail/concurrent-map - package: github.com/parnurzeal/gorequest +- package: github.com/mattn/go-shellwords +- package: github.com/moul/http2curl diff --git a/integration/access_log_test.go b/integration/access_log_test.go new file mode 100644 index 000000000..ffa2b0ae8 --- /dev/null +++ b/integration/access_log_test.go @@ -0,0 +1,110 @@ +package main + +import ( + "fmt" + "io/ioutil" + "net" + "net/http" + "net/http/httptest" + "os" + "os/exec" + "regexp" + "strings" + "time" + + "github.com/go-check/check" + shellwords "github.com/mattn/go-shellwords" + + checker "github.com/vdemeester/shakers" +) + +// AccessLogSuite +type AccessLogSuite struct{ BaseSuite } + +func (s *AccessLogSuite) TestAccessLog(c *check.C) { + // Ensure working directory is clean + os.Remove("access.log") + os.Remove("traefik.log") + + // Start Traefik + cmd := exec.Command(traefikBinary, "--configFile=fixtures/access_log_config.toml") + err := cmd.Start() + c.Assert(err, checker.IsNil) + defer cmd.Process.Kill() + defer os.Remove("access.log") + defer os.Remove("traefik.log") + + time.Sleep(500 * time.Millisecond) + + // Verify Traefik started OK + if traefikLog, err := ioutil.ReadFile("traefik.log"); err != nil { + c.Assert(err.Error(), checker.Equals, "") + } else if len(traefikLog) > 0 { + fmt.Printf("%s\n", string(traefikLog)) + c.Assert(len(traefikLog), checker.Equals, 0) + } + + // Start test servers + ts1 := startAccessLogServer(8081) + defer ts1.Close() + ts2 := startAccessLogServer(8082) + defer ts2.Close() + ts3 := startAccessLogServer(8083) + defer ts3.Close() + + // Make some requests + _, err = http.Get("http://127.0.0.1:8000/test1") + c.Assert(err, checker.IsNil) + _, err = http.Get("http://127.0.0.1:8000/test2") + c.Assert(err, checker.IsNil) + _, err = http.Get("http://127.0.0.1:8000/test2") + c.Assert(err, checker.IsNil) + + // Verify access.log output as expected + if accessLog, err := ioutil.ReadFile("access.log"); err != nil { + c.Assert(err.Error(), checker.Equals, "") + } else { + lines := strings.Split(string(accessLog), "\n") + count := 0 + for i, line := range lines { + if len(line) > 0 { + count++ + if tokens, err := shellwords.Parse(line); err != nil { + c.Assert(err.Error(), checker.Equals, "") + } else { + c.Assert(len(tokens), checker.Equals, 13) + c.Assert(tokens[6], checker.Equals, "200") + c.Assert(tokens[9], checker.Equals, fmt.Sprintf("%d", i+1)) + c.Assert(strings.HasPrefix(tokens[10], "frontend"), checker.True) + c.Assert(strings.HasPrefix(tokens[11], "http://127.0.0.1:808"), checker.True) + c.Assert(regexp.MustCompile("^\\d+\\.\\d+.*s$").MatchString(tokens[12]), checker.True) + } + } + } + c.Assert(count, checker.Equals, 3) + } + + // Verify no other Traefik problems + if traefikLog, err := ioutil.ReadFile("traefik.log"); err != nil { + c.Assert(err.Error(), checker.Equals, "") + } else if len(traefikLog) > 0 { + fmt.Printf("%s\n", string(traefikLog)) + c.Assert(len(traefikLog), checker.Equals, 0) + } +} + +func startAccessLogServer(port int) (ts *httptest.Server) { + handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + fmt.Fprintf(w, "Received query %s!\n", r.URL.Path[1:]) + }) + if listener, err := net.Listen("tcp", fmt.Sprintf("127.0.0.1:%d", port)); err != nil { + panic(err) + } else { + ts = &httptest.Server{ + Listener: listener, + Config: &http.Server{Handler: handler}, + } + ts.Start() + } + return +} diff --git a/integration/fixtures/access_log_config.toml b/integration/fixtures/access_log_config.toml new file mode 100644 index 000000000..2a3e0ed08 --- /dev/null +++ b/integration/fixtures/access_log_config.toml @@ -0,0 +1,46 @@ +################################################################ +# Global configuration +################################################################ +traefikLogsFile = "traefik.log" +accessLogsFile = "access.log" +logLevel = "ERROR" +defaultEntryPoints = ["http"] +[entryPoints] + [entryPoints.http] + address = ":8000" + +################################################################ +# 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/integration/integration_test.go b/integration/integration_test.go index 7178bb070..d472f7d23 100644 --- a/integration/integration_test.go +++ b/integration/integration_test.go @@ -23,6 +23,7 @@ func Test(t *testing.T) { func init() { check.Suite(&SimpleSuite{}) + check.Suite(&AccessLogSuite{}) check.Suite(&HTTPSSuite{}) check.Suite(&FileSuite{}) check.Suite(&DockerSuite{}) diff --git a/middlewares/logger.go b/middlewares/logger.go index 34baf6f9f..ea2d228f7 100644 --- a/middlewares/logger.go +++ b/middlewares/logger.go @@ -1,18 +1,56 @@ 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/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 +63,132 @@ 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) + 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) { + 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.(*logInfoResponseWriter).SetBackend(backendName) + infoRw.(*logInfoResponseWriter).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 77d558947..39a09c271 100644 --- a/server.go +++ b/server.go @@ -180,9 +180,9 @@ func (server *Server) listenConfigurations(stop chan bool) { } currentConfigurations := server.currentConfigurations.Get().(configs) if configMsg.Configuration == nil { - log.Info("Skipping empty Configuration") + log.Infof("Skipping empty Configuration for provider %s", configMsg.ProviderName) } else if reflect.DeepEqual(currentConfigurations[configMsg.ProviderName], configMsg.Configuration) { - log.Info("Skipping same 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) @@ -372,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 { @@ -379,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 @@ -414,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) } @@ -432,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 @@ -445,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 @@ -506,6 +510,7 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo } } } + middlewares.SetBackend2FrontendMap(&backend2FrontendMap) return serverEntryPoints, nil }