refactor: replace logger

This replaces the zap logging engine with Go 1.21's new
structured logger, log/slog, or more precisely a thin
wrapper around that ("xlog").

The log/slog package has a few things missing, which are
present in xlog:

1. xlog provides a no-op logger, which simply discards any
   log output. This is extensively used in our tests.
2. xlog has a Fatal() output method, which simply calls
   Error() and then os.Exit(1).
3. xlog treats error values as first-class citizen. Since
   (log/slog).Error() is a convenience function for their
   default logger instance, there is no built-in way to treat
   errors as values. In comparison, (xlog).Error() constructs
   an slog.Attr, since xlog does not provide a default logger.

Point (2) is debatable, since xlog.Fatal is only used in
cmd/texd/main.go, so I'd be willing to forfeit it.

Some TODOs remain:

- xlog, i.e. its extension over log/slog, is not really tested
- documentation is missing
- the current xlog constructor (New) is a bit clunky to use,
  maybe switch to functional options?
- some tests create a local buffer as log output target - this
  could be made easier with a `log, buf := xlog.NewBuffered()`
  constructor (albeit, the overhead is minimal)
- for local development, I still like to have some colorization

Issue: #1

Author: dmke

cmd/texd/main.go

@@ -4,10 +4,12 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log/slog"
 	"os"
 	"os/signal"
 	"runtime"
 	"runtime/debug"
+	"strings"
 	"sync"
 	"syscall"
 	"time"
@@ -20,11 +22,10 @@ import (
 	"github.com/digineo/texd/refstore/nop"
 	"github.com/digineo/texd/service"
 	"github.com/digineo/texd/tex"
+	"github.com/digineo/texd/xlog"
 	"github.com/docker/go-units"
 	"github.com/spf13/pflag"
 	"github.com/thediveo/enumflag"
-	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
 )
 
 var opts = service.Options{
@@ -42,7 +43,7 @@ var (
 	engine      = tex.DefaultEngine.Name()
 	jobdir      = ""
 	pull        = false
-	logLevel    = zapcore.InfoLevel.String()
+	logLevel    = slog.LevelInfo.String()
 	maxJobSize  = units.BytesSize(float64(opts.MaxJobSize))
 	storageDSN  = ""
 	showVersion = false
@@ -108,7 +109,7 @@ func parseFlags() []string {
 		fmt.Sprintf("enable reference store and configure with `DSN`, available adapters are: %v", refstore.AvailableAdapters()))
 	fs.BoolVar(&pull, "pull", pull, "always pull Docker images")
 	fs.StringVar(&logLevel, "log-level", logLevel,
-		"set logging verbosity, acceptable values are: [debug, info, warn, error, dpanic, panic, fatal]")
+		"set logging verbosity, acceptable values are: [debug, info, warn, error, fatal]")
 	fs.BoolVarP(&showVersion, "version", "v", showVersion,
 		`print version information and exit`)
 
@@ -137,8 +138,10 @@ func parseFlags() []string {
 func main() {
 	texd.PrintBanner(os.Stdout)
 	images := parseFlags() //nolint:ifshort // func has sideeffects
-	log, sync := setupLogger()
-	defer sync()
+	log, err := setupLogger()
+	if err != nil {
+		panic(err)
+	}
 
 	if showVersion {
 		printVersion()
@@ -147,32 +150,32 @@ func main() {
 
 	if err := tex.SetJobBaseDir(jobdir); err != nil {
 		log.Fatal("error setting job directory",
-			zap.String("flag", "--job-directory"),
-			zap.Error(err))
+			xlog.String("flag", "--job-directory"),
+			xlog.Error(err))
 	}
 	if err := tex.SetDefaultEngine(engine); err != nil {
 		log.Fatal("error setting default TeX engine",
-			zap.String("flag", "--tex-engine"),
-			zap.Error(err))
+			xlog.String("flag", "--tex-engine"),
+			xlog.Error(err))
 	}
 	if max, err := units.FromHumanSize(maxJobSize); err != nil {
 		log.Fatal("error parsing maximum job size",
-			zap.String("flag", "--max-job-size"),
-			zap.Error(err))
+			xlog.String("flag", "--max-job-size"),
+			xlog.Error(err))
 	} else {
 		opts.MaxJobSize = max
 	}
 	if storageDSN != "" {
 		rp, err := retentionPolicy()
 		if err != nil {
 			log.Fatal("error initializing retention policy",
-				zap.String("flag", "--retention-policy, and/or --rp-access-items, --rp-access-size"),
-				zap.Error(err))
+				xlog.String("flag", "--retention-policy, and/or --rp-access-items, --rp-access-size"),
+				xlog.Error(err))
 		}
 		if adapter, err := refstore.NewStore(storageDSN, rp); err != nil {
 			log.Fatal("error parsing reference store DSN",
-				zap.String("flag", "--reference-store"),
-				zap.Error(err))
+				xlog.String("flag", "--reference-store"),
+				xlog.Error(err))
 		} else {
 			opts.RefStore = adapter
 		}
@@ -181,23 +184,25 @@ func main() {
 	}
 
 	if len(images) > 0 {
-		log.Info("using docker", zap.Strings("images", images))
+		log.Info("using docker", xlog.String("images", strings.Join(images, ",")))
 		cli, err := exec.NewDockerClient(log, tex.JobBaseDir())
 		if err != nil {
-			log.Fatal("error connecting to dockerd", zap.Error(err))
+			log.Error("error connecting to dockerd", xlog.Error(err))
+			os.Exit(1)
 		}
 
 		opts.Images, err = cli.SetImages(context.Background(), pull, images...)
 		opts.Mode = "container"
 		if err != nil {
-			log.Fatal("error setting images", zap.Error(err))
+			log.Error("error setting images", xlog.Error(err))
+			os.Exit(1)
 		}
 		opts.Executor = cli.Executor
 	}
 
 	stop, err := service.Start(opts, log)
 	if err != nil {
-		log.Fatal("failed to start service", zap.Error(err))
+		log.Fatal("failed to start service", xlog.Error(err))
 	}
 	onExit(log, stop)
 }
