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/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 042281ae..9dd988b8 100644 --- a/pkg/logs/logs.go +++ b/pkg/logs/logs.go @@ -1,8 +1,161 @@ package logs import ( + "bytes" + "fmt" "log" + "log/slog" "os" + "strings" + + "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 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 +// 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 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) +// - [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 + // 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 + // 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 split-stream options are enabled by default, so that errors are logged to +// 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 + logsapi.AddFlags(configuration, &tfs) + features.AddFlag(&tfs) + tfs.VisitAll(func(f *pflag.Flag) { + if !visibleFlagNames.Has(f.Name) { + tfs.MarkHidden(f.Name) + } + + // 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".` + } + 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")) + } + + // 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 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 + if f.Name == "v" { + f.Name = "log-level" + f.Shorthand = "v" + } + }) + 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() { + // 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. + 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 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) + } + return len(p), nil +} diff --git a/pkg/logs/logs_test.go b/pkg/logs/logs_test.go new file mode 100644 index 00000000..3ddd6da1 --- /dev/null +++ b/pkg/logs/logs_test.go @@ -0,0 +1,448 @@ +package logs_test + +import ( + "bytes" + "context" + "errors" + "log" + "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" + + "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() + } + + 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 + expectStdout string + expectStderr string + }{ + { + name: "help", + flags: "-h", + expectError: true, + expectStdout: ` +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 "text") + --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: + -v, --log-level Level number for the log level verbosity + --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) +`, + }, + { + 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 "text") + --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: ` +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: ` +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: "logging-format-json", + flags: "--logging-format=json", + 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"} +`, + }, + { + name: "log-json-split-stream-false", + flags: "--logging-format=json --log-json-split-stream=false", + expectStderr: ` +{"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"} +{"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 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: ` +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 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" +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: ` +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: ` +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-level-3", + flags: "--log-level=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" +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" +`, + }, + { + name: "vmodule-level-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" +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" +`, + }, + } + + 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` + 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) + 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) + } + + // 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+`) + 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 +} + +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"`, + }, + { + 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) { + 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. + // + // 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()) +}