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 e796f6ff..6fd6d60e 100644 --- a/go.mod +++ b/go.mod @@ -4,6 +4,7 @@ go 1.22.0 require ( github.com/Jeffail/gabs/v2 v2.7.0 + 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 @@ -24,13 +25,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 @@ -39,6 +40,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 @@ -63,7 +65,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 ( @@ -101,7 +102,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..94afd20f --- /dev/null +++ b/pkg/logs/logs_test.go @@ -0,0 +1,146 @@ +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) + t.Logf("STDOUT\n%s\n", stdout.String()) + 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) + } + }) + } +}