Added some instrubmentation for the speed of middleware and the API c…

…alls

coprocess.go

@@ -33,6 +33,10 @@ type CoProcessMiddleware struct {
 	MiddlewareDriver tykcommon.MiddlewareDriver
 }
 
+func (mw *CoProcessMiddleware) GetName() string {
+	return "CoProcessMiddleware"
+}
+
 // CreateCoProcessMiddleware initializes a new CP middleware, takes hook type (pre, post, etc.), hook name ("my_hook") and driver ("python").
 func CreateCoProcessMiddleware(hookName string, hookType coprocess.HookType, mwDriver tykcommon.MiddlewareDriver, tykMwSuper *TykMiddleware) func(http.Handler) http.Handler {
 	dMiddleware := &CoProcessMiddleware{

coprocess_dummy.go

@@ -22,7 +22,6 @@ type Dispatcher interface {
 	Reload()
 }
 
-
 var GlobalDispatcher Dispatcher
 
 var EnableCoProcess bool = false
@@ -34,6 +33,10 @@ type CoProcessMiddleware struct {
 	MiddlewareDriver tykcommon.MiddlewareDriver
 }
 
+func (mw *CoProcessMiddleware) GetName() string {
+	return "CoProcessMiddlewareDummy"
+}
+
 func (m *CoProcessMiddleware) New() {}
 
 func (a *CoProcessMiddleware) IsEnabledForSpec() bool {

main.go

@@ -25,6 +25,7 @@ import (
 	logger "github.com/TykTechnologies/tykcommon-logger"
 	"github.com/docopt/docopt.go"
 	"github.com/facebookgo/pidfile"
+	"github.com/gocraft/health"
 	"github.com/gorilla/mux"
 	"github.com/justinas/alice"
 	"github.com/lonelycode/logrus-graylog-hook"
@@ -34,6 +35,7 @@ import (
 )
 
 var log = logger.GetLogger()
+var instrument = health.NewStream()
 var config = Config{}
 var templates = &template.Template{}
 var analytics = RedisAnalyticsHandler{}
@@ -316,26 +318,26 @@ func loadAPIEndpoints(Muxer *mux.Router) {
 	}
 
 	// set up main API handlers
-	ApiMuxer.HandleFunc("/tyk/reload/group", CheckIsAPIOwner(groupResetHandler))
-	ApiMuxer.HandleFunc("/tyk/reload/", CheckIsAPIOwner(resetHandler))
+	ApiMuxer.HandleFunc("/tyk/reload/group", CheckIsAPIOwner(InstrumentationMW(groupResetHandler)))
+	ApiMuxer.HandleFunc("/tyk/reload/", CheckIsAPIOwner(InstrumentationMW(resetHandler)))
 
 	if !IsRPCMode() {
-		ApiMuxer.HandleFunc("/tyk/org/keys/"+"{rest:.*}", CheckIsAPIOwner(orgHandler))
-		ApiMuxer.HandleFunc("/tyk/keys/policy/"+"{rest:.*}", CheckIsAPIOwner(policyUpdateHandler))
-		ApiMuxer.HandleFunc("/tyk/keys/create", CheckIsAPIOwner(createKeyHandler))
-		ApiMuxer.HandleFunc("/tyk/apis/"+"{rest:.*}", CheckIsAPIOwner(apiHandler))
-		ApiMuxer.HandleFunc("/tyk/health/", CheckIsAPIOwner(healthCheckhandler))
-		ApiMuxer.HandleFunc("/tyk/oauth/clients/create", CheckIsAPIOwner(createOauthClient))
-		ApiMuxer.HandleFunc("/tyk/oauth/refresh/"+"{rest:.*}", CheckIsAPIOwner(invalidateOauthRefresh))
-		ApiMuxer.HandleFunc("/tyk/cache/"+"{rest:.*}", CheckIsAPIOwner(invalidateCacheHandler))
+		ApiMuxer.HandleFunc("/tyk/org/keys/"+"{rest:.*}", CheckIsAPIOwner(InstrumentationMW(orgHandler)))
+		ApiMuxer.HandleFunc("/tyk/keys/policy/"+"{rest:.*}", CheckIsAPIOwner(InstrumentationMW(policyUpdateHandler)))
+		ApiMuxer.HandleFunc("/tyk/keys/create", CheckIsAPIOwner(InstrumentationMW(createKeyHandler)))
+		ApiMuxer.HandleFunc("/tyk/apis/"+"{rest:.*}", CheckIsAPIOwner(InstrumentationMW(apiHandler)))
+		ApiMuxer.HandleFunc("/tyk/health/", CheckIsAPIOwner(InstrumentationMW(healthCheckhandler)))
+		ApiMuxer.HandleFunc("/tyk/oauth/clients/create", CheckIsAPIOwner(InstrumentationMW(createOauthClient)))
+		ApiMuxer.HandleFunc("/tyk/oauth/refresh/"+"{rest:.*}", CheckIsAPIOwner(InstrumentationMW(invalidateOauthRefresh)))
+		ApiMuxer.HandleFunc("/tyk/cache/"+"{rest:.*}", CheckIsAPIOwner(InstrumentationMW(invalidateCacheHandler)))
 	} else {
 		log.WithFields(logrus.Fields{
 			"prefix": "main",
 		}).Info("Node is slaved, REST API minimised")
 	}
 
-	ApiMuxer.HandleFunc("/tyk/keys/"+"{rest:.*}", CheckIsAPIOwner(keyHandler))
-	ApiMuxer.HandleFunc("/tyk/oauth/clients/"+"{rest:.*}", CheckIsAPIOwner(oAuthClientHandler))
+	ApiMuxer.HandleFunc("/tyk/keys/"+"{rest:.*}", CheckIsAPIOwner(InstrumentationMW(keyHandler)))
+	ApiMuxer.HandleFunc("/tyk/oauth/clients/"+"{rest:.*}", CheckIsAPIOwner(InstrumentationMW(oAuthClientHandler)))
 
 	log.WithFields(logrus.Fields{
 		"prefix": "main",
@@ -944,6 +946,15 @@ func initialiseSystem(arguments map[string]interface{}) {
 		}).Error("Failed to write PIDFile: ", pfErr)
 	}
 
+	doInstrumentation, _ := arguments["--log-instrumentation"].(bool)
+
+	if doInstrumentation == true {
+		instrument.AddSink(&health.WriterSink{os.Stdout})
+	}
+
+	log.Warning("TODO: Disable auto-instrumentation logging")
+	instrument.AddSink(&health.WriterSink{os.Stdout})
+
 	GetHostDetails()
 
 	go StartPeriodicStateBackup(&LE_MANAGER)
@@ -970,6 +981,7 @@ func getCmdArguments() map[string]interface{} {
 		--as-mock                    Creates the API as a mock based on example fields
 		--for-api=<path>             Adds blueprint to existing API Defintition as version
 		--as-version=<version>       The version number to use when inserting
+		--log-instrumentation        Output instrumentation data to stdout
 	`
 
 	arguments, err := docopt.Parse(usage, nil, true, VERSION, false, false)

middleware.go

@@ -1,9 +1,13 @@
 package main
 
 import (
-	"github.com/paulbellamy/ratecounter"
+	"fmt"
 	"net/http"
+	"strconv"
 	"time"
+
+	"github.com/gocraft/health"
+	"github.com/paulbellamy/ratecounter"
 )
 
 var GlobalRate *ratecounter.RateCounter = ratecounter.NewRateCounter(1 * time.Second)
@@ -13,6 +17,7 @@ type TykMiddlewareImplementation interface {
 	GetConfig() (interface{}, error)
 	ProcessRequest(w http.ResponseWriter, r *http.Request, configuration interface{}) (error, int) // Handles request
 	IsEnabledForSpec() bool
+	GetName() string
 }
 
 func CreateDynamicMiddleware(MiddlewareName string, IsPre, UseSession bool, tykMwSuper *TykMiddleware) func(http.Handler) http.Handler {
@@ -53,6 +58,17 @@ func CreateMiddleware(mw TykMiddlewareImplementation, tykMwSuper *TykMiddleware)
 
 	aliceHandler := func(h http.Handler) http.Handler {
 		thisHandler := func(w http.ResponseWriter, r *http.Request) {
+			job := instrument.NewJob("gw_mw")
+			meta := health.Kvs{
+				"from_ip":  fmt.Sprint(r.RemoteAddr),
+				"method":   r.Method,
+				"endpoint": r.URL.Path,
+				"raw_url":  r.URL.String(),
+				"size":     strconv.Itoa(int(r.ContentLength)),
+				"mw_name":  mw.GetName(),
+			}
+			job.EventKv("executed", meta)
+			startTime := time.Now()
 
 			if (tykMwSuper.Spec.CORS.OptionsPassthrough) && (r.Method == "OPTIONS") {
 				h.ServeHTTP(w, r)
@@ -61,21 +77,28 @@ func CreateMiddleware(mw TykMiddlewareImplementation, tykMwSuper *TykMiddleware)
 				if reqErr != nil {
 					handler := ErrorHandler{tykMwSuper}
 					handler.HandleError(w, r, reqErr.Error(), errCode)
+					meta["error"] = reqErr.Error()
+					job.TimingKv("exec_time", time.Since(startTime).Nanoseconds(), meta)
 					return
 				}
 
 				// Special code, stops execution
 				if errCode == 1666 {
 					// Stop
 					log.Info("[Middleware] Received stop code")
+					meta["stopped"] = "1"
+					job.TimingKv("exec_time", time.Since(startTime).Nanoseconds(), meta)
 					return
 				}
 
 				// Special code, bypasses all other execution
 				if errCode != 666 {
 					// No error, carry on...
+					meta["bypass"] = "1"
 					h.ServeHTTP(w, r)
 				}
+
+				job.TimingKv("exec_time", time.Since(startTime).Nanoseconds(), meta)
 			}
 
 		}

middleware_HMAC.go

@@ -5,15 +5,16 @@ import (
 	"crypto/sha1"
 	"encoding/base64"
 	"errors"
-	"github.com/TykTechnologies/logrus"
-	"github.com/TykTechnologies/tykcommon"
-	"github.com/gorilla/context"
 	"math"
 	"net/http"
-	"regexp"
 	"net/url"
+	"regexp"
 	"strings"
 	"time"
+
+	"github.com/TykTechnologies/logrus"
+	"github.com/TykTechnologies/tykcommon"
+	"github.com/gorilla/context"
 )
 
 const DateHeaderSpec string = "Date"
@@ -26,6 +27,10 @@ type HMACMiddleware struct {
 	lowercasePattern *regexp.Regexp
 }
 
+func (mw *HMACMiddleware) GetName() string {
+	return "HMAC"
+}
+
 // New lets you do any initializations for the object can be done here
 func (hm *HMACMiddleware) New() {
 	hm.lowercasePattern, _ = regexp.Compile("%[a-f0-9][a-f0-9]")
@@ -147,7 +152,7 @@ func (hm *HMACMiddleware) hasLowerCaseEscaped(signature string) (bool, []string)
 
 func (hm *HMACMiddleware) replaceWithUpperCase(originalSignature string, lowercaseList []string) string {
 	newSignature := originalSignature
-	for _, lStr := range(lowercaseList) {
+	for _, lStr := range lowercaseList {
 		asUpper := strings.ToUpper(lStr)
 		newSignature = strings.Replace(newSignature, lStr, asUpper, -1)
 	}

middleware_access_rights.go

@@ -4,6 +4,7 @@ import "net/http"
 
 import (
 	"errors"
+
 	"github.com/TykTechnologies/logrus"
 	"github.com/gorilla/context"
 )
@@ -15,6 +16,10 @@ type AccessRightsCheck struct {
 	*TykMiddleware
 }
 
+func (mw *AccessRightsCheck) GetName() string {
+	return "AccessRightsCheck"
+}
+
 // New lets you do any initialisations for the object can be done here
 func (a *AccessRightsCheck) New() {}
 

middleware_auth_key.go

@@ -5,11 +5,12 @@ import "net/http"
 import (
 	"bytes"
 	"errors"
+	"io"
+	"io/ioutil"
+
 	"github.com/TykTechnologies/logrus"
 	"github.com/TykTechnologies/tykcommon"
 	"github.com/gorilla/context"
-	"io"
-	"io/ioutil"
 )
 
 // KeyExists will check if the key being used to access the API is in the request data,
@@ -18,6 +19,10 @@ type AuthKey struct {
 	*TykMiddleware
 }
 
+func (mw *AuthKey) GetName() string {
+	return "AuthKey"
+}
+
 func (k AuthKey) New() {}
 
 // GetConfig retrieves the configuration from the API config

middleware_basic_auth_check.go

@@ -5,18 +5,23 @@ import "net/http"
 import (
 	"encoding/base64"
 	"errors"
+	"strings"
+
 	"github.com/TykTechnologies/logrus"
 	"github.com/TykTechnologies/tykcommon"
 	"github.com/gorilla/context"
 	"golang.org/x/crypto/bcrypt"
-	"strings"
 )
 
 // BasicAuthKeyIsValid uses a username instead of
 type BasicAuthKeyIsValid struct {
 	*TykMiddleware
 }
 
+func (mw *BasicAuthKeyIsValid) GetName() string {
+	return "BasicAuthKeyIsValid"
+}
+
 // New lets you do any initialisations for the object can be done here
 func (k *BasicAuthKeyIsValid) New() {}
 

middleware_context_vars.go

@@ -1,9 +1,10 @@
 package main
 
 import (
-	"github.com/gorilla/context"
 	"net/http"
 	"strings"
+
+	"github.com/gorilla/context"
 )
 
 type MiddlewareContextVars struct {
@@ -15,6 +16,10 @@ type MiddlewareContextVarsConfig struct{}
 // New lets you do any initialisations for the object can be done here
 func (m *MiddlewareContextVars) New() {}
 
+func (mw *MiddlewareContextVars) GetName() string {
+	return "MiddlewareContextVars"
+}
+
 // GetConfig retrieves the configuration from the API config - we user mapstructure for this for simplicity
 func (m *MiddlewareContextVars) GetConfig() (interface{}, error) {
 	var thisModuleConfig MiddlewareContextVarsConfig

middleware_granular_access.go

@@ -2,10 +2,11 @@ package main
 
 import (
 	"errors"
-	"github.com/TykTechnologies/logrus"
-	"github.com/gorilla/context"
 	"net/http"
 	"regexp"
+
+	"github.com/TykTechnologies/logrus"
+	"github.com/gorilla/context"
 )
 
 // GranularAccessMiddleware will check if a URL is specifically enabled for the key
@@ -17,6 +18,10 @@ type GranularAccessMiddlewareConfig struct{}
 
 func (m *GranularAccessMiddleware) New() {}
 
+func (mw *GranularAccessMiddleware) GetName() string {
+	return "GranularAccessMiddleware"
+}
+
 // GetConfig retrieves the configuration from the API config - we user mapstructure for this for simplicity
 func (m *GranularAccessMiddleware) GetConfig() (interface{}, error) {
 	return nil, nil

middleware_instrumentation_handlers.go

@@ -0,0 +1,26 @@
+package main
+
+import (
+	"fmt"
+	"net/http"
+	"strconv"
+
+	"github.com/gocraft/health"
+)
+
+// InstrumentationMW will set basic instrumentation events, variables and timers on API jobs
+func InstrumentationMW(handler func(http.ResponseWriter, *http.Request)) func(http.ResponseWriter, *http.Request) {
+	return func(w http.ResponseWriter, r *http.Request) {
+		job := instrument.NewJob("gw_api_call")
+
+		handler(w, r)
+		job.EventKv("called", health.Kvs{
+			"from_ip":  fmt.Sprint(r.RemoteAddr),
+			"method":   r.Method,
+			"endpoint": r.URL.Path,
+			"raw_url":  r.URL.String(),
+			"size":     strconv.Itoa(int(r.ContentLength)),
+		})
+		job.Complete(health.Success)
+	}
+}

middleware_ip_whitelist.go

@@ -12,6 +12,10 @@ type IPWhiteListMiddleware struct {
 	*TykMiddleware
 }
 
+func (mw *IPWhiteListMiddleware) GetName() string {
+	return "IPWhiteListMiddleware"
+}
+
 // New lets you do any initialisations for the object can be done here
 func (i *IPWhiteListMiddleware) New() {}
 

middleware_jwt.go

@@ -26,6 +26,10 @@ type JWTMiddleware struct {
 	*TykMiddleware
 }
 
+func (mw *JWTMiddleware) GetName() string {
+	return "JWTMiddleware"
+}
+
 var JWKCache *cache.Cache
 
 type JWK struct {