fix(logging): Log galactic-cni and fabric-config-agent as JSON

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,18 +90,24 @@ type options struct {
 
 func main() {
 	if err := newRootCommand().Execute(); err != nil {
+		slog.Error(appName+" failed", "error", err)
 		os.Exit(1)
 	}
 }
 
 // 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
 }
 

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)
 	}
 }

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 <overlay> | go run go.datum.net/galactic/hack/check-log-settings@<version> -
 ```
 
-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.

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
+}

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)
+		}
+	}
+}

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",

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() {