Make logging more consumable #143

roypaulin · 2022-01-20T18:33:07Z

Before, logging for the operator wrote everything to stdout. The logging levels were not tunable, all of the error, warning and info messages are written out.
Now thanks to new helm parameters, we can log to file too and we built log rotation into the operator. We add 2 extra parameters, stdout and devMode that we use respectively to enforce logging to stdout and to select developement/production mode.
The scenario are as follow:

if no filepath is specified, we log to stdout only and keep as level debug. So the ability to select the level is something supported only when a filepath is given. (That could be easily changed)
if filepath is invalid or you do not have access to the file you will have error msgs all over stdout .
if a valid filepath is specififed and stdout is false, the logging will be only to file, if stdout is true, the logging will be to both file and stdout

First it was decided to define more helm parameters for sidecar and volume that are used for testing, as the manager container is distroless, but I decided instead to patch to the already installed operator the sidecar container and the volume and then verify that the log has been done to the file using that sidecar.

Closes #56
Closes #116

roypaulin · 2022-01-20T18:37:43Z

I used busybox for the sidecar container but I don't think we want that. Any suggestion for a sidecar container?

Also I ran into a funlen issue as the 50 statements/func limit has been exceeded in the main (now there are 53). So I am wondering whether we can move the flag parameters setting inside init func in order to decrease the number of statements in the main.

spilchen · 2022-01-21T01:19:20Z

Also I ran into a funlen issue as the 50 statements/func limit has been exceeded in the main (now there are 53). So I am wondering whether we can move the flag parameters setting inside init func in order to decrease the number of statements in the main.

Yes, by all means move to a separate function to keep the code readable.

spilchen

Some initial comments.

spilchen · 2022-01-21T01:30:45Z

scripts/create-patch.sh

+        - while true; do tail -n 1 /var/logs/try.log; sleep 5;done
+        command:
+        - /bin/sh
+        image: busybox


Rather than busybox, lets use one that we already use in the testsuite. The requirement for what is needed in the image is quite low, so most will do. I would suggest quay.io/helmpack/chart-testing:v3.3.1 or amazon/aws-cli:2.2.24. Introducing a new image puts disk pressure on our CI runs as we already get pretty close to the limit.

spilchen · 2022-01-21T01:33:54Z

helm-charts/verticadb-operator/values.yaml

+  # level is the minimum logging level. Valid values are: debug, info, warn, and error
+  level: info
+  # stdOut is used to enforce logging to stdout.
+  stdOut: false


minor nit: we do camelcase all the parms, but standard out is usually always shortened to stdout. So lets use that.

spilchen · 2022-01-21T01:37:53Z

helm-charts/verticadb-operator/values.yaml

+  stdOut: false
+
+# devEnables development mode if true and production mode otherwise
+dev: true


dev mode should not be the default for the helm chart. It should only be the default when we deploy through the makefile. That way it will stay off when used in production.

spilchen · 2022-01-21T01:38:57Z

helm-charts/verticadb-operator/values.yaml

+  # stdOut is used to enforce logging to stdout.
+  stdOut: false
+
+# devEnables development mode if true and production mode otherwise


This relates to logging, so should dev be part of the logging group. Can we add some comments about how logging changes when in dev mode?

spilchen · 2022-01-21T01:40:49Z

config/default/manager_auth_proxy_patch.yaml

@@ -24,3 +24,10 @@ spec:
        - "--health-probe-bind-address=:8081"
        - "--metrics-bind-address=127.0.0.1:8080"
        - "--leader-elect"
+        - "--filepath="


I take it these are all placeholders that we patch in when applying the helm chart. How does this work for olm? Can we have a comment to explain this part a bit.

helm-charts/verticadb-operator/values.yaml

spilchen

I like the approach. Here are some remaining comments.

spilchen · 2022-01-21T12:31:23Z

helm-charts/verticadb-operator/values.yaml

+  # level is the minimum logging level. Valid values are: debug, info, warn, and error
+  level: info
+  # stdOut is used to enforce logging to stdout.
+  stdOut: false


This is a hard parameter to explain. Instead of a new one, could we just piggyback on dev. If dev is true, we always log to stdout, even if a file path is choosen. If dev is false, we only log to the file or stdout never both.

Yes sounds good

spilchen · 2022-01-21T12:35:43Z

scripts/create-patch.sh

@@ -0,0 +1,42 @@
+#!/bin/bash


Does this need to be a script? Could it be just a yaml manifest in the custom-cert-webhook directory?

