routesrv: log route updates only when changed (#2526)

* log and change route update metric only when routes changed
* speedup tests from 20s to 2.5s by reducing poll interval

Signed-off-by: Alexander Yastrebov <[email protected]>

routesrv/eskipbytes.go

@@ -30,26 +30,27 @@ type eskipBytes struct {
 }
 
 // formatAndSet takes a slice of routes and stores them eskip-formatted
-// in a synchronized way. It returns a number of stored bytes and a boolean,
-// being true, when the stored bytes were set for the first time.
-func (e *eskipBytes) formatAndSet(routes []*eskip.Route) (int, bool) {
+// in a synchronized way. It returns the length of the stored data, and
+// flags signaling whether the data was initialized and updated.
+func (e *eskipBytes) formatAndSet(routes []*eskip.Route) (_ int, initialized bool, updated bool) {
 	buf := &bytes.Buffer{}
 	eskip.Fprint(buf, eskip.PrettyPrintInfo{Pretty: false, IndentStr: ""}, routes...)
+	data := buf.Bytes()
 
 	e.mu.Lock()
 	defer e.mu.Unlock()
-	if updated := buf.Bytes(); !bytes.Equal(e.data, updated) {
+
+	updated = !bytes.Equal(e.data, data)
+	if updated {
 		e.lastModified = time.Now()
-		e.data = updated
-		h := sha256.New()
-		h.Write(e.data)
-		e.etag = fmt.Sprintf(`"%x"`, h.Sum(nil))
+		e.data = data
+		e.etag = fmt.Sprintf(`"%x"`, sha256.Sum256(e.data))
+		e.count = len(routes)
 	}
-	oldInitialized := e.initialized
+	initialized = !e.initialized
 	e.initialized = true
-	e.count = len(routes)
 
-	return len(e.data), !oldInitialized
+	return len(e.data), initialized, updated
 }
 
 func (e *eskipBytes) ServeHTTP(w http.ResponseWriter, r *http.Request) {

routesrv/polling.go

@@ -63,12 +63,6 @@ type poller struct {
 func (p *poller) poll(wg *sync.WaitGroup) {
 	defer wg.Done()
 
-	var (
-		routesCount, routesBytes int
-		initialized              bool
-		msg                      string
-	)
-
 	log.WithField("timeout", p.timeout).Info(LogPollingStarted)
 	ticker := time.NewTicker(p.timeout)
 	defer ticker.Stop()
@@ -81,7 +75,7 @@ func (p *poller) poll(wg *sync.WaitGroup) {
 
 		routes = p.process(routes)
 
-		routesCount = len(routes)
+		routesCount := len(routes)
 
 		switch {
 		case err != nil:
@@ -98,19 +92,20 @@ func (p *poller) poll(wg *sync.WaitGroup) {
 			span.SetTag("error", true)
 			span.LogKV(
 				"event", "error",
-				"message", msg,
+				"message", LogRoutesEmpty,
 			)
 		case routesCount > 0:
-			routesBytes, initialized = p.b.formatAndSet(routes)
+			routesBytes, initialized, updated := p.b.formatAndSet(routes)
 			logger := log.WithFields(log.Fields{"count": routesCount, "bytes": routesBytes})
 			if initialized {
 				logger.Info(LogRoutesInitialized)
 				span.SetTag("routes.initialized", true)
 				routesInitialized.SetToCurrentTime()
-			} else {
+			}
+			if updated {
 				logger.Info(LogRoutesUpdated)
+				routesUpdated.SetToCurrentTime()
 			}
-			routesUpdated.SetToCurrentTime()
 			span.SetTag("routes.count", routesCount)
 			span.SetTag("routes.bytes", routesBytes)
 		}

routesrv/routesrv_test.go

@@ -147,8 +147,8 @@ func wantHTTPCode(t *testing.T, w *httptest.ResponseRecorder, want int) {
 }
 
 const (
-	pollInterval = 3 * time.Second
-	waitTimeout  = 5 * time.Second
+	pollInterval = 100 * time.Millisecond
+	waitTimeout  = 1 * time.Second
 )
 
 var tl *loggingtest.Logger
@@ -303,7 +303,7 @@ func TestRoutesAreUpdated(t *testing.T) {
 	w1 := getRoutes(rs)
 
 	handler.set(newKubeAPI(t, loadKubeYAML(t, "testdata/lb-target-single.yaml")))
-	if err := tl.WaitForN(routesrv.LogRoutesUpdated, 2, waitTimeout*2); err != nil {
+	if err := tl.WaitForN(routesrv.LogRoutesUpdated, 2, waitTimeout); err != nil {
 		t.Error("routes not updated")
 	}
 	w2 := getRoutes(rs)
@@ -459,7 +459,7 @@ func TestESkipBytesHandlerWithStaleEtag(t *testing.T) {
 
 	// update the routes, which also updates e.etag
 	handler.set(newKubeAPI(t, loadKubeYAML(t, "testdata/lb-target-single.yaml")))
-	if err := tl.WaitForN(routesrv.LogRoutesUpdated, 2, waitTimeout*2); err != nil {
+	if err := tl.WaitForN(routesrv.LogRoutesUpdated, 2, waitTimeout); err != nil {
 		t.Error("routes not updated")
 	}
 
@@ -512,9 +512,13 @@ func TestESkipBytesHandlerWithOldLastModified(t *testing.T) {
 	w1 := getRoutes(rs)
 	lastModified := w1.Header().Get("Last-Modified")
 	header := map[string]string{"If-Modified-Since": lastModified}
+
+	// Last-Modified has a second precision so we need to wait a bit for it to change
+	time.Sleep(2 * time.Second)
+
 	// update the routes, which also updated the e.lastModified
 	handler.set(newKubeAPI(t, loadKubeYAML(t, "testdata/lb-target-single.yaml")))
-	if err := tl.WaitForN(routesrv.LogRoutesUpdated, 2, waitTimeout*2); err != nil {
+	if err := tl.WaitForN(routesrv.LogRoutesUpdated, 2, waitTimeout); err != nil {
 		t.Error("routes not updated")
 	}