From 64ce7dff1b38ecda027d67c8ba54d8290755afa0 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 11 Jun 2019 13:44:59 -0400 Subject: [PATCH 01/12] Changed time resolution for metrics collection Set the resolution of metrics data collection to be every 24 hours --- broker/metrics.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/broker/metrics.go b/broker/metrics.go index f961d1f..4ba762a 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -13,6 +13,8 @@ var ( once sync.Once ) +const metricsResolution = 24 * time.Hour + type CountryStats struct { counts map[string]int } @@ -94,7 +96,7 @@ func NewMetrics(metricsLogger *log.Logger) (*Metrics, error) { // Write to log file every hour with updated metrics go once.Do(func() { - heartbeat := time.Tick(time.Hour) + heartbeat := time.Tick(metricsResolution) for range heartbeat { metricsLogger.Println("Country stats: ", m.countryStats.Display()) From d57cd0759918d9f6c6734440acc58b24dc95766d Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 11 Jun 2019 14:16:01 -0400 Subject: [PATCH 02/12] Implemented count metrics for broker events Added three new metrics: - proxyIdleCount counts the number of times a proxy polls and receives no snowflakes - clientDeniedCount counts the number of times a client requested a snowflake but none were available - clientProxyMatchCount counts the number of times a client successfully received a snowflake --- broker/broker.go | 3 +++ broker/metrics.go | 40 ++++++++++++++++++++++++++-------------- 2 files changed, 29 insertions(+), 14 deletions(-) diff --git a/broker/broker.go b/broker/broker.go index 274d87c..971e3ad 100644 --- a/broker/broker.go +++ b/broker/broker.go @@ -153,6 +153,7 @@ func proxyPolls(ctx *BrokerContext, w http.ResponseWriter, r *http.Request) { offer := ctx.RequestOffer(id) if nil == offer { log.Println("Proxy " + id + " did not receive a Client offer.") + ctx.metrics.proxyIdleCount++ w.WriteHeader(http.StatusGatewayTimeout) return } @@ -176,6 +177,7 @@ func clientOffers(ctx *BrokerContext, w http.ResponseWriter, r *http.Request) { // Immediately fail if there are no snowflakes available. if ctx.snowflakes.Len() <= 0 { log.Println("Client: No snowflake proxies available.") + ctx.metrics.clientDeniedCount++ w.WriteHeader(http.StatusServiceUnavailable) return } @@ -189,6 +191,7 @@ func clientOffers(ctx *BrokerContext, w http.ResponseWriter, r *http.Request) { select { case answer := <-snowflake.answerChannel: log.Println("Client: Retrieving answer") + ctx.metrics.clientProxyMatchCount++ w.Write(answer) // Initial tracking of elapsed time. ctx.metrics.clientRoundtripEstimate = time.Since(startTime) / diff --git a/broker/metrics.go b/broker/metrics.go index 4ba762a..38cdc10 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -21,11 +21,15 @@ type CountryStats struct { // Implements Observable type Metrics struct { - tablev4 *GeoIPv4Table - tablev6 *GeoIPv6Table - countryStats CountryStats - // snowflakes timeseries.Float + logger *log.Logger + tablev4 *GeoIPv4Table + tablev6 *GeoIPv6Table + + countryStats CountryStats clientRoundtripEstimate time.Duration + proxyIdleCount int + clientDeniedCount int + clientProxyMatchCount int } func (s CountryStats) Display() string { @@ -94,17 +98,25 @@ func NewMetrics(metricsLogger *log.Logger) (*Metrics, error) { counts: make(map[string]int), } + m.logger = metricsLogger + // Write to log file every hour with updated metrics - go once.Do(func() { - heartbeat := time.Tick(metricsResolution) - for range heartbeat { - metricsLogger.Println("Country stats: ", m.countryStats.Display()) - - //restore all metrics to original values - m.countryStats.counts = make(map[string]int) - - } - }) + go once.Do(m.logMetrics) return m, nil } + +func (m *Metrics) logMetrics() { + + heartbeat := time.Tick(metricsResolution) + for range heartbeat { + m.logger.Println("snowflake-stats-end ") + m.logger.Println("snowflake-ips ", m.countryStats.Display()) + m.logger.Println("snowflake-idle-count ", m.proxyIdleCount) + m.logger.Println("client-denied-count ", m.clientDeniedCount) + m.logger.Println("client-snowflake-match-count ", m.clientProxyMatchCount) + + //restore all metrics to original values + m.countryStats.counts = make(map[string]int) + } +} From 0293674e38f5a3a389c92560412f9074307cb911 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 11 Jun 2019 14:19:14 -0400 Subject: [PATCH 03/12] Zero out counts for next time step --- broker/metrics.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/broker/metrics.go b/broker/metrics.go index 38cdc10..4159f70 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -117,6 +117,9 @@ func (m *Metrics) logMetrics() { m.logger.Println("client-snowflake-match-count ", m.clientProxyMatchCount) //restore all metrics to original values + m.proxyIdleCount = 0 + m.clientDeniedCount = 0 + m.clientProxyMatchCount = 0 m.countryStats.counts = make(map[string]int) } } From 175b8efb045f2ab89d3524c4e276b2ff7298c61c Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 11 Jun 2019 14:27:42 -0400 Subject: [PATCH 04/12] Bin metrics to nearest mult of 8 --- broker/metrics.go | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/broker/metrics.go b/broker/metrics.go index 4159f70..2c798ee 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -4,6 +4,7 @@ import ( // "golang.org/x/net/internal/timeseries" "fmt" "log" + "math" "net" "sync" "time" @@ -112,9 +113,9 @@ func (m *Metrics) logMetrics() { for range heartbeat { m.logger.Println("snowflake-stats-end ") m.logger.Println("snowflake-ips ", m.countryStats.Display()) - m.logger.Println("snowflake-idle-count ", m.proxyIdleCount) - m.logger.Println("client-denied-count ", m.clientDeniedCount) - m.logger.Println("client-snowflake-match-count ", m.clientProxyMatchCount) + m.logger.Println("snowflake-idle-count ", binCount(m.proxyIdleCount)) + m.logger.Println("client-denied-count ", binCount(m.clientDeniedCount)) + m.logger.Println("client-snowflake-match-count ", binCount(m.clientProxyMatchCount)) //restore all metrics to original values m.proxyIdleCount = 0 @@ -123,3 +124,8 @@ func (m *Metrics) logMetrics() { m.countryStats.counts = make(map[string]int) } } + +// Rounds up a count to the nearest multiple of 8. +func binCount(count int) int { + return int((math.Ceil(float64(count) / 8)) * 8) +} From c782ebdcea30aa0156921939ee99299381245cd7 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 11 Jun 2019 15:01:05 -0400 Subject: [PATCH 05/12] Format output to meet specification Output is now printed out in Tor Directory Protocol Format, as specified in https://trac.torproject.org/projects/tor/ticket/21315#comment:19. --- broker/broker.go | 2 +- broker/metrics.go | 18 +++++++++++------- 2 files changed, 12 insertions(+), 8 deletions(-) diff --git a/broker/broker.go b/broker/broker.go index 971e3ad..3795f2b 100644 --- a/broker/broker.go +++ b/broker/broker.go @@ -292,7 +292,7 @@ func main() { metricsFile = os.Stdout } - metricsLogger := log.New(metricsFile, "", log.LstdFlags|log.LUTC) + metricsLogger := log.New(metricsFile, "", 0) ctx := NewBrokerContext(metricsLogger) diff --git a/broker/metrics.go b/broker/metrics.go index 2c798ee..a7f077a 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -14,7 +14,7 @@ var ( once sync.Once ) -const metricsResolution = 24 * time.Hour +const metricsResolution = 86400 * time.Second type CountryStats struct { counts map[string]int @@ -34,7 +34,11 @@ type Metrics struct { } func (s CountryStats) Display() string { - return fmt.Sprint(s.counts) + output := "" + for cc, count := range s.counts { + output += fmt.Sprintf("%s=%d,", cc, count) + } + return output } func (m *Metrics) UpdateCountryStats(addr string) { @@ -111,11 +115,11 @@ func (m *Metrics) logMetrics() { heartbeat := time.Tick(metricsResolution) for range heartbeat { - m.logger.Println("snowflake-stats-end ") - m.logger.Println("snowflake-ips ", m.countryStats.Display()) - m.logger.Println("snowflake-idle-count ", binCount(m.proxyIdleCount)) - m.logger.Println("client-denied-count ", binCount(m.clientDeniedCount)) - m.logger.Println("client-snowflake-match-count ", binCount(m.clientProxyMatchCount)) + m.logger.Println("snowflake-stats-end", time.Now().UTC().Format("2006-01-02 15:04:05"), "(", int(metricsResolution.Seconds()), "s)") + m.logger.Println("snowflake-ips", m.countryStats.Display()) + m.logger.Println("snowflake-idle-count", binCount(m.proxyIdleCount)) + m.logger.Println("client-denied-count", binCount(m.clientDeniedCount)) + m.logger.Println("client-snowflake-match-count", binCount(m.clientProxyMatchCount)) //restore all metrics to original values m.proxyIdleCount = 0 From 25f059f4c4adf98a6ae9bdeae731e3f8ff3d609e Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 11 Jun 2019 15:43:59 -0400 Subject: [PATCH 06/12] Log geoip stats of proxies by unique IP Change it so that we log the geoip country code of proxies if they poll within the current metrics epoch. We make sure we log by unique IP address --- broker/broker.go | 18 +++++++++--------- broker/metrics.go | 10 ++++++++-- 2 files changed, 17 insertions(+), 11 deletions(-) diff --git a/broker/broker.go b/broker/broker.go index 3795f2b..26fc450 100644 --- a/broker/broker.go +++ b/broker/broker.go @@ -149,6 +149,15 @@ func proxyPolls(ctx *BrokerContext, w http.ResponseWriter, r *http.Request) { return } log.Println("Received snowflake: ", id) + + // Log geoip stats + remoteIP, _, err := net.SplitHostPort(r.RemoteAddr) + if err != nil { + log.Println("Error processing proxy IP: ", err.Error()) + } else { + ctx.metrics.UpdateCountryStats(remoteIP) + } + // Wait for a client to avail an offer to the snowflake, or timeout if nil. offer := ctx.RequestOffer(id) if nil == offer { @@ -224,15 +233,6 @@ func proxyAnswers(ctx *BrokerContext, w http.ResponseWriter, r *http.Request) { return } - // Get proxy country stats - remoteIP, _, err := net.SplitHostPort(r.RemoteAddr) - if err != nil { - log.Println("Error processing proxy IP: ", err.Error()) - } else { - - ctx.metrics.UpdateCountryStats(remoteIP) - } - log.Println("Received answer.") snowflake.answerChannel <- body } diff --git a/broker/metrics.go b/broker/metrics.go index a7f077a..b03c6db 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -17,6 +17,7 @@ var ( const metricsResolution = 86400 * time.Second type CountryStats struct { + ips map[string]bool counts map[string]int } @@ -65,8 +66,11 @@ func (m *Metrics) UpdateCountryStats(addr string) { log.Println("Unknown geoip") } - //update map of countries and counts - m.countryStats.counts[country]++ + //update map of unique ips and counts + if !m.countryStats.ips[addr] { + m.countryStats.counts[country]++ + m.countryStats.ips[addr] = true + } return } @@ -101,6 +105,7 @@ func NewMetrics(metricsLogger *log.Logger) (*Metrics, error) { m.countryStats = CountryStats{ counts: make(map[string]int), + ips: make(map[string]bool), } m.logger = metricsLogger @@ -126,6 +131,7 @@ func (m *Metrics) logMetrics() { m.clientDeniedCount = 0 m.clientProxyMatchCount = 0 m.countryStats.counts = make(map[string]int) + m.countryStats.ips = make(map[string]bool) } } From fe3356a54dccebe5d474d67068f817ef69f5c099 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Wed, 12 Jun 2019 10:14:21 -0400 Subject: [PATCH 07/12] Unit tests for metrics code Added unit tests for metrics logging. Refactored the logMetrics() function to allow for easier testing --- broker/metrics.go | 33 ++++---- broker/snowflake-broker_test.go | 129 ++++++++++++++++++++++++++++++++ 2 files changed, 149 insertions(+), 13 deletions(-) diff --git a/broker/metrics.go b/broker/metrics.go index b03c6db..5ac4192 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -116,25 +116,32 @@ func NewMetrics(metricsLogger *log.Logger) (*Metrics, error) { return m, nil } +// Logs metrics in intervals specified by metricsResolution func (m *Metrics) logMetrics() { - heartbeat := time.Tick(metricsResolution) for range heartbeat { - m.logger.Println("snowflake-stats-end", time.Now().UTC().Format("2006-01-02 15:04:05"), "(", int(metricsResolution.Seconds()), "s)") - m.logger.Println("snowflake-ips", m.countryStats.Display()) - m.logger.Println("snowflake-idle-count", binCount(m.proxyIdleCount)) - m.logger.Println("client-denied-count", binCount(m.clientDeniedCount)) - m.logger.Println("client-snowflake-match-count", binCount(m.clientProxyMatchCount)) - - //restore all metrics to original values - m.proxyIdleCount = 0 - m.clientDeniedCount = 0 - m.clientProxyMatchCount = 0 - m.countryStats.counts = make(map[string]int) - m.countryStats.ips = make(map[string]bool) + m.printMetrics() + m.zeroMetrics() } } +func (m *Metrics) printMetrics() { + m.logger.Println("snowflake-stats-end", time.Now().UTC().Format("2006-01-02 15:04:05"), "(", int(metricsResolution.Seconds()), "s)") + m.logger.Println("snowflake-ips", m.countryStats.Display()) + m.logger.Println("snowflake-idle-count", binCount(m.proxyIdleCount)) + m.logger.Println("client-denied-count", binCount(m.clientDeniedCount)) + m.logger.Println("client-snowflake-match-count", binCount(m.clientProxyMatchCount)) +} + +// Restores all metrics to original values +func (m *Metrics) zeroMetrics() { + m.proxyIdleCount = 0 + m.clientDeniedCount = 0 + m.clientProxyMatchCount = 0 + m.countryStats.counts = make(map[string]int) + m.countryStats.ips = make(map[string]bool) +} + // Rounds up a count to the nearest multiple of 8. func binCount(count int) int { return int((math.Ceil(float64(count) / 8)) * 8) diff --git a/broker/snowflake-broker_test.go b/broker/snowflake-broker_test.go index 03aa2b4..021122e 100644 --- a/broker/snowflake-broker_test.go +++ b/broker/snowflake-broker_test.go @@ -11,6 +11,7 @@ import ( "net/http/httptest" "os" "testing" + "time" ) func NullLogger() *log.Logger { @@ -390,3 +391,131 @@ func TestGeoip(t *testing.T) { }) } + +func TestMetrics(t *testing.T) { + + Convey("Test metrics...", t, func() { + done := make(chan bool) + buf := new(bytes.Buffer) + ctx := NewBrokerContext(log.New(buf, "", 0)) + + err := ctx.metrics.LoadGeoipDatabases("test_geoip", "test_geoip6") + So(err, ShouldEqual, nil) + + //Test addition of proxy polls + Convey("for proxy polls", func() { + w := httptest.NewRecorder() + data := bytes.NewReader([]byte("test")) + r, err := http.NewRequest("POST", "snowflake.broker/proxy", data) + r.Header.Set("X-Session-ID", "test") + r.RemoteAddr = "129.97.208.23:8888" //CA geoip + So(err, ShouldBeNil) + go func(ctx *BrokerContext) { + proxyPolls(ctx, w, r) + done <- true + }(ctx) + p := <-ctx.proxyPolls //manually unblock poll + p.offerChannel <- nil + <-done + + ctx.metrics.printMetrics() + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips CA=1,\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + }) + + //Test addition of client failures + Convey("for no proxies available", func() { + w := httptest.NewRecorder() + data := bytes.NewReader([]byte("test")) + r, err := http.NewRequest("POST", "snowflake.broker/client", data) + So(err, ShouldBeNil) + + clientOffers(ctx, w, r) + + ctx.metrics.printMetrics() + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") + + // Test reset + buf.Reset() + ctx.metrics.zeroMetrics() + ctx.metrics.printMetrics() + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + }) + //Test addition of client matches + Convey("for client-proxy match", func() { + w := httptest.NewRecorder() + data := bytes.NewReader([]byte("test")) + r, err := http.NewRequest("POST", "snowflake.broker/client", data) + So(err, ShouldBeNil) + + // Prepare a fake proxy to respond with. + snowflake := ctx.AddSnowflake("fake") + go func() { + clientOffers(ctx, w, r) + done <- true + }() + offer := <-snowflake.offerChannel + So(offer, ShouldResemble, []byte("test")) + snowflake.answerChannel <- []byte("fake answer") + <-done + + ctx.metrics.printMetrics() + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 8\n") + }) + //Test rounding boundary + Convey("binning boundary", func() { + w := httptest.NewRecorder() + data := bytes.NewReader([]byte("test")) + r, err := http.NewRequest("POST", "snowflake.broker/client", data) + So(err, ShouldBeNil) + + clientOffers(ctx, w, r) + clientOffers(ctx, w, r) + clientOffers(ctx, w, r) + clientOffers(ctx, w, r) + clientOffers(ctx, w, r) + clientOffers(ctx, w, r) + clientOffers(ctx, w, r) + clientOffers(ctx, w, r) + + ctx.metrics.printMetrics() + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") + + clientOffers(ctx, w, r) + buf.Reset() + ctx.metrics.printMetrics() + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 16\nclient-snowflake-match-count 0\n") + }) + + //Test unique ip + Convey("proxy counts by unique ip", func() { + w := httptest.NewRecorder() + data := bytes.NewReader([]byte("test")) + r, err := http.NewRequest("POST", "snowflake.broker/proxy", data) + r.Header.Set("X-Session-ID", "test") + r.RemoteAddr = "129.97.208.23:8888" //CA geoip + So(err, ShouldBeNil) + go func(ctx *BrokerContext) { + proxyPolls(ctx, w, r) + done <- true + }(ctx) + p := <-ctx.proxyPolls //manually unblock poll + p.offerChannel <- nil + <-done + + data = bytes.NewReader([]byte("test")) + r, err = http.NewRequest("POST", "snowflake.broker/proxy", data) + r.Header.Set("X-Session-ID", "test") + r.RemoteAddr = "129.97.208.23:8888" //CA geoip + go func(ctx *BrokerContext) { + proxyPolls(ctx, w, r) + done <- true + }(ctx) + p = <-ctx.proxyPolls //manually unblock poll + p.offerChannel <- nil + <-done + + ctx.metrics.printMetrics() + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips CA=1,\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + }) + }) +} From 92d61f2555cfafc738bca70c64c93edc1342d965 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Wed, 12 Jun 2019 10:17:55 -0400 Subject: [PATCH 08/12] Added a comment for the metrics specification --- broker/metrics.go | 35 +++++++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+) diff --git a/broker/metrics.go b/broker/metrics.go index 5ac4192..cca716f 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -1,3 +1,38 @@ +/* +We export metrics in the following format: + + "snowflake-stats-end" YYYY-MM-DD HH:MM:SS (NSEC s) NL + [At most once.] + + YYYY-MM-DD HH:MM:SS defines the end of the included measurement + interval of length NSEC seconds (86400 seconds by default). + + "snowflake-ips" CC=NUM,CC=NUM,... NL + [At most once.] + + List of mappings from two-letter country codes to the number of + unique IP addresses of snowflake proxies that have polled. + + "snowflake-idle-count" NUM NL + [At most once.] + + A count of the number of times a proxy has polled but received + no client offer, rounded up to the nearest multiple of 8. + + "client-denied-count" NUM NL + [At most once.] + + A count of the number of times a client has requested a proxy + from the broker but no proxies were available, rounded up to + the nearest multiple of 8. + + "client-snowflake-match-count" NUM NL + [At most once.] + + A count of the number of times a client successfully received a + proxy from the broker, rounded up to the nearest multiple of 8. +*/ + package main import ( From 0767a637c1f07dab71708762dd975adaa35b0bd9 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Fri, 14 Jun 2019 17:00:31 -0400 Subject: [PATCH 09/12] Changed variable names/types to be more reasonable Also moved the geoip check to occur after we've make sure the proxy IP hasn't yet been recorded. This is will cut down on unecessary computation. --- broker/metrics.go | 28 +++++++++++++++------------- 1 file changed, 15 insertions(+), 13 deletions(-) diff --git a/broker/metrics.go b/broker/metrics.go index cca716f..f37ec8a 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -49,10 +49,10 @@ var ( once sync.Once ) -const metricsResolution = 86400 * time.Second +const metricsResolution = 60 * 60 * 24 * time.Second //86400 seconds type CountryStats struct { - ips map[string]bool + addrs map[string]bool counts map[string]int } @@ -64,9 +64,9 @@ type Metrics struct { countryStats CountryStats clientRoundtripEstimate time.Duration - proxyIdleCount int - clientDeniedCount int - clientProxyMatchCount int + proxyIdleCount uint + clientDeniedCount uint + clientProxyMatchCount uint } func (s CountryStats) Display() string { @@ -82,6 +82,10 @@ func (m *Metrics) UpdateCountryStats(addr string) { var country string var ok bool + if m.countryStats.addrs[addr] { + return + } + ip := net.ParseIP(addr) if ip.To4() != nil { //This is an IPv4 address @@ -102,10 +106,8 @@ func (m *Metrics) UpdateCountryStats(addr string) { } //update map of unique ips and counts - if !m.countryStats.ips[addr] { - m.countryStats.counts[country]++ - m.countryStats.ips[addr] = true - } + m.countryStats.counts[country]++ + m.countryStats.addrs[addr] = true return } @@ -140,7 +142,7 @@ func NewMetrics(metricsLogger *log.Logger) (*Metrics, error) { m.countryStats = CountryStats{ counts: make(map[string]int), - ips: make(map[string]bool), + addrs: make(map[string]bool), } m.logger = metricsLogger @@ -174,10 +176,10 @@ func (m *Metrics) zeroMetrics() { m.clientDeniedCount = 0 m.clientProxyMatchCount = 0 m.countryStats.counts = make(map[string]int) - m.countryStats.ips = make(map[string]bool) + m.countryStats.addrs = make(map[string]bool) } // Rounds up a count to the nearest multiple of 8. -func binCount(count int) int { - return int((math.Ceil(float64(count) / 8)) * 8) +func binCount(count uint) uint { + return uint((math.Ceil(float64(count) / 8)) * 8) } From f779013b2d356cf67dda9d96145cbddd87497532 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Fri, 14 Jun 2019 17:09:06 -0400 Subject: [PATCH 10/12] Fixed small formatting errors of log output - removed trailing ","s - removed unecessary space before seconds --- broker/metrics.go | 8 +++++++- broker/snowflake-broker_test.go | 14 +++++++------- 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/broker/metrics.go b/broker/metrics.go index f37ec8a..a45179f 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -74,6 +74,12 @@ func (s CountryStats) Display() string { for cc, count := range s.counts { output += fmt.Sprintf("%s=%d,", cc, count) } + + // cut off trailing "," + if len(output) > 0 { + return output[:len(output)-1] + } + return output } @@ -163,7 +169,7 @@ func (m *Metrics) logMetrics() { } func (m *Metrics) printMetrics() { - m.logger.Println("snowflake-stats-end", time.Now().UTC().Format("2006-01-02 15:04:05"), "(", int(metricsResolution.Seconds()), "s)") + m.logger.Println("snowflake-stats-end", time.Now().UTC().Format("2006-01-02 15:04:05"), fmt.Sprintf("(%d s)", int(metricsResolution.Seconds()))) m.logger.Println("snowflake-ips", m.countryStats.Display()) m.logger.Println("snowflake-idle-count", binCount(m.proxyIdleCount)) m.logger.Println("client-denied-count", binCount(m.clientDeniedCount)) diff --git a/broker/snowflake-broker_test.go b/broker/snowflake-broker_test.go index 021122e..bbbad3d 100644 --- a/broker/snowflake-broker_test.go +++ b/broker/snowflake-broker_test.go @@ -419,7 +419,7 @@ func TestMetrics(t *testing.T) { <-done ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips CA=1,\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips CA=1\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") }) //Test addition of client failures @@ -432,13 +432,13 @@ func TestMetrics(t *testing.T) { clientOffers(ctx, w, r) ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") // Test reset buf.Reset() ctx.metrics.zeroMetrics() ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 0\n") }) //Test addition of client matches Convey("for client-proxy match", func() { @@ -459,7 +459,7 @@ func TestMetrics(t *testing.T) { <-done ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 8\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 8\n") }) //Test rounding boundary Convey("binning boundary", func() { @@ -478,12 +478,12 @@ func TestMetrics(t *testing.T) { clientOffers(ctx, w, r) ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") clientOffers(ctx, w, r) buf.Reset() ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 16\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 16\nclient-snowflake-match-count 0\n") }) //Test unique ip @@ -515,7 +515,7 @@ func TestMetrics(t *testing.T) { <-done ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" ( 86400 s)\nsnowflake-ips CA=1,\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips CA=1\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") }) }) } From 8f2dc3563b1922b285f406a48da85a5a94ee86f9 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 25 Jun 2019 09:33:45 -0400 Subject: [PATCH 11/12] Added a metric that sums available snowflakes Added another metrics item that counts the total availabel snowflakes (unique by IP address) --- broker/metrics.go | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/broker/metrics.go b/broker/metrics.go index a45179f..ffa61e2 100644 --- a/broker/metrics.go +++ b/broker/metrics.go @@ -13,6 +13,12 @@ We export metrics in the following format: List of mappings from two-letter country codes to the number of unique IP addresses of snowflake proxies that have polled. + "snowflake-ips-total" NUM NL + [At most once.] + + A count of the total number of unique IP addresses of snowflake + proxies that have polled. + "snowflake-idle-count" NUM NL [At most once.] @@ -171,6 +177,7 @@ func (m *Metrics) logMetrics() { func (m *Metrics) printMetrics() { m.logger.Println("snowflake-stats-end", time.Now().UTC().Format("2006-01-02 15:04:05"), fmt.Sprintf("(%d s)", int(metricsResolution.Seconds()))) m.logger.Println("snowflake-ips", m.countryStats.Display()) + m.logger.Println("snowflake-ips-total", len(m.countryStats.addrs)) m.logger.Println("snowflake-idle-count", binCount(m.proxyIdleCount)) m.logger.Println("client-denied-count", binCount(m.clientDeniedCount)) m.logger.Println("client-snowflake-match-count", binCount(m.clientProxyMatchCount)) From 908cf3fc6413930dacdf8a29b5834a5dcf5eab92 Mon Sep 17 00:00:00 2001 From: Cecylia Bocovich Date: Tue, 25 Jun 2019 10:06:00 -0400 Subject: [PATCH 12/12] Updated tests to check new stats Updated the tests to pass with our new snowflake-ips-total stat --- broker/snowflake-broker_test.go | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/broker/snowflake-broker_test.go b/broker/snowflake-broker_test.go index bbbad3d..5afbe33 100644 --- a/broker/snowflake-broker_test.go +++ b/broker/snowflake-broker_test.go @@ -419,7 +419,7 @@ func TestMetrics(t *testing.T) { <-done ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips CA=1\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips CA=1\nsnowflake-ips-total 1\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") }) //Test addition of client failures @@ -432,13 +432,13 @@ func TestMetrics(t *testing.T) { clientOffers(ctx, w, r) ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-ips-total 0\nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") // Test reset buf.Reset() ctx.metrics.zeroMetrics() ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-ips-total 0\nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 0\n") }) //Test addition of client matches Convey("for client-proxy match", func() { @@ -459,7 +459,7 @@ func TestMetrics(t *testing.T) { <-done ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 8\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-ips-total 0\nsnowflake-idle-count 0\nclient-denied-count 0\nclient-snowflake-match-count 8\n") }) //Test rounding boundary Convey("binning boundary", func() { @@ -478,12 +478,12 @@ func TestMetrics(t *testing.T) { clientOffers(ctx, w, r) ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-ips-total 0\nsnowflake-idle-count 0\nclient-denied-count 8\nclient-snowflake-match-count 0\n") clientOffers(ctx, w, r) buf.Reset() ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-idle-count 0\nclient-denied-count 16\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips \nsnowflake-ips-total 0\nsnowflake-idle-count 0\nclient-denied-count 16\nclient-snowflake-match-count 0\n") }) //Test unique ip @@ -515,7 +515,7 @@ func TestMetrics(t *testing.T) { <-done ctx.metrics.printMetrics() - So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips CA=1\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") + So(buf.String(), ShouldResemble, "snowflake-stats-end "+time.Now().UTC().Format("2006-01-02 15:04:05")+" (86400 s)\nsnowflake-ips CA=1\nsnowflake-ips-total 1\nsnowflake-idle-count 8\nclient-denied-count 0\nclient-snowflake-match-count 0\n") }) }) }