-
Notifications
You must be signed in to change notification settings - Fork 25
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Log with klog to stdout and stderr in JSON format
Signed-off-by: Richard Wall <richard.wall@venafi.com>
- Loading branch information
Showing
5 changed files
with
263 additions
and
12 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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() | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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) | ||
| } | ||
| }) | ||
| } | ||
| } |