Skip to content

Commit

Permalink
dataclients/kubernetes: improve logging (#2637)
Browse files Browse the repository at this point in the history
* log number of received routegroups
* log distinct messages once per ingress/routegroup
* log number or all routes loaded and mapped

Signed-off-by: Alexander Yastrebov <[email protected]>
  • Loading branch information
AlexanderYastrebov authored Oct 2, 2023
1 parent 6e304f6 commit 6b332ac
Show file tree
Hide file tree
Showing 7 changed files with 182 additions and 82 deletions.
19 changes: 11 additions & 8 deletions dataclients/kubernetes/clusterclient.go
Original file line number Diff line number Diff line change
Expand Up @@ -362,11 +362,13 @@ func (c *clusterClient) loadIngressesV1() ([]*definitions.IngressV1Item, error)
log.Debugf("requesting all ingresses failed: %v", err)
return nil, err
}

log.Debugf("all ingresses received: %d", len(il.Items))

fItems := c.filterIngressesV1ByClass(il.Items)
log.Debugf("filtered ingresses by ingress class: %d", len(fItems))

sortByMetadata(fItems, func(i int) *definitions.Metadata { return fItems[i].Metadata })

return fItems, nil
}

Expand All @@ -375,6 +377,7 @@ func (c *clusterClient) LoadRouteGroups() ([]*definitions.RouteGroupItem, error)
if err := c.getJSON(c.routeGroupsURI+c.routeGroupsLabelSelectors, &rgl); err != nil {
return nil, err
}
log.Debugf("all routegroups received: %d", len(rgl.Items))

rgs := make([]*definitions.RouteGroupItem, 0, len(rgl.Items))
for _, i := range rgl.Items {
Expand All @@ -396,19 +399,21 @@ func (c *clusterClient) LoadRouteGroups() ([]*definitions.RouteGroupItem, error)
rgs = append(rgs, i)
}

log.Debugf("filtered valid routegroups by routegroups class: %d", len(rgs))

sortByMetadata(rgs, func(i int) *definitions.Metadata { return rgs[i].Metadata })

return rgs, nil
}

