diff --git a/cmd/fabric-config-agent/main.go b/cmd/fabric-config-agent/main.go index 23e313b6a..3f8a603ea 100644 --- a/cmd/fabric-config-agent/main.go +++ b/cmd/fabric-config-agent/main.go @@ -42,6 +42,7 @@ import ( networkv1alpha1 "go.datum.net/galactic/api/network/v1alpha1" "go.datum.net/galactic/internal/fabricconfig" "go.datum.net/galactic/internal/fabricconfig/activation" + "go.datum.net/galactic/internal/logging" "go.datum.net/galactic/internal/metadata" ) @@ -89,6 +90,7 @@ type options struct { func main() { if err := newRootCommand().Execute(); err != nil { + slog.Error(appName+" failed", "error", err) os.Exit(1) } } @@ -96,11 +98,16 @@ func main() { // newRootCommand builds the root command and its init and watch subcommands. func newRootCommand() *cobra.Command { opts := &options{} + var logOpts logging.Options cmd := &cobra.Command{ - Use: appName, - Short: strings.Split(appDesc, "\n")[0], - Long: appDesc, - SilenceUsage: true, + Use: appName, + Short: strings.Split(appDesc, "\n")[0], + Long: appDesc, + SilenceErrors: true, + SilenceUsage: true, + PersistentPreRunE: func(*cobra.Command, []string) error { + return logOpts.Setup() + }, RunE: func(cmd *cobra.Command, _ []string) error { if ok, _ := cmd.Flags().GetBool("build-info"); ok { fmt.Println(metadata.BuildInfo(appName)) @@ -167,6 +174,7 @@ func newRootCommand() *cobra.Command { watch.Flags().BoolVar(&opts.nextHopDetectOnly, "detect-only", false, "Report IPv6 sessions announcing an IPv4-mapped next hop without resetting them") cmd.AddCommand(watch) + logOpts.BindFlags(pf) return cmd } diff --git a/cmd/galactic-cni/main.go b/cmd/galactic-cni/main.go index 9444ce5e1..6a92bd8cb 100644 --- a/cmd/galactic-cni/main.go +++ b/cmd/galactic-cni/main.go @@ -7,13 +7,14 @@ package main import ( "errors" "fmt" - "log" + "log/slog" "os" "strings" "github.com/spf13/cobra" "go.datum.net/galactic/internal/installer" + "go.datum.net/galactic/internal/logging" "go.datum.net/galactic/internal/metadata" ) @@ -74,10 +75,16 @@ func newRunCommand() *cobra.Command { } func newRootCommand() *cobra.Command { + var logOpts logging.Options cmd := &cobra.Command{ - Use: appName, - Short: strings.Split(appDesc, "\n")[0], - Long: appDesc, + Use: appName, + Short: strings.Split(appDesc, "\n")[0], + Long: appDesc, + SilenceErrors: true, + SilenceUsage: true, + PersistentPreRunE: func(*cobra.Command, []string) error { + return logOpts.Setup() + }, RunE: func(cmd *cobra.Command, _ []string) error { if ok, _ := cmd.Flags().GetBool("build-info"); ok { fmt.Println(metadata.BuildInfo(appName)) @@ -95,11 +102,13 @@ func newRootCommand() *cobra.Command { cmd.Flags().BoolP("version", "V", false, "Print version and exit") cmd.AddCommand(newInitCommand(), newRunCommand()) + logOpts.BindFlags(cmd.PersistentFlags()) return cmd } func main() { if err := newRootCommand().Execute(); err != nil { - log.Fatalf("error: %v", err) + slog.Error(appName+" failed", "error", err) + os.Exit(1) } } diff --git a/docs/observability/logging.md b/docs/observability/logging.md index bcc3fd7e6..c204917fa 100644 --- a/docs/observability/logging.md +++ b/docs/observability/logging.md @@ -1,12 +1,15 @@ # Logging -Every Galactic binary that runs controller-runtime (`galactic-router`, -`galactic-gateway`, `galactic-nat`, `galactic-vrf`, `galactic-controller`, -`galactic-edge`, `fabric-router-controller` and `fabric-api`) installs one -logger at startup through `internal/logging`. The same handler writes the -binary's own `slog` lines, the standard `log` package, controller-runtime -(reconciler errors, cache and leader election) and klog (client-go), so every -line has one format and one level threshold. +Every long-running Galactic binary (`galactic-router`, `galactic-gateway`, +`galactic-nat`, `galactic-vrf`, `galactic-controller`, `galactic-edge`, +`galactic-cni`, `fabric-router-controller`, `fabric-api` and +`fabric-config-agent`) installs one logger at startup through +`internal/logging`. The same handler writes the binary's own `slog` lines, the +standard `log` package, controller-runtime (reconciler errors, cache and leader +election) and klog (client-go), so every line has one format and one level +threshold. For `galactic-cni` that covers the `install-cni` init container and +the `credential-refresh` daemon; for `fabric-config-agent`, the `frr-init` init +container and the `config-agent` sidecar. | Flag | Env | Default | Meaning | | -------------- | ------------ | ------- | ---------------------------------- | @@ -31,8 +34,10 @@ it: kustomize build | go run go.datum.net/galactic/hack/check-log-settings@ - ``` -It recognizes a Galactic container by its image repository name, and checks -only literal values, not ones read from a ConfigMap or Secret. An empty +It recognizes a Galactic container by its image repository name, or by a +command that runs one of these binaries: `fabric-config-agent` ships in the +`fabric-router` image, run directly by `config-agent` and from a shell script +by `frr-init`. It checks only literal values, not ones read from a ConfigMap or Secret. An empty `LOG_LEVEL` or `LOG_FORMAT` counts as unset. In source YAML that isn't rendered, such as the containerlab overlays, it reads strategic-merge patches but not JSON 6902 patches. @@ -43,13 +48,20 @@ Production runs the defaults: one JSON object per line on stderr, with only at `--log-level=debug`. klog keeps its own verbosity setting, which these flags don't change, so client-go's `klog.V(n)` lines stay off. +A binary that fails after reading its flags logs the error as one `error` +line through the same handler, then exits 1. A bad flag or an invalid +`--log-level` or `--log-format` fails before the handler exists, so that one +line is Go's default text. + For local runs, `--log-format=text --log-level=debug` gives readable output with the verbose lines. No binary enables controller-runtime's zap development mode: `internal/logging`'s `TestBinariesUseThisPackage` fails when a command under `cmd/` imports controller-runtime's zap package or calls `SetLogger` -itself. +itself, and `TestLongRunningBinariesInstallTheHandler` fails when a command +under `cmd/` doesn't import `internal/logging` at all. -The CNI plugins, the `galactic-cni` installer and `fabric-config-agent` don't -run controller-runtime's logger and configure their logging separately; see -the [CNI environment variables](../cni/environment-variables.md) for the -plugins' log file. +Two kinds of command are exempt. The CNI plugins (`galactic-veth`, +`galactic-tap`, `galactic-ipam`, `galactic-bgp` and `galactic-route`) run once +per CNI call and write JSON to their own log file; see the +[CNI environment variables](../cni/environment-variables.md). +`galactic-usid` is a one-shot codec command in the debug image. diff --git a/hack/check-log-settings/main.go b/hack/check-log-settings/main.go index f41659aff..c71cf6d9b 100644 --- a/hack/check-log-settings/main.go +++ b/hack/check-log-settings/main.go @@ -10,7 +10,8 @@ // kustomize output, or source YAML such as a patch file or a kustomization // with inline patches. A container is a Galactic one when its image // repository, or, in a patch without an image, its name, is one of -// logging.Binaries. Only literal values are checked; one taken from a +// logging.Binaries, or when its command runs one of them, directly or from a +// shell script. Only literal values are checked; one taken from a // ConfigMap, a Secret or a $(VAR) reference is not. // // kustomize build config/galactic-router/overlays/router | check-log-settings -label galactic-router - @@ -198,7 +199,8 @@ func inlinePatches(doc any) []string { func checkContainer(c map[string]any) []string { name, _ := c["name"].(string) image, _ := c["image"].(string) - if !isGalactic(name, image) { + command, _ := c["command"].([]any) + if !isGalactic(name, image) && !runsGalactic(command) { return nil } var findings []string @@ -254,8 +256,8 @@ func checkContainer(c map[string]any) []string { return findings } -// isGalactic reports whether a container runs a binary that calls -// logging.Setup. Each such binary is published as an image of its own name. +// isGalactic reports whether a container's image, or its name in a patch +// without an image, is a binary that calls logging.Setup. func isGalactic(name, image string) bool { if image == "" { return slices.Contains(logging.Binaries, name) @@ -266,3 +268,18 @@ func isGalactic(name, image string) bool { } return slices.Contains(logging.Binaries, path.Base(repo)) } + +// runsGalactic reports whether command runs a binary that calls +// logging.Setup, such as fabric-config-agent, which ships in the +// fabric-router image and runs from a shell script in frr-init. +func runsGalactic(command []any) bool { + for _, a := range command { + arg, _ := a.(string) + for _, word := range strings.Fields(arg) { + if slices.Contains(logging.Binaries, path.Base(word)) { + return true + } + } + } + return false +} diff --git a/hack/check-log-settings/main_test.go b/hack/check-log-settings/main_test.go index 2e8c68bf2..be52a3dca 100644 --- a/hack/check-log-settings/main_test.go +++ b/hack/check-log-settings/main_test.go @@ -129,6 +129,33 @@ patches: `, want: []string{`inline patch: DaemonSet fabric-router: container fabric-api: --log-level "chatty"`}, }, + { + name: "fabric-config-agent in the fabric-router image, run directly or from a script", + yaml: ` +kind: DaemonSet +metadata: {name: fabric-router} +spec: + template: + spec: + initContainers: + - name: frr-init + image: ghcr.io/example/fabric-router:v1 + command: [sh, -ec, "install -d /run/frr\nexec fabric-config-agent init\n"] + env: [{name: LOG_LEVEL, value: noisy}] + containers: + - name: config-agent + image: ghcr.io/example/fabric-router:v1 + command: [fabric-config-agent, watch, --log-format=xml] + - name: frr + image: ghcr.io/example/fabric-router:v1 + command: [/usr/lib/frr/docker-start] + env: [{name: LOG_LEVEL, value: noisy}] +`, + want: []string{ + `container config-agent: --log-format "xml"`, + `container frr-init: LOG_LEVEL "noisy"`, + }, + }, } { t.Run(tc.name, func(t *testing.T) { got, err := check(strings.NewReader(tc.yaml)) @@ -155,7 +182,8 @@ func TestIsGalactic(t *testing.T) { {"x", "ghcr.io/example/galactic-gateway:v1", true}, {"x", "localhost:5000/fabric-api", true}, {"x", "galactic-vrf@sha256:00", true}, - {"x", "ghcr.io/example/galactic-cni:v1", false}, + {"x", "ghcr.io/example/galactic-cni:v1", true}, + {"x", "ghcr.io/example/galactic-usid:v1", false}, {"x", "ghcr.io/example/galactic-router-extra:v1", false}, {"galactic-edge", "", true}, {"frr", "", false}, @@ -165,3 +193,21 @@ func TestIsGalactic(t *testing.T) { } } } + +func TestRunsGalactic(t *testing.T) { + for _, tc := range []struct { + command []any + want bool + }{ + {[]any{"fabric-config-agent", "watch"}, true}, + {[]any{"/usr/local/bin/galactic-cni", "run"}, true}, + {[]any{"sh", "-ec", "set -x\nexec fabric-config-agent init"}, true}, + {[]any{"/usr/lib/frr/docker-start"}, false}, + {[]any{"galactic-usid", "decode"}, false}, + {nil, false}, + } { + if got := runsGalactic(tc.command); got != tc.want { + t.Errorf("runsGalactic(%q) = %v, want %v", tc.command, got, tc.want) + } + } +} diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 602c5d062..3b22eb220 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -41,13 +41,16 @@ var ( Levels = []string{"debug", "info", "warn", "error"} // Formats are the accepted --log-format values. Formats = []string{FormatJSON, FormatText} - // Binaries are the commands under cmd/ that call Setup. Each publishes an - // image of the same name, so a manifest check uses this list to find the - // containers whose LOG_LEVEL, LOG_FORMAT, --log-level and --log-format - // these rules govern. + // Binaries are the commands under cmd/ that call Setup. A manifest check + // uses this list to find the containers whose LOG_LEVEL, LOG_FORMAT, + // --log-level and --log-format these rules govern: by image name, as most + // publish an image of their own, or by command, as fabric-config-agent + // ships in the fabric-router image. Binaries = []string{ "fabric-api", + "fabric-config-agent", "fabric-router-controller", + "galactic-cni", "galactic-controller", "galactic-edge", "galactic-gateway", diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go index 1863e1220..80e37dede 100644 --- a/internal/logging/logging_test.go +++ b/internal/logging/logging_test.go @@ -209,6 +209,62 @@ func TestBinariesUseThisPackage(t *testing.T) { } } +// unmanagedBinaries are the commands under cmd/ that don't install the shared +// handler. The CNI plugins are exec'd per call by the container runtime, and +// galactic-usid is a one-shot codec command. +var unmanagedBinaries = map[string]bool{ + "galactic-bgp": true, + "galactic-ipam": true, + "galactic-route": true, + "galactic-tap": true, + "galactic-veth": true, + "galactic-usid": true, +} + +// TestLongRunningBinariesInstallTheHandler fails when a command under cmd/ +// doesn't import this package, so a new long-running binary can't log through +// slog's unconfigured default. A binary that needs no shared handler is added +// to unmanagedBinaries with the reason. +func TestLongRunningBinariesInstallTheHandler(t *testing.T) { + const pkg = "go.datum.net/galactic/internal/logging" + root := filepath.Join("..", "..", "cmd") + dirs, err := os.ReadDir(root) + if err != nil { + t.Fatal(err) + } + fset := token.NewFileSet() + for _, d := range dirs { + if !d.IsDir() { + continue + } + files, err := filepath.Glob(filepath.Join(root, d.Name(), "*.go")) + if err != nil { + t.Fatal(err) + } + uses := false + for _, file := range files { + if strings.HasSuffix(file, "_test.go") { + continue + } + f, err := parser.ParseFile(fset, file, nil, parser.ImportsOnly) + if err != nil { + t.Fatal(err) + } + for _, imp := range f.Imports { + if path, _ := strconv.Unquote(imp.Path.Value); path == pkg { + uses = true + } + } + } + switch { + case uses && unmanagedBinaries[d.Name()]: + t.Errorf("cmd/%s imports %s; remove it from unmanagedBinaries", d.Name(), pkg) + case !uses && !unmanagedBinaries[d.Name()]: + t.Errorf("cmd/%s doesn't import %s; call logging.Setup from its root command", d.Name(), pkg) + } + } +} + // restoreDefaults returns a function that puts slog's default logger back, so // one test's handler doesn't receive another package's output. func restoreDefaults(t *testing.T) func() {