dataclients/kubernetes,routesrv: update logging (zalando#2781)

* dataclients/kubernetes: use trace level for non-essential messages
* routesrv: log route ids in debug level and route definitions in trace level

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

Author: AlexanderYastrebov

dataclients/kubernetes/clusterclient.go

@@ -254,7 +254,7 @@ func (c *clusterClient) createRequest(uri string, body io.Reader) (*http.Request
 }
 
 func (c *clusterClient) getJSON(uri string, a interface{}) error {
-	log.Debugf("making request to: %s", uri)
+	log.Tracef("making request to: %s", uri)
 
 	req, err := c.createRequest(uri, nil)
 	if err != nil {
@@ -263,31 +263,31 @@ func (c *clusterClient) getJSON(uri string, a interface{}) error {
 
 	rsp, err := c.httpClient.Do(req)
 	if err != nil {
-		log.Debugf("request to %s failed: %v", uri, err)
+		log.Tracef("request to %s failed: %v", uri, err)
 		return err
 	}
 
-	log.Debugf("request to %s succeeded", uri)
+	log.Tracef("request to %s succeeded", uri)
 	defer rsp.Body.Close()
 
 	if rsp.StatusCode == http.StatusNotFound {
 		return errResourceNotFound
 	}
 
 	if rsp.StatusCode != http.StatusOK {
-		log.Debugf("request failed, status: %d, %s", rsp.StatusCode, rsp.Status)
+		log.Tracef("request failed, status: %d, %s", rsp.StatusCode, rsp.Status)
 		return fmt.Errorf("request failed, status: %d, %s", rsp.StatusCode, rsp.Status)
 	}
 
 	b := bytes.NewBuffer(nil)
 	if _, err = io.Copy(b, rsp.Body); err != nil {
-		log.Debugf("reading response body failed: %v", err)
+		log.Tracef("reading response body failed: %v", err)
 		return err
 	}
 
 	err = json.Unmarshal(b.Bytes(), a)
 	if err != nil {
-		log.Debugf("invalid response format: %v", err)
+		log.Tracef("invalid response format: %v", err)
 	}
 
 	return err

dataclients/kubernetes/ingressv1.go

@@ -119,10 +119,9 @@ func convertPathRuleV1(
 		}
 
 		eps = state.GetEndpointsByService(ns, svcName, protocol, servicePort)
-		ic.logger.Debugf("Found %d endpoints for %s, %s", len(eps), svcName, servicePort)
 	}
 	if len(eps) == 0 {
-		ic.logger.Debugf("Target endpoints not found, shuntroute for %s:%s", svcName, svcPort)
+		ic.logger.Tracef("Target endpoints not found, shuntroute for %s:%s", svcName, svcPort)
 
 		r := &eskip.Route{
 			Id:          routeID(ns, name, host, prule.Path, svcName),
@@ -135,7 +134,7 @@ func convertPathRuleV1(
 		return r, nil
 	}
 
-	ic.logger.Debugf("%d routes for %s/%s", len(eps), svcName, svcPort)
+	ic.logger.Tracef("Found %d endpoints for %s:%s", len(eps), svcName, svcPort)
 	if len(eps) == 1 {
 		r := &eskip.Route{
 			Id:          routeID(ns, name, host, prule.Path, svcName),
@@ -364,7 +363,7 @@ func (ing *ingress) convertDefaultBackendV1(
 	}
 
 	if len(eps) == 0 {
-		ic.logger.Debugf("Target endpoints not found, shuntroute for %s:%s", svcName, svcPort)
+		ic.logger.Tracef("Target endpoints not found, shuntroute for %s:%s", svcName, svcPort)
 
 		r := &eskip.Route{
 			Id: routeID(ns, name, "", "", ""),

dataclients/kubernetes/logger.go

@@ -24,6 +24,12 @@ func newLogger(kind, namespace, name string, enabled bool) *logger {
 	return &logger{logger: log.WithFields(log.Fields{"kind": kind, "ns": namespace, "name": name})}
 }
 
+func (l *logger) Tracef(format string, args ...any) {
+	if l != nil {
+		l.once(log.TraceLevel, format, args...)
+	}
+}
+
 func (l *logger) Debugf(format string, args ...any) {
 	if l != nil {
 		l.once(log.DebugLevel, format, args...)

dataclients/kubernetes/routegroup.go

@@ -193,7 +193,7 @@ func applyServiceBackend(ctx *routeGroupContext, backend *definitions.SkipperBac
 	)
 
 	if len(eps) == 0 {
-		ctx.logger.Debugf("Target endpoints not found, shuntroute for %s:%d", backend.ServiceName, backend.ServicePort)
+		ctx.logger.Tracef("Target endpoints not found, shuntroute for %s:%d", backend.ServiceName, backend.ServicePort)
 
 		shuntRoute(r)
 		return nil

routesrv/polling.go

@@ -151,31 +151,28 @@ func mapRoutes(routes []*eskip.Route) map[string]string {
 }
 
 func logChanges(routesById map[string]string, lastRoutesById map[string]string) {
+	logf := func(op string, id string, format string, args ...any) {
+		level := log.GetLevel()
+		fields := log.Fields{"op": op, "id": id}
+		if level == log.TraceLevel {
+			fields["route"] = routesById[id]
+		}
+		log.WithFields(fields).Logf(level, format, args...)
+	}
+
 	inserted := notIn(routesById, lastRoutesById)
 	for i, id := range inserted {
-		log.WithFields(log.Fields{
-			"op":    "inserted",
-			"id":    id,
-			"route": routesById[id],
-		}).Debugf("Inserted route %d of %d", i+1, len(inserted))
+		logf("inserted", id, "Inserted route %d of %d", i+1, len(inserted))
 	}
 
 	deleted := notIn(lastRoutesById, routesById)
 	for i, id := range deleted {
-		log.WithFields(log.Fields{
-			"op":    "deleted",
-			"id":    id,
-			"route": lastRoutesById[id],
-		}).Debugf("Deleted route %d of %d", i+1, len(deleted))
+		logf("deleted", id, "Deleted route %d of %d", i+1, len(deleted))
 	}
 
 	updated := valueMismatch(routesById, lastRoutesById)
 	for i, id := range updated {
-		log.WithFields(log.Fields{
-			"op":    "updated",
-			"id":    id,
-			"route": routesById[id],
-		}).Debugf("Updated route %d of %d", i+1, len(updated))
+		logf("updated", id, "Updated route %d of %d", i+1, len(updated))
 	}
 }