func (c *clusterClient) loadServices() (map[definitions.ResourceID]*service, error) {
var services serviceList

if err := c.getJSON(c.servicesURI+c.servicesLabelSelectors, &services); err != nil {
log.Debugf("requesting all services failed: %v", err)
return nil, err
}

log.Debugf("all services received: %d", len(services.Items))

result := make(map[definitions.ResourceID]*service)
var hasInvalidService bool
for _, service := range services.Items {
Expand All @@ -429,13 +434,12 @@ func (c *clusterClient) loadServices() (map[definitions.ResourceID]*service, err

func (c *clusterClient) loadSecrets() (map[definitions.ResourceID]*secret, error) {
var secrets secretList

if err := c.getJSON(c.secretsURI+c.secretsLabelSelectors, &secrets); err != nil {
log.Debugf("requesting all secrets failed: %v", err)
return nil, err
}

log.Debugf("all secrets received: %d", len(secrets.Items))

result := make(map[definitions.ResourceID]*secret)
for _, secret := range secrets.Items {
if secret == nil || secret.Metadata == nil {
Expand All @@ -454,8 +458,8 @@ func (c *clusterClient) loadEndpoints() (map[definitions.ResourceID]*endpoint, e
log.Debugf("requesting all endpoints failed: %v", err)
return nil, err
}

log.Debugf("all endpoints received: %d", len(endpoints.Items))

result := make(map[definitions.ResourceID]*endpoint)
for _, endpoint := range endpoints.Items {
resID := endpoint.Meta.ToResourceID()
Expand All @@ -476,13 +480,12 @@ func (c *clusterClient) loadEndpoints() (map[definitions.ResourceID]*endpoint, e
// given service, check endpointSlice.ToResourceID().
func (c *clusterClient) loadEndpointSlices() (map[definitions.ResourceID]*skipperEndpointSlice, error) {
var endpointSlices endpointSliceList

if err := c.getJSON(c.endpointSlicesURI+c.endpointSlicesLabelSelectors, &endpointSlices); err != nil {
log.Debugf("requesting all endpointslices failed: %v", err)
return nil, err
}

log.Debugf("all endpointslices received: %d", len(endpointSlices.Items))

mapSlices := make(map[definitions.ResourceID][]*endpointSlice)
for _, endpointSlice := range endpointSlices.Items {
resID := endpointSlice.ToResourceID() // service resource ID
Expand Down
63 changes: 63 additions & 0 deletions dataclients/kubernetes/clusterclient_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,8 +6,11 @@ import (
"os"
"strings"
"testing"
"time"

log "github.com/sirupsen/logrus"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"

"github.com/zalando/skipper/dataclients/kubernetes"
"github.com/zalando/skipper/dataclients/kubernetes/kubernetestest"
Expand Down Expand Up @@ -251,3 +254,63 @@ spec:
})
}
}

func TestLoggingInterval(t *testing.T) {
// TODO: with validation changes we need to update/refactor this test
manifest, err := os.Open("testdata/routegroups/convert/missing-service.yaml")
require.NoError(t, err)
defer manifest.Close()

var out bytes.Buffer
log.SetOutput(&out)
defer log.SetOutput(os.Stderr)

countMessages := func() int {
return strings.Count(out.String(), "Error transforming external hosts")
}

a, err := kubernetestest.NewAPI(kubernetestest.TestAPIOptions{}, manifest)
require.NoError(t, err)

s := httptest.NewServer(a)
defer s.Close()

c, err := kubernetes.New(kubernetes.Options{KubernetesURL: s.URL})
require.NoError(t, err)
defer c.Close()

const loggingInterval = 100 * time.Millisecond
c.SetLoggingInterval(loggingInterval)

_, err = c.LoadAll()
require.NoError(t, err)

assert.Equal(t, 1, countMessages(), "one message expected after initial load")

const (
n = 2
updateDuration = time.Duration(n)*loggingInterval + loggingInterval/2
)

start := time.Now()
for time.Since(start) < updateDuration {
_, _, err := c.LoadUpdate()
require.NoError(t, err)

time.Sleep(loggingInterval / 10)
}

assert.Equal(t, 1+n, countMessages(), "%d additional messages expected", n)

oldLevel := log.GetLevel()
defer log.SetLevel(oldLevel)

log.SetLevel(log.DebugLevel)

for i := 1; i <= 10; i++ {
_, _, err := c.LoadUpdate()
require.NoError(t, err)

assert.Equal(t, 1+n+i, countMessages(), "a new message expected for each subsequent update when log level is debug")
}
}
8 changes: 4 additions & 4 deletions dataclients/kubernetes/ingressv1.go
Original file line number Diff line number Diff line change
Expand Up @@ -122,8 +122,8 @@ func convertPathRuleV1(
ic.logger.Debugf("Found %d endpoints for %s, %s", len(eps), svcName, servicePort)
}
if len(eps) == 0 {
// add shunt route https://github.com/zalando/skipper/issues/1525
ic.logger.Debugf("Adding shuntroute to return 502 for service %s with %d endpoints", svcName, len(eps))
ic.logger.Debugf("Target endpoints not found, shuntroute for %s:%s", svcName, svcPort)

r := &eskip.Route{
Id: routeID(ns, name, host, prule.Path, svcName),
HostRegexps: hostRegexp,
Expand Down Expand Up @@ -364,8 +364,8 @@ func (ing *ingress) convertDefaultBackendV1(
}

if len(eps) == 0 {
// add shunt route https://github.com/zalando/skipper/issues/1525
ic.logger.Debugf("Adding shuntroute to return 502 for service %s with %d endpoints", svcName, len(eps))
ic.logger.Debugf("Target endpoints not found, shuntroute for %s:%s", svcName, svcPort)

r := &eskip.Route{
Id: routeID(ns, name, "", "", ""),
}
Expand Down
4 changes: 3 additions & 1 deletion dataclients/kubernetes/kube.go
Original file line number Diff line number Diff line change
Expand Up @@ -437,6 +437,8 @@ func (c *Client) loadAndConvert() ([]*eskip.Route, error) {
return r, nil
}

// shuntRoute creates a route that returns a 502 status code when there are no endpoints found,
// see https://github.com/zalando/skipper/issues/1525
func shuntRoute(r *eskip.Route) {
r.Filters = []*eskip.Filter{
{
Expand Down Expand Up @@ -499,7 +501,7 @@ func (c *Client) LoadAll() ([]*eskip.Route, error) {

c.current, r = mapRoutes(r)

log.Debugf("all routes loaded and mapped")
log.Debugf("all routes loaded and mapped: %d", len(r))

return r, nil
}
Expand Down
40 changes: 35 additions & 5 deletions dataclients/kubernetes/logger.go
Original file line number Diff line number Diff line change
@@ -1,32 +1,62 @@
package kubernetes

import log "github.com/sirupsen/logrus"
import (
"fmt"
"sync"

log "github.com/sirupsen/logrus"
)

type logger struct {
logger *log.Entry

mu sync.Mutex
history map[string]struct{}
}

// newLogger creates a logger that logs each unique message once
// for the resource identified by kind, namespace and name.
// It logs nothing when disabled.
func newLogger(kind, namespace, name string, enabled bool) *logger {
if !enabled {
return nil
}
return &logger{log.WithFields(log.Fields{"kind": kind, "ns": namespace, "name": name})}
return &logger{logger: log.WithFields(log.Fields{"kind": kind, "ns": namespace, "name": name})}
}

func (l *logger) Debugf(format string, args ...any) {
if l != nil {
l.logger.Debugf(format, args...)
l.once(log.DebugLevel, format, args...)
}
}

func (l *logger) Infof(format string, args ...any) {
if l != nil {
l.logger.Infof(format, args...)
l.once(log.InfoLevel, format, args...)
}
}

func (l *logger) Errorf(format string, args ...any) {
if l != nil {
l.logger.Errorf(format, args...)
l.once(log.ErrorLevel, format, args...)
}
}

func (l *logger) once(level log.Level, format string, args ...any) {
if !l.logger.Logger.IsLevelEnabled(level) {
return
}
l.mu.Lock()
defer l.mu.Unlock()

if l.history == nil {
l.history = make(map[string]struct{})
}

msg := fmt.Sprintf(format, args...)
key := fmt.Sprintf("%s %s", level, msg)
if _, ok := l.history[key]; !ok {
l.logger.Log(level, msg)
l.history[key] = struct{}{}
}
}
Loading

0 comments on commit 6b332ac

Please sign in to comment.