From fb12df6036b455b22e17c267eb9af42927a3e18a Mon Sep 17 00:00:00 2001 From: Mike Lang Date: Mon, 5 Dec 2016 15:43:36 -0800 Subject: [PATCH 1/6] ecs reporter: Fix some log lines that were passing *string instead of string --- probe/awsecs/client.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/probe/awsecs/client.go b/probe/awsecs/client.go index 8774544afb..2fb3071f5c 100644 --- a/probe/awsecs/client.go +++ b/probe/awsecs/client.go @@ -73,7 +73,7 @@ func (c ecsClient) getServices() map[string]*ecs.Service { } for _, failure := range resp.Failures { - log.Warnf("Failed to describe ECS service %s, ECS service report may be incomplete: %s", failure.Arn, failure.Reason) + log.Warnf("Failed to describe ECS service %s, ECS service report may be incomplete: %s", *failure.Arn, *failure.Reason) } lock.Lock() @@ -110,7 +110,7 @@ func (c ecsClient) getTasks(taskArns []string) (map[string]*ecs.Task, error) { } for _, failure := range resp.Failures { - log.Warnf("Failed to describe ECS task %s, ECS service report may be incomplete: %s", failure.Arn, failure.Reason) + log.Warnf("Failed to describe ECS task %s, ECS service report may be incomplete: %s", *failure.Arn, *failure.Reason) } results := make(map[string]*ecs.Task, len(resp.Tasks)) From 4fcf9a1e36d1714fac470c5433718065df894e3e Mon Sep 17 00:00:00 2001 From: Jonathan Lange Date: Mon, 12 Dec 2016 17:12:28 +0000 Subject: [PATCH 2/6] Add flag for logging headers --- prog/app.go | 6 +++++- prog/main.go | 14 ++++++++------ 2 files changed, 13 insertions(+), 7 deletions(-) diff --git a/prog/app.go b/prog/app.go index 0e66b8f196..454f3b909f 100644 --- a/prog/app.go +++ b/prog/app.go @@ -270,7 +270,11 @@ func appMain(flags appFlags) { handler := router(collector, controlRouter, pipeRouter, flags.externalUI) if flags.logHTTP { - handler = middleware.LogFailed.Wrap(handler) + if flags.logHTTPHeaders { + handler = middleware.Log{LogRequestHeaders: true}.Wrap(handler) + } else { + handler = middleware.LogFailed.Wrap(handler) + } } server := &graceful.Server{ diff --git a/prog/main.go b/prog/main.go index 0a679970c6..ac1ca13a79 100644 --- a/prog/main.go +++ b/prog/main.go @@ -112,12 +112,13 @@ type probeFlags struct { } type appFlags struct { - window time.Duration - listen string - stopTimeout time.Duration - logLevel string - logPrefix string - logHTTP bool + window time.Duration + listen string + stopTimeout time.Duration + logLevel string + logPrefix string + logHTTP bool + logHTTPHeaders bool weaveEnabled bool weaveAddr string @@ -298,6 +299,7 @@ func main() { flag.StringVar(&flags.app.logLevel, "app.log.level", "info", "logging threshold level: debug|info|warn|error|fatal|panic") flag.StringVar(&flags.app.logPrefix, "app.log.prefix", "", "prefix for each log line") flag.BoolVar(&flags.app.logHTTP, "app.log.http", false, "Log individual HTTP requests") + flag.BoolVar(&flags.app.logHTTPHeaders, "app.log.httpHeaders", false, "Log HTTP headers. Needs app.log.http to be enabled.") flag.StringVar(&flags.app.weaveAddr, "app.weave.addr", app.DefaultWeaveURL, "Address on which to contact WeaveDNS") flag.StringVar(&flags.app.weaveHostname, "app.weave.hostname", app.DefaultHostname, "Hostname to advertise in WeaveDNS") From 626e8a3e9fdf4a736ca48793caf41a0b772cbbd1 Mon Sep 17 00:00:00 2001 From: Jonathan Lange Date: Mon, 12 Dec 2016 17:40:15 +0000 Subject: [PATCH 3/6] Neater way of doing it --- prog/app.go | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/prog/app.go b/prog/app.go index 454f3b909f..dfa108d84f 100644 --- a/prog/app.go +++ b/prog/app.go @@ -270,11 +270,10 @@ func appMain(flags appFlags) { handler := router(collector, controlRouter, pipeRouter, flags.externalUI) if flags.logHTTP { - if flags.logHTTPHeaders { - handler = middleware.Log{LogRequestHeaders: true}.Wrap(handler) - } else { - handler = middleware.LogFailed.Wrap(handler) - } + handler = middleware.Log{ + LogRequestHeaders: flags.logHTTPHeaders, + LogSuccess: false, + }.Wrap(handler) } server := &graceful.Server{ From 256e480accf1d6bee8d11d6e8a842f48c3fa8e46 Mon Sep 17 00:00:00 2001 From: Jonathan Lange Date: Mon, 12 Dec 2016 17:40:46 +0000 Subject: [PATCH 4/6] Vendor new weaveworks/common --- .../weaveworks/common/logging/event.go | 135 ------------------ .../weaveworks/common/middleware/logging.go | 16 ++- .../weaveworks/common/middleware/redirect.go | 48 +++++++ vendor/manifest | 2 +- 4 files changed, 63 insertions(+), 138 deletions(-) delete mode 100644 vendor/github.com/weaveworks/common/logging/event.go create mode 100644 vendor/github.com/weaveworks/common/middleware/redirect.go diff --git a/vendor/github.com/weaveworks/common/logging/event.go b/vendor/github.com/weaveworks/common/logging/event.go deleted file mode 100644 index ddffc73e25..0000000000 --- a/vendor/github.com/weaveworks/common/logging/event.go +++ /dev/null @@ -1,135 +0,0 @@ -package logging - -import ( - "fmt" - "net" - "net/http" - "strconv" - - log "github.com/Sirupsen/logrus" - "github.com/fluent/fluent-logger-golang/fluent" -) - -const maxBufferedEvents = 100 - -// Event is a user event to be sent to out analytics system -type Event struct { - ID string `msg:"event"` - SessionID string `msg:"session_id"` - Product string `msg:"product"` - Version string `msg:"version"` - UserAgent string `msg:"user_agent"` - ClientID string `msg:"client_id"` - OrganizationID string `msg:"org_id"` - UserID string `msg:"user_id"` - Values string `msg:"values"` -} - -// EventLogger logs events to the analytics system -type EventLogger struct { - stop chan struct{} - events chan Event - logger *fluent.Fluent -} - -// NewEventLogger creates a new EventLogger. -func NewEventLogger(fluentHostPort string) (*EventLogger, error) { - host, port, err := net.SplitHostPort(fluentHostPort) - if err != nil { - return nil, err - } - intPort, err := strconv.Atoi(port) - if err != nil { - return nil, err - } - logger, err := fluent.New(fluent.Config{ - FluentPort: intPort, - FluentHost: host, - AsyncConnect: true, - MaxRetry: -1, - }) - if err != nil { - return nil, err - } - - el := &EventLogger{ - stop: make(chan struct{}), - events: make(chan Event, maxBufferedEvents), - logger: logger, - } - go el.logLoop() - return el, nil -} - -func (el *EventLogger) post(e Event) { - if err := el.logger.Post("events", e); err != nil { - log.Warnf("EventLogger: failed to log event: %v", e) - } -} - -func (el *EventLogger) logLoop() { - for done := false; !done; { - select { - case event := <-el.events: - el.post(event) - case <-el.stop: - done = true - } - } - - // flush remaining events - for done := false; !done; { - select { - case event := <-el.events: - el.post(event) - default: - done = true - } - } - - el.logger.Close() -} - -// Close closes and deallocates the event logger -func (el *EventLogger) Close() error { - close(el.stop) - return nil -} - -// LogEvent logs an event to the analytics system -func (el *EventLogger) LogEvent(e Event) error { - select { - case <-el.stop: - return fmt.Errorf("Stopping, discarding event: %v", e) - default: - } - - select { - case el.events <- e: // Put event in the channel unless it is full - return nil - default: - // full - } - return fmt.Errorf("Reached event buffer limit (%d), discarding event: %v", maxBufferedEvents, e) -} - -// HTTPEventExtractor extracts an event from an http requests indicating whether it should be loggged -type HTTPEventExtractor func(*http.Request) (Event, bool) - -// HTTPEventLogger logs an events extracted from an http request -type HTTPEventLogger struct { - Extractor HTTPEventExtractor - Logger *EventLogger -} - -// Wrap implements middleware.Wrap() -func (el HTTPEventLogger) Wrap(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - if event, shouldLog := el.Extractor(r); shouldLog { - if err := el.Logger.LogEvent(event); err != nil { - log.Warnf("HTTPEventLogger: failed to log event: %v", err) - } - } - next.ServeHTTP(w, r) - }) -} diff --git a/vendor/github.com/weaveworks/common/middleware/logging.go b/vendor/github.com/weaveworks/common/middleware/logging.go index e05a80ce14..e7e1365708 100644 --- a/vendor/github.com/weaveworks/common/middleware/logging.go +++ b/vendor/github.com/weaveworks/common/middleware/logging.go @@ -5,6 +5,7 @@ import ( "fmt" "net" "net/http" + "net/http/httputil" "time" log "github.com/Sirupsen/logrus" @@ -12,7 +13,8 @@ import ( // Log middleware logs http requests type Log struct { - LogSuccess bool // LogSuccess true -> log successful queries; false -> only log failed queries + LogSuccess bool // LogSuccess true -> log successful queries; false -> only log failed queries + LogRequestHeaders bool // LogRequestHeaders true -> dump http headers at debug log level } // Wrap implements Middleware @@ -20,6 +22,15 @@ func (l Log) Wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { begin := time.Now() uri := r.RequestURI // capture the URI before running next, as it may get rewritten + if l.LogRequestHeaders { + // Log headers before running 'next' in case other interceptors change the data. + headers, err := httputil.DumpRequest(r, false) + if err != nil { + log.Warnf("Could not dump request headers: %v", err) + return + } + log.Debugf(string(headers)) + } i := &interceptor{ResponseWriter: w, statusCode: http.StatusOK} next.ServeHTTP(i, r) if l.LogSuccess || !(100 <= i.statusCode && i.statusCode < 400) { @@ -31,7 +42,8 @@ func (l Log) Wrap(next http.Handler) http.Handler { // Logging middleware logs each HTTP request method, path, response code and // duration for all HTTP requests. var Logging = Log{ - LogSuccess: true, + LogSuccess: true, + LogRequestHeaders: false, } // LogFailed middleware logs each HTTP request method, path, response code and diff --git a/vendor/github.com/weaveworks/common/middleware/redirect.go b/vendor/github.com/weaveworks/common/middleware/redirect.go new file mode 100644 index 0000000000..34c1772817 --- /dev/null +++ b/vendor/github.com/weaveworks/common/middleware/redirect.go @@ -0,0 +1,48 @@ +package middleware + +import ( + "net/http" + "net/url" +) + +// Redirect middleware, will redirect requests to hosts which match any of the +// Matches to RedirectScheme://RedirectHost +type Redirect struct { + Matches []Match + + RedirectHost string + RedirectScheme string +} + +// Match specifies a match for a redirect. Host and/or Scheme can be empty +// signify match-all. +type Match struct { + Host, Scheme string +} + +func (m Match) match(u *url.URL) bool { + if m.Host != "" && m.Host != u.Host { + return false + } + + if m.Scheme != "" && m.Scheme != u.Scheme { + return false + } + + return true +} + +// Wrap implements Middleware +func (m Redirect) Wrap(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + for _, match := range m.Matches { + if match.match(r.URL) { + r.URL.Host = m.RedirectHost + r.URL.Scheme = m.RedirectScheme + http.Redirect(w, r, r.URL.String(), http.StatusMovedPermanently) + return + } + } + next.ServeHTTP(w, r) + }) +} diff --git a/vendor/manifest b/vendor/manifest index b3b8f980f7..18abf2e347 100644 --- a/vendor/manifest +++ b/vendor/manifest @@ -1361,7 +1361,7 @@ "importpath": "github.com/weaveworks/common", "repository": "https://github.com/weaveworks/common", "vcs": "git", - "revision": "cc20acf03ebf74be0facaae4259dff6cde01ce77", + "revision": "033d5c87743012524cc813c4a66f7d18afdb20b6", "branch": "master", "notests": true }, From a8ba7b2c86be6c2b81644df69b1a95d5557184d8 Mon Sep 17 00:00:00 2001 From: Jonathan Lange Date: Mon, 12 Dec 2016 17:57:48 +0000 Subject: [PATCH 5/6] Log whether it's a websocket request --- vendor/github.com/weaveworks/common/middleware/logging.go | 2 +- vendor/manifest | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/vendor/github.com/weaveworks/common/middleware/logging.go b/vendor/github.com/weaveworks/common/middleware/logging.go index e7e1365708..19d29cd84a 100644 --- a/vendor/github.com/weaveworks/common/middleware/logging.go +++ b/vendor/github.com/weaveworks/common/middleware/logging.go @@ -29,7 +29,7 @@ func (l Log) Wrap(next http.Handler) http.Handler { log.Warnf("Could not dump request headers: %v", err) return } - log.Debugf(string(headers)) + log.Debugf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers)) } i := &interceptor{ResponseWriter: w, statusCode: http.StatusOK} next.ServeHTTP(i, r) diff --git a/vendor/manifest b/vendor/manifest index 18abf2e347..7b3bf7510a 100644 --- a/vendor/manifest +++ b/vendor/manifest @@ -1361,7 +1361,7 @@ "importpath": "github.com/weaveworks/common", "repository": "https://github.com/weaveworks/common", "vcs": "git", - "revision": "033d5c87743012524cc813c4a66f7d18afdb20b6", + "revision": "139d0313ac15170e9de8187b26e7df03b4cb910e", "branch": "master", "notests": true }, From 4d20a91a974d08abbcab6f49e98d131025b6727b Mon Sep 17 00:00:00 2001 From: Michael Schubert Date: Mon, 12 Dec 2016 16:17:44 +0100 Subject: [PATCH 6/6] Add extras/dialer Based on the dialer.sh script by @alban: https://gist.github.com/alban/7abe7f6307184c58be7429e63a2d9053 Signed-off-by: Michael Schubert --- extras/dialer/.gitignore | 1 + extras/dialer/Dockerfile | 2 + extras/dialer/README.md | 46 ++++++++++++++++++++ extras/dialer/dialer | 26 ++++++++++++ extras/dialer/dialer.go | 76 ++++++++++++++++++++++++++++++++++ extras/dialer/listener | 8 ++++ extras/dialer/time-scope-probe | 33 +++++++++++++++ 7 files changed, 192 insertions(+) create mode 100644 extras/dialer/.gitignore create mode 100644 extras/dialer/Dockerfile create mode 100644 extras/dialer/README.md create mode 100755 extras/dialer/dialer create mode 100644 extras/dialer/dialer.go create mode 100755 extras/dialer/listener create mode 100755 extras/dialer/time-scope-probe diff --git a/extras/dialer/.gitignore b/extras/dialer/.gitignore new file mode 100644 index 0000000000..e660fd93d3 --- /dev/null +++ b/extras/dialer/.gitignore @@ -0,0 +1 @@ +bin/ diff --git a/extras/dialer/Dockerfile b/extras/dialer/Dockerfile new file mode 100644 index 0000000000..942f2c4eff --- /dev/null +++ b/extras/dialer/Dockerfile @@ -0,0 +1,2 @@ +FROM golang:1.7 +ADD ./bin/dialer /go/bin diff --git a/extras/dialer/README.md b/extras/dialer/README.md new file mode 100644 index 0000000000..8e67cafd1c --- /dev/null +++ b/extras/dialer/README.md @@ -0,0 +1,46 @@ +## Overview + +The dialer scripts can be used to test Scope with a high number of +containers and connections. + +The dialer server is a TCP server that holds incoming connections +forever. + +The dialer client is a TCP client that opens n connection to a server +and holds them forever. + +The `listener` script starts a dialer server and prints its address for +usage with the `dialer` script. The `dialer` scripts starts up to n +(default 50) client containers, each opening a random (1-20) number of +connections. + +`time-scope-probe` then can be used to measure the scheduled time +(utime + stime) of the scope-probe process on the host. The results +can be used to compare performance under different scenarios/branches. + +## Usage example + +``` +# Start a listener +./tools/dialer/listener +Listening on :8082 +IP addr + port: 172.17.0.2:8082 + + +# Start the dialer script with a maximum of 10 dialer containers +# (default 50) +./tools/dialer/dialer 172.17.0.2:8082 10 + + +# Start time-scope-probe to measure the scheduled time of scope-probe +# every 3 seconds (default 10 seconds) for 3 times (default 60 times) +sudo ./tools/dialer/time-scope-probe 3 3 +... +``` + +## Build dialer container + +``` +go build -o bin/dialer +docker build -t dialer . +``` diff --git a/extras/dialer/dialer b/extras/dialer/dialer new file mode 100755 index 0000000000..a14d9d798a --- /dev/null +++ b/extras/dialer/dialer @@ -0,0 +1,26 @@ +#!/bin/bash +set -eu +if [ $# -lt 1 ]; then + echo "Usage: $0 []" >&2 + exit 1 +fi + +readonly addr=$1 +readonly max_dialer=${2:-50} + +dialer=() +trap 'echo -n "stopping ... "; for c in "${dialer[@]}"; do docker rm -f "$c" >/dev/null; done; echo "done"' EXIT + +while true; do + rand=$(( ( RANDOM % max_dialer ) + 1 )) + dialer+=("$(docker run -d dialer /go/bin/dialer connect "$addr" "$rand")") + + if [ ${#dialer[@]} -gt "$max_dialer" ]; then + container=${dialer[$rand]} + docker rm -f "$container" >/dev/null & + unset dialer[$rand] + dialer=("${dialer[@]}") + fi + + sleep $(( rand % 3 )) +done diff --git a/extras/dialer/dialer.go b/extras/dialer/dialer.go new file mode 100644 index 0000000000..3eef4a66f8 --- /dev/null +++ b/extras/dialer/dialer.go @@ -0,0 +1,76 @@ +package main + +import ( + "fmt" + "net" + "os" + "strconv" +) + +func connect(url string, numConn int) { + fmt.Printf("Establishing %d TCP connections to %s\n", numConn, url) + for x := 0; x < numConn; x++ { + _, err := net.Dial("tcp", url) + + if err != nil { + fmt.Printf("Error: %v\n", err) + os.Exit(1) + } + } + + // wait forever + select {} +} + +func listen(url string) { + l, err := net.Listen("tcp", url) + if err != nil { + fmt.Println("Error listening:", err.Error()) + os.Exit(1) + } + defer l.Close() + fmt.Println("Listening on " + url) + for { + _, err := l.Accept() + if err != nil { + fmt.Println("Error accepting: ", err.Error()) + os.Exit(1) + } + } + +} + +func main() { + if len(os.Args) < 2 { + fmt.Println("Not enough arguments") + os.Exit(1) + } + + verb := os.Args[1] + + if verb == "connect" { + if len(os.Args) != 4 { + fmt.Println("Not enough arguments") + os.Exit(1) + } + + url := os.Args[2] + numConn, err := strconv.Atoi(os.Args[3]) + if err != nil { + fmt.Printf("Error with second argument\n") + os.Exit(1) + } + + connect(url, numConn) + } + if verb == "listen" { + if len(os.Args) != 3 { + fmt.Println("Not enough arguments") + os.Exit(1) + } + + port := os.Args[2] + listen(":" + port) + } + +} diff --git a/extras/dialer/listener b/extras/dialer/listener new file mode 100755 index 0000000000..7e6112a67d --- /dev/null +++ b/extras/dialer/listener @@ -0,0 +1,8 @@ +#!/bin/bash +set -eu +readonly port=${1:-8082} +( +sleep 5 # wait for dialerserver to start +echo "IP addr + port: $(docker inspect -f '{{ .NetworkSettings.IPAddress }}' dialerserver):$port" +) & +docker run --rm --name dialerserver dialer /go/bin/dialer listen "$port" diff --git a/extras/dialer/time-scope-probe b/extras/dialer/time-scope-probe new file mode 100755 index 0000000000..bc28644fd6 --- /dev/null +++ b/extras/dialer/time-scope-probe @@ -0,0 +1,33 @@ +#!/bin/bash +set -eu +if [ $EUID -ne 0 ]; then + echo "You must be root!" >&2 + exit 1 +fi + +readonly interval_num=${1:-60} +readonly interval_sleep=${2:-10} + +TIME_U1=0 +TIME_K1=0 +TIME_T1=0 +TIME_U2=0 +TIME_K2=0 +TIME_T2=0 + +if [ "$(pidof scope-probe)" == "" ]; then + echo "No scope-probe process running - aborting" >&2 + exit 1 +fi + +for ((i=0; i<"$interval_num"; i++)); do + sleep "$interval_sleep" + TIME_U1=$TIME_U2 + TIME_K1=$TIME_K2 + TIME_T1=$TIME_T2 + + TIME_U2=$(gawk '{print $14"*10"}'<"/proc/$(pidof scope-probe)/stat" | bc) + TIME_K2=$(gawk '{print $15"*10"}'<"/proc/$(pidof scope-probe)/stat" | bc) + TIME_T2=$(( TIME_U2 + TIME_K2 )) + echo "utime $(( TIME_U2 - TIME_U1)) + stime $(( TIME_K2 - TIME_K1 )) = $(( TIME_T2 - TIME_T1 ))" +done