Merge pull request #86 from slok/refactor-logs

Refactor log package

CHANGELOG.md

@@ -12,6 +12,8 @@ NOTE: Breaking release in controllers.
 - Disable retry handling on controllers in case of error by default.
 - Remove tracing.
 - Minimum Go version v1.13 (error wrapping required).
+- Refactor Logger with structured logging.
+- Add Logrus helper wrapper.
 
 ## [0.8.0] - 2019-12-11
 

controller/generic.go

@@ -66,9 +66,13 @@ func (c *Config) setDefaults() error {
 	}
 
 	if c.Logger == nil {
-		c.Logger = &log.Std{}
+		c.Logger = log.NewStd(false)
 		c.Logger.Warningf("no logger specified, fallback to default logger, to disable logging use a explicit Noop logger")
 	}
+	c.Logger = c.Logger.WithKV(log.KV{
+		"source-service": "kooper/controller",
+		"controller-id":  c.Name,
+	})
 
 	if c.MetricRecorder == nil {
 		c.MetricRecorder = metrics.Dummy
@@ -256,13 +260,14 @@ func (g *generic) processNextJob() bool {
 	ctx := context.Background()
 	err := g.processor.Process(ctx, key)
 
+	logger := g.logger.WithKV(log.KV{"object-key": key})
 	switch {
 	case err == nil:
-		g.logger.Infof("object with key %s processed", key)
+		logger.Debugf("object processed")
 	case errors.Is(err, errRequeued):
-		g.logger.Warningf("error on object with key %s processing, retrying", key)
+		logger.Warningf("error on object processing, retrying: %v", err)
 	default:
-		g.logger.Errorf("error on object with key %s processing", key)
+		logger.Errorf("error on object processing: %v", err)
 	}
 
 	return false

controller/leaderelection/leaderelection.go

@@ -74,7 +74,10 @@ func New(key, namespace string, lockCfg *LockConfig, k8scli kubernetes.Interface
 		key:       key,
 		namespace: namespace,
 		k8scli:    k8scli,
-		logger:    logger,
+		logger: logger.WithKV(log.KV{
+			"source-service":     "kooper/leader-election",
+			"leader-election-id": fmt.Sprintf("%s/%s", namespace, key),
+		}),
 	}
 
 	if err := r.validate(); err != nil {

examples/config-custom-controller/main.go

@@ -7,6 +7,7 @@ import (
 	"path/filepath"
 	"time"
 
+	"github.com/sirupsen/logrus"
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
@@ -20,11 +21,13 @@ import (
 
 	"github.com/spotahome/kooper/controller"
 	"github.com/spotahome/kooper/log"
+	kooperlogrus "github.com/spotahome/kooper/log/logrus"
 )
 
 func run() error {
 	// Initialize logger.
-	log := &log.Std{}
+	logger := kooperlogrus.New(logrus.NewEntry(logrus.New())).
+		WithKV(log.KV{"example": "config-custom-controller"})
 
 	// Get k8s client.
 	k8scfg, err := rest.InClusterConfig()
@@ -58,20 +61,21 @@ func run() error {
 	hand := &controller.HandlerFunc{
 		AddFunc: func(_ context.Context, obj runtime.Object) error {
 			pod := obj.(*corev1.Pod)
-			log.Infof("Pod added: %s/%s", pod.Namespace, pod.Name)
+			logger.Infof("Pod added: %s/%s", pod.Namespace, pod.Name)
 			return nil
 		},
 		DeleteFunc: func(_ context.Context, s string) error {
-			log.Infof("Pod deleted: %s", s)
+			logger.Infof("Pod deleted: %s", s)
 			return nil
 		},
 	}
 
 	// Create the controller with custom configuration.
 	cfg := &controller.Config{
+		Name:      "config-custom-controller",
 		Handler:   hand,
 		Retriever: retr,
-		Logger:    log,
+		Logger:    logger,
 
 		ProcessingJobRetries: 5,
 		ResyncInterval:       45 * time.Second,

examples/controller-concurrency-handling-example/main.go → examples/controller-concurrency-handling/main.go

@@ -8,6 +8,7 @@ import (
 	"path/filepath"
 	"time"
 
+	"github.com/sirupsen/logrus"
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
@@ -19,24 +20,25 @@ import (
 	"k8s.io/client-go/tools/clientcmd"
 	"k8s.io/client-go/util/homedir"
 
-	"github.com/spotahome/kooper/log"
 	"github.com/spotahome/kooper/controller"
+	"github.com/spotahome/kooper/log"
+	kooperlogrus "github.com/spotahome/kooper/log/logrus"
 )
 
 var (
 	concurrentWorkers int
 	sleepMS           int
-	intervalS int
-	retries int
+	intervalS         int
+	retries           int
 )
 
 func initFlags() error {
 	fg := flag.NewFlagSet(os.Args[0], flag.ExitOnError)
 	fg.IntVar(&concurrentWorkers, "concurrency", 3, "The number of concurrent event handling")
 	fg.IntVar(&sleepMS, "sleep-ms", 25, "The number of milliseconds to sleep on each event handling")
-	fg.IntVar(&intervalS, "interval-s", 300, "The number of seconds to for reconciliation loop intervals")
+	fg.IntVar(&intervalS, "interval-s", 45, "The number of seconds to for reconciliation loop intervals")
 	fg.IntVar(&retries, "retries", 3, "The number of retries in case of error")
-	
+
 	err := fg.Parse(os.Args[1:])
 	if err != nil {
 		return err
@@ -66,7 +68,8 @@ func sleep() {
 
 func run() error {
 	// Initialize logger.
-	log := &log.Std{}
+	logger := kooperlogrus.New(logrus.NewEntry(logrus.New())).
+		WithKV(log.KV{"example": "controller-concurrency-handling"})
 
 	// Init flags.
 	if err := initFlags(); err != nil {
@@ -101,26 +104,27 @@ func run() error {
 		},
 	}
 
-	// Our domain logic that will print every add/sync/update and delete event we .
+	// Our domain logic that will print every add/sync/update and delete event we.
 	hand := &controller.HandlerFunc{
 		AddFunc: func(_ context.Context, obj runtime.Object) error {
 			pod := obj.(*corev1.Pod)
 			sleep()
-			log.Infof("Pod added: %s/%s", pod.Namespace, pod.Name)
+			logger.Infof("Pod added: %s/%s", pod.Namespace, pod.Name)
 			return nil
 		},
 		DeleteFunc: func(_ context.Context, s string) error {
 			sleep()
-			log.Infof("Pod deleted: %s", s)
+			logger.Infof("Pod deleted: %s", s)
 			return nil
 		},
 	}
 
-	// Create the controller that will refresh every 30 seconds.
+	// Create the controller.
 	cfg := &controller.Config{
-		Handler: hand,
+		Name:      "controller-concurrency-handling",
+		Handler:   hand,
 		Retriever: retr,
-		Logger: log,
+		Logger:    logger,
 
 		ProcessingJobRetries: retries,
 		ResyncInterval:       time.Duration(intervalS) * time.Second,
@@ -148,4 +152,4 @@ func main() {
 	}
 
 	os.Exit(0)
-}
+}