Merge pull request stripe#181 from stripe/ransford-dns-query-time-metric

Add timing metric for DNS resolution

pkg/smokescreen/metrics/metrics.go

@@ -39,6 +39,7 @@ var metrics = []string{
 	"resolver.deny.not_global_unicast",
 	"resolver.deny.private_range",
 	"resolver.deny.user_configured",
+	"resolver.lookup_time", // DNS lookup time in ms, not tagged
 	"resolver.errors_total",
 }
 

pkg/smokescreen/smokescreen.go

@@ -216,11 +216,15 @@ func resolveTCPAddr(config *Config, network, addr string) (*net.TCPAddr, error)
 
 func safeResolve(config *Config, network, addr string) (*net.TCPAddr, string, error) {
 	config.MetricsClient.Incr("resolver.attempts_total", 1)
+
+	resolveStart := time.Now()
 	resolved, err := resolveTCPAddr(config, network, addr)
+	resolveDuration := time.Since(resolveStart)
 	if err != nil {
 		config.MetricsClient.Incr("resolver.errors_total", 1)
 		return nil, "", err
 	}
+	config.MetricsClient.Timing("resolver.lookup_time", resolveDuration, 0.5)
 
 	classification := classifyAddr(config, resolved)
 	config.MetricsClient.Incr(classification.statsdString(), 1)

pkg/smokescreen/smokescreen_test.go

@@ -559,8 +559,22 @@ func TestProxyProtocols(t *testing.T) {
 			client.Do(req)
 			clientCh <- true
 		}()
-
 		<-clientCh
+
+		// Metrics should show one successful connection and a corresponding successful
+		// DNS request along with its timing metric.
+		tmc, ok := cfg.MetricsClient.(*metrics.MockMetricsClient)
+		r.True(ok)
+		i, err := tmc.GetCount("cn.atpt.total", "success:true")
+		r.NoError(err)
+		r.Equal(i, uint64(1))
+		lookups, err := tmc.GetCount("resolver.attempts_total")
+		r.NoError(err)
+		r.Equal(lookups, uint64(1))
+		ltime, err := tmc.GetCount("resolver.lookup_time")
+		r.NoError(err)
+		r.Equal(ltime, uint64(1))
+
 		entry := findCanonicalProxyDecision(logHook.AllEntries())
 		r.NotNil(entry)
 
@@ -611,6 +625,20 @@ func TestProxyProtocols(t *testing.T) {
 		serverCh <- true
 		<-clientCh
 
+		// Metrics should show one successful connection and a corresponding successful
+		// DNS request along with its timing metric.
+		tmc, ok := cfg.MetricsClient.(*metrics.MockMetricsClient)
+		r.True(ok)
+		i, err := tmc.GetCount("cn.atpt.total", "success:true")
+		r.NoError(err)
+		r.Equal(i, uint64(1))
+		lookups, err := tmc.GetCount("resolver.attempts_total")
+		r.NoError(err)
+		r.Equal(lookups, uint64(1))
+		ltime, err := tmc.GetCount("resolver.lookup_time")
+		r.NoError(err)
+		r.Equal(ltime, uint64(1))
+
 		entry := findCanonicalProxyDecision(logHook.AllEntries())
 		r.NotNil(entry)
 		r.Contains(entry.Data, "proxy_type")