diff --git a/pkg/datagatherer/k8s/cache.go b/pkg/datagatherer/k8s/cache.go index f40c3c09..e64f13c5 100644 --- a/pkg/datagatherer/k8s/cache.go +++ b/pkg/datagatherer/k8s/cache.go @@ -1,13 +1,14 @@ package k8s import ( + "fmt" "time" + "github.com/go-logr/logr" "github.com/pmylund/go-cache" "k8s.io/apimachinery/pkg/types" "github.com/jetstack/preflight/api" - "github.com/jetstack/preflight/pkg/logs" ) // time interface, this is used to fetch the current time @@ -30,9 +31,17 @@ type cacheResource interface { GetNamespace() string } +func logCacheUpdateFailure(log logr.Logger, obj interface{}, operation string) { + // We use WithCallStackHelper to ensure the correct caller line numbers in the log messages + helper, log := log.WithCallStackHelper() + helper() + err := fmt.Errorf("not a cacheResource type: %T missing metadata/uid field", obj) + log.Error(err, "Cache update failure", "operation", operation) +} + // onAdd handles the informer creation events, adding the created runtime.Object // to the data gatherer's cache. The cache key is the uid of the object -func onAdd(obj interface{}, dgCache *cache.Cache) { +func onAdd(log logr.Logger, obj interface{}, dgCache *cache.Cache) { item, ok := obj.(cacheResource) if ok { cacheObject := &api.GatheredResource{ @@ -41,28 +50,26 @@ func onAdd(obj interface{}, dgCache *cache.Cache) { dgCache.Set(string(item.GetUID()), cacheObject, cache.DefaultExpiration) return } - logs.Log.Printf("could not %q resource to the cache, missing metadata/uid field", "add") - + logCacheUpdateFailure(log, obj, "add") } // onUpdate handles the informer update events, replacing the old object with the new one // if it's present in the data gatherer's cache, (if the object isn't present, it gets added). // The cache key is the uid of the object -func onUpdate(old, new interface{}, dgCache *cache.Cache) { +func onUpdate(log logr.Logger, old, new interface{}, dgCache *cache.Cache) { item, ok := old.(cacheResource) if ok { cacheObject := updateCacheGatheredResource(string(item.GetUID()), new, dgCache) dgCache.Set(string(item.GetUID()), cacheObject, cache.DefaultExpiration) return } - - logs.Log.Printf("could not %q resource to the cache, missing metadata/uid field", "update") + logCacheUpdateFailure(log, old, "update") } // onDelete handles the informer deletion events, updating the object's properties with the deletion // time of the object (but not removing the object from the cache). // The cache key is the uid of the object -func onDelete(obj interface{}, dgCache *cache.Cache) { +func onDelete(log logr.Logger, obj interface{}, dgCache *cache.Cache) { item, ok := obj.(cacheResource) if ok { cacheObject := updateCacheGatheredResource(string(item.GetUID()), obj, dgCache) @@ -70,7 +77,7 @@ func onDelete(obj interface{}, dgCache *cache.Cache) { dgCache.Set(string(item.GetUID()), cacheObject, cache.DefaultExpiration) return } - logs.Log.Printf("could not %q resource to the cache, missing metadata/uid field", "delete") + logCacheUpdateFailure(log, obj, "delete") } // creates a new updated instance of a cache object, with the resource diff --git a/pkg/datagatherer/k8s/cache_test.go b/pkg/datagatherer/k8s/cache_test.go index 80ab6a9e..a8616b89 100644 --- a/pkg/datagatherer/k8s/cache_test.go +++ b/pkg/datagatherer/k8s/cache_test.go @@ -6,8 +6,10 @@ import ( "time" "github.com/d4l3k/messagediff" + "github.com/go-logr/logr" "github.com/pmylund/go-cache" "k8s.io/apimachinery/pkg/runtime" + "k8s.io/klog/v2/ktesting" "github.com/jetstack/preflight/api" ) @@ -23,7 +25,7 @@ func TestOnAddCache(t *testing.T) { tcs := map[string]struct { inputObjects []runtime.Object eventObjects []runtime.Object - eventFunc func(old, obj interface{}, dgCache *cache.Cache) + eventFunc func(log logr.Logger, old, obj interface{}, dgCache *cache.Cache) expected []*api.GatheredResource }{ "add all objects": { @@ -50,7 +52,7 @@ func TestOnAddCache(t *testing.T) { getObject("v1", "Service", "testservice", "testns", false), getObject("foobar/v1", "NotFoo", "notfoo", "testns", false), }, - eventFunc: func(old, new interface{}, dgCache *cache.Cache) { onDelete(old, dgCache) }, + eventFunc: func(log logr.Logger, old, new interface{}, dgCache *cache.Cache) { onDelete(log, old, dgCache) }, expected: []*api.GatheredResource{ makeGatheredResource( getObject("foobar/v1", "Foo", "testfoo", "testns", false), @@ -98,16 +100,17 @@ func TestOnAddCache(t *testing.T) { for name, tc := range tcs { t.Run(name, func(t *testing.T) { + log := ktesting.NewLogger(t, ktesting.NewConfig(ktesting.Verbosity(10))) dgCache := cache.New(5*time.Minute, 30*time.Second) // adding initial objetcs to the cache for _, obj := range tc.inputObjects { - onAdd(obj, dgCache) + onAdd(log, obj, dgCache) } // Testing event founction on set of objects for _, obj := range tc.eventObjects { if tc.eventFunc != nil { - tc.eventFunc(obj, obj, dgCache) + tc.eventFunc(log, obj, obj, dgCache) } } @@ -136,3 +139,14 @@ func TestOnAddCache(t *testing.T) { }) } } + +// TestNoneCache demonstrates that the cache helpers do not crash if passed a +// non-cachable object, but log an error with a reference to the object type. +func TestNoneCache(t *testing.T) { + log := ktesting.NewLogger(t, ktesting.NewConfig(ktesting.Verbosity(10))) + + type notCachable struct{} + onAdd(log, ¬Cachable{}, nil) + onUpdate(log, ¬Cachable{}, nil, nil) + onDelete(log, ¬Cachable{}, nil) +} diff --git a/pkg/datagatherer/k8s/dynamic.go b/pkg/datagatherer/k8s/dynamic.go index d24b0629..e80dc75d 100644 --- a/pkg/datagatherer/k8s/dynamic.go +++ b/pkg/datagatherer/k8s/dynamic.go @@ -23,10 +23,10 @@ import ( "k8s.io/client-go/kubernetes" "k8s.io/client-go/kubernetes/scheme" k8scache "k8s.io/client-go/tools/cache" + "k8s.io/klog/v2" "github.com/jetstack/preflight/api" "github.com/jetstack/preflight/pkg/datagatherer" - "github.com/jetstack/preflight/pkg/logs" ) // ConfigDynamic contains the configuration for the data-gatherer. @@ -161,6 +161,7 @@ func (c *ConfigDynamic) NewDataGatherer(ctx context.Context) (datagatherer.DataG } func (c *ConfigDynamic) newDataGathererWithClient(ctx context.Context, cl dynamic.Interface, clientset kubernetes.Interface) (datagatherer.DataGatherer, error) { + log := klog.FromContext(ctx) if err := c.validate(); err != nil { return nil, err } @@ -216,13 +217,13 @@ func (c *ConfigDynamic) newDataGathererWithClient(ctx context.Context, cl dynami registration, err := newDataGatherer.informer.AddEventHandler(k8scache.ResourceEventHandlerFuncs{ AddFunc: func(obj interface{}) { - onAdd(obj, dgCache) + onAdd(log, obj, dgCache) }, UpdateFunc: func(old, new interface{}) { - onUpdate(old, new, dgCache) + onUpdate(log, old, new, dgCache) }, DeleteFunc: func(obj interface{}) { - onDelete(obj, dgCache) + onDelete(log, obj, dgCache) }, }) if err != nil { @@ -264,6 +265,7 @@ type DataGathererDynamic struct { // Returns error if the data gatherer informer wasn't initialized, Run blocks // until the stopCh is closed. func (g *DataGathererDynamic) Run(stopCh <-chan struct{}) error { + log := klog.FromContext(g.ctx) if g.informer == nil { return fmt.Errorf("informer was not initialized, impossible to start") } @@ -271,9 +273,9 @@ func (g *DataGathererDynamic) Run(stopCh <-chan struct{}) error { // attach WatchErrorHandler, it needs to be set before starting an informer err := g.informer.SetWatchErrorHandler(func(r *k8scache.Reflector, err error) { if strings.Contains(fmt.Sprintf("%s", err), "the server could not find the requested resource") { - logs.Log.Printf("server missing resource for datagatherer of %q ", g.groupVersionResource) + log.Info("server missing resource for datagatherer", "groupVersionResource", g.groupVersionResource) } else { - logs.Log.Printf("datagatherer informer for %q has failed and is backing off due to error: %s", g.groupVersionResource, err) + log.Info("datagatherer informer has failed and is backing off", "groupVersionResource", g.groupVersionResource, "reason", err) } }) if err != nil { diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index b8ffd71f..35366ab4 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -34,12 +34,6 @@ import ( // upon which this code was based. var ( - // This is the Agent's logger. For now, it is still a *log.Logger, but we - // mean to migrate everything to slog with the klog backend. We avoid using - // log.Default because log.Default is already used by the VCert library, and - // we need to keep the agent's logger from the VCert's logger to be able to - // remove the `vCert: ` prefix from the VCert logs. - Log *log.Logger // All but the essential logging flags will be hidden to avoid overwhelming // the user. The hidden flags can still be used. For example if a user does @@ -120,9 +114,6 @@ func Initialize() error { // the agent, which still uses log.Printf. slog := slog.Default() - Log = &log.Logger{} - Log.SetOutput(LogToSlogWriter{Slog: slog, Source: "agent"}) - // Let's make sure the VCert library, which is the only library we import to // be using the global log.Default, also uses the common slog logger. vcertLog := log.Default()