logging: respect env vars

coordinator/main.go

@@ -3,13 +3,13 @@ package main
 import (
 	"errors"
 	"fmt"
-	"log/slog"
 	"net"
 	"os"
 
 	"github.com/edgelesssys/nunki/internal/ca"
 	"github.com/edgelesssys/nunki/internal/coordapi"
 	"github.com/edgelesssys/nunki/internal/intercom"
+	"github.com/edgelesssys/nunki/internal/logger"
 )
 
 func main() {
@@ -19,7 +19,11 @@ func main() {
 }
 
 func run() (retErr error) {
-	logger := slog.Default()
+	logger, err := logger.Default()
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "Error: creating logger: %v\n", err)
+		return err
+	}
 	defer func() {
 		if retErr != nil {
 			logger.Error(retErr.Error())

deployments/emojivoto/coordinator.yml

@@ -26,6 +26,8 @@ spec:
               valueFrom:
                 fieldRef:
                   fieldPath: metadata.namespace
+            - name: NUNKI_LOG_LEVEL
+              value: "debug"
 ---
 apiVersion: v1
 kind: Service

deployments/openssl/coordinator.yml

@@ -26,6 +26,8 @@ spec:
               valueFrom:
                 fieldRef:
                   fieldPath: metadata.namespace
+            - name: NUNKI_LOG_LEVEL
+              value: "debug"
 ---
 apiVersion: v1
 kind: Service

deployments/simple/coordinator.yml

@@ -26,6 +26,8 @@ spec:
               valueFrom:
                 fieldRef:
                   fieldPath: metadata.namespace
+            - name: NUNKI_LOG_LEVEL
+              value: "debug"
 ---
 apiVersion: v1
 kind: Service

initializer/main.go

@@ -11,7 +11,6 @@ import (
 	"encoding/pem"
 	"errors"
 	"fmt"
-	"log/slog"
 	"net"
 	"os"
 	"time"
@@ -20,6 +19,7 @@ import (
 	"github.com/edgelesssys/nunki/internal/attestation/snp"
 	"github.com/edgelesssys/nunki/internal/grpc/dialer"
 	"github.com/edgelesssys/nunki/internal/intercom"
+	"github.com/edgelesssys/nunki/internal/logger"
 )
 
 func main() {
@@ -29,7 +29,11 @@ func main() {
 }
 
 func run() (retErr error) {
-	logger := slog.Default()
+	logger, err := logger.Default()
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "Error: creating logger: %v\n", err)
+		return err
+	}
 	defer func() {
 		if retErr != nil {
 			logger.Error(retErr.Error())

internal/attestation/snp/cached_client.go

@@ -3,6 +3,7 @@ package snp
 import (
 	"log/slog"
 
+	"github.com/edgelesssys/nunki/internal/logger"
 	"github.com/edgelesssys/nunki/internal/memstore"
 	"github.com/google/go-sev-guest/verify/trust"
 	"k8s.io/utils/clock"
@@ -21,7 +22,7 @@ func newCachedKDSHTTPClient(ticker clock.Ticker, log *slog.Logger) *cachedKDSHTT
 
 	c := &cachedKDSHTTPClient{
 		HTTPSGetter: trust.DefaultHTTPSGetter(),
-		logger:      log.WithGroup("cached-kds-http-client"),
+		logger:      slog.New(logger.NewHandler(log.Handler(), "cached-kds-http-client")),
 		cache:       memstore.New[string, []byte](),
 		gcTicker:    ticker,
 	}

internal/attestation/snp/issuer.go

@@ -14,6 +14,7 @@ import (
 	"fmt"
 	"log/slog"
 
+	"github.com/edgelesssys/nunki/internal/logger"
 	"github.com/google/go-sev-guest/client"
 )
 
@@ -24,7 +25,7 @@ type Issuer struct {
 
 // NewIssuer returns a new Issuer.
 func NewIssuer(log *slog.Logger) *Issuer {
-	return &Issuer{logger: log.WithGroup("snp-issuer")}
+	return &Issuer{logger: slog.New(logger.NewHandler(log.Handler(), "snp-issuer"))}
 }
 
 // OID returns the OID of the issuer.

internal/attestation/snp/validator.go

@@ -14,6 +14,7 @@ import (
 	"fmt"
 	"log/slog"
 
+	"github.com/edgelesssys/nunki/internal/logger"
 	"github.com/google/go-sev-guest/abi"
 	"github.com/google/go-sev-guest/proto/sevsnp"
 	"github.com/google/go-sev-guest/validate"
@@ -52,9 +53,10 @@ func (v *StaticValidateOptsGenerator) SNPValidateOpts(_ *sevsnp.Report) (*valida
 
 // NewValidator returns a new Validator.
 func NewValidator(optsGen validateOptsGenerator, log *slog.Logger) *Validator {
+	handler := logger.NewHandler(log.Handler(), "snp-validator")
 	return &Validator{
 		validateOptsGen: optsGen,
-		logger:          log.WithGroup("snp-validator"),
+		logger:          slog.New(handler),
 	}
 }
 
@@ -64,7 +66,7 @@ func NewValidatorWithCallbacks(optsGen validateOptsGenerator, ticker clock.Ticke
 		validateOptsGen: optsGen,
 		callbackers:     callbacks,
 		kdsGetter:       newCachedKDSHTTPClient(ticker, log),
-		logger:          log.WithGroup("snp-validator"),
+		logger:          slog.New(logger.NewHandler(log.Handler(), "snp-validator")),
 	}
 }
 

internal/logger/handler.go

@@ -0,0 +1,78 @@
+package logger
+
+import (
+	"context"
+	"log/slog"
+	"os"
+	"strings"
+)
+
+// Handler is a slog.Handler that can be used to enable logging on a per-subsystem basis.
+type Handler struct {
+	inner     slog.Handler
+	subsystem string
+	enabled   bool
+}
+
+// NewHandler returns a new Handler.
+func NewHandler(inner slog.Handler, subsystem string) *Handler {
+	handler := &Handler{
+		inner:     inner.WithGroup(subsystem),
+		subsystem: subsystem,
+		enabled:   subsystemEnvEnabled(os.Getenv, subsystem),
+	}
+	slog.New(handler).Info("Subsystem logger initialized", "subsystem", subsystem, "state", handler.state())
+	return handler
+}
+
+// Enabled returns true if the given level is enabled.
+func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool {
+	return h.enabled && h.inner.Enabled(ctx, level)
+}
+
+// Handle handles the given record.
+func (h *Handler) Handle(ctx context.Context, record slog.Record) error {
+	return h.inner.Handle(ctx, record)
+}
+
+// WithAttrs returns a new Handler with the given attributes.
+func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return &Handler{
+		inner:     h.inner.WithAttrs(attrs),
+		subsystem: h.subsystem,
+		enabled:   h.enabled,
+	}
+}
+
+// WithGroup returns a new Handler with the given group.
+func (h *Handler) WithGroup(name string) slog.Handler {
+	return &Handler{
+		inner:     h.inner.WithGroup(name),
+		subsystem: h.subsystem,
+		enabled:   h.enabled,
+	}
+}
+
+func (h *Handler) state() string {
+	if h.enabled {
+		return "enabled"
+	}
+	return "disabled"
+}
+
+func subsystemEnvEnabled(getEnv func(string) string, subsystem string) bool {
+	return subsystemAllowListMatch(subsystem, getEnv(LogSubsystems))
+}
+
+func subsystemAllowListMatch(subsystem string, allowList string) bool {
+	if allowList == "*" {
+		return true
+	}
+	for _, allow := range strings.Split(allowList, ",") {
+		allow = strings.ToLower(strings.TrimSpace(allow))
+		if allow == subsystem {
+			return true
+		}
+	}
+	return false
+}

internal/logger/handler_test.go

@@ -0,0 +1,109 @@
+package logger
+
+import (
+	"bytes"
+	"log/slog"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestHandlerOutput(t *testing.T) {
+	testCases := map[string]struct {
+		subsystem        string
+		subsystemEnvList string
+		wantMessages     int
+	}{
+		"star": {
+			subsystem:        "foo",
+			subsystemEnvList: "*",
+			wantMessages:     2, // message and empty line
+		},
+		"match": {
+			subsystem:        "foo",
+			subsystemEnvList: "foo,bar,baz",
+			wantMessages:     2, // message and empty line
+		},
+		"no match": {
+			subsystem:    "foo",
+			wantMessages: 1, // empty line
+		},
+	}
+
+	for name, tc := range testCases {
+		t.Run(name, func(t *testing.T) {
+			assert := assert.New(t)
+
+			getEnv := newTestGetEnv(map[string]string{
+				LogSubsystems: tc.subsystemEnvList,
+			})
+
+			buf := bytes.Buffer{}
+
+			handler := &Handler{
+				inner:     slog.NewJSONHandler(&buf, nil).WithGroup(tc.subsystem),
+				subsystem: tc.subsystem,
+				enabled:   subsystemEnvEnabled(getEnv, tc.subsystem),
+			}
+			logger := slog.New(handler)
+
+			logger.Info("info", "key", "value")
+
+			got := buf.String()
+			lines := strings.Split(got, "\n")
+			assert.Len(lines, tc.wantMessages)
+			for _, line := range lines {
+				if line == "" {
+					continue
+				}
+				assert.Contains(line, tc.subsystem)
+			}
+		})
+	}
+}
+
+func TestSubsystemEnvEnabled(t *testing.T) {
+	testCases := map[string]struct {
+		subsystem        string
+		subsystemEnvList string
+		wantEnabled      bool
+	}{
+		"empty with star": {
+			subsystem:        "",
+			subsystemEnvList: "*",
+			wantEnabled:      true,
+		},
+		"value with star": {
+			subsystem:        "foo",
+			subsystemEnvList: "*",
+			wantEnabled:      true,
+		},
+		"empty list": {
+			subsystem:        "bar",
+			subsystemEnvList: "",
+		},
+		"match": {
+			subsystem:        "bar",
+			subsystemEnvList: "foo,bar,baz",
+			wantEnabled:      true,
+		},
+		"no match": {
+			subsystem:        "bar",
+			subsystemEnvList: "foo,baz",
+		},
+	}
+
+	for name, tc := range testCases {
+		t.Run(name, func(t *testing.T) {
+			assert := assert.New(t)
+
+			getEnv := newTestGetEnv(map[string]string{
+				LogSubsystems: tc.subsystemEnvList,
+			})
+
+			got := subsystemEnvEnabled(getEnv, tc.subsystem)
+			assert.Equal(tc.wantEnabled, got)
+		})
+	}
+}