From e745fe0489b50e3d73bafb11ce51c77f1f48932a Mon Sep 17 00:00:00 2001 From: Richard Wall Date: Mon, 14 Oct 2024 07:25:02 +0100 Subject: [PATCH 01/12] Log with klog to stdout and stderr in JSON format Signed-off-by: Richard Wall --- cmd/root.go | 6 ++ go.mod | 7 +- hack/e2e/test.sh | 13 ++-- pkg/logs/logs.go | 101 +++++++++++++++++++++++++++- pkg/logs/logs_test.go | 148 ++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 263 insertions(+), 12 deletions(-) create mode 100644 pkg/logs/logs_test.go diff --git a/cmd/root.go b/cmd/root.go index a83f604b..826b4295 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -5,6 +5,7 @@ import ( "os" "strings" + "github.com/jetstack/preflight/pkg/logs" "github.com/spf13/cobra" "github.com/spf13/pflag" ) @@ -17,6 +18,9 @@ var rootCmd = &cobra.Command{ configuration checks using Open Policy Agent (OPA). Preflight checks are bundled into Packages`, + PersistentPreRun: func(cmd *cobra.Command, args []string) { + logs.Initialize() + }, } func init() { @@ -28,6 +32,8 @@ func init() { // Execute adds all child commands to the root command and sets flags appropriately. // This is called by main.main(). It only needs to happen once to the rootCmd. func Execute() { + logs.AddFlags(rootCmd.PersistentFlags()) + if err := rootCmd.Execute(); err != nil { fmt.Println(err) os.Exit(1) diff --git a/go.mod b/go.mod index 8c0d2cc4..307a7710 100644 --- a/go.mod +++ b/go.mod @@ -3,6 +3,7 @@ module github.com/jetstack/preflight go 1.22.0 require ( + github.com/Venafi/vcert/v5 v5.7.1 github.com/cenkalti/backoff v2.2.1+incompatible github.com/d4l3k/messagediff v1.2.1 github.com/fatih/color v1.17.0 @@ -22,13 +23,13 @@ require ( k8s.io/api v0.31.1 k8s.io/apimachinery v0.31.1 k8s.io/client-go v0.31.1 + k8s.io/component-base v0.31.0 sigs.k8s.io/controller-runtime v0.19.0 sigs.k8s.io/yaml v1.4.0 ) require ( github.com/Khan/genqlient v0.7.0 // indirect - github.com/Venafi/vcert/v5 v5.7.1 // indirect github.com/antlr4-go/antlr/v4 v4.13.0 // indirect github.com/asaskevich/govalidator v0.0.0-20230301143203-a9d515a09cc2 // indirect github.com/aymerick/douceur v0.2.0 // indirect @@ -37,6 +38,7 @@ require ( github.com/fsnotify/fsnotify v1.7.0 // indirect github.com/fxamacker/cbor/v2 v2.7.0 // indirect github.com/go-http-utils/headers v0.0.0-20181008091004-fed159eddc2a // indirect + github.com/go-logr/zapr v1.3.0 // indirect github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da // indirect github.com/google/cel-go v0.20.1 // indirect github.com/google/gnostic-models v0.6.9-0.20230804172637-c7be7c783f49 // indirect @@ -62,7 +64,6 @@ require ( gopkg.in/ini.v1 v1.67.0 // indirect k8s.io/apiextensions-apiserver v0.31.0 // indirect k8s.io/apiserver v0.31.0 // indirect - k8s.io/component-base v0.31.0 // indirect ) require ( @@ -100,7 +101,7 @@ require ( google.golang.org/protobuf v1.34.2 // indirect gopkg.in/inf.v0 v0.9.1 // indirect gopkg.in/yaml.v3 v3.0.1 - k8s.io/klog/v2 v2.130.1 // indirect + k8s.io/klog/v2 v2.130.1 k8s.io/kube-openapi v0.0.0-20240430033511-f0e62f92d13f // indirect k8s.io/utils v0.0.0-20240711033017-18e509b52bc8 // indirect sigs.k8s.io/json v0.0.0-20221116044647-bc3834ca7abd // indirect diff --git a/hack/e2e/test.sh b/hack/e2e/test.sh index a7b90cbf..c1f88be6 100755 --- a/hack/e2e/test.sh +++ b/hack/e2e/test.sh @@ -191,14 +191,11 @@ EOF envsubst (grep -v -e "reflector\.go" -e "datagatherer" -e "data gatherer" >/dev/stderr) \ - | grep -q "Data sent successfully" + --follow \ + --namespace venafi \ + | timeout 60 jq 'if .msg | test("Data sent successfully") then . | halt_error(0) end' diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index 042281ae..8360bc49 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -1,8 +1,107 @@ package logs import ( + "fmt" "log" "os" + + "github.com/spf13/pflag" + "k8s.io/apimachinery/pkg/util/runtime" + "k8s.io/apimachinery/pkg/util/sets" + "k8s.io/component-base/featuregate" + "k8s.io/component-base/logs" + logsapi "k8s.io/component-base/logs/api/v1" + _ "k8s.io/component-base/logs/json/register" +) + +// venafi-kubernetes-agent follows [Kubernetes Logging Conventions] +// and writes logs in [Kubernetes JSON logging format] by default. +// It does not support named levels (AKA severity), instead it uses arbitrary levels. +// Errors are logged to stderr and Info messages to stdout, because that is how +// some cloud logging systems (notably Google Cloud Logs Explorer) assign a +// severity (INFO or ERROR) in the UI. +// Messages logged using the legacy log module are all logged as Info messages +// with level=0. +// +// Further reading: +// - [Kubernetes logging conventions](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md) +// - [Kubernetes JSON logging format](https://kubernetes.io/docs/concepts/cluster-administration/system-logs/#json-log-format) +// - [Why not named levels, like Info/Warning/Error?](https://github.com/go-logr/logr?tab=readme-ov-file#why-not-named-levels-like-infowarningerror) +// - [GKE logs best practices](https://cloud.google.com/kubernetes-engine/docs/concepts/about-logs#best_practices) +// - [Structured Logging KEP](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/1602-structured-logging/README.md) +// - [Examples of using k8s.io/component-base/logs](https://github.com/kubernetes/kubernetes/tree/master/staging/src/k8s.io/component-base/logs/example), +// upon which this code was based. + +var ( + // Deprecated: Log is a `log` logger, which is being phased out. + Log = log.Default() + // 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 + // not like the split-stream behavior and a Venafi field engineer can + // instruct them to patch --log-json-split-stream=false on to the Deployment + // arguments. + visibleFlagNames = sets.New[string]("v", "vmodule", "logging-format") + // This default logging configuration will be updated with values from the + // logging flags, even those that are hidden. + configuration = logsapi.NewLoggingConfiguration() + // Logging features will be added to this feature gate, but the + // feature-gates flag will be hidden from the user. + features = featuregate.NewFeatureGate() ) -var Log = log.New(os.Stderr, "", log.LstdFlags) +func init() { + runtime.Must(logsapi.AddFeatureGates(features)) + // Turn on ALPHA options to enable the split-stream logging options. + runtime.Must(features.OverrideDefault(logsapi.LoggingAlphaOptions, true)) +} + +// AddFlags adds log related flags to the supplied flag set. +// +// The default logging format is changed to JSON. The default in Kubernetes +// component base is "text", for backwards compatibility, but that is not a +// concern for venafi-kubernetes-agent. +// The split-stream options are enabled by default, so that errors are logged to +// stderr and info to stdout, allowing cloud logging systems to assign an +// severity INFO or ERROR to the messages. +func AddFlags(fs *pflag.FlagSet) { + var tfs pflag.FlagSet + logsapi.AddFlags(configuration, &tfs) + features.AddFlag(&tfs) + tfs.VisitAll(func(f *pflag.Flag) { + if !visibleFlagNames.Has(f.Name) { + tfs.MarkHidden(f.Name) + } + // The default is "text" and the usage string includes details about how + // JSON logging is only available when BETA logging features are + // enabled, but that's not relevant here because the feature is enabled + // by default. + if f.Name == "logging-format" { + f.Usage = `Sets the log format. Permitted formats: "json", "text".` + f.DefValue = "json" + runtime.Must(f.Value.Set("json")) + } + if f.Name == "log-text-split-stream" { + f.DefValue = "true" + runtime.Must(f.Value.Set("true")) + } + if f.Name == "log-json-split-stream" { + f.DefValue = "true" + runtime.Must(f.Value.Set("true")) + } + }) + fs.AddFlagSet(&tfs) +} + +// Initialize uses k8s.io/component-base/logs, to configure the following global +// loggers: log, slog, and klog. All are configured to write in the same format. +func Initialize() { + if err := logsapi.ValidateAndApply(configuration, features); err != nil { + fmt.Fprintf(os.Stderr, "Error in logging configuration: %v\n", err) + os.Exit(2) + } + // This is a work around for a bug in vcert where it adds a `vcert: ` prefix + // to the global log logger. + // Can be removed when this is fixed upstream in vcert: https://github.com/Venafi/vcert/pull/512 + log.SetPrefix("") + logs.InitLogs() +} diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go new file mode 100644 index 00000000..80508a4b --- /dev/null +++ b/pkg/logs/logs_test.go @@ -0,0 +1,148 @@ +package logs_test + +import ( + "bytes" + "context" + "errors" + "log" + "log/slog" + "os" + "os/exec" + "strings" + "testing" + "time" + + _ "github.com/Venafi/vcert/v5" + "github.com/spf13/pflag" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "k8s.io/klog/v2" + + "github.com/jetstack/preflight/pkg/logs" +) + +// TestLogs demonstrates how the logging flags affect the logging output. +// +// The test executes itself with as a sub-process to avoid mutating the global +// logging configuration. +// +// Inspired by: +// - https://stackoverflow.com/a/67945462 +// - https://go.dev/src/flag/flag_test.go (TestExitCode) +func TestLogs(t *testing.T) { + if flags, found := os.LookupEnv("GO_CHILD_FLAG"); found { + if _, found := os.LookupEnv("GO_CHILD_SKIP_INITIALIZE"); !found { + fs := pflag.NewFlagSet("test-logs", pflag.ExitOnError) + logs.AddFlags(fs) + fs.Parse(strings.Split(flags, " ")) + logs.Initialize() + assert.Equal(t, "", log.Prefix(), "removes the `vCert: ` prefix from the global log logger") + } + + log.Print("log Print") + slog.Info("slog Info") + slog.Warn("slog Warn") + slog.Error("slog Error") + klog.Info("klog Info") + klog.Warning("klog Warning") + klog.ErrorS(errors.New("fake-error"), "klog Error") + klog.InfoS("klog InfoS", "key", "value") + logger := klog.FromContext(context.Background()).WithName("foo") + logger.V(3).Info("Contextual Info Level 3", "key", "value") + logger.Error(errors.New("fake-error"), "Contextual error", "key", "value") + + klog.FlushAndExit(time.Second, 0) + } + + tests := []struct { + name string + flags string + skipIntialize bool + expectError bool + }{ + { + name: "help", + flags: "-h", + expectError: true, + }, + { + name: "unrecognized-flag", + flags: "--foo", + expectError: true, + }, + { + name: "logging-format-unrecognized", + flags: "--logging-format=foo", + expectError: true, + }, + { + name: "original-defaults", + flags: "", + skipIntialize: true, + }, + { + name: "modified-defaults", + flags: "", + }, + { + name: "logging-format-json", + flags: "--logging-format=json", + }, + { + name: "log-json-split-stream-false", + flags: "--logging-format=json --log-json-split-stream=false", + }, + { + name: "logging-format-text", + flags: "--logging-format=text", + }, + { + name: "log-text-split-stream-false", + flags: "--logging-format=text --log-text-split-stream=false", + }, + { + name: "v-level-3", + flags: "--v=3", + }, + { + name: "vmodule-level-3", + flags: "--logging-format=text --vmodule=logs_test=3", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + cmd := exec.Command(os.Args[0], "-test.run=^TestLogs$", "-test.v") + var ( + stdout bytes.Buffer + stderr bytes.Buffer + ) + cmd.Stdout = &stdout + cmd.Stderr = &stderr + cmd.Env = append( + os.Environ(), + "GO_CHILD_FLAG="+test.flags, + ) + if test.skipIntialize { + cmd.Env = append( + cmd.Env, + "GO_CHILD_SKIP_INITIALIZE=true", + ) + } + err := cmd.Run() + + t.Logf("FLAGS\n%s\n", test.flags) + // Remove the standard output generated by `-test.v` + t.Logf("STDOUT\n%s\n", strings.TrimPrefix(stdout.String(), "=== RUN TestLogs\n")) + t.Logf("STDERR\n%s\n", stderr.String()) + if test.expectError { + var target *exec.ExitError + require.ErrorAs(t, err, &target) + require.Equal(t, 2, target.ExitCode(), "Flag parsing failures should always result in exit code 2") + t.Logf("ERROR: %v", err) + } else { + require.NoError(t, err) + } + }) + } +} From 08d5e8c077ab7ff0ce8d2ab9525402abc91abf8a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 14:55:05 +0200 Subject: [PATCH 02/12] logs_test.go: assert didn't make the test exit with 1, move to require For some reason, `assert.Equal` doesn't cause the test sub-process to exit with 1. Instead, it returns 0 which means we can't notice the error from the parent process. --- pkg/logs/logs_test.go | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index 80508a4b..c438e980 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -36,7 +36,12 @@ func TestLogs(t *testing.T) { logs.AddFlags(fs) fs.Parse(strings.Split(flags, " ")) logs.Initialize() - assert.Equal(t, "", log.Prefix(), "removes the `vCert: ` prefix from the global log logger") + + // Remember to not use `assert.Equal` from within the sub-process + // since (for some reason) `assert.Equal` doesn't cause the test + // sub-process to exit with 1. Instead, it exits with 0, which means + // we can't notice the error from the parent process. + require.Equal(t, "", log.Prefix(), "logs.Initialize should remove the `vCert: ` prefix from the global log logger") } log.Print("log Print") From dcca1b38693e9f3dbae1d614b3967a2449412f5d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 15:46:50 +0200 Subject: [PATCH 03/12] logs_test.go: assert the logs themselves That's useful to keep track what the logs look like, especially now that I'm trying to switch from plain klog to slog. --- pkg/logs/logs_test.go | 171 +++++++++++++++++++++++++++++++++++++++++- 1 file changed, 168 insertions(+), 3 deletions(-) diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index c438e980..d14b422c 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -8,13 +8,13 @@ import ( "log/slog" "os" "os/exec" + "regexp" "strings" "testing" "time" _ "github.com/Venafi/vcert/v5" "github.com/spf13/pflag" - "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "k8s.io/klog/v2" @@ -64,54 +64,178 @@ func TestLogs(t *testing.T) { flags string skipIntialize bool expectError bool + expectStdout string + expectStderr string }{ { name: "help", flags: "-h", expectError: true, + expectStdout: ` +pflag: help requested +`, + expectStderr: ` +Usage of test-logs: + --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") + -v, --v Level number for the log level verbosity + --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) +`, }, { name: "unrecognized-flag", flags: "--foo", expectError: true, + expectStdout: ` +unknown flag: --foo +`, + expectStderr: ` +unknown flag: --foo +Usage of test-logs: + --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") + -v, --v Level number for the log level verbosity + --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) +`, }, { name: "logging-format-unrecognized", flags: "--logging-format=foo", expectError: true, + expectStderr: ` +Error in logging configuration: format: Invalid value: "foo": Unsupported log format +`, }, { name: "original-defaults", flags: "", skipIntialize: true, + expectStderr: ` +vCert: 0000/00/00 00:00:00 log Print +vCert: 0000/00/00 00:00:00 INFO slog Info +vCert: 0000/00/00 00:00:00 WARN slog Warn +vCert: 0000/00/00 00:00:00 ERROR slog Error +I0000 00:00:00.000000 00000 logs_test.go:000] klog Info +W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning +E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error" +I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" +E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value" +`, }, { name: "modified-defaults", flags: "", + expectStdout: ` +{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} +`, + expectStderr: ` +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} +{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +`, }, { name: "logging-format-json", flags: "--logging-format=json", + expectStdout: ` +{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} +`, + expectStderr: ` +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} +{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +`, }, { name: "log-json-split-stream-false", flags: "--logging-format=json --log-json-split-stream=false", + expectStderr: ` +{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} +{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +`, }, { name: "logging-format-text", flags: "--logging-format=text", + expectStdout: ` +I0000 00:00:00.000000 00000 log.go:000] log Print +I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" +I0000 00:00:00.000000 00000 logs_test.go:000] klog Info +I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" +`, + expectStderr: ` +W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn" +E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error" +W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning +E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error" +E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value" +`, }, { name: "log-text-split-stream-false", flags: "--logging-format=text --log-text-split-stream=false", + expectStderr: ` +I0000 00:00:00.000000 00000 log.go:000] log Print +I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" +W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn" +E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error" +I0000 00:00:00.000000 00000 logs_test.go:000] klog Info +W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning +E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error" +I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" +E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value" +`, }, { name: "v-level-3", flags: "--v=3", + expectStdout: ` +{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} +{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual Info Level 3","v":3,"key":"value"} +`, + expectStderr: ` +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} +{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +`, }, { name: "vmodule-level-3", flags: "--logging-format=text --vmodule=logs_test=3", + expectStdout: ` +I0000 00:00:00.000000 00000 log.go:000] log Print +I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" +I0000 00:00:00.000000 00000 logs_test.go:000] klog Info +I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" +I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value" +`, + expectStderr: ` +W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn" +E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error" +W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning +E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error" +E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value" +`, }, } @@ -138,8 +262,10 @@ func TestLogs(t *testing.T) { t.Logf("FLAGS\n%s\n", test.flags) // Remove the standard output generated by `-test.v` - t.Logf("STDOUT\n%s\n", strings.TrimPrefix(stdout.String(), "=== RUN TestLogs\n")) - t.Logf("STDERR\n%s\n", stderr.String()) + stdoutStr := strings.TrimPrefix(stdout.String(), "=== RUN TestLogs\n") + stderrStr := stderr.String() + t.Logf("STDOUT\n%s\n", stdoutStr) + t.Logf("STDERR\n%s\n", stderrStr) if test.expectError { var target *exec.ExitError require.ErrorAs(t, err, &target) @@ -148,6 +274,45 @@ func TestLogs(t *testing.T) { } else { require.NoError(t, err) } + + // This trick helps with the readability of the table test: we can + // have the first "expected" log line at the same level as the other + // lines. + test.expectStdout = strings.TrimPrefix(test.expectStdout, "\n") + test.expectStderr = strings.TrimPrefix(test.expectStderr, "\n") + + require.Equal(t, test.expectStdout, replaceWithStaticTimestamps(stdoutStr), "stdout doesn't match") + require.Equal(t, test.expectStderr, replaceWithStaticTimestamps(stderrStr), "stderr doesn't match") }) } } + +var ( + timestampRegexpStdLog = regexp.MustCompile(`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}`) + timestampRegexpKlog = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6} \d{5}`) + timestampRegexpJSON = regexp.MustCompile(`"ts":\d+\.\d+`) + fileAndLineRegexpJSON = regexp.MustCompile(`"caller":"([^"]+).go:\d+"`) + fileAndLineRegexpKlog = regexp.MustCompile(` ([^:]+).go:\d+`) +) + +// Replaces the klog and JSON timestamps with a static timestamp to make it +// easier to assert the logs. It also replaces the line number with 000 as it +// often changes. +// +// I1018 15:12:57.953433 22183 logs.go:000] log +// {"ts":1729258473588.828,"caller":"log/log.go:000","msg":"log Print","v":0} +// 2024/10/18 15:40:50 log Print +// +// to the fixed: +// +// I0000 00:00:00.000000 00000 logs.go:000] log +// {"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +// 0000/00/00 00:00:00 log Print +func replaceWithStaticTimestamps(input string) string { + input = timestampRegexpKlog.ReplaceAllString(input, "0000 00:00:00.000000 00000") + input = timestampRegexpJSON.ReplaceAllString(input, `"ts":0000000000000.000`) + input = timestampRegexpStdLog.ReplaceAllString(input, "0000/00/00 00:00:00") + input = fileAndLineRegexpJSON.ReplaceAllString(input, `"caller":"$1.go:000"`) + input = fileAndLineRegexpKlog.ReplaceAllString(input, " $1.go:000") + return input +} From ba052e40524e029adce093149791254ff3028e75 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 15:57:33 +0200 Subject: [PATCH 04/12] logs.go: move to slog and show the src (vcert or agent) of the logs Before, there was no way to know if a given log came from the VCert library or from the agent itself. I had to tweak logToSlogWriter's Writer to remove the extraneous "\n" that log.Printf prints. --- pkg/logs/logs.go | 61 ++++++++++++++++++++++++++++++++++++++----- pkg/logs/logs_test.go | 14 +++++----- 2 files changed, 61 insertions(+), 14 deletions(-) diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index 8360bc49..219108d6 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -1,9 +1,12 @@ package logs import ( + "bytes" "fmt" "log" + "log/slog" "os" + "strings" "github.com/spf13/pflag" "k8s.io/apimachinery/pkg/util/runtime" @@ -33,8 +36,13 @@ import ( // upon which this code was based. var ( - // Deprecated: Log is a `log` logger, which is being phased out. - Log = log.Default() + // 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 // not like the split-stream behavior and a Venafi field engineer can @@ -95,13 +103,52 @@ func AddFlags(fs *pflag.FlagSet) { // Initialize uses k8s.io/component-base/logs, to configure the following global // loggers: log, slog, and klog. All are configured to write in the same format. func Initialize() { + // This configures the global logger in klog *and* slog, if compiled + // with Go >= 1.21. + logs.InitLogs() if err := logsapi.ValidateAndApply(configuration, features); err != nil { fmt.Fprintf(os.Stderr, "Error in logging configuration: %v\n", err) os.Exit(2) } - // This is a work around for a bug in vcert where it adds a `vcert: ` prefix - // to the global log logger. - // Can be removed when this is fixed upstream in vcert: https://github.com/Venafi/vcert/pull/512 - log.SetPrefix("") - logs.InitLogs() + + // Thanks to logs.InitLogs(), slog.Default() now uses klog as its backend. + // Thus, the client-go library, which relies on klog.Info, has the same + // logger as 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() + vcertLog.SetOutput(logToSlogWriter{slog: slog, source: "vcert"}) + // This is a work around for a bug in vcert where it adds a `vCert: ` prefix + // to the global log logger. It can be removed when this is fixed upstream + // in vcert: https://github.com/Venafi/vcert/pull/512 + vcertLog.SetPrefix("") +} + +type logToSlogWriter struct { + slog *slog.Logger + source string +} + +func (w logToSlogWriter) Write(p []byte) (n int, err error) { + // log.Printf writes a newline at the end of the message, so we need to trim + // it. + p = bytes.TrimSuffix(p, []byte("\n")) + + message := string(p) + if isCritical(message) { + w.slog.With("source", w.source).Error(message) + } else { + w.slog.With("source", w.source).Info(message) + } + return len(p), nil +} + +func isCritical(msg string) bool { + // You can implement more robust logic to detect critical log messages + return strings.Contains(msg, "FATAL") || strings.Contains(msg, "ERROR") } diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index d14b422c..bba0b6c8 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -124,7 +124,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "modified-defaults", flags: "", expectStdout: ` -{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} @@ -141,7 +141,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "logging-format-json", flags: "--logging-format=json", expectStdout: ` -{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} @@ -158,7 +158,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "log-json-split-stream-false", flags: "--logging-format=json --log-json-split-stream=false", expectStderr: ` -{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} @@ -173,7 +173,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "logging-format-text", flags: "--logging-format=text", expectStdout: ` -I0000 00:00:00.000000 00000 log.go:000] log Print +I0000 00:00:00.000000 00000 logs.go:000] "log Print" source="vcert" I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" I0000 00:00:00.000000 00000 logs_test.go:000] klog Info I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" @@ -190,7 +190,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "log-text-split-stream-false", flags: "--logging-format=text --log-text-split-stream=false", expectStderr: ` -I0000 00:00:00.000000 00000 log.go:000] log Print +I0000 00:00:00.000000 00000 logs.go:000] "log Print" source="vcert" I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn" E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error" @@ -205,7 +205,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "v-level-3", flags: "--v=3", expectStdout: ` -{"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0} +{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} @@ -223,7 +223,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "vmodule-level-3", flags: "--logging-format=text --vmodule=logs_test=3", expectStdout: ` -I0000 00:00:00.000000 00000 log.go:000] log Print +I0000 00:00:00.000000 00000 logs.go:000] "log Print" source="vcert" I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" I0000 00:00:00.000000 00000 logs_test.go:000] klog Info I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" From fda1d3eec89a6efb9b820ec48fccdefb8bdbb0cc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 14:20:47 +0200 Subject: [PATCH 05/12] logs.go: re-wrap the introductionary comment, AKA -> aka. --- pkg/logs/logs.go | 39 +++++++++++++++++++-------------------- 1 file changed, 19 insertions(+), 20 deletions(-) diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index 219108d6..9c20f4b8 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -17,23 +17,22 @@ import ( _ "k8s.io/component-base/logs/json/register" ) -// venafi-kubernetes-agent follows [Kubernetes Logging Conventions] -// and writes logs in [Kubernetes JSON logging format] by default. -// It does not support named levels (AKA severity), instead it uses arbitrary levels. -// Errors are logged to stderr and Info messages to stdout, because that is how -// some cloud logging systems (notably Google Cloud Logs Explorer) assign a -// severity (INFO or ERROR) in the UI. -// Messages logged using the legacy log module are all logged as Info messages -// with level=0. +// venafi-kubernetes-agent follows [Kubernetes Logging Conventions] and writes +// logs in [Kubernetes JSON logging format] by default. It does not support +// named levels (aka. severity), instead it uses arbitrary levels. Errors and +// warnings are logged to stderr and Info messages to stdout, because that is +// how some cloud logging systems (notably Google Cloud Logs Explorer) assign a +// severity (INFO or ERROR) in the UI. The agent's and vcert's logs are written +// logged as Info messages with level=0. // // Further reading: -// - [Kubernetes logging conventions](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md) -// - [Kubernetes JSON logging format](https://kubernetes.io/docs/concepts/cluster-administration/system-logs/#json-log-format) -// - [Why not named levels, like Info/Warning/Error?](https://github.com/go-logr/logr?tab=readme-ov-file#why-not-named-levels-like-infowarningerror) -// - [GKE logs best practices](https://cloud.google.com/kubernetes-engine/docs/concepts/about-logs#best_practices) -// - [Structured Logging KEP](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/1602-structured-logging/README.md) -// - [Examples of using k8s.io/component-base/logs](https://github.com/kubernetes/kubernetes/tree/master/staging/src/k8s.io/component-base/logs/example), -// upon which this code was based. +// - [Kubernetes logging conventions](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md) +// - [Kubernetes JSON logging format](https://kubernetes.io/docs/concepts/cluster-administration/system-logs/#json-log-format) +// - [Why not named levels, like Info/Warning/Error?](https://github.com/go-logr/logr?tab=readme-ov-file#why-not-named-levels-like-infowarningerror) +// - [GKE logs best practices](https://cloud.google.com/kubernetes-engine/docs/concepts/about-logs#best_practices) +// - [Structured Logging KEP](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/1602-structured-logging/README.md) +// - [Examples of using k8s.io/component-base/logs](https://github.com/kubernetes/kubernetes/tree/master/staging/src/k8s.io/component-base/logs/example), +// upon which this code was based. var ( // This is the Agent's logger. For now, it is still a *log.Logger, but we @@ -103,17 +102,17 @@ func AddFlags(fs *pflag.FlagSet) { // Initialize uses k8s.io/component-base/logs, to configure the following global // loggers: log, slog, and klog. All are configured to write in the same format. func Initialize() { - // This configures the global logger in klog *and* slog, if compiled - // with Go >= 1.21. + // This configures the global logger in klog *and* slog, if compiled with Go + // >= 1.21. logs.InitLogs() if err := logsapi.ValidateAndApply(configuration, features); err != nil { fmt.Fprintf(os.Stderr, "Error in logging configuration: %v\n", err) os.Exit(2) } - // Thanks to logs.InitLogs(), slog.Default() now uses klog as its backend. - // Thus, the client-go library, which relies on klog.Info, has the same - // logger as the agent, which still uses log.Printf. + // Thanks to logs.InitLogs, slog.Default now uses klog as its backend. Thus, + // the client-go library, which relies on klog.Info, has the same logger as + // the agent, which still uses log.Printf. slog := slog.Default() Log = &log.Logger{} From e4bf7cb240c6e454a265e3ea25495c593037fdf4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 17:07:09 +0200 Subject: [PATCH 06/12] logs.go: LogToSlogWriter wasn't setting the right logs as ERROR --- pkg/logs/logs.go | 29 +++++++++-------- pkg/logs/logs_test.go | 74 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 89 insertions(+), 14 deletions(-) diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index 9c20f4b8..226f9c1b 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -116,38 +116,39 @@ func Initialize() { slog := slog.Default() Log = &log.Logger{} - Log.SetOutput(logToSlogWriter{slog: slog, source: "agent"}) + 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() - vcertLog.SetOutput(logToSlogWriter{slog: slog, source: "vcert"}) + vcertLog.SetOutput(LogToSlogWriter{Slog: slog, Source: "vcert"}) // This is a work around for a bug in vcert where it adds a `vCert: ` prefix // to the global log logger. It can be removed when this is fixed upstream // in vcert: https://github.com/Venafi/vcert/pull/512 vcertLog.SetPrefix("") } -type logToSlogWriter struct { - slog *slog.Logger - source string +type LogToSlogWriter struct { + Slog *slog.Logger + Source string } -func (w logToSlogWriter) Write(p []byte) (n int, err error) { +func (w LogToSlogWriter) Write(p []byte) (n int, err error) { // log.Printf writes a newline at the end of the message, so we need to trim // it. p = bytes.TrimSuffix(p, []byte("\n")) message := string(p) - if isCritical(message) { - w.slog.With("source", w.source).Error(message) + if strings.Contains(message, "error") || + strings.Contains(message, "failed") || + strings.Contains(message, "fatal") || + strings.Contains(message, "Failed") || + strings.Contains(message, "While evaluating configuration") || + strings.Contains(message, "data-path override present") || + strings.Contains(message, "Cannot marshal readings") { + w.Slog.With("source", w.Source).Error(message) } else { - w.slog.With("source", w.source).Info(message) + w.Slog.With("source", w.Source).Info(message) } return len(p), nil } - -func isCritical(msg string) bool { - // You can implement more robust logic to detect critical log messages - return strings.Contains(msg, "FATAL") || strings.Contains(msg, "ERROR") -} diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index bba0b6c8..24a4d7ef 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -15,6 +15,7 @@ import ( _ "github.com/Venafi/vcert/v5" "github.com/spf13/pflag" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "k8s.io/klog/v2" @@ -316,3 +317,76 @@ func replaceWithStaticTimestamps(input string) string { input = fileAndLineRegexpKlog.ReplaceAllString(input, " $1.go:000") return input } + +func TestLogToSlogWriter(t *testing.T) { + // This test makes sure that all the agent's Log.Fatalf calls are correctly + // translated to slog.Error calls. + // + // This list was generated using: + // grep -r "Log\.Fatalf" ./cmd ./pkg + given := strings.TrimPrefix(` +Failed to load config file for agent from +Failed to read config file +Failed to parse config file +While evaluating configuration +failed to run pprof profiler +failed to run the health check server +failed to start a controller-runtime component +failed to wait for controller-runtime component to stop +running data gatherer %s of type %s as Local, data-path override present +failed to instantiate %q data gatherer +failed to read local data file +failed to unmarshal local data file +failed to output to local file +Exiting due to fatal error uploading +halting datagathering in strict mode due to error +Cannot marshal readings +Failed to read config file +Failed to parse config file +Failed to validate data gatherers +this is a happy log that should show as INFO`, "\n") + expect := strings.TrimPrefix(` +level=ERROR msg="Failed to load config file for agent from" source=agent +level=ERROR msg="Failed to read config file" source=agent +level=ERROR msg="Failed to parse config file" source=agent +level=ERROR msg="While evaluating configuration" source=agent +level=ERROR msg="failed to run pprof profiler" source=agent +level=ERROR msg="failed to run the health check server" source=agent +level=ERROR msg="failed to start a controller-runtime component" source=agent +level=ERROR msg="failed to wait for controller-runtime component to stop" source=agent +level=ERROR msg="running data gatherer %!s(MISSING) of type %!s(MISSING) as Local, data-path override present" source=agent +level=ERROR msg="failed to instantiate %!q(MISSING) data gatherer" source=agent +level=ERROR msg="failed to read local data file" source=agent +level=ERROR msg="failed to unmarshal local data file" source=agent +level=ERROR msg="failed to output to local file" source=agent +level=ERROR msg="Exiting due to fatal error uploading" source=agent +level=ERROR msg="halting datagathering in strict mode due to error" source=agent +level=ERROR msg="Cannot marshal readings" source=agent +level=ERROR msg="Failed to read config file" source=agent +level=ERROR msg="Failed to parse config file" source=agent +level=ERROR msg="Failed to validate data gatherers" source=agent +level=INFO msg="this is a happy log that should show as INFO" source=agent +`, "\n") + + gotBuf := &bytes.Buffer{} + slogHandler := slog.NewTextHandler(gotBuf, &slog.HandlerOptions{ + // Remove the timestamp from the logs so that we can compare them. + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == "time" { + return slog.Attr{} + } + return a + }, + }) + slogLogger := slog.New(slogHandler) + + logger := log.New(&bytes.Buffer{}, "", 0) + logger.SetOutput(logs.LogToSlogWriter{Slog: slogLogger, Source: "agent"}) + + for _, line := range strings.Split(given, "\n") { + // Simulate the current agent's logs. + logger.Printf(line) + } + + assert.Equal(t, expect, gotBuf.String()) +} From d9bc223c8ae205f20bdc3d3e4f22d011268226a2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 17:34:19 +0200 Subject: [PATCH 07/12] logs_test.go: replaceWithStaticTimestamps breaks for short PIDs --- pkg/logs/logs_test.go | 21 ++++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index 24a4d7ef..5e7aba5d 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -290,7 +290,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err var ( timestampRegexpStdLog = regexp.MustCompile(`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}`) - timestampRegexpKlog = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6} \d{5}`) + timestampRegexpKlog = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6} +\d+`) timestampRegexpJSON = regexp.MustCompile(`"ts":\d+\.\d+`) fileAndLineRegexpJSON = regexp.MustCompile(`"caller":"([^"]+).go:\d+"`) fileAndLineRegexpKlog = regexp.MustCompile(` ([^:]+).go:\d+`) @@ -318,6 +318,25 @@ func replaceWithStaticTimestamps(input string) string { return input } +func Test_replaceWithStaticTimestamps(t *testing.T) { + tests := []struct { + name string + input string + expected string + }{ + { + name: "klog", + input: `I1018 15:20:42.861239 2386 logs_test.go:13] "Contextual Info Level 3" logger="foo" key="value"`, + expected: `I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value"`, + }, + } + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + assert.Equal(t, test.expected, replaceWithStaticTimestamps(test.input)) + }) + } +} + func TestLogToSlogWriter(t *testing.T) { // This test makes sure that all the agent's Log.Fatalf calls are correctly // translated to slog.Error calls. From c39594a617f9109dda604de4fce7d5d2ff7a787f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 18:47:32 +0200 Subject: [PATCH 08/12] logs.go: use --log-level instead of --v --- pkg/logs/logs.go | 12 ++++++++++++ pkg/logs/logs_test.go | 38 +++++++++++++++++++++++++++++++++++--- 2 files changed, 47 insertions(+), 3 deletions(-) diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index 226f9c1b..9a70cd34 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -78,6 +78,7 @@ func AddFlags(fs *pflag.FlagSet) { if !visibleFlagNames.Has(f.Name) { tfs.MarkHidden(f.Name) } + // The default is "text" and the usage string includes details about how // JSON logging is only available when BETA logging features are // enabled, but that's not relevant here because the feature is enabled @@ -95,6 +96,17 @@ func AddFlags(fs *pflag.FlagSet) { f.DefValue = "true" runtime.Must(f.Value.Set("true")) } + + // Since `--v` (which is the long form of `-v`) isn't the standard in + // our projects (it only exists in cert-manager, webhook, and such), + // let's rename it to the more commong `--log-level`, which appears in + // openshift-routes, csi-driver, trust-manager, and approver-policy. + // More details at: + // https://github.com/jetstack/jetstack-secure/pull/596#issuecomment-2421708181 + if f.Name == "v" { + f.Name = "log-level" + f.Shorthand = "v" + } }) fs.AddFlagSet(&tfs) } diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index 5e7aba5d..e82e5660 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -77,8 +77,8 @@ pflag: help requested `, expectStderr: ` Usage of test-logs: + -v, --log-level Level number for the log level verbosity --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") - -v, --v Level number for the log level verbosity --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) `, }, @@ -92,8 +92,23 @@ unknown flag: --foo expectStderr: ` unknown flag: --foo Usage of test-logs: + -v, --log-level Level number for the log level verbosity + --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") + --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) +`, + }, + { + name: "v-long-form-not-available", + flags: "--v=3", + expectError: true, + expectStdout: ` +unknown flag: --v +`, + expectStderr: ` +unknown flag: --v +Usage of test-logs: + -v, --log-level Level number for the log level verbosity --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") - -v, --v Level number for the log level verbosity --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) `, }, @@ -204,7 +219,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err }, { name: "v-level-3", - flags: "--v=3", + flags: "-v=3", expectStdout: ` {"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} @@ -218,6 +233,23 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} {"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} {"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +`, + }, + { + name: "v-level-long-form", + flags: "--log-level=0", + expectStdout: ` +{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} +`, + expectStderr: ` +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} +{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} +{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} `, }, { From f3b721ec966103cfec1bf454a47adc7f4f496b80 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Fri, 18 Oct 2024 18:55:52 +0200 Subject: [PATCH 09/12] logs_test.go: replaceWithStaticTimestamps: ts may not have nanoseconds --- pkg/logs/logs_test.go | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index e82e5660..522d308f 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -323,7 +323,7 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err var ( timestampRegexpStdLog = regexp.MustCompile(`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}`) timestampRegexpKlog = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6} +\d+`) - timestampRegexpJSON = regexp.MustCompile(`"ts":\d+\.\d+`) + timestampRegexpJSON = regexp.MustCompile(`"ts":\d+\.?\d*`) fileAndLineRegexpJSON = regexp.MustCompile(`"caller":"([^"]+).go:\d+"`) fileAndLineRegexpKlog = regexp.MustCompile(` ([^:]+).go:\d+`) ) @@ -361,6 +361,16 @@ func Test_replaceWithStaticTimestamps(t *testing.T) { input: `I1018 15:20:42.861239 2386 logs_test.go:13] "Contextual Info Level 3" logger="foo" key="value"`, expected: `I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value"`, }, + { + name: "json-with-nanoseconds", + input: `{"ts":1729270111728.125,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}`, + expected: `{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}`, + }, + { + name: "json-might-not-have-nanoseconds", + input: `{"ts":1729270111728,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}`, + expected: `{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}`, + }, } for _, test := range tests { t.Run(test.name, func(t *testing.T) { From 6f8c52e22f76628aa1e17e08f65e469f1faca380 Mon Sep 17 00:00:00 2001 From: Richard Wall Date: Fri, 25 Oct 2024 17:25:19 +0100 Subject: [PATCH 10/12] Set the default logging format to text Signed-off-by: Richard Wall --- hack/e2e/values.venafi-kubernetes-agent.yaml | 3 + pkg/logs/logs.go | 10 ++- pkg/logs/logs_test.go | 69 ++++++++++---------- 3 files changed, 42 insertions(+), 40 deletions(-) diff --git a/hack/e2e/values.venafi-kubernetes-agent.yaml b/hack/e2e/values.venafi-kubernetes-agent.yaml index ff55025d..06b475f1 100644 --- a/hack/e2e/values.venafi-kubernetes-agent.yaml +++ b/hack/e2e/values.venafi-kubernetes-agent.yaml @@ -6,3 +6,6 @@ config: authentication: venafiConnection: enabled: true + +extraArgs: +- --logging-format=json diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index 9a70cd34..cac33d22 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -18,7 +18,7 @@ import ( ) // venafi-kubernetes-agent follows [Kubernetes Logging Conventions] and writes -// logs in [Kubernetes JSON logging format] by default. It does not support +// logs in [Kubernetes text logging format] by default. It does not support // named levels (aka. severity), instead it uses arbitrary levels. Errors and // warnings are logged to stderr and Info messages to stdout, because that is // how some cloud logging systems (notably Google Cloud Logs Explorer) assign a @@ -27,7 +27,7 @@ import ( // // Further reading: // - [Kubernetes logging conventions](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md) -// - [Kubernetes JSON logging format](https://kubernetes.io/docs/concepts/cluster-administration/system-logs/#json-log-format) +// - [Kubernetes text logging format](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md#text-logging-format) // - [Why not named levels, like Info/Warning/Error?](https://github.com/go-logr/logr?tab=readme-ov-file#why-not-named-levels-like-infowarningerror) // - [GKE logs best practices](https://cloud.google.com/kubernetes-engine/docs/concepts/about-logs#best_practices) // - [Structured Logging KEP](https://github.com/kubernetes/enhancements/blob/master/keps/sig-instrumentation/1602-structured-logging/README.md) @@ -79,14 +79,12 @@ func AddFlags(fs *pflag.FlagSet) { tfs.MarkHidden(f.Name) } - // The default is "text" and the usage string includes details about how + // The original usage string includes details about how // JSON logging is only available when BETA logging features are // enabled, but that's not relevant here because the feature is enabled // by default. if f.Name == "logging-format" { f.Usage = `Sets the log format. Permitted formats: "json", "text".` - f.DefValue = "json" - runtime.Must(f.Value.Set("json")) } if f.Name == "log-text-split-stream" { f.DefValue = "true" @@ -99,7 +97,7 @@ func AddFlags(fs *pflag.FlagSet) { // Since `--v` (which is the long form of `-v`) isn't the standard in // our projects (it only exists in cert-manager, webhook, and such), - // let's rename it to the more commong `--log-level`, which appears in + // let's rename it to the more common `--log-level`, which appears in // openshift-routes, csi-driver, trust-manager, and approver-policy. // More details at: // https://github.com/jetstack/jetstack-secure/pull/596#issuecomment-2421708181 diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index 522d308f..1ecf846c 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -78,7 +78,7 @@ pflag: help requested expectStderr: ` Usage of test-logs: -v, --log-level Level number for the log level verbosity - --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") + --logging-format string Sets the log format. Permitted formats: "json", "text". (default "text") --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) `, }, @@ -93,7 +93,7 @@ unknown flag: --foo unknown flag: --foo Usage of test-logs: -v, --log-level Level number for the log level verbosity - --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") + --logging-format string Sets the log format. Permitted formats: "json", "text". (default "text") --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) `, }, @@ -108,7 +108,7 @@ unknown flag: --v unknown flag: --v Usage of test-logs: -v, --log-level Level number for the log level verbosity - --logging-format string Sets the log format. Permitted formats: "json", "text". (default "json") + --logging-format string Sets the log format. Permitted formats: "json", "text". (default "text") --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) `, }, @@ -140,17 +140,17 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "modified-defaults", flags: "", expectStdout: ` -{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} +I0000 00:00:00.000000 00000 logs.go:000] "log Print" source="vcert" +I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" +I0000 00:00:00.000000 00000 logs_test.go:000] klog Info +I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" `, expectStderr: ` -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} -{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn" +E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error" +W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning +E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error" +E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value" `, }, { @@ -221,40 +221,41 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err name: "v-level-3", flags: "-v=3", expectStdout: ` -{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} -{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual Info Level 3","v":3,"key":"value"} +I0000 00:00:00.000000 00000 logs.go:000] "log Print" source="vcert" +I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" +I0000 00:00:00.000000 00000 logs_test.go:000] klog Info +I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" +I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value" `, expectStderr: ` -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} -{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn" +E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error" +W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning +E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error" +E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value" `, }, { - name: "v-level-long-form", - flags: "--log-level=0", + name: "log-level-3", + flags: "--log-level=3", expectStdout: ` -{"ts":0000000000000.000,"caller":"logs/logs.go:000","msg":"log Print","source":"vcert","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Info","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Warning","v":0} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog InfoS","v":0,"key":"value"} +I0000 00:00:00.000000 00000 logs.go:000] "log Print" source="vcert" +I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" +I0000 00:00:00.000000 00000 logs_test.go:000] klog Info +I0000 00:00:00.000000 00000 logs_test.go:000] "klog InfoS" key="value" +I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value" `, expectStderr: ` -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Error"} -{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"klog Error","err":"fake-error"} -{"ts":0000000000000.000,"logger":"foo","caller":"logs/logs_test.go:000","msg":"Contextual error","key":"value","err":"fake-error"} +W0000 00:00:00.000000 00000 logs_test.go:000] "slog Warn" +E0000 00:00:00.000000 00000 logs_test.go:000] "slog Error" +W0000 00:00:00.000000 00000 logs_test.go:000] klog Warning +E0000 00:00:00.000000 00000 logs_test.go:000] "klog Error" err="fake-error" +E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-error" logger="foo" key="value" `, }, { name: "vmodule-level-3", - flags: "--logging-format=text --vmodule=logs_test=3", + flags: "--vmodule=logs_test=3", expectStdout: ` I0000 00:00:00.000000 00000 logs.go:000] "log Print" source="vcert" I0000 00:00:00.000000 00000 logs_test.go:000] "slog Info" From 73526f3b3d2930c5cd19d563ffe05dac62e2ecb0 Mon Sep 17 00:00:00 2001 From: Richard Wall Date: Fri, 25 Oct 2024 17:25:43 +0100 Subject: [PATCH 11/12] Remove redundant test for vcert log prefix The exact logs output is now verified. Signed-off-by: Richard Wall --- pkg/logs/logs_test.go | 6 ------ 1 file changed, 6 deletions(-) diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go index 1ecf846c..3ddd6da1 100644 --- a/pkg/logs/logs_test.go +++ b/pkg/logs/logs_test.go @@ -37,12 +37,6 @@ func TestLogs(t *testing.T) { logs.AddFlags(fs) fs.Parse(strings.Split(flags, " ")) logs.Initialize() - - // Remember to not use `assert.Equal` from within the sub-process - // since (for some reason) `assert.Equal` doesn't cause the test - // sub-process to exit with 1. Instead, it exits with 0, which means - // we can't notice the error from the parent process. - require.Equal(t, "", log.Prefix(), "logs.Initialize should remove the `vCert: ` prefix from the global log logger") } log.Print("log Print") From 54eb5a5dfe6f4c11d8ec14dc6c7148a50d4c1968 Mon Sep 17 00:00:00 2001 From: Richard Wall Date: Tue, 29 Oct 2024 10:27:42 +0000 Subject: [PATCH 12/12] Fix some out-of-date comments Signed-off-by: Richard Wall --- pkg/logs/logs.go | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/pkg/logs/logs.go b/pkg/logs/logs.go index cac33d22..9dd988b8 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -64,11 +64,8 @@ func init() { // AddFlags adds log related flags to the supplied flag set. // -// The default logging format is changed to JSON. The default in Kubernetes -// component base is "text", for backwards compatibility, but that is not a -// concern for venafi-kubernetes-agent. // The split-stream options are enabled by default, so that errors are logged to -// stderr and info to stdout, allowing cloud logging systems to assign an +// stderr and info to stdout, allowing cloud logging systems to assign a // severity INFO or ERROR to the messages. func AddFlags(fs *pflag.FlagSet) { var tfs pflag.FlagSet