Skip to content

Commit 3eebf29

Browse files
authored
DVO-203: Revamp logging (#322)
* draft validations cache key rewriting to include namespace Id * cleanup error replication and logging lines * Fix logging levels and minor refactor * Refactor loglines in GenericReconciler * Refactor loglines in ValidationEngine * Fix Options for the log to work in debug mode * Update go mod golang.org/x/net
1 parent 51ecc11 commit 3eebf29

File tree

7 files changed

+85
-74
lines changed

7 files changed

+85
-74
lines changed

Diff for: go.mod

+5-5
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ require (
1717
github.com/spf13/pflag v1.0.5
1818
github.com/spf13/viper v1.17.0
1919
github.com/stretchr/testify v1.8.4
20+
go.uber.org/zap v1.25.0
2021
golang.stackrox.io/kube-linter v0.6.5
2122
k8s.io/api v0.29.0
2223
k8s.io/apimachinery v0.29.0
@@ -124,14 +125,13 @@ require (
124125
go.opentelemetry.io/otel/trace v1.19.0 // indirect
125126
go.starlark.net v0.0.0-20230525235612-a134d8f9ddca // indirect
126127
go.uber.org/multierr v1.11.0 // indirect
127-
go.uber.org/zap v1.25.0 // indirect
128-
golang.org/x/crypto v0.17.0 // indirect
128+
golang.org/x/crypto v0.21.0 // indirect
129129
golang.org/x/exp v0.0.0-20230905200255-921286631fa9 // indirect
130-
golang.org/x/net v0.17.0 // indirect
130+
golang.org/x/net v0.23.0 // indirect
131131
golang.org/x/oauth2 v0.12.0 // indirect
132132
golang.org/x/sync v0.4.0 // indirect
133-
golang.org/x/sys v0.15.0 // indirect
134-
golang.org/x/term v0.15.0 // indirect
133+
golang.org/x/sys v0.18.0 // indirect
134+
golang.org/x/term v0.18.0 // indirect
135135
golang.org/x/text v0.14.0 // indirect
136136
golang.org/x/time v0.3.0 // indirect
137137
golang.org/x/tools v0.14.0 // indirect

Diff for: go.sum

+8-8
Original file line numberDiff line numberDiff line change
@@ -513,8 +513,8 @@ golang.org/x/crypto v0.0.0-20210421170649-83a5a9bb288b/go.mod h1:T9bdIzuCu7OtxOm
513513
golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc=
514514
golang.org/x/crypto v0.0.0-20220722155217-630584e8d5aa/go.mod h1:IxCIyHEi3zRg3s0A5j5BB6A9Jmi73HwBIUl50j+osU4=
515515
golang.org/x/crypto v0.3.0/go.mod h1:hebNnKkNXi2UzZN1eVRvBB7co0a+JxK6XbPiWVs/3J4=
516-
golang.org/x/crypto v0.17.0 h1:r8bRNjWL3GshPW3gkd+RpvzWrZAwPS49OmTGZ/uhM4k=
517-
golang.org/x/crypto v0.17.0/go.mod h1:gCAAfMLgwOJRpTjQ2zCCt2OcSfYMTeZVSRtQlPC7Nq4=
516+
golang.org/x/crypto v0.21.0 h1:X31++rzVUdKhX5sWmSOFZxx8UW/ldWx55cbf08iNAMA=
517+
golang.org/x/crypto v0.21.0/go.mod h1:0BP7YvVV9gBbVKyeTG0Gyn+gZm94bibOW5BjDEYAOMs=
518518
golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
519519
golang.org/x/exp v0.0.0-20190306152737-a1d7652674e8/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
520520
golang.org/x/exp v0.0.0-20190510132918-efd6b22b2522/go.mod h1:ZjyILWgesfNpC6sMxTJOJm9Kp84zZh5NQWvqDGG3Qr8=
@@ -591,8 +591,8 @@ golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96b
591591
golang.org/x/net v0.0.0-20211112202133-69e39bad7dc2/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
592592
golang.org/x/net v0.0.0-20220722155237-a158d28d115b/go.mod h1:XRhObCWvk6IyKnWLug+ECip1KBveYUHfp+8e9klMJ9c=
593593
golang.org/x/net v0.2.0/go.mod h1:KqCZLdyyvdV855qA2rE3GC2aiw5xGR5TEjj8smXukLY=
594-
golang.org/x/net v0.17.0 h1:pVaXccu2ozPjCXewfr1S7xza/zcXTity9cCdXQYSjIM=
595-
golang.org/x/net v0.17.0/go.mod h1:NxSsAGuq816PNPmqtQdLE42eU2Fs7NoRIZrHJAlaCOE=
594+
golang.org/x/net v0.23.0 h1:7EYJ93RZ9vYSZAIb2x3lnuvqO5zneoD6IvWjuhfxjTs=
595+
golang.org/x/net v0.23.0/go.mod h1:JKghWKKOSdJwpW2GEx0Ja7fmaKnMsbu+MWVZTokSYmg=
596596
golang.org/x/oauth2 v0.0.0-20180821212333-d2e6202438be/go.mod h1:N/0e6XlmueqKjAGxoOufVs8QHGRruUQn6yWY3a++T0U=
597597
golang.org/x/oauth2 v0.0.0-20190226205417-e64efc72b421/go.mod h1:gOpvHmFTYa4IltrdGE7lF6nIHvwfUNPOp7c8zoXwtLw=
598598
golang.org/x/oauth2 v0.0.0-20190604053449-0f29369cfe45/go.mod h1:gOpvHmFTYa4IltrdGE7lF6nIHvwfUNPOp7c8zoXwtLw=
@@ -663,14 +663,14 @@ golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBc
663663
golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
664664
golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
665665
golang.org/x/sys v0.2.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
666-
golang.org/x/sys v0.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc=
667-
golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
666+
golang.org/x/sys v0.18.0 h1:DBdB3niSjOA/O0blCZBqDefyWNYveAYMNF1Wum0DYQ4=
667+
golang.org/x/sys v0.18.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
668668
golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
669669
golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8=
670670
golang.org/x/term v0.0.0-20220526004731-065cf7ba2467/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8=
671671
golang.org/x/term v0.2.0/go.mod h1:TVmDHMZPmdnySmBfhjOoOdhjzdE1h4u1VwSiw2l1Nuc=
672-
golang.org/x/term v0.15.0 h1:y/Oo/a/q3IXu26lQgl04j/gjuBDOBlx7X6Om1j2CPW4=
673-
golang.org/x/term v0.15.0/go.mod h1:BDl952bC7+uMoWR75FIrCDx79TPU9oHkTZ9yRbYOrX0=
672+
golang.org/x/term v0.18.0 h1:FcHjZXDMxI8mM3nwhX9HlKop4C0YQvCVCdwYl2wOtE8=
673+
golang.org/x/term v0.18.0/go.mod h1:ILwASektA3OnRv7amZ1xhE/KTR+u50pbXfZ03+6Nx58=
674674
golang.org/x/text v0.0.0-20170915032832-14c0d48ead0c/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
675675
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
676676
golang.org/x/text v0.3.1-0.20180807135948-17ff2d5776d2/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

Diff for: internal/options/options.go

+2
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66
"os"
77

88
"github.com/spf13/pflag"
9+
"go.uber.org/zap/zapcore"
910
"sigs.k8s.io/controller-runtime/pkg/log/zap"
1011
)
1112

@@ -39,6 +40,7 @@ func (o *Options) processFlags() {
3940
// Add the zap logger flag set to the CLI. The flag set must
4041
// be added before calling pflag.Parse().
4142
o.Zap.BindFlags(flag.CommandLine)
43+
o.Zap.Level = zapcore.Level(-1) // Set to debug to not alter current behavior. TODO: Remove when configurable.
4244

4345
// Add flags registered by imported packages (e.g. glog and
4446
// controller-runtime)

Diff for: main.go

+25-24
Original file line numberDiff line numberDiff line change
@@ -63,10 +63,11 @@ func main() {
6363
logf.SetLogger(zap.New(zap.UseFlagOptions(&opts.Zap)))
6464

6565
log := logf.Log.WithName("DeploymentValidation")
66+
logVersion(log)
6667

6768
log.Info("Setting Up Manager")
6869

69-
mgr, err := setupManager(log, opts)
70+
mgr, err := setupManager(log.V(1), opts)
7071
if err != nil {
7172
fail(log, err, "Unexpected error occurred while setting up manager")
7273
}
@@ -78,34 +79,33 @@ func main() {
7879
}
7980
}
8081

81-
func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error) {
82-
logVersion(log)
82+
func setupManager(logger logr.Logger, opts options.Options) (manager.Manager, error) {
8383

84-
log.Info("Load KubeConfig")
84+
logger.Info("Load KubeConfig")
8585

8686
cfg, err := config.GetConfig()
8787
if err != nil {
8888
return nil, fmt.Errorf("getting config: %w", err)
8989
}
9090

91-
log.Info("Initialize Manager")
91+
logger.Info("Initialize Manager")
9292

93-
mgr, err := initManager(log, opts, cfg)
93+
mgr, err := initManager(logger, opts, cfg)
9494
if err != nil {
9595
return nil, fmt.Errorf("initializing manager: %w", err)
9696
}
9797

98-
log.Info("Registering Components")
98+
logger.Info("Registering Components")
9999

100-
log.Info("Initialize Prometheus Registry")
100+
logger.Info("Initialize Prometheus Registry")
101101

102102
reg := prometheus.NewRegistry()
103103
metrics, err := dvoProm.PreloadMetrics(reg)
104104
if err != nil {
105105
return nil, fmt.Errorf("preloading kube-linter metrics: %w", err)
106106
}
107107

108-
log.Info(fmt.Sprintf("Initialize Prometheus metrics endpoint on %q", opts.MetricsEndpoint()))
108+
logger.Info("Initialize Prometheus metrics endpoint", "endpoint", opts.MetricsEndpoint())
109109

110110
srv, err := dvoProm.NewServer(reg, opts.MetricsPath, fmt.Sprintf(":%d", opts.MetricsPort))
111111
if err != nil {
@@ -116,7 +116,7 @@ func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error
116116
return nil, fmt.Errorf("adding metrics server to manager: %w", err)
117117
}
118118

119-
log.Info("Initialize ConfigMap watcher")
119+
logger.Info("Initialize ConfigMap watcher")
120120

121121
cmWatcher, err := configmap.NewWatcher(cfg)
122122
if err != nil {
@@ -127,14 +127,14 @@ func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error
127127
return nil, fmt.Errorf("adding configmap watcher to manager: %w", err)
128128
}
129129

130-
log.Info("Initialize Validation Engine")
130+
logger.Info("Initialize Validation Engine")
131131

132132
validationEngine, err := validations.NewValidationEngine(opts.ConfigFile, metrics)
133133
if err != nil {
134134
return nil, fmt.Errorf("initializing validation engine: %w", err)
135135
}
136136

137-
log.Info("Initialize Reconciler")
137+
logger.Info("Initialize Reconciler")
138138

139139
discoveryClient, err := discovery.NewDiscoveryClientForConfig(mgr.GetConfig())
140140
if err != nil {
@@ -153,16 +153,16 @@ func setupManager(log logr.Logger, opts options.Options) (manager.Manager, error
153153
return mgr, nil
154154
}
155155

156-
func fail(log logr.Logger, err error, msg string) {
157-
log.Error(err, msg)
156+
func fail(logger logr.Logger, err error, msg string) {
157+
logger.Error(err, msg)
158158

159159
os.Exit(1)
160160
}
161161

162-
func logVersion(log logr.Logger) {
163-
log.Info(fmt.Sprintf("Operator Version: %s", version.Version))
164-
log.Info(fmt.Sprintf("Go Version: %s", runtime.Version()))
165-
log.Info(fmt.Sprintf("Go OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH))
162+
func logVersion(logger logr.Logger) {
163+
logger.Info(fmt.Sprintf("Operator Version: %s", version.Version))
164+
logger.Info(fmt.Sprintf("Go Version: %s", runtime.Version()))
165+
logger.Info(fmt.Sprintf("Go OS/Arch: %s/%s", runtime.GOOS, runtime.GOARCH))
166166
}
167167

168168
func initializeScheme() (*k8sruntime.Scheme, error) {
@@ -185,7 +185,7 @@ func initializeScheme() (*k8sruntime.Scheme, error) {
185185

186186
var errWatchNamespaceNotSet = errors.New("'WatchNamespace' not set")
187187

188-
func getManagerOptions(scheme *k8sruntime.Scheme, opts options.Options) (manager.Options, error) {
188+
func getManagerOptions(scheme *k8sruntime.Scheme, opts options.Options, logger logr.Logger) (manager.Options, error) {
189189
ns, ok := opts.GetWatchNamespace()
190190
if !ok {
191191
return manager.Options{}, errWatchNamespaceNotSet
@@ -196,6 +196,7 @@ func getManagerOptions(scheme *k8sruntime.Scheme, opts options.Options) (manager
196196
// disable caching of everything
197197
NewClient: newClient,
198198
Scheme: scheme,
199+
Logger: logger,
199200
}
200201

201202
// disable controller-runtime managed prometheus endpoint
@@ -241,15 +242,15 @@ func kubeClientQPS() (float32, error) {
241242
return qps, err
242243
}
243244

244-
func initManager(log logr.Logger, opts options.Options, cfg *rest.Config) (manager.Manager, error) {
245-
log.Info("Initialize Scheme")
245+
func initManager(logger logr.Logger, opts options.Options, cfg *rest.Config) (manager.Manager, error) {
246+
logger.Info("Initialize Scheme")
246247
scheme, err := initializeScheme()
247248
if err != nil {
248249
return nil, fmt.Errorf("initializing scheme: %w", err)
249250
}
250251

251-
log.Info("Getting Manager Options")
252-
mgrOpts, err := getManagerOptions(scheme, opts)
252+
logger.Info("Getting Manager Options")
253+
mgrOpts, err := getManagerOptions(scheme, opts, logger)
253254
if err != nil {
254255
return nil, fmt.Errorf("getting manager options: %w", err)
255256
}
@@ -259,7 +260,7 @@ func initManager(log logr.Logger, opts options.Options, cfg *rest.Config) (manag
259260
return nil, fmt.Errorf("getting new manager: %w", err)
260261
}
261262

262-
log.Info("Adding Healthz and Readyz checks")
263+
logger.Info("Adding Healthz and Readyz checks")
263264
if err := mgr.AddHealthzCheck("health", healthz.Ping); err != nil {
264265
return nil, fmt.Errorf("adding healthz check: %w", err)
265266
}

Diff for: pkg/controller/generic_reconciler.go

+17-12
Original file line numberDiff line numberDiff line change
@@ -65,7 +65,7 @@ func NewGenericReconciler(
6565
watchNamespaces: newWatchNamespacesCache(),
6666
objectValidationCache: newValidationCache(),
6767
currentObjects: newValidationCache(),
68-
logger: ctrl.Log.WithName("reconcile"),
68+
logger: ctrl.Log.WithName("GenericReconciler"),
6969
cmWatcher: cmw,
7070
validationEngine: validationEngine,
7171
}, nil
@@ -116,6 +116,7 @@ func (gr *GenericReconciler) Start(ctx context.Context) error {
116116
// stop reconciling
117117
return nil
118118
default:
119+
gr.logger.Info("Reconciliation loop has started")
119120
if err := gr.reconcileEverything(ctx); err != nil && !errors.Is(err, context.Canceled) {
120121
// TODO: Improve error handling so that error can be returned to manager from here
121122
// this is done to make sure errors caused by skew in k8s version on server and
@@ -124,6 +125,7 @@ func (gr *GenericReconciler) Start(ctx context.Context) error {
124125
// nikthoma: oct 11, 2022
125126
gr.logger.Error(err, "error fetching and validating resource types")
126127
}
128+
gr.logger.Info("Reconciliation loop has ended")
127129
}
128130
}
129131
}
@@ -147,10 +149,11 @@ func (gr *GenericReconciler) LookForConfigUpdates(ctx context.Context) {
147149
gr.objectValidationCache.drain()
148150
gr.validationEngine.ResetMetrics()
149151

150-
gr.logger.Info(
152+
gr.logger.V(1).Info(
151153
"Current set of enabled checks",
152154
"checks", strings.Join(gr.validationEngine.GetEnabledChecks(), ", "),
153155
)
156+
gr.logger.Info("The ConfigMap has been updated")
154157

155158
case <-ctx.Done():
156159
return
@@ -169,7 +172,7 @@ func (gr *GenericReconciler) reconcileEverything(ctx context.Context) error {
169172
})
170173

171174
for i, resource := range gr.apiResources {
172-
gr.logger.Info("apiResource", "no", i+1, "Group", resource.Group,
175+
gr.logger.V(1).Info("apiResource", "no", i+1, "Group", resource.Group,
173176
"Version", resource.Version,
174177
"Kind", resource.Kind)
175178
}
@@ -287,15 +290,17 @@ func (gr *GenericReconciler) processNamespacedResources(
287290
ctx context.Context, gvks []schema.GroupVersionKind, namespaces *[]namespace) error {
288291

289292
for _, ns := range *namespaces {
293+
logger := gr.logger.WithValues("ns", ns.name).V(1)
294+
290295
relatedObjects, err := gr.groupAppObjects(ctx, ns.name, gvks)
291296
if err != nil {
292297
return err
293298
}
294299
for label, objects := range relatedObjects {
295-
gr.logger.Info("reconcileNamespaceResources",
296-
"Reconciling group of", len(objects), "objects with labels", label,
297-
"in the namespace", ns.name)
298-
err := gr.reconcileGroupOfObjects(objects, ns.uid)
300+
logger.Info("Reconciling Namespace Resources",
301+
"items", len(objects), "labels", label)
302+
303+
err := gr.reconcileGroupOfObjects(objects, ns)
299304
if err != nil {
300305
return fmt.Errorf(
301306
"reconciling related objects with labels '%s': %w", label, err,
@@ -307,10 +312,10 @@ func (gr *GenericReconciler) processNamespacedResources(
307312
return nil
308313
}
309314

310-
func (gr *GenericReconciler) reconcileGroupOfObjects(objs []*unstructured.Unstructured, namespaceUID string) error {
315+
func (gr *GenericReconciler) reconcileGroupOfObjects(objs []*unstructured.Unstructured, ns namespace) error {
311316

312-
if gr.allObjectsValidated(objs, namespaceUID) {
313-
gr.logger.Info("reconcileGroupOfObjects", "All objects are validated", "Nothing to do")
317+
if gr.allObjectsValidated(objs, ns.uid) {
318+
gr.logger.V(1).Info("All objects are validated, ending loop", "ns", ns.name)
314319
return nil
315320
}
316321

@@ -323,12 +328,12 @@ func (gr *GenericReconciler) reconcileGroupOfObjects(objs []*unstructured.Unstru
323328
cliObjects = append(cliObjects, typedClientObject)
324329
}
325330

326-
outcome, err := gr.validationEngine.RunValidationsForObjects(cliObjects, namespaceUID)
331+
outcome, err := gr.validationEngine.RunValidationsForObjects(cliObjects, ns.uid)
327332
if err != nil {
328333
return fmt.Errorf("running validations: %w", err)
329334
}
330335
for _, o := range objs {
331-
gr.objectValidationCache.store(o, namespaceUID, outcome)
336+
gr.objectValidationCache.store(o, ns.uid, outcome)
332337
}
333338

334339
return nil

Diff for: pkg/validations/utils.go

+2-4
Original file line numberDiff line numberDiff line change
@@ -23,8 +23,7 @@ import (
2323
func GetKubeLinterRegistry() (checkregistry.CheckRegistry, error) {
2424
registry := checkregistry.New()
2525
if err := builtinchecks.LoadInto(registry); err != nil {
26-
log.Error(err, "failed to load kube-linter built-in validations")
27-
return nil, err
26+
return nil, fmt.Errorf("failed to load kube-linter built-in validations: %w", err)
2827
}
2928

3029
return registry, nil
@@ -49,8 +48,7 @@ func GetAllNamesFromRegistry(reg checkregistry.CheckRegistry) ([]string, error)
4948

5049
checks, err := configresolver.GetEnabledChecksAndValidate(&cfg, reg)
5150
if err != nil {
52-
log.Error(err, "error getting enabled validations")
53-
return nil, err
51+
return nil, fmt.Errorf("error getting enabled validations: %w", err)
5452
}
5553

5654
return checks, nil

0 commit comments

Comments
 (0)