Api latency

discovery/cmd/openstack-discoverer/main.go

@@ -49,8 +49,11 @@ var (
 	openstackCertificateAuthorityFile string
 	prometheusListenPort              int
 	discovererMetrics                 localmetrics.DiscovererMetrics
+	log                               *logrus.Logger
 )
 
+const clusterType = "openstack"
+
 func init() {
 	flag.BoolVar(&printVersion, "version", false, "Show version and quit")
 	flag.StringVar(&gimbalKubeCfgFile, "gimbal-kubecfg-file", "", "Location of kubecfg file for access to gimbal system kubernetes api, defaults to service account tokens")
@@ -73,7 +76,7 @@ func main() {
 		os.Exit(0)
 	}
 
-	var log = logrus.New()
+	log = logrus.New()
 	log.Formatter = util.GetFormatter()
 	if debug {
 		log.Level = logrus.DebugLevel
@@ -118,18 +121,33 @@ func main() {
 	if err != nil {
 		log.Fatalf("Failed to create OpenStack client: %v", err)
 	}
-	osClient.HTTPClient.Timeout = httpClientTimeout
+
+	dClient := http.Client{
+		Transport: &openstack.LogRoundTripper{
+			RoundTripper: http.DefaultTransport,
+			Log:          log,
+			ClusterName:  clusterName,
+			ClusterType:  clusterType,
+			Metrics:      &discovererMetrics,
+		},
+		Timeout: httpClientTimeout,
+	}
+
 	if openstackCertificateAuthorityFile != "" {
-		osClient.HTTPClient.Transport = httpTransportWithCA(log, openstackCertificateAuthorityFile)
+		dClient.Transport = httpTransportWithCA(log, openstackCertificateAuthorityFile)
 	}
 
+	// Pass http client
+	osClient.HTTPClient = dClient
+
 	osAuthOptions := gophercloud.AuthOptions{
 		IdentityEndpoint: identityEndpoint,
 		Username:         username,
 		Password:         password,
 		DomainName:       "Default",
 		TenantName:       tenantName,
 	}
+
 	if err := gopheropenstack.Authenticate(osClient, osAuthOptions); err != nil {
 		log.Fatalf("Failed to authenticate with OpenStack: %v", err)
 	}
@@ -146,6 +164,7 @@ func main() {
 
 	reconciler := openstack.NewReconciler(
 		clusterName,
+		clusterType,
 		gimbalKubeClient,
 		reconciliationPeriod,
 		lbv2,

discovery/pkg/metrics/metrics.go

@@ -85,7 +85,7 @@ func NewMetrics() DiscovererMetrics {
 			Name: DiscovererAPILatencyMSGauge,
 			Help: "The milliseconds it takes for requests to return from a remote discoverer api",
 		},
-		[]string{"clustername", "clustertype"},
+		[]string{"clustername", "clustertype", "path"},
 	)
 
 	metrics[DiscovererCycleDurationMSGauge] = prometheus.NewGaugeVec(
@@ -172,3 +172,11 @@ func (d *DiscovererMetrics) CycleDurationMetric(clusterName, clusterType string,
 		m.WithLabelValues(clusterName, clusterType).Set(math.Floor(duration.Seconds() * 1e3))
 	}
 }
+
+// APILatencyMetric formats a cycle duration gauge prometheus metric
+func (d *DiscovererMetrics) APILatencyMetric(clusterName, clusterType, path string, duration time.Duration) {
+	m, ok := d.metrics[DiscovererAPILatencyMSGauge].(*prometheus.GaugeVec)
+	if ok {
+		m.WithLabelValues(clusterName, clusterType, path).Set(math.Floor(duration.Seconds() * 1e3))
+	}
+}

discovery/pkg/openstack/httplogger.go

@@ -0,0 +1,70 @@
+// Copyright © 2018 Heptio
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package openstack
+
+import (
+	"fmt"
+	"math"
+	"net/http"
+	"net/http/httptrace"
+	"time"
+
+	localmetrics "github.com/heptio/gimbal/discovery/pkg/metrics"
+	"github.com/sirupsen/logrus"
+)
+
+// LogRoundTripper satisfies the http.RoundTripper interface and is used to
+// customize the default Gophercloud RoundTripper to allow for logging.
+type LogRoundTripper struct {
+	RoundTripper      http.RoundTripper
+	numReauthAttempts int
+	Log               *logrus.Logger
+	Metrics           *localmetrics.DiscovererMetrics
+	ClusterName       string
+	ClusterType       string
+}
+
+// RoundTrip performs a round-trip HTTP request and logs relevant information about it.
+func (lrt *LogRoundTripper) RoundTrip(request *http.Request) (*http.Response, error) {
+	lrt.Log.Debugf("Request URL: %s", request.URL)
+
+	start := time.Now()
+	var latency time.Duration
+
+	trace := &httptrace.ClientTrace{
+		GotFirstResponseByte: func() {
+			latency = time.Now().Sub(start)
+			lrt.Log.Debug("-- API Latency: ", math.Floor(latency.Seconds()*1e3))
+		},
+	}
+	request = request.WithContext(httptrace.WithClientTrace(request.Context(), trace))
+
+	response, err := lrt.RoundTripper.RoundTrip(request)
+	if response == nil {
+		return nil, err
+	}
+
+	if response.StatusCode == http.StatusUnauthorized {
+		if lrt.numReauthAttempts == 3 {
+			return response, fmt.Errorf("Tried to re-authenticate 3 times with no success.")
+		}
+		lrt.numReauthAttempts++
+	}
+
+	lrt.Log.Debugf("-- Response Status: %s", response.Status)
+
+	lrt.Metrics.APILatencyMetric(lrt.ClusterName, lrt.ClusterType, request.URL.Path, latency)
+
+	return response, nil
+}

discovery/pkg/openstack/reconciler.go

@@ -29,8 +29,6 @@ import (
 	"k8s.io/client-go/kubernetes"
 )
 
-const clusterType = "openstack"
-
 type ProjectLister interface {
 	ListProjects() ([]projects.Project, error)
 }
@@ -50,6 +48,7 @@ type Reconciler struct {
 
 	// ClusterName is the name of the OpenStack cluster
 	ClusterName string
+	ClusterType string
 	// GimbalKubeClient is the client of the Kubernetes cluster where Gimbal is running
 	GimbalKubeClient kubernetes.Interface
 	// Interval between reconciliation loops
@@ -61,10 +60,11 @@ type Reconciler struct {
 }
 
 // NewReconciler returns an OpenStack reconciler
-func NewReconciler(clusterName string, gimbalKubeClient kubernetes.Interface, syncPeriod time.Duration, lbLister LoadBalancerLister,
+func NewReconciler(clusterName, clusterType string, gimbalKubeClient kubernetes.Interface, syncPeriod time.Duration, lbLister LoadBalancerLister,
 	projectLister ProjectLister, log *logrus.Logger, queueWorkers int, metrics localmetrics.DiscovererMetrics) Reconciler {
 	return Reconciler{
 		ClusterName:        clusterName,
+		ClusterType:        clusterType,
 		GimbalKubeClient:   gimbalKubeClient,
 		SyncPeriod:         syncPeriod,
 		LoadBalancerLister: lbLister,
@@ -155,7 +155,7 @@ func (r *Reconciler) reconcile() {
 	}
 
 	// Log to Prometheus the cycle duration
-	r.Metrics.CycleDurationMetric(r.ClusterName, clusterType, time.Now().Sub(start))
+	r.Metrics.CycleDurationMetric(r.ClusterName, r.ClusterType, time.Now().Sub(start))
 }
 
 func (r *Reconciler) reconcileSvcs(desiredSvcs, currentSvcs []v1.Service) {

docs/monitoring.md

@@ -94,6 +94,7 @@ The Gimbal Discoverer currently has two different systems it can monitor, Kubern
   - **gimbal_discoverer_api_latency_ms (gauge):** The milliseconds it takes for requests to return from a remote discoverer api (e.g. Openstack)
     - clustername
     - clustertype
+    - path: API request path
   - **gimbal_discoverer_cycle_duration_ms (gauge):** The milliseconds it takes for all objects to be synced from a remote discoverer api (e.g. Openstack)
     - clustername
     - clustertype