Migrate to slog, get rid of all format based logging (#18)

.github/workflows/main.yml

@@ -22,19 +22,19 @@ jobs:
 
     steps:
     - name: Log in to the Container registry
-      uses: docker/login-action@v2
+      uses: docker/login-action@v3
       with:
         registry: ${{ env.REGISTRY }}
         username: ${{ github.actor }}
         password: ${{ secrets.GITHUB_TOKEN }}
 
     - name: Check out code into the Go module directory
-      uses: actions/checkout@v3
+      uses: actions/checkout@v4
 
-    - name: Set up Go 1.21
+    - name: Set up Go 1.22
       uses: actions/setup-go@v4
       with:
-        go-version: "1.21"
+        go-version: "1.22"
         cache: false
 
     - name: Lint

Dockerfile

@@ -1,5 +1,5 @@
 # be aware that bookworm has a newer gcc which can not compile the older ipxe
-FROM golang:1.21-bullseye as builder
+FROM golang:1.22-bullseye as builder
 WORKDIR /work
 COPY . .
 RUN apt update \

dhcp4/conn_test.go

@@ -19,8 +19,6 @@ import (
 	"reflect"
 	"testing"
 	"time"
-
-	"github.com/stretchr/testify/require"
 )
 
 func testConn(t *testing.T, impl conn, addr string) {
@@ -55,7 +53,9 @@ func testConn(t *testing.T, impl conn, addr string) {
 
 	go func() {
 		_, err := s.Write(bs)
-		require.NoError(t, err)
+		if err != nil {
+			panic(err)
+		}
 	}()
 	if err = c.SetReadDeadline(time.Now().Add(time.Second)); err != nil {
 		t.Fatal(err)
@@ -86,7 +86,9 @@ func testConn(t *testing.T, impl conn, addr string) {
 	ch := make(chan *Packet, 1)
 	go func() {
 		err := s.SetReadDeadline(time.Now().Add(time.Second))
-		require.NoError(t, err)
+		if err != nil {
+			panic(err)
+		}
 		var buf [1500]byte
 		n, err := s.Read(buf[:])
 		if err != nil {

go.mod

@@ -1,6 +1,6 @@
 module github.com/metal-stack/pixie
 
-go 1.21
+go 1.22
 
 require (
 	github.com/metal-stack/metal-api v0.26.3
@@ -10,9 +10,8 @@ require (
 	github.com/spf13/cobra v1.8.0
 	github.com/spf13/viper v1.18.2
 	github.com/stretchr/testify v1.8.4
-	go.uber.org/zap v1.26.0
-	golang.org/x/crypto v0.18.0
-	golang.org/x/net v0.20.0
+	golang.org/x/crypto v0.19.0
+	golang.org/x/net v0.21.0
 	google.golang.org/grpc v1.61.0
 )
 
@@ -39,10 +38,10 @@ require (
 	github.com/spf13/pflag v1.0.5 // indirect
 	github.com/subosito/gotenv v1.6.0 // indirect
 	go.uber.org/multierr v1.11.0 // indirect
-	golang.org/x/exp v0.0.0-20240119083558-1b970713d09a // indirect
-	golang.org/x/sys v0.16.0 // indirect
+	golang.org/x/exp v0.0.0-20240205201215-2c58cdc269a3 // indirect
+	golang.org/x/sys v0.17.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
-	google.golang.org/genproto/googleapis/rpc v0.0.0-20240125205218-1f4bbc51befe // indirect
+	google.golang.org/genproto/googleapis/rpc v0.0.0-20240205150955-31a09d347014 // indirect
 	google.golang.org/protobuf v1.32.0 // indirect
 	gopkg.in/ini.v1 v1.67.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect

go.sum

@@ -76,29 +76,25 @@ github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcU
 github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
 github.com/subosito/gotenv v1.6.0 h1:9NlTDc1FTs4qu0DDq7AEtTPNw6SVm7uBMsUCUjABIf8=
 github.com/subosito/gotenv v1.6.0/go.mod h1:Dk4QP5c2W3ibzajGcXpNraDfq2IrhjMIvMSWPKKo0FU=
-go.uber.org/goleak v1.2.0 h1:xqgm/S+aQvhWFTtR0XK3Jvg7z8kGV8P4X14IzwN3Eqk=
-go.uber.org/goleak v1.2.0/go.mod h1:XJYK+MuIchqpmGmUSAzotztawfKvYLUIgg7guXrwVUo=
 go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0=
 go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
-go.uber.org/zap v1.26.0 h1:sI7k6L95XOKS281NhVKOFCUNIvv9e0w4BF8N3u+tCRo=
-go.uber.org/zap v1.26.0/go.mod h1:dtElttAiwGvoJ/vj4IwHBS/gXsEu/pZ50mUIRWuG0so=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
-golang.org/x/crypto v0.18.0 h1:PGVlW0xEltQnzFZ55hkuX5+KLyrMYhHld1YHO4AKcdc=
-golang.org/x/crypto v0.18.0/go.mod h1:R0j02AL6hcrfOiy9T4ZYp/rcWeMxM3L6QYxlOuEG1mg=
-golang.org/x/exp v0.0.0-20240119083558-1b970713d09a h1:Q8/wZp0KX97QFTc2ywcOE0YRjZPVIx+MXInMzdvQqcA=
-golang.org/x/exp v0.0.0-20240119083558-1b970713d09a/go.mod h1:idGWGoKP1toJGkd5/ig9ZLuPcZBC3ewk7SzmH0uou08=
+golang.org/x/crypto v0.19.0 h1:ENy+Az/9Y1vSrlrvBSyna3PITt4tiZLf7sgCjZBX7Wo=
+golang.org/x/crypto v0.19.0/go.mod h1:Iy9bg/ha4yyC70EfRS8jz+B6ybOBKMaSxLj6P6oBDfU=
+golang.org/x/exp v0.0.0-20240205201215-2c58cdc269a3 h1:/RIbNt/Zr7rVhIkQhooTxCxFcdWLGIKnZA4IXNFSrvo=
+golang.org/x/exp v0.0.0-20240205201215-2c58cdc269a3/go.mod h1:idGWGoKP1toJGkd5/ig9ZLuPcZBC3ewk7SzmH0uou08=
 golang.org/x/net v0.0.0-20200202094626-16171245cfb2/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
-golang.org/x/net v0.20.0 h1:aCL9BSgETF1k+blQaYUBx9hJ9LOGP3gAVemcZlf1Kpo=
-golang.org/x/net v0.20.0/go.mod h1:z8BVo6PvndSri0LbOE3hAn0apkU+1YvI6E70E9jsnvY=
+golang.org/x/net v0.21.0 h1:AQyQV4dYCvJ7vGmJyKki9+PBdyvhkSd8EIx/qb0AYv4=
+golang.org/x/net v0.21.0/go.mod h1:bIjVDfnllIU7BJ2DNgfnXvpSvtn8VRwhlsaeUTyUS44=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
-golang.org/x/sys v0.16.0 h1:xWw16ngr6ZMtmxDyKyIgsE93KNKz5HKmMa3b8ALHidU=
-golang.org/x/sys v0.16.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.17.0 h1:25cE3gD+tdBA7lp7QfhuV+rJiE9YXTcS3VG1SqssI/Y=
+golang.org/x/sys v0.17.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=
 golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
-google.golang.org/genproto/googleapis/rpc v0.0.0-20240125205218-1f4bbc51befe h1:bQnxqljG/wqi4NTXu2+DJ3n7APcEA882QZ1JvhQAq9o=
-google.golang.org/genproto/googleapis/rpc v0.0.0-20240125205218-1f4bbc51befe/go.mod h1:PAREbraiVEVGVdTZsVWjSbbTtSyGbAgIIvni8a8CD5s=
+google.golang.org/genproto/googleapis/rpc v0.0.0-20240205150955-31a09d347014 h1:FSL3lRCkhaPFxqi0s9o+V4UI2WTzAVOvkgbd4kVV4Wg=
+google.golang.org/genproto/googleapis/rpc v0.0.0-20240205150955-31a09d347014/go.mod h1:SaPjaZGWb0lPqs6Ittu0spdfrOArqji4ZdeP5IC/9N4=
 google.golang.org/grpc v1.61.0 h1:TOvOcuXn30kRao+gfcvsebNEa5iZIiLkisYEkf7R7o0=
 google.golang.org/grpc v1.61.0/go.mod h1:VUbo7IFqmF1QtCAstipjG0GIoq49KvMe9+h1jFLBNJs=
 google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw=

pixiecore/booters.go

@@ -20,6 +20,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/url"
 	"os"
@@ -28,8 +29,6 @@ import (
 	"text/template"
 	"time"
 
-	"go.uber.org/zap"
-
 	v1 "github.com/metal-stack/metal-api/pkg/api/v1"
 	"github.com/metal-stack/pixie/api"
 )
@@ -51,7 +50,7 @@ func APIBooter(url string, timeout time.Duration) (Booter, error) {
 
 	return ret, nil
 }
-func GRPCBooter(log *zap.SugaredLogger, client *GrpcClient, partition string, metalAPIConfig *api.MetalConfig) (Booter, error) {
+func GRPCBooter(log *slog.Logger, client *GrpcClient, partition string, metalAPIConfig *api.MetalConfig) (Booter, error) {
 	ret := &grpcbooter{
 		grpc:      client,
 		partition: partition,
@@ -61,7 +60,7 @@ func GRPCBooter(log *zap.SugaredLogger, client *GrpcClient, partition string, me
 	if _, err := io.ReadFull(rand.Reader, ret.key[:]); err != nil {
 		return nil, fmt.Errorf("failed to get randomness for signing key: %w", err)
 	}
-	log.Infow("starting grpc booter", "partition", partition)
+	log.Info("starting grpc booter", "partition", partition)
 	return ret, nil
 }
 
@@ -76,12 +75,12 @@ type grpcbooter struct {
 	grpc      *GrpcClient
 	config    *api.MetalConfig
 	partition string
-	log       *zap.SugaredLogger
+	log       *slog.Logger
 }
 
 // BootSpec implements Booter
 func (g *grpcbooter) BootSpec(m Machine) (*Spec, error) {
-	g.log.Infow("bootspec", "machine", m)
+	g.log.Info("bootspec", "machine", m)
 	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
 	defer cancel()
 
@@ -91,10 +90,10 @@ func (g *grpcbooter) BootSpec(m Machine) (*Spec, error) {
 		req := &v1.BootServiceDhcpRequest{
 			Uuid: string(m.GUID),
 		}
-		g.log.Infow("dhcp", "req", req)
+		g.log.Info("dhcp", "req", req)
 		_, err := g.grpc.BootService().Dhcp(ctx, req)
 		if err != nil {
-			g.log.Errorw("boot", "error", err)
+			g.log.Error("boot", "error", err)
 			return nil, err
 		}
 		r = rawSpec{}
@@ -104,13 +103,13 @@ func (g *grpcbooter) BootSpec(m Machine) (*Spec, error) {
 			Mac:         m.MAC.String(),
 			PartitionId: g.partition,
 		}
-		g.log.Infow("boot", "req", req)
+		g.log.Info("boot", "req", req)
 		resp, err := g.grpc.BootService().Boot(ctx, req)
 		if err != nil {
-			g.log.Errorw("boot", "error", err)
+			g.log.Error("boot", "error", err)
 			return nil, err
 		}
-		g.log.Infow("boot", "resp", resp)
+		g.log.Info("boot", "resp", resp)
 
 		cmdline := []string{resp.GetCmdline(), fmt.Sprintf("PIXIE_API_URL=%s", g.config.PixieAPIURL)}
 		if g.config.Debug {
@@ -125,7 +124,7 @@ func (g *grpcbooter) BootSpec(m Machine) (*Spec, error) {
 	}
 
 	spec, err := bootSpec(g.key, g.urlPrefix, r)
-	g.log.Infow("bootspec", "return spec", spec)
+	g.log.Info("bootspec", "return spec", spec)
 	return spec, err
 }
 

pixiecore/cli/cli.go

@@ -17,19 +17,18 @@ package cli // import "github.com/metal-stack/pixie/cli"
 
 import (
 	"fmt"
+	"log/slog"
 	"os"
 
 	"github.com/metal-stack/pixie/pixiecore"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
-	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
 )
 
-// Ipxe is the set of ipxe binaries for supported firmwares.
+// Ipxe is the set of ipxe binaries for supported firmware.
 //
 // Can be set externally before calling CLI(), and set/extended by
-// commandline processing in CLI().
+// command line processing in CLI().
 var Ipxe = map[pixiecore.Firmware][]byte{}
 
 // CLI runs the Pixiecore commandline.
@@ -133,14 +132,10 @@ func serverFromFlags(cmd *cobra.Command) *pixiecore.Server {
 	if httpPort <= 0 {
 		fatalf("HTTP port must be >0")
 	}
-	log, err := getLogger(debug)
-	if err != nil {
-		fatalf("Error creating logging: %s", err)
-	}
 
 	ret := &pixiecore.Server{
 		Ipxe:           map[pixiecore.Firmware][]byte{},
-		Log:            log,
+		Log:            getLogger(debug).WithGroup("dhcp"),
 		HTTPPort:       httpPort,
 		HTTPStatusPort: httpStatusPort,
 		MetricsPort:    metricsPort,
@@ -170,18 +165,14 @@ func serverFromFlags(cmd *cobra.Command) *pixiecore.Server {
 	return ret
 }
 
-func getLogger(debug bool) (*zap.SugaredLogger, error) {
-	cfg := zap.NewProductionConfig()
-	level := zap.InfoLevel
-	if debug {
-		level = zap.DebugLevel
+func getLogger(debug bool) *slog.Logger {
+	opts := &slog.HandlerOptions{
+		Level:     slog.LevelInfo,
+		AddSource: debug,
 	}
-	cfg.Level = zap.NewAtomicLevelAt(level)
-	cfg.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
-	zlog, err := cfg.Build()
-	if err != nil {
-		return nil, err
+	if debug {
+		opts.Level = slog.LevelDebug
 	}
 
-	return zlog.Sugar(), nil
+	return slog.New(slog.NewJSONHandler(os.Stdout, opts))
 }

pixiecore/cli/ipv6apicmd.go

@@ -36,11 +36,7 @@ var ipv6ApiCmd = &cobra.Command{
 		if err != nil {
 			fatalf("Error reading flag: %s", err)
 		}
-		l, err := getLogger(debug)
-		if err != nil {
-			fatalf("Error creating logging: %s", err)
-		}
-		s.Log = l
+		s.Log = getLogger(debug).WithGroup("dhcpv6")
 
 		if addr == "" {
 			fatalf("Please specify address to bind to")

pixiecore/dhcp.go

@@ -33,29 +33,29 @@ func (s *Server) serveDHCP(conn *dhcp4.Conn) error {
 		}
 
 		if err = s.isBootDHCP(pkt); err != nil {
-			s.Log.Debugf("Ignoring packet from %s: %s", pkt.HardwareAddr, err)
+			s.Log.Debug("Ignoring packet", "mac", pkt.HardwareAddr, "error", err)
 			continue
 		}
 		mach, fwtype, err := s.validateDHCP(pkt)
 		if err != nil {
-			s.Log.Infof("Unusable packet from %s: %s", pkt.HardwareAddr, err)
+			s.Log.Info("Unusable packet", "mac", pkt.HardwareAddr, "error", err)
 			continue
 		}
 
-		s.Log.Debugf("Got valid request to boot %s (%s, %s)", mach.MAC, mach.GUID, mach.Arch)
+		s.Log.Debug("Got valid request to boot", "mac", mach.MAC, "guid", mach.GUID, "arch", mach.Arch)
 
 		spec, err := s.Booter.BootSpec(mach)
 		if err != nil {
-			s.Log.Infof("Couldn't get bootspec for %s: %s", pkt.HardwareAddr, err)
+			s.Log.Info("Couldn't get bootspec", "mac", pkt.HardwareAddr, "error", err)
 			continue
 		}
 		if spec == nil {
-			s.Log.Debugf("No boot spec for %s, ignoring boot request", pkt.HardwareAddr)
+			s.Log.Debug("No boot spec, ignoring boot request", "mac", pkt.HardwareAddr)
 			s.machineEvent(pkt.HardwareAddr, machineStateIgnored, "Machine should not netboot")
 			continue
 		}
 
-		s.Log.Infof("Offering to boot %s", pkt.HardwareAddr)
+		s.Log.Info("Offering to boot", "mac", pkt.HardwareAddr)
 		if fwtype == FirmwarePixiecoreIpxe {
 			s.machineEvent(pkt.HardwareAddr, machineStateProxyDHCPIpxe, "Offering to boot iPXE")
 		} else {
@@ -65,18 +65,18 @@ func (s *Server) serveDHCP(conn *dhcp4.Conn) error {
 		// Machine should be booted.
 		serverIP, err := interfaceIP(intf)
 		if err != nil {
-			s.Log.Infof("Want to boot %s on %s, but couldn't get a source address: %s", pkt.HardwareAddr, intf.Name, err)
+			s.Log.Info("Want to boot, but couldn't get a source address", "mac", pkt.HardwareAddr, "interface", intf.Name, "error", err)
 			continue
 		}
 
 		resp, err := s.offerDHCP(pkt, mach, serverIP, fwtype)
 		if err != nil {
-			s.Log.Infof("Failed to construct ProxyDHCP offer for %s: %s", pkt.HardwareAddr, err)
+			s.Log.Info("Failed to construct ProxyDHCP offer", "mac", pkt.HardwareAddr, "error", err)
 			continue
 		}
 
 		if err = conn.SendDHCP(resp, intf); err != nil {
-			s.Log.Infof("Failed to send ProxyDHCP offer for %s: %s", pkt.HardwareAddr, err)
+			s.Log.Info("Failed to send ProxyDHCP offer", "mac", pkt.HardwareAddr, "error", err)
 			continue
 		}
 	}