From 434dafa45fa376d609846f98d63380bdf43a2010 Mon Sep 17 00:00:00 2001 From: Eguzki Astiz Lezaun Date: Sat, 30 Oct 2021 00:18:37 +0200 Subject: [PATCH] enhanced logging --- Makefile | 4 +- controllers/limitador_controller.go | 20 +-- controllers/ratelimit_controller.go | 18 +-- controllers/suite_test.go | 12 +- doc/logging.md | 18 +++ go.mod | 4 +- go.sum | 12 ++ main.go | 40 ++++-- pkg/helpers/helpers.go | 10 ++ pkg/limitador/client.go | 4 +- pkg/log/log.go | 158 ++++++++++++++++++++++++ pkg/log/log_test.go | 58 +++++++++ pkg/reconcilers/base_reconciler.go | 17 +-- pkg/reconcilers/base_reconciler_test.go | 39 ++++-- 14 files changed, 357 insertions(+), 57 deletions(-) create mode 100644 doc/logging.md create mode 100644 pkg/log/log.go create mode 100644 pkg/log/log_test.go diff --git a/Makefile b/Makefile index 409fbfac..d21fc920 100644 --- a/Makefile +++ b/Makefile @@ -93,6 +93,8 @@ test: manifests generate fmt vet ## Run tests. build: generate fmt vet ## Build manager binary. go build -o bin/manager main.go +run: export LOG_LEVEL = debug +run: export LOG_MODE = development run: manifests generate fmt vet ## Run a controller from your host. go run ./main.go @@ -144,7 +146,7 @@ local-setup: local-cleanup local-setup-kind docker-build ## Deploy operator in l .PHONY: local-dev-setup local-dev-setup: local-cleanup local-setup-kind install run ## Run operator locally in local kind cluster -.PHONY: local-cleanup +.PHONY: local-cleanup local-cleanup: kind ## Clean up local kind cluster $(KIND) delete cluster --name $(KIND_CLUSTER_NAME) diff --git a/controllers/limitador_controller.go b/controllers/limitador_controller.go index 64dee0ab..acb9c327 100644 --- a/controllers/limitador_controller.go +++ b/controllers/limitador_controller.go @@ -20,6 +20,7 @@ import ( "context" "fmt" + "github.com/go-logr/logr" appsv1 "k8s.io/api/apps/v1" "k8s.io/apimachinery/pkg/api/errors" ctrl "sigs.k8s.io/controller-runtime" @@ -41,9 +42,10 @@ type LimitadorReconciler struct { //+kubebuilder:rbac:groups=core,resources=services,verbs=get;list;watch;create;update;delete //+kubebuilder:rbac:groups=apps,resources=deployments,verbs=get;list;watch;create;update;delete -func (r *LimitadorReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - reqLogger := r.Logger().WithValues("limitador", req.NamespacedName) - reqLogger.V(1).Info("Reconciling Limitador") +func (r *LimitadorReconciler) Reconcile(eventCtx context.Context, req ctrl.Request) (ctrl.Result, error) { + logger := r.Logger().WithValues("limitador", req.NamespacedName) + logger.V(1).Info("Reconciling Limitador") + ctx := logr.NewContext(eventCtx, logger) // Delete Limitador deployment and service if needed limitadorObj := &limitadorv1alpha1.Limitador{} @@ -52,27 +54,27 @@ func (r *LimitadorReconciler) Reconcile(ctx context.Context, req ctrl.Request) ( // The deployment and the service should be deleted automatically // because they have an owner ref to Limitador return ctrl.Result{}, nil - } else { - reqLogger.Error(err, "Failed to get Limitador object.") - return ctrl.Result{}, err } + + logger.Error(err, "Failed to get Limitador object.") + return ctrl.Result{}, err } if limitadorObj.GetDeletionTimestamp() != nil { // Marked to be deleted - reqLogger.V(1).Info("marked to be deleted") + logger.V(1).Info("marked to be deleted") return ctrl.Result{}, nil } limitadorService := limitador.LimitadorService(limitadorObj) err := r.ReconcileService(ctx, limitadorService, reconcilers.CreateOnlyMutator) - reqLogger.V(1).Info("reconcile service", "error", err) + logger.V(1).Info("reconcile service", "error", err) if err != nil { return ctrl.Result{}, err } deployment := limitador.LimitadorDeployment(limitadorObj) err = r.ReconcileDeployment(ctx, deployment, mutateLimitadorDeployment) - reqLogger.V(1).Info("reconcile deployment", "error", err) + logger.V(1).Info("reconcile deployment", "error", err) if err != nil { return ctrl.Result{}, err } diff --git a/controllers/ratelimit_controller.go b/controllers/ratelimit_controller.go index 03ac92f5..2ea2f537 100644 --- a/controllers/ratelimit_controller.go +++ b/controllers/ratelimit_controller.go @@ -70,9 +70,10 @@ type RateLimitReconciler struct { // // For more details, check Reconcile and its Result here: // - https://pkg.go.dev/sigs.k8s.io/controller-runtime@v0.7.2/pkg/reconcile -func (r *RateLimitReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) { - reqLogger := r.Logger().WithValues("ratelimit", req.NamespacedName) - reqLogger.V(1).Info("Reconciling RateLimit") +func (r *RateLimitReconciler) Reconcile(eventCtx context.Context, req ctrl.Request) (ctrl.Result, error) { + logger := r.Logger().WithValues("ratelimit", req.NamespacedName) + logger.V(1).Info("Reconciling RateLimit") + ctx := logr.NewContext(eventCtx, logger) limit := &limitadorv1alpha1.RateLimit{} if err := r.Client().Get(ctx, req.NamespacedName, limit); err != nil { @@ -80,7 +81,7 @@ func (r *RateLimitReconciler) Reconcile(ctx context.Context, req ctrl.Request) ( return ctrl.Result{}, nil } - reqLogger.Error(err, "Failed to get RateLimit object.") + logger.Error(err, "Failed to get RateLimit object.") return ctrl.Result{}, err } @@ -102,12 +103,12 @@ func (r *RateLimitReconciler) Reconcile(ctx context.Context, req ctrl.Request) ( return ctrl.Result{}, nil } - if err := r.ensureFinalizerIsAdded(ctx, limit, reqLogger); err != nil { + if err := r.ensureFinalizerIsAdded(ctx, limit); err != nil { return ctrl.Result{}, err } if err := r.createLimitInLimitador(limit); err != nil { - reqLogger.Error(err, "Failed to create rate limit in Limitador.") + logger.Error(err, "Failed to create rate limit in Limitador.") return ctrl.Result{}, err } @@ -166,7 +167,8 @@ func (r *RateLimitReconciler) createLimitInLimitador(limit *limitadorv1alpha1.Ra return limitadorClient.CreateLimit(&limit.Spec) } -func (r *RateLimitReconciler) ensureFinalizerIsAdded(ctx context.Context, limit *limitadorv1alpha1.RateLimit, reqLogger logr.Logger) error { +func (r *RateLimitReconciler) ensureFinalizerIsAdded(ctx context.Context, limit *limitadorv1alpha1.RateLimit) error { + logger := logr.FromContext(ctx) numberOfFinalizers := len(limit.GetFinalizers()) controllerutil.AddFinalizer(limit, rateLimitFinalizer) if numberOfFinalizers == len(limit.GetFinalizers()) { @@ -175,7 +177,7 @@ func (r *RateLimitReconciler) ensureFinalizerIsAdded(ctx context.Context, limit } if err := r.Client().Update(ctx, limit); err != nil { - reqLogger.Error(err, "Failed to update the rate limit with finalizer") + logger.Error(err, "Failed to update the rate limit with finalizer") return err } diff --git a/controllers/suite_test.go b/controllers/suite_test.go index 9cf5f80b..517411b3 100644 --- a/controllers/suite_test.go +++ b/controllers/suite_test.go @@ -25,15 +25,13 @@ import ( . "github.com/onsi/gomega" "github.com/onsi/gomega/ghttp" "k8s.io/client-go/kubernetes/scheme" - "k8s.io/client-go/rest" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/envtest" "sigs.k8s.io/controller-runtime/pkg/envtest/printer" - logf "sigs.k8s.io/controller-runtime/pkg/log" - "sigs.k8s.io/controller-runtime/pkg/log/zap" limitadorv1alpha1 "github.com/kuadrant/limitador-operator/api/v1alpha1" + "github.com/kuadrant/limitador-operator/pkg/log" "github.com/kuadrant/limitador-operator/pkg/reconcilers" //+kubebuilder:scaffold:imports ) @@ -41,7 +39,6 @@ import ( // These tests use Ginkgo (BDD-style Go testing framework). Refer to // http://onsi.github.io/ginkgo/ to learn more about Ginkgo. -var cfg *rest.Config var k8sClient client.Client var testEnv *envtest.Environment var mockedHTTPServer *ghttp.Server @@ -64,7 +61,12 @@ func (sd *TestLimitadorServiceDiscovery) URL(_ string) (*url.URL, error) { } var _ = BeforeSuite(func() { - logf.SetLogger(zap.New(zap.WriteTo(GinkgoWriter), zap.UseDevMode(true))) + logger := log.NewLogger( + log.SetLevel(log.DebugLevel), + log.SetMode(log.ModeDev), + log.WriteTo(GinkgoWriter), + ).WithName("controller_test") + log.SetLogger(logger) By("bootstrapping test environment") testEnv = &envtest.Environment{ diff --git a/doc/logging.md b/doc/logging.md new file mode 100644 index 00000000..497d4a45 --- /dev/null +++ b/doc/logging.md @@ -0,0 +1,18 @@ +# Logging + +The limitador operator outputs 3 levels of log messages: (from lowest to highest level) +1. `debug` +2. `info` (default) +3. `error` + +`info` logging is restricted to high-level information. Actions like creating, deleteing or updating kubernetes resources will be logged with reduced details about the corresponding objects, and without any further detailed logs of the steps in between, except for errors. + +Only `debug` logging will include processing details. + +To configure the desired log level, set the environment variable `LOG_LEVEL` to one of the supported values listed above. Default log level is `info`. + +Apart from log level, the controller can output messages to the logs in 2 different formats: +- `production` (default): each line is a parseable JSON object with properties `{"level":string, "ts":int, "msg":string, "logger":string, extra values...}` +- `development`: more human-readable outputs, extra stack traces and logging info, plus extra values output as JSON, in the format: `\t\t\t\t{extra-values-as-json}` + +To configure the desired log mode, set the environment variable `LOG_MODE` to one of the supported values listed above. Default log level is `production`. diff --git a/go.mod b/go.mod index 21611911..11a3d192 100644 --- a/go.mod +++ b/go.mod @@ -7,9 +7,11 @@ require ( github.com/onsi/ginkgo v1.14.1 github.com/onsi/gomega v1.10.2 github.com/stretchr/testify v1.5.1 - golang.org/x/oauth2 v0.0.0-20191202225959-858c2ad4c8b6 // indirect + go.uber.org/zap v1.15.0 + gotest.tools v2.2.0+incompatible k8s.io/api v0.19.2 k8s.io/apimachinery v0.19.2 k8s.io/client-go v0.19.2 + k8s.io/klog/v2 v2.2.0 sigs.k8s.io/controller-runtime v0.7.2 ) diff --git a/go.sum b/go.sum index 938d8fa1..c2e9f6f5 100644 --- a/go.sum +++ b/go.sum @@ -24,11 +24,13 @@ github.com/Azure/go-autorest/autorest/date v0.2.0 h1:yW+Zlqf26583pE43KhfnhFcdmSW github.com/Azure/go-autorest/autorest/date v0.2.0/go.mod h1:vcORJHLJEh643/Ioh9+vPmf1Ij9AEBM5FuBIXLmIy0g= github.com/Azure/go-autorest/autorest/mocks v0.1.0/go.mod h1:OTyCOPRA2IgIlWxVYxBee2F5Gr4kF2zd2J5cFRaIDN0= github.com/Azure/go-autorest/autorest/mocks v0.2.0/go.mod h1:OTyCOPRA2IgIlWxVYxBee2F5Gr4kF2zd2J5cFRaIDN0= +github.com/Azure/go-autorest/autorest/mocks v0.3.0 h1:qJumjCaCudz+OcqE9/XtEPfvtOjOmKaui4EOpFI6zZc= github.com/Azure/go-autorest/autorest/mocks v0.3.0/go.mod h1:a8FDP3DYzQ4RYfVAxAN3SVSiiO77gL2j2ronKKP0syM= github.com/Azure/go-autorest/logger v0.1.0 h1:ruG4BSDXONFRrZZJ2GUXDiUyVpayPmb1GnWeHDdaNKY= github.com/Azure/go-autorest/logger v0.1.0/go.mod h1:oExouG+K6PryycPJfVSxi/koC6LSNgds39diKLz7Vrc= github.com/Azure/go-autorest/tracing v0.5.0 h1:TRn4WjSnkcSy5AEG3pnbtFSwNtwzjr4VYyQflFE619k= github.com/Azure/go-autorest/tracing v0.5.0/go.mod h1:r/s2XiOKccPW3HrqB+W0TQzfbtp2fGCgRFtBroKn4Dk= +github.com/BurntSushi/toml v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ= github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU= github.com/BurntSushi/xgb v0.0.0-20160522181843-27f122750802/go.mod h1:IVnqGOEym/WlBOVXweHU+Q+/VP0lqqI8lqeDx9IjBqo= github.com/NYTimes/gziphandler v0.0.0-20170623195520-56545f4a5d46/go.mod h1:3wb06e3pkSAbeQ52E9H9iFoQsEEwGN64994WTCIhntQ= @@ -240,9 +242,11 @@ github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxv github.com/konsorten/go-windows-terminal-sequences v1.0.3/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ= github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= +github.com/kr/pretty v0.2.0 h1:s5hAObm+yFO5uHYt5dYjxi2rXrsnmRpJx4OYvIWUaQs= github.com/kr/pretty v0.2.0/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/pty v1.1.5/go.mod h1:9r2w37qlBe7rQ6e1fg1S/9xpWHSnaqNdHD3WcMdbPDA= +github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czPbwD3XqdrwzmxQ= github.com/mailru/easyjson v0.0.0-20160728113105-d5b7844b561a/go.mod h1:C1wdFJiN94OJF2b5HbByQZoLdCWB1Yqtg26g4irojpc= @@ -371,10 +375,12 @@ go.uber.org/atomic v1.3.2/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE= go.uber.org/atomic v1.4.0/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE= go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk= go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ= +go.uber.org/goleak v1.1.10 h1:z+mqJhf6ss6BSfSM671tgKyZBFPTTJM+HLxnhPC3wu0= go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A= go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0= go.uber.org/multierr v1.5.0 h1:KCa4XfM8CWFCpxXRGok+Q0SS/0XBhMDbHHGABQLvD2A= go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU= +go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEaUSmT1ysygQC7qYo7sG4= go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA= go.uber.org/zap v1.8.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q= go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q= @@ -405,6 +411,7 @@ golang.org/x/lint v0.0.0-20190313153728-d0100b6bd8b3/go.mod h1:6SW0HCj/g11FgYtHl golang.org/x/lint v0.0.0-20190409202823-959b441ac422/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= golang.org/x/lint v0.0.0-20190909230951-414d861bb4ac/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= +golang.org/x/lint v0.0.0-20191125180803-fdd1cda4f05f h1:J5lckAjkw6qYlOZNj90mLYNTEKDvWeuc1yieZ8qUzUE= golang.org/x/lint v0.0.0-20191125180803-fdd1cda4f05f/go.mod h1:5qLYkcX4OjUUV8bRuDixDT3tpyyb+LUpUlRWLxfhWrs= golang.org/x/mobile v0.0.0-20190312151609-d3739f865fa6/go.mod h1:z+o9i4GpDbdi3rU15maQ/Ox0txvL9dWGYEHz965HBQE= golang.org/x/mobile v0.0.0-20190719004257-d2bd2a29d028/go.mod h1:E/iHnbuqvinMTCcRqshq8CkpyQDoeVncDDYHnLhea+o= @@ -412,6 +419,7 @@ golang.org/x/mod v0.0.0-20190513183733-4bf6d317e70e/go.mod h1:mXi4GBBbnImb6dmsKG golang.org/x/mod v0.1.0/go.mod h1:0QHyrYULN0/3qlju5TqG8bIK38QM8yzMo5ekMj3DlcY= golang.org/x/mod v0.1.1-0.20191105210325-c90efee705ee/go.mod h1:QqPTAvyqsEbceGzBzNggFXnrqF1CaUcvgkdR5Ot7KZg= golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= +golang.org/x/mod v0.3.0 h1:RM4zey1++hCTbCVQfnWeKs9/IEsaBLA8vTkd0WVtmH4= golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= @@ -517,6 +525,7 @@ golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtn golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191125144606-a911d9008d1f/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191227053925-7b8e75db28f4/go.mod h1:TB2adYChydJhpapKDTa4BR/hXlZSLoq2Wpct/0txZ28= +golang.org/x/tools v0.0.0-20200616133436-c1934b75d054 h1:HHeAlu5H9b71C+Fx0K+1dGgVFN1DM1/wz4aoGOA5qS8= golang.org/x/tools v0.0.0-20200616133436-c1934b75d054/go.mod h1:EkVYQZoAsY45+roYkvgYkIh4xh/qjgUK9TdY2XT94GE= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= @@ -566,6 +575,7 @@ google.golang.org/protobuf v1.24.0/go.mod h1:r/3tXBNzIEhYS9I1OUVjXDlt8tc493IdKGj gopkg.in/alecthomas/kingpin.v2 v2.2.6/go.mod h1:FMv+mEhP44yOT+4EoQTLFTRgOQ1FBLkstjWtayDeSgw= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 h1:YR8cESwS4TdDjEe65xsg0ogRM/Nc3DYOhEAlW+xobZo= gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/cheggaaa/pb.v1 v1.0.25/go.mod h1:V/YB90LKu/1FcN3WVnfiiE5oMCibMjukxqG/qStrOgw= gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI= @@ -587,12 +597,14 @@ gopkg.in/yaml.v2 v2.3.0 h1:clyUAQHOM3G0M3f5vQj7LuJrETvjVot3Z5el9nffUtU= gopkg.in/yaml.v2 v2.3.0/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v3 v3.0.0-20200615113413-eeeca48fe776 h1:tQIYjPdBoyREyB9XMu+nnTclpTYkz2zFM+lzLJFO4gQ= gopkg.in/yaml.v3 v3.0.0-20200615113413-eeeca48fe776/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +gotest.tools v2.2.0+incompatible h1:VsBPFP1AI068pPrMxtb/S8Zkgf9xEmTLJjfM+P5UIEo= gotest.tools v2.2.0+incompatible/go.mod h1:DsYFclhRJ6vuDpmuTbkuFWG+y2sxOXAzmJt81HFBacw= gotest.tools/v3 v3.0.2/go.mod h1:3SzNCllyD9/Y+b5r9JIKQ474KzkZyqLqEfYqMsX94Bk= honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.0-20190106161140-3f1c8253044a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.0-20190418001031-e561f6794a2a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4= +honnef.co/go/tools v0.0.1-2019.2.3 h1:3JgtbtFHMiCmsznwGVTUWbgGov+pVqnlf1dEJTNAXeM= honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg= k8s.io/api v0.19.2 h1:q+/krnHWKsL7OBZg/rxnycsl9569Pud76UJ77MvKXms= k8s.io/api v0.19.2/go.mod h1:IQpK0zFQ1xc5iNIQPqzgoOwuFugaYHK4iCknlAQP9nI= diff --git a/main.go b/main.go index fd98c7a6..1ec43934 100644 --- a/main.go +++ b/main.go @@ -18,27 +18,31 @@ package main import ( "flag" + "fmt" "os" + "runtime" // Import all Kubernetes client auth plugins (e.g. Azure, GCP, OIDC, etc.) // to ensure that exec-entrypoint and run can make use of them. - "k8s.io/apimachinery/pkg/runtime" + k8sruntime "k8s.io/apimachinery/pkg/runtime" utilruntime "k8s.io/apimachinery/pkg/util/runtime" clientgoscheme "k8s.io/client-go/kubernetes/scheme" _ "k8s.io/client-go/plugin/pkg/client/auth" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/healthz" - "sigs.k8s.io/controller-runtime/pkg/log/zap" limitadorv1alpha1 "github.com/kuadrant/limitador-operator/api/v1alpha1" "github.com/kuadrant/limitador-operator/controllers" + "github.com/kuadrant/limitador-operator/pkg/helpers" + "github.com/kuadrant/limitador-operator/pkg/log" "github.com/kuadrant/limitador-operator/pkg/reconcilers" //+kubebuilder:scaffold:imports ) var ( - scheme = runtime.NewScheme() - setupLog = ctrl.Log.WithName("setup") + scheme = k8sruntime.NewScheme() + logLevel = helpers.FetchEnv("LOG_LEVEL", "info") + logMode = helpers.FetchEnv("LOG_MODE", "production") ) func init() { @@ -46,9 +50,27 @@ func init() { utilruntime.Must(limitadorv1alpha1.AddToScheme(scheme)) //+kubebuilder:scaffold:scheme + + logger := log.NewLogger( + log.SetLevel(log.ToLevel(logLevel)), + log.SetMode(log.ToMode(logMode)), + log.WriteTo(os.Stdout), + ) + log.SetLogger(logger) +} + +func printControllerMetaInfo() { + setupLog := log.Log + + setupLog.Info(fmt.Sprintf("go version: %s", runtime.Version())) + setupLog.Info(fmt.Sprintf("go os/arch: %s/%s", runtime.GOOS, runtime.GOARCH)) + setupLog.Info("base logger", "log level", logLevel, "log mode", logMode) } func main() { + printControllerMetaInfo() + setupLog := log.Log + var metricsAddr string var enableLeaderElection bool var probeAddr string @@ -57,14 +79,8 @@ func main() { flag.BoolVar(&enableLeaderElection, "leader-elect", false, "Enable leader election for controller manager. "+ "Enabling this will ensure there is only one active controller manager.") - opts := zap.Options{ - Development: true, - } - opts.BindFlags(flag.CommandLine) flag.Parse() - ctrl.SetLogger(zap.New(zap.UseFlagOptions(&opts))) - mgr, err := ctrl.NewManager(ctrl.GetConfigOrDie(), ctrl.Options{ Scheme: scheme, MetricsBindAddress: metricsAddr, @@ -80,7 +96,7 @@ func main() { rateLimitBaseReconciler := reconcilers.NewBaseReconciler( mgr.GetClient(), mgr.GetScheme(), mgr.GetAPIReader(), - ctrl.Log.WithName("controllers").WithName("ratelimit"), + log.Log.WithName("ratelimit"), mgr.GetEventRecorderFor("RateLimit"), ) @@ -93,7 +109,7 @@ func main() { limitadorBaseReconciler := reconcilers.NewBaseReconciler( mgr.GetClient(), mgr.GetScheme(), mgr.GetAPIReader(), - ctrl.Log.WithName("controllers").WithName("limitador"), + log.Log.WithName("limitador"), mgr.GetEventRecorderFor("Limitador"), ) diff --git a/pkg/helpers/helpers.go b/pkg/helpers/helpers.go index ba01db73..bd2c714e 100644 --- a/pkg/helpers/helpers.go +++ b/pkg/helpers/helpers.go @@ -2,6 +2,7 @@ package helpers import ( "fmt" + "os" "sigs.k8s.io/controller-runtime/pkg/client" ) @@ -42,3 +43,12 @@ func IsObjectTaggedToDelete(obj client.Object) bool { annotation, ok := annotations[DeleteTagAnnotation] return ok && annotation == "true" } + +func FetchEnv(key string, def string) string { + val, ok := os.LookupEnv(key) + if !ok { + return def + } + + return val +} diff --git a/pkg/limitador/client.go b/pkg/limitador/client.go index ac7991d4..6395069d 100644 --- a/pkg/limitador/client.go +++ b/pkg/limitador/client.go @@ -7,10 +7,10 @@ import ( "net/url" "k8s.io/apimachinery/pkg/util/json" - ctrl "sigs.k8s.io/controller-runtime" limitadorv1alpha1 "github.com/kuadrant/limitador-operator/api/v1alpha1" "github.com/kuadrant/limitador-operator/pkg/helpers" + "github.com/kuadrant/limitador-operator/pkg/log" ) type Client struct { @@ -20,7 +20,7 @@ type Client struct { func NewClient(url url.URL) Client { var transport http.RoundTripper - if ctrl.Log.V(1).Enabled() { + if log.Log.V(1).Enabled() { transport = &helpers.VerboseTransport{} } diff --git a/pkg/log/log.go b/pkg/log/log.go new file mode 100644 index 00000000..657605a8 --- /dev/null +++ b/pkg/log/log.go @@ -0,0 +1,158 @@ +/* +Copyright 2021 Red Hat, Inc. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package log + +import ( + "fmt" + "io" + "os" + "strings" + + "github.com/go-logr/logr" + "go.uber.org/zap/zapcore" + "k8s.io/klog/v2" + ctrl "sigs.k8s.io/controller-runtime" + ctrllog "sigs.k8s.io/controller-runtime/pkg/log" + "sigs.k8s.io/controller-runtime/pkg/log/zap" +) + +var ( + // Log is the base logger + Log logr.Logger = ctrllog.NullLogger{} +) + +// Level configures the verbosity of the logging. +type Level zapcore.Level + +const ( + // DebugLevel logs are typically voluminous, and are usually disabled in production. + DebugLevel = Level(zapcore.DebugLevel) + // InfoLevel is the default logging priority. + InfoLevel = Level(zapcore.InfoLevel) + // WarnLevel logs are more important than Info, but don't need individual human review. + WarnLevel = Level(zapcore.WarnLevel) + // ErrorLevel logs are high-priority. If an application is running smoothly, + // it shouldn't generate any error-level logs. + ErrorLevel = Level(zapcore.ErrorLevel) + // DPanicLevel logs are particularly important errors. In development the + // logger panics after writing the message. + DPanicLevel = Level(zapcore.DPanicLevel) + // PanicLevel logs a message, then panics. + PanicLevel = Level(zapcore.PanicLevel) + // FatalLevel logs a message, then calls os.Exit(1). + FatalLevel = Level(zapcore.FatalLevel) +) + +// ToLevel converts a string to a log level. +func ToLevel(level string) Level { + var l zapcore.Level + err := l.UnmarshalText([]byte(level)) + if err != nil { + panic(err) + } + return Level(l) +} + +// Mode defines the log output mode. +type Mode int8 + +const ( + // ModeProd is the log mode for production. + ModeProd Mode = iota + // ModeDev is for more human-readable outputs, extra stack traces + // and logging info. (aka Zap's "development config".) + // https://pkg.go.dev/sigs.k8s.io/controller-runtime/pkg/log/zap#UseDevMode + ModeDev +) + +// ToMode converts a string to a log mode. +// Use either 'production' for `LogModeProd` or 'development' for `LogModeDev`. +func ToMode(mode string) Mode { + switch strings.ToLower(mode) { + case "production": + return ModeProd + case "development": + return ModeDev + default: + panic(fmt.Sprintf("unknown log mode: %s", mode)) + } +} + +// Opts allows to manipulate Options. +type Opts func(*Options) + +// Options contains all possible settings. +type Options struct { + // LogLevel configures the verbosity of the logging. + LogLevel Level + // LogMode defines the log output mode. + LogMode Mode + // DestWriter controls the destination of the log output. Defaults to + // os.Stderr. + DestWriter io.Writer +} + +// SetLogger sets a concrete logging implementation for all deferred Loggers. +// Being top level application and not a library or dependency, +// let's delegation logger used by any dependency +func SetLogger(logger logr.Logger) { + Log = logger + + ctrl.SetLogger(logger) // fulfills `logger` as the de facto logger used by controller-runtime + klog.SetLogger(logger) +} + +// WriteTo configures the logger to write to the given io.Writer, instead of standard error. +// See Options.DestWriter. +func WriteTo(out io.Writer) Opts { + return func(o *Options) { + o.DestWriter = out + } +} + +// SetLevel sets Options.LogLevel, which configures the the minimum enabled logging level e.g Debug, Info. +func SetLevel(level Level) func(o *Options) { + return func(o *Options) { + o.LogLevel = level + } +} + +// SetMode sets Options.LogMode, which configures to use (or not use) development mode +func SetMode(mode Mode) func(o *Options) { + return func(o *Options) { + o.LogMode = mode + } +} + +// NewLogger creates new Logger based on controller runtime zap logger +func NewLogger(opts ...Opts) logr.Logger { + o := &Options{} + for _, opt := range opts { + opt(o) + } + + // defaults + if o.DestWriter == nil { + o.DestWriter = os.Stderr + } + + return zap.New( + zap.Level(zapcore.Level(o.LogLevel)), + zap.UseDevMode(o.LogMode == ModeDev), + zap.WriteTo(o.DestWriter), + ) +} diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go new file mode 100644 index 00000000..8264eb35 --- /dev/null +++ b/pkg/log/log_test.go @@ -0,0 +1,58 @@ +/* +Copyright 2021 Red Hat, Inc. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package log + +import ( + "testing" + + "gotest.tools/assert" +) + +func TestToLevel(t *testing.T) { + assert.Equal(t, int(ToLevel("debug")), -1) + assert.Equal(t, int(ToLevel("info")), 0) + assert.Equal(t, int(ToLevel("warn")), 1) + assert.Equal(t, int(ToLevel("error")), 2) + assert.Equal(t, int(ToLevel("dpanic")), 3) + assert.Equal(t, int(ToLevel("panic")), 4) + assert.Equal(t, int(ToLevel("fatal")), 5) + + func() { + defer func() { + if r := recover(); r == nil { + t.Errorf("ToLevel(\"invalid\") should have panicked!") + } + }() + // should panic + ToLevel("invalid") + }() +} + +func TestToMode(t *testing.T) { + assert.Equal(t, int(ToMode("production")), 0) + assert.Equal(t, int(ToMode("development")), 1) + + func() { + defer func() { + if r := recover(); r == nil { + t.Errorf("ToMode(\"invalid\") should have panicked!") + } + }() + // should panic + ToMode("invalid") + }() +} diff --git a/pkg/reconcilers/base_reconciler.go b/pkg/reconcilers/base_reconciler.go index 9377fc31..d374549e 100644 --- a/pkg/reconcilers/base_reconciler.go +++ b/pkg/reconcilers/base_reconciler.go @@ -18,8 +18,6 @@ package reconcilers import ( "context" - "fmt" - "strings" "github.com/go-logr/logr" appsv1 "k8s.io/api/apps/v1" @@ -147,27 +145,32 @@ func (b *BaseReconciler) ReconcileDeployment(ctx context.Context, desired *appsv } func (b *BaseReconciler) GetResource(ctx context.Context, objKey types.NamespacedName, obj client.Object) error { - b.Logger().Info("get object", "kind", strings.Replace(fmt.Sprintf("%T", obj), "*", "", 1), "name", objKey.Name, "namespace", objKey.Namespace) + logger := logr.FromContext(ctx) + logger.Info("get object", "GKV", obj.GetObjectKind().GroupVersionKind(), "name", obj.GetName(), "namespace", obj.GetNamespace()) return b.Client().Get(ctx, objKey, obj) } func (b *BaseReconciler) CreateResource(ctx context.Context, obj client.Object) error { - b.Logger().Info("create object", "kind", strings.Replace(fmt.Sprintf("%T", obj), "*", "", 1), "name", obj.GetName(), "namespace", obj.GetNamespace()) + logger := logr.FromContext(ctx) + logger.Info("create object", "GKV", obj.GetObjectKind().GroupVersionKind(), "name", obj.GetName(), "namespace", obj.GetNamespace()) return b.Client().Create(ctx, obj) } func (b *BaseReconciler) UpdateResource(ctx context.Context, obj client.Object) error { - b.Logger().Info("update object", "kind", strings.Replace(fmt.Sprintf("%T", obj), "*", "", 1), "name", obj.GetName(), "namespace", obj.GetNamespace()) + logger := logr.FromContext(ctx) + logger.Info("update object", "GKV", obj.GetObjectKind().GroupVersionKind(), "name", obj.GetName(), "namespace", obj.GetNamespace()) return b.Client().Update(ctx, obj) } func (b *BaseReconciler) DeleteResource(ctx context.Context, obj client.Object, options ...client.DeleteOption) error { - b.Logger().Info("delete object", "kind", strings.Replace(fmt.Sprintf("%T", obj), "*", "", 1), "name", obj.GetName(), "namespace", obj.GetNamespace()) + logger := logr.FromContext(ctx) + logger.Info("delete object", "GKV", obj.GetObjectKind().GroupVersionKind(), "name", obj.GetName(), "namespace", obj.GetNamespace()) return b.Client().Delete(ctx, obj, options...) } func (b *BaseReconciler) UpdateResourceStatus(ctx context.Context, obj client.Object) error { - b.Logger().Info("update object status", "kind", strings.Replace(fmt.Sprintf("%T", obj), "*", "", 1), "name", obj.GetName(), "namespace", obj.GetNamespace()) + logger := logr.FromContext(ctx) + logger.Info("update object status", "GKV", obj.GetObjectKind().GroupVersionKind(), "name", obj.GetName(), "namespace", obj.GetNamespace()) return b.Client().Status().Update(ctx, obj) } diff --git a/pkg/reconcilers/base_reconciler_test.go b/pkg/reconcilers/base_reconciler_test.go index d0ec5483..6d35aeea 100644 --- a/pkg/reconcilers/base_reconciler_test.go +++ b/pkg/reconcilers/base_reconciler_test.go @@ -1,5 +1,3 @@ -// +build unit - /* Copyright 2021 Red Hat, Inc. @@ -21,8 +19,10 @@ package reconcilers import ( "context" "fmt" + "os" "testing" + "github.com/go-logr/logr" appsv1 "k8s.io/api/apps/v1" v1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/api/errors" @@ -30,16 +30,22 @@ import ( "k8s.io/apimachinery/pkg/runtime" "k8s.io/client-go/kubernetes/scheme" "k8s.io/client-go/tools/record" - ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/client/fake" "github.com/kuadrant/limitador-operator/pkg/helpers" + "github.com/kuadrant/limitador-operator/pkg/log" ) -var ( - LOGTEST = ctrl.Log.WithName("test_base_reconcilers") -) +func TestMain(m *testing.M) { + logger := log.NewLogger( + log.SetLevel(log.DebugLevel), + log.SetMode(log.ModeDev), + log.WriteTo(os.Stdout), + ).WithName("test_base_reconcilers") + log.SetLogger(logger) + os.Exit(m.Run()) +} func TestCreateOnlyMutator(t *testing.T) { desired := &v1.ConfigMap{} @@ -53,6 +59,9 @@ func TestBaseReconcilerCreate(t *testing.T) { var ( namespace = "operator-unittest" ) + logger := log.Log.WithName("base_test") + baseCtx := context.Background() + ctx := logr.NewContext(baseCtx, logger) s := scheme.Scheme err := appsv1.AddToScheme(s) @@ -68,7 +77,7 @@ func TestBaseReconcilerCreate(t *testing.T) { clientAPIReader := fake.NewFakeClient(objs...) recorder := record.NewFakeRecorder(10000) - baseReconciler := NewBaseReconciler(cl, s, clientAPIReader, LOGTEST, recorder) + baseReconciler := NewBaseReconciler(cl, s, clientAPIReader, logger, recorder) desiredConfigmap := &v1.ConfigMap{ TypeMeta: metav1.TypeMeta{ @@ -84,7 +93,7 @@ func TestBaseReconcilerCreate(t *testing.T) { }, } - err = baseReconciler.ReconcileResource(context.TODO(), &v1.ConfigMap{}, desiredConfigmap, CreateOnlyMutator) + err = baseReconciler.ReconcileResource(ctx, &v1.ConfigMap{}, desiredConfigmap, CreateOnlyMutator) if err != nil { t.Fatal(err) } @@ -104,6 +113,9 @@ func TestBaseReconcilerUpdateNeeded(t *testing.T) { name = "myConfigmap" namespace = "operator-unittest" ) + logger := log.Log.WithName("base_test") + baseCtx := context.Background() + ctx := logr.NewContext(baseCtx, logger) s := runtime.NewScheme() err := appsv1.AddToScheme(s) @@ -133,7 +145,7 @@ func TestBaseReconcilerUpdateNeeded(t *testing.T) { clientAPIReader := fake.NewFakeClient(objs...) recorder := record.NewFakeRecorder(10000) - baseReconciler := NewBaseReconciler(cl, s, clientAPIReader, LOGTEST, recorder) + baseReconciler := NewBaseReconciler(cl, s, clientAPIReader, logger, recorder) desiredConfigmap := &v1.ConfigMap{ TypeMeta: metav1.TypeMeta{ @@ -161,7 +173,7 @@ func TestBaseReconcilerUpdateNeeded(t *testing.T) { return true, nil } - err = baseReconciler.ReconcileResource(context.TODO(), &v1.ConfigMap{}, desiredConfigmap, customMutator) + err = baseReconciler.ReconcileResource(ctx, &v1.ConfigMap{}, desiredConfigmap, customMutator) if err != nil { t.Fatal(err) } @@ -188,6 +200,9 @@ func TestBaseReconcilerDelete(t *testing.T) { resourceName = "example-resource" namespace = "operator-unittest" ) + logger := log.Log.WithName("base_test") + baseCtx := context.Background() + ctx := logr.NewContext(baseCtx, logger) s := runtime.NewScheme() err := appsv1.AddToScheme(s) @@ -217,7 +232,7 @@ func TestBaseReconcilerDelete(t *testing.T) { clientAPIReader := fake.NewFakeClient(objs...) recorder := record.NewFakeRecorder(10000) - baseReconciler := NewBaseReconciler(cl, s, clientAPIReader, LOGTEST, recorder) + baseReconciler := NewBaseReconciler(cl, s, clientAPIReader, logger, recorder) desired := &v1.ConfigMap{ TypeMeta: metav1.TypeMeta{ @@ -234,7 +249,7 @@ func TestBaseReconcilerDelete(t *testing.T) { } helpers.TagObjectToDelete(desired) - err = baseReconciler.ReconcileResource(context.TODO(), &v1.ConfigMap{}, desired, CreateOnlyMutator) + err = baseReconciler.ReconcileResource(ctx, &v1.ConfigMap{}, desired, CreateOnlyMutator) if err != nil { t.Fatal(err) }