No. I thought it was not a good idea to change the dir structure. I will add a manifest in custom-cert-webhook

spilchen · 2022-01-21T12:36:43Z

scripts/create-patch.sh

+          name: shared-data
+      - args:
+        - -c
+        - while true; do tail -n 1 /var/logs/try.log; sleep 5;done


Can we be consistent with the log directory between the two containers? Any reason why couldn't make it /logs in both?

spilchen · 2022-01-21T12:37:18Z

tests/e2e/custom-cert-webhook/12-check-log-file.yaml

+  - script: |
+      PN=$(kubectl get pods -n $NAMESPACE --no-headers -o custom-columns=":metadata.name" | grep verticadb ) \
+      && kubectl wait --for=condition=Ready=true pod/$PN -n $NAMESPACE \
+      && kubectl exec $PN -n $NAMESPACE -c sidecar-container -- tail -n 1  var/logs/try.log


Can we add a leading '/' to the path?

Yes I forgot that, will add it.

spilchen · 2022-01-21T12:48:50Z

cmd/operator/main.go

+// zapcore.Level. If the string level is invalid, it returns the default
+// level
+func getZapcoreLevel(lvl string) zapcore.Level {
+	lvls := map[string]zapcore.Level{


I think you can use zapcore.UnmarshalText here instead of having the map.

Ok I will take a look, thanks.

spilchen · 2022-01-21T12:51:52Z

cmd/operator/main.go

+	lvl := zap.NewAtomicLevelAt(zap.DebugLevel)
+	if logArgs.FilePath != "" {
+		w := getLogWriter(logArgs.FilePath, logArgs.MaxFileAge, logArgs.MaxFileSize, logArgs.MaxFileRotation)
+		lvl = zap.NewAtomicLevelAt(getZapcoreLevel(logArgs.Level))


We will want the level to be configurable, even when not using FilePath.

spilchen · 2022-01-21T12:55:24Z

cmd/operator/main.go

+	writes := []zapcore.WriteSyncer{}
+	lvl := zap.NewAtomicLevelAt(zap.DebugLevel)
+	if logArgs.FilePath != "" {
+		w := getLogWriter(logArgs.FilePath, logArgs.MaxFileAge, logArgs.MaxFileSize, logArgs.MaxFileRotation)


Can we just pass in the Logging struct instead of each individual field?

Yes I am already changing that.

spilchen · 2022-01-21T20:54:34Z

cmd/operator/main.go

+		"The maximum size in megabytes of the log file "+
+			"before it gets rotated.")
+	flag.IntVar(&l.MaxFileAge, "maxfileage", DefaultMaxFileAge,
+		"This is the maximum age, in days, of the logging "+


Can the help usage be this? It was taken from the lumberjack documentation:

The maximum number of days to retain old log files based on the timestamp encoded in the file.

spilchen · 2022-01-21T20:55:24Z

cmd/operator/main.go

@@ -73,6 +81,35 @@ func init() {
 	//+kubebuilder:scaffold:scheme
 }

+// setLoggingFlagArgs define logging flags with specified names and default values
+func (l *Logging) setLoggingFlagArgs() {
+	flag.StringVar(&l.FilePath, "filepath", "", "The file logging will write to.")


Can the help text say?

The path to the log file. If omitted, all logging will be written to stdout.

spilchen · 2022-01-21T20:56:02Z

cmd/operator/main.go

+		"This is the maximum age, in days, of the logging "+
+			"before log rotation gets rid of it.")
+	flag.IntVar(&l.MaxFileRotation, "maxfilerotation", DefaultMaxFileRotation,
+		"this is the maximum number of files that are kept in rotation before the old ones are removed.")


minor: "The maximum number of files that are kept in rotation before the old ones are removed"

spilchen · 2022-01-21T20:59:35Z

helm-charts/verticadb-operator/README.md

@@ -5,5 +5,11 @@ This helm chart will install the operator and an admission controller webhook.
 | image.name | The name of image that runs the operator. | vertica/verticadb-operator:1.0.0 |
 | webhook.caBundle | A PEM encoded CA bundle that will be used to validate the webhook's server certificate.  If unspecified, system trust roots on the apiserver are used. | |
 | webhook.tlsSecret | The webhook requires a TLS certficate to work.  By default we rely on cert-manager to be installed as we use it generate the cert.  If you don't want to use cert-manager, you need to specify your own cert, which you can do with this parameter.  When set, it is a name of a secret in the same namespace the chart is being installed in.  The secret must have the keys: tls.key, ca.crt, and tls.crt. | |
+| logging.filePath | When specified, it is the file logging will write to. When empty, logging will write to standard out.  | |
+| logging.maxFileSize | When logging to a file, it is the maximum size, in MB, of the logging file before log rotation occurs. | 500 |
+| logging.maxFileAge | When logging to a file, it is the maximum age, in days, of the logging before log rotation gets rid of it. | 7 |


Can the description be:

The maximum number of days to retain old log files based on the timestamp encoded in the file. This is only applicable if logging to a file.

spilchen · 2022-01-21T21:05:59Z

helm-charts/verticadb-operator/values.yaml

+  # example:
+  # dev ->  2022-01-21T12:50:10.078Z        INFO    controller-runtime.certwatcher  Starting certificate watcher
+  # prod -> 1.6427683530752437e+09  info    controller-runtime.certwatcher  Starting certificate watcher
+  dev: false


I think dev mode disables sampling of logging messages and produces stack traces more liberally. The are probably the key things to mention.

Yeah. Those are more meaningful.

spilchen · 2022-01-21T21:06:57Z

scripts/create-helm-charts.sh

-sed -i "s/--level=/--level={{ .Values.logging.level }}/" $TEMPLATE_DIR/verticadb-operator-controller-manager-deployment.yaml
-sed -i "s/--dev=/--dev={{ .Values.dev }}/" $TEMPLATE_DIR/verticadb-operator-controller-manager-deployment.yaml
-sed -i "s/--stdout=/--stdout={{ .Values.logging.stdOut }}/" $TEMPLATE_DIR/verticadb-operator-controller-manager-deployment.yaml
+sed -i "s/--maxfilesize=500/--maxfilesize={{ .Values.logging.maxFileSize }}/" $TEMPLATE_DIR/verticadb-operator-controller-manager-deployment.yaml


We are duplicating these defaults around a lot. Can we do pattern matching for the value of each of the parms?

Sorry what do you mean by pattern matching?

You mean with reg exp?

Yeah, add a reg exp portion so that we don't hard code the default in the pattern.

cmd/operator/main.go

spilchen

Looks good.

spilchen · 2022-01-25T14:36:17Z

changes/unreleased/Added-20220125-150323.yaml

+  operator pod
+time: 2022-01-25T15:03:23.6521708+01:00
+custom:
+  Issue: "116"


Lets use the PR issue number of 143. We can still find our way back to the original GitHub issue.

Make logging more consumable

c76caff

spilchen reviewed Jan 21, 2022

View reviewed changes

Apply 1st review comments

177c08a

spilchen reviewed Jan 21, 2022

View reviewed changes

Apply 2nd review comments

477d53e

roypaulin commented Jan 24, 2022

View reviewed changes

cmd/operator/main.go Show resolved Hide resolved

spilchen approved these changes Jan 25, 2022

View reviewed changes

spilchen reviewed Jan 25, 2022

View reviewed changes

roypaulin force-pushed the improve-logging branch from a2530f7 to 477d53e Compare January 25, 2022 14:45

Add Changie entry for logging changes

31102ad

spilchen merged commit ff10c43 into vertica:main Jan 25, 2022

roypaulin deleted the improve-logging branch March 10, 2022 20:33

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make logging more consumable #143

Make logging more consumable #143

roypaulin commented Jan 20, 2022 •

edited by spilchen

Loading

roypaulin commented Jan 20, 2022 •

edited

Loading

spilchen commented Jan 21, 2022

spilchen left a comment

spilchen Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

spilchen left a comment

spilchen Jan 21, 2022

roypaulin Jan 21, 2022

spilchen Jan 21, 2022

roypaulin Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

roypaulin Jan 21, 2022

spilchen Jan 21, 2022

roypaulin Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

roypaulin Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

spilchen Jan 21, 2022

roypaulin Jan 21, 2022

spilchen Jan 21, 2022

roypaulin Jan 21, 2022

roypaulin Jan 21, 2022

spilchen Jan 24, 2022

spilchen left a comment

spilchen Jan 25, 2022

Make logging more consumable #143

Make logging more consumable #143

Conversation

roypaulin commented Jan 20, 2022 • edited by spilchen Loading

roypaulin commented Jan 20, 2022 • edited Loading

spilchen commented Jan 21, 2022

spilchen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

spilchen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

spilchen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

roypaulin commented Jan 20, 2022 •

edited by spilchen

Loading

roypaulin commented Jan 20, 2022 •

edited

Loading