@@ -206,14 +211,14 @@ const exitTimeout = 10 * time.Second
 
 type stopFun func(context.Context) error
 
-func onExit(log *zap.Logger, stopper ...stopFun) {
+func onExit(log xlog.Logger, stopper ...stopFun) {
 	exitCh := make(chan os.Signal, 2)
 	signal.Notify(exitCh, syscall.SIGINT, syscall.SIGTERM)
 	sig := <-exitCh
 
 	log.Info("performing shutdown, press Ctrl+C to exit now",
-		zap.String("signal", sig.String()),
-		zap.Duration("graceful-wait-timeout", exitTimeout))
+		xlog.String("signal", sig.String()),
+		slog.Duration("graceful-wait-timeout", exitTimeout))
 
 	ctx, cancel := context.WithTimeout(context.Background(), exitTimeout)
 	defer cancel()
@@ -223,7 +228,7 @@ func onExit(log *zap.Logger, stopper ...stopFun) {
 	for _, stop := range stopper {
 		go func(f stopFun) {
 			if err := f(ctx); err != nil {
-				log.Error("error while shutting down", zap.Error(err))
+				log.Error("error while shutting down", xlog.Error(err))
 			}
 			wg.Done()
 		}(stop)
@@ -266,34 +271,20 @@ func printVersion() {
 	}
 }
 
-func setupLogger() (*zap.Logger, func()) {
-	var cfg zap.Config
-	if texd.Development() {
-		cfg = zap.NewDevelopmentConfig()
-	} else {
-		cfg = zap.NewProductionConfig()
-	}
-
-	lvl, lvlErr := zapcore.ParseLevel(logLevel)
-	if lvlErr == nil {
-		cfg.Level = zap.NewAtomicLevelAt(lvl)
-	}
-
-	log, err := cfg.Build()
+func setupLogger() (xlog.Logger, error) {
+	lvl, err := xlog.ParseLevel(logLevel)
 	if err != nil {
-		// we don't have a logger yet, so logging the error
-		// proves to be complicated :)
-		panic(err)
+		return nil, err
 	}
 
-	if lvlErr != nil {
-		log.Error("error parsing log level",
-			zap.String("flag", "--log-level"),
-			zap.Error(lvlErr))
+	o := &slog.HandlerOptions{
+		AddSource: true,
+		// XXX: provide ReplaceAttr callback to normalize Source locations?
+		Level: lvl,
 	}
 
-	zap.ReplaceGlobals(log)
-	return log, func() {
-		_ = log.Sync()
+	if texd.Development() {
+		return xlog.New(xlog.TypeText, os.Stderr, o)
 	}
+	return xlog.New(xlog.TypeJSON, os.Stdout, o)
 }

exec/docker.go

@@ -4,7 +4,7 @@ import (
 	"context"
 
 	"github.com/digineo/texd/tex"
-	"go.uber.org/zap"
+	"github.com/digineo/texd/xlog"
 )
 
 type dockerRunner interface {
@@ -23,17 +23,17 @@ func (dc *DockerClient) Executor(doc Document) Exec {
 	}
 }
 
-func (x *dockerExec) Run(ctx context.Context, log *zap.Logger) error {
+func (x *dockerExec) Run(ctx context.Context, log xlog.Logger) error {
 	dir, cmd, err := x.extract()
 	if err != nil {
 		return tex.CompilationError("invalid document", err, nil)
 	}
 
 	tag := x.doc.Image()
-	log.Debug("running latexmk", zap.Strings("args", cmd[1:]))
+	log.Debug("running latexmk", xlog.Any("args", cmd[1:]))
 	output, err := x.cli.Run(ctx, tag, dir, cmd)
 	if err != nil {
-		log.Error("compilation failed", zap.Error(err))
+		log.Error("compilation failed", xlog.Error(err))
 		return tex.CompilationError("compilation failed", err, tex.KV{
 			"cmd":    cmd[0],
 			"args":   cmd[1:],

exec/docker_client.go

@@ -8,6 +8,7 @@ import (
 	"os"
 
 	"github.com/digineo/texd/service/middleware"
+	"github.com/digineo/texd/xlog"
 	"github.com/docker/docker/api/types"
 	"github.com/docker/docker/api/types/container"
 	"github.com/docker/docker/api/types/image"
@@ -16,7 +17,6 @@ import (
 	"github.com/docker/docker/pkg/jsonmessage"
 	"github.com/docker/docker/pkg/stdcopy"
 	"github.com/moby/term"
-	"go.uber.org/zap"
 )
 
 // newClient is swapped in tests
@@ -27,7 +27,7 @@ var newClient = func() (client.APIClient, error) {
 // DockerClient wraps a Docker client instance and provides methods to
 // pull images and start containers.
 type DockerClient struct {
-	log    *zap.Logger
+	log    xlog.Logger
 	cli    client.APIClient
 	images []image.Summary
 
@@ -41,14 +41,14 @@ type DockerClient struct {
 // When running in a Docker-in-Docker environment, baseDir is used to
 // determine the volume path on the Docker host, in order to mount
 // job directories correctly.
-func NewDockerClient(log *zap.Logger, baseDir string) (h *DockerClient, err error) {
+func NewDockerClient(log xlog.Logger, baseDir string) (h *DockerClient, err error) {
 	cli, err := newClient()
 	if err != nil {
 		return nil, err
 	}
 
 	if log == nil {
-		log = zap.NewNop()
+		log = xlog.NewNop()
 	}
 	dc := &DockerClient{
 		log: log,
@@ -83,14 +83,14 @@ func (dc *DockerClient) SetImages(ctx context.Context, alwaysPull bool, tags ...
 		if img.ID == "" || alwaysPull {
 			toPull = append(toPull, tag)
 		} else {
-			dc.log.Info("image already present", zap.String("image", tag))
+			dc.log.Info("image already present", xlog.String("image", tag))
 			knownImages = append(knownImages, img)
 		}
 	}
 
 	p := newProgressReporter(os.Stdout)
 	for _, tag := range toPull {
-		dc.log.Info("pulling missing image", zap.String("image", tag))
+		dc.log.Info("pulling missing image", xlog.String("image", tag))
 		if err := dc.pull(ctx, tag, p); err != nil {
 			return nil, err
 		}
@@ -210,8 +210,8 @@ func (dc *DockerClient) prepareContainer(ctx context.Context, tag, wd string, cm
 	}
 	dc.log.Debug("container is ready",
 		middleware.RequestIDField(ctx),
-		zap.String("id", worker.ID),
-		zap.String("work-dir", wd))
+		xlog.String("id", worker.ID),
+		xlog.String("work-dir", wd))
 	return worker.ID, nil
 }
 

exec/docker_client_test.go

@@ -12,6 +12,7 @@ import (
 	"syscall"
 	"testing"
 
+	"github.com/digineo/texd/xlog"
 	"github.com/docker/docker/api/types"
 	"github.com/docker/docker/api/types/container"
 	"github.com/docker/docker/api/types/image"
@@ -22,7 +23,6 @@ import (
 	"github.com/spf13/afero"
 	"github.com/stretchr/testify/mock"
 	"github.com/stretchr/testify/suite"
-	"go.uber.org/zap"
 )
 
 // bg is used as default context given to the apiMock stubs.
@@ -115,7 +115,7 @@ func (s *dockerClientSuite) SetupTest() {
 	s.cli = &apiMock{}
 	s.subject = &DockerClient{
 		cli: s.cli,
-		log: zap.NewNop(),
+		log: xlog.NewNop(),
 	}
 }
 

exec/docker_test.go

@@ -7,10 +7,10 @@ import (
 	"testing"
 
 	"github.com/digineo/texd/tex"
+	"github.com/digineo/texd/xlog"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
 	"github.com/stretchr/testify/require"
-	"go.uber.org/zap"
 )
 
 type dockerClientMock struct {
@@ -24,7 +24,7 @@ func (m *dockerClientMock) Run(ctx context.Context, tag, wd string, cmd []string
 
 func TestDockerClient_Executor(t *testing.T) {
 	subject := (&DockerClient{
-		log: zap.NewNop(),
+		log: xlog.NewNop(),
 		cli: &apiMock{},
 	}).Executor(&mockDocument{})
 	require.NotNil(t, subject)
@@ -37,7 +37,7 @@ func TestDockerExec_invalidDocument(t *testing.T) {
 		cli:      nil, // not accessed
 	}
 
-	err := exec.Run(bg, zap.NewNop())
+	err := exec.Run(bg, xlog.NewNop())
 	require.EqualError(t, err, "invalid document: "+io.ErrClosedPipe.Error())
 }
 
@@ -55,7 +55,7 @@ func TestDockerExec_latexmkFailed(t *testing.T) {
 		cli:      cli,
 	}
 
-	err := exec.Run(bg, zap.NewNop())
+	err := exec.Run(bg, xlog.NewNop())
 	require.EqualError(t, err, "compilation failed: "+errStart.Error())
 	assert.True(t, tex.IsCompilationError(err))
 
@@ -78,6 +78,6 @@ func TestDockerExec_success(t *testing.T) {
 		cli:      cli,
 	}
 
-	err := exec.Run(bg, zap.NewNop())
+	err := exec.Run(bg, xlog.NewNop())
 	require.NoError(t, err)
 }

exec/exec.go

@@ -4,11 +4,11 @@ import (
 	"context"
 
 	"github.com/digineo/texd/tex"
-	"go.uber.org/zap"
+	"github.com/digineo/texd/xlog"
 )
 
 type Exec interface {
-	Run(context.Context, *zap.Logger) error
+	Run(context.Context, xlog.Logger) error
 }
 
 // Document is a sub-set of the tex.Document interface.