diff --git a/pkg/smokescreen/metrics/metrics.go b/pkg/smokescreen/metrics/metrics.go index f3f9ac23..562269ef 100644 --- a/pkg/smokescreen/metrics/metrics.go +++ b/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", } diff --git a/pkg/smokescreen/smokescreen.go b/pkg/smokescreen/smokescreen.go index 8da0903a..fbda0e5d 100644 --- a/pkg/smokescreen/smokescreen.go +++ b/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) diff --git a/pkg/smokescreen/smokescreen_test.go b/pkg/smokescreen/smokescreen_test.go index 67ccd43f..0207dddc 100644 --- a/pkg/smokescreen/smokescreen_test.go +++ b/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")