improve logging

- introduce go.uber.org/zap
- introduce --log-level CLI flag
- ensure the request ID is logged

Issue: #1

.goreleaser.yaml

@@ -12,6 +12,7 @@ builds:
       - -X github.com/digineo/texd.commit={{ .Commit }}
       - -X github.com/digineo/texd.commitat={{ .CommitDate }}
       - -X github.com/digineo/texd.buildat={{ .Date }}
+      - -X github.com/digineo/texd.isdev=0
     env:
       - CGO_ENABLED=0
     goos:

Makefile

@@ -5,13 +5,18 @@ TARGET = texd
 VERSION     = $(shell git describe --tags --always --dirty)
 COMMIT_DATE = $(shell git show -s --format=%cI HEAD)
 BUILD_DATE  = $(shell date --iso-8601=seconds)
+DEVELOPMENT = 1
 
 LDFLAGS = -s -w \
           -X 'github.com/digineo/texd.version=$(VERSION)' \
-          -X 'github.com/digineo/texd.commitdate=$(COMMIT_DATE)' \
-          -X 'github.com/digineo/texd.builddate=$(BUILD_DATE)'
+          -X 'github.com/digineo/texd.commitat=$(COMMIT_DATE)' \
+          -X 'github.com/digineo/texd.buildat=$(BUILD_DATE)' \
+          -X 'github.com/digineo/texd.isdev=$(DEVELOPMENT)'
 GOFLAGS = -trimpath -ldflags="$(LDFLAGS)"
 
+# passed to run-* targets
+RUN_ARGS = --job-directory ./tmp --log-level debug
+
 ## help (prints target names with trailing "## comment")
 
 PHONY: help
@@ -40,11 +45,11 @@ lint: ## runs golangci-lint on source files
 
 .PHONY: run-local
 run-local: tmp build ## builds and runs texd in local mode
-	./$(TARGET) -D ./tmp
+	./$(TARGET) $(RUN_ARGS)
 
 .PHONY: run-container
 run-container: tmp build ## builds and runs texd in container mode
-	./$(TARGET) -D ./tmp texlive/texlive:latest
+	./$(TARGET) $(RUN_ARGS) texlive/texlive:latest
 
 
 ## testing

cmd/texd/main.go

@@ -3,7 +3,6 @@ package main
 import (
 	"context"
 	"fmt"
-	"log"
 	"os"
 	"os/signal"
 	"runtime"
@@ -17,6 +16,8 @@ import (
 	"github.com/digineo/texd/service"
 	"github.com/digineo/texd/tex"
 	flag "github.com/spf13/pflag"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 )
 
 var opts = service.Options{
@@ -29,13 +30,15 @@ var opts = service.Options{
 }
 
 var (
-	engine = tex.DefaultEngine.Name()
-	jobdir = ""
-	pull   = false
+	engine   = tex.DefaultEngine.Name()
+	jobdir   = ""
+	pull     = false
+	logLevel = zapcore.InfoLevel.String()
 )
 
-func main() {
-	log.SetFlags(log.Lshortfile)
+var log = zap.L()
+
+func main() { //nolint:funlen
 	texd.PrintBanner(os.Stdout)
 
 	flag.StringVarP(&opts.Addr, "listen-address", "b", opts.Addr,
@@ -51,6 +54,8 @@ func main() {
 	flag.StringVarP(&jobdir, "job-directory", "D", jobdir,
 		"`path` to base directory to place temporary jobs into (path must exist and it must be writable; defaults to the OS's temp directory)")
 	flag.BoolVar(&pull, "pull", pull, "always pull Docker images")
+	flag.StringVar(&logLevel, "log-level", logLevel,
+		"set logging verbosity, acceptable values are: [debug, info, warn, error, dpanic, panic, fatal]")
 	versionRequested := flag.BoolP("version", "v", false, `print version information and exit`)
 	flag.Parse()
 
@@ -59,29 +64,44 @@ func main() {
 		os.Exit(0)
 	}
 
+	if lvl, err := zapcore.ParseLevel(logLevel); err != nil {
+		zap.L().Fatal("error parsing log level",
+			zap.String("flag", "--log-level"),
+			zap.Error(err))
+	} else if log, err = newLogger(lvl); err != nil {
+		zap.L().Fatal("error constructing logger",
+			zap.Error(err))
+	} else {
+		defer log.Sync()
+	}
+
 	if err := tex.SetJobBaseDir(jobdir); err != nil {
-		log.Fatalf("error parsing --job-directory: %v", err)
+		log.Fatal("error setting job directory",
+			zap.String("flag", "--job-directory"),
+			zap.Error(err))
 	}
 
 	if err := tex.SetDefaultEngine(engine); err != nil {
-		log.Fatalf("error parsing --tex-engine: %v", err)
+		log.Fatal("error setting default TeX engine",
+			zap.String("flag", "--tex-engine"),
+			zap.Error(err))
 	}
 
 	if images := flag.Args(); len(images) > 0 {
-		cli, err := exec.NewDockerClient()
+		cli, err := exec.NewDockerClient(log)
 		if err != nil {
-			log.Fatalf("error connecting to dockerd: %v", err)
+			log.Fatal("error connecting to dockerd", zap.Error(err))
 		}
 
 		opts.Images, err = cli.SetImages(context.Background(), pull, images...)
 		opts.Mode = "container"
 		if err != nil {
-			log.Fatalf("error setting images: %v", err)
+			log.Fatal("error setting images", zap.Error(err))
 		}
 		opts.Executor = cli.Executor
 	}
 
-	stop := service.Start(opts)
+	stop := service.Start(opts, log)
 	onExit(stop)
 }
 
@@ -93,17 +113,20 @@ func onExit(stopper ...stopFun) {
 	exitCh := make(chan os.Signal, 2)
 	signal.Notify(exitCh, syscall.SIGINT, syscall.SIGTERM)
 	sig := <-exitCh
-	log.Printf("received signal %s, performing shutdown (max. %s, press Ctrl+C to exit now)",
-		sig, exitTimeout)
+
+	log.Info("performing shutdown, press Ctrl+C to exit now",
+		zap.String("signal", sig.String()),
+		zap.Duration("graceful-wait-timeout", exitTimeout))
 
 	ctx, cancel := context.WithTimeout(context.Background(), exitTimeout)
+	defer cancel()
 
 	wg := sync.WaitGroup{}
 	wg.Add(len(stopper))
 	for _, stop := range stopper {
 		go func(f stopFun) {
 			if err := f(ctx); err != nil {
-				log.Printf("error while shutting down: %v", err)
+				log.Error("error while shutting down", zap.Error(err))
 			}
 			wg.Done()
 		}(stop)
@@ -117,13 +140,12 @@ func onExit(stopper ...stopFun) {
 
 	select {
 	case <-exitCh:
-		log.Println("forcing exit")
+		log.Warn("forcing exit")
 	case <-doneCh:
-		log.Println("shutdown complete")
+		log.Info("shutdown complete")
 	case <-ctx.Done():
-		log.Println("shutdown incomplete, exiting anyway")
+		log.Warn("shutdown incomplete, exiting anyway")
 	}
-	cancel()
 }
 
 func printVersion() {
@@ -146,3 +168,15 @@ func printVersion() {
 		}
 	}
 }
+
+func newLogger(level zapcore.Level) (*zap.Logger, error) {
+	var cfg zap.Config
+	if texd.Development() {
+		cfg = zap.NewDevelopmentConfig()
+	} else {
+		cfg = zap.NewProductionConfig()
+	}
+
+	cfg.Level = zap.NewAtomicLevelAt(level)
+	return cfg.Build()
+}

exec/docker.go

@@ -4,6 +4,7 @@ import (
 	"context"
 
 	"github.com/digineo/texd/tex"
+	"go.uber.org/zap"
 )
 
 type dockerExec struct {
@@ -18,17 +19,20 @@ func (dc *DockerClient) Executor(doc tex.Document) Exec {
 	}
 }
 
-func (x *dockerExec) Run(ctx context.Context) error {
+func (x *dockerExec) Run(ctx context.Context, log *zap.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:]))
 	output, err := x.cli.Run(ctx, tag, dir, cmd)
 	if err != nil {
+		log.Error("compilation failed", zap.Error(err))
 		return tex.CompilationError("compilation failed", err, tex.KV{
-			"flags":  cmd,
+			"cmd":    cmd[0],
+			"args":   cmd[1:],
 			"output": output,
 			"image":  tag,
 		})

exec/docker_client.go

@@ -5,35 +5,40 @@ import (
 	"context"
 	"fmt"
 	"io"
-	"log"
 	"os"
 
+	"github.com/digineo/texd/service/middleware"
 	"github.com/docker/docker/api/types"
 	"github.com/docker/docker/api/types/container"
 	"github.com/docker/docker/api/types/mount"
 	"github.com/docker/docker/client"
 	"github.com/docker/docker/pkg/jsonmessage"
 	"github.com/docker/docker/pkg/stdcopy"
 	"github.com/moby/term"
+	"go.uber.org/zap"
 )
 
 // DockerClient wraps a Docker client instance and provides methods to
 // pull images and start containers.
 type DockerClient struct {
+	log    *zap.Logger
 	cli    *client.Client
 	images []types.ImageSummary
 }
 
 // NewDockerClient creates a new DockerClient. To configure the client,
 // use environment variables: DOCKER_HOST, DOCKER_API_VERSION,
 // DOCKER_CERT_PATH and DOCKER_TLS_VERIFY are supported.
-func NewDockerClient() (h *DockerClient, err error) {
+func NewDockerClient(log *zap.Logger) (h *DockerClient, err error) {
 	cli, err := client.NewClientWithOpts(client.FromEnv, client.WithAPIVersionNegotiation())
 	if err != nil {
 		return nil, err
 	}
 
-	return &DockerClient{cli: cli}, nil
+	if log == nil {
+		log = zap.NewNop()
+	}
+	return &DockerClient{log, cli, nil}, nil
 }
 
 // SetImages ensures that the given image tags are present on the
@@ -59,14 +64,14 @@ func (dc *DockerClient) SetImages(ctx context.Context, alwaysPull bool, tags ...
 		if img.ID == "" || alwaysPull {
 			toPull = append(toPull, tag)
 		} else {
-			log.Println("image already present:", tag)
+			dc.log.Info("image already present", zap.String("image", tag))
 			knownImages = append(knownImages, img)
 		}
 	}
 
 	p := newProgressReporter(os.Stdout)
 	for _, tag := range toPull {
-		log.Println("pulling missing image:", tag)
+		dc.log.Info("pulling missing image", zap.String("image", tag))
 		if err := dc.pull(ctx, tag, p); err != nil {
 			return nil, err
 		}
@@ -138,25 +143,29 @@ func (dc *DockerClient) pull(ctx context.Context, tag string, p *progess) error
 	return err
 }
 
-func (dc *DockerClient) allowed(tag string) (ok bool) {
+func (dc *DockerClient) findAllowedImageID(tag string) string {
+	if tag == "" && len(dc.images) > 0 {
+		return dc.images[0].ID
+	}
 	for _, img := range dc.images {
 		for _, t := range img.RepoTags {
 			if t == tag {
-				return true
+				return img.ID
 			}
 		}
 	}
-	return false
+	return ""
 }
 
 func (dc *DockerClient) prepareContainer(ctx context.Context, tag, wd string, cmd []string) (string, error) {
-	if ok := dc.allowed(tag); !ok {
+	id := dc.findAllowedImageID(tag)
+	if id == "" {
 		return "", fmt.Errorf("image %q not allowed", tag)
 	}
 
 	const containerWd = "/texd"
 	containerCfg := &container.Config{
-		Image:           tag,
+		Image:           id,
 		Cmd:             cmd,
 		WorkingDir:      containerWd,
 		NetworkDisabled: true,
@@ -177,7 +186,10 @@ func (dc *DockerClient) prepareContainer(ctx context.Context, tag, wd string, cm
 	if err != nil {
 		return "", fmt.Errorf("failed to create container: %w", err)
 	}
-	log.Printf("container %s ready (%s)", worker.ID, wd)
+	dc.log.Debug("container is ready",
+		middleware.RequestIDField(ctx),
+		zap.String("id", worker.ID),
+		zap.String("work-dir", wd))
 	return worker.ID, nil
 }
 

exec/exec.go

@@ -4,10 +4,11 @@ import (
 	"context"
 
 	"github.com/digineo/texd/tex"
+	"go.uber.org/zap"
 )
 
 type Exec interface {
-	Run(context.Context) error
+	Run(context.Context, *zap.Logger) error
 }
 
 type baseExec struct {

exec/local.go

@@ -6,6 +6,7 @@ import (
 	"os/exec"
 
 	"github.com/digineo/texd/tex"
+	"go.uber.org/zap"
 )
 
 type localExec struct {
@@ -18,7 +19,7 @@ func LocalExec(doc tex.Document) Exec {
 	}
 }
 
-func (x *localExec) Run(ctx context.Context) error {
+func (x *localExec) Run(ctx context.Context, log *zap.Logger) error {
 	dir, args, err := x.extract()
 	if err != nil {
 		return tex.CompilationError("invalid document", err, nil)
@@ -35,7 +36,9 @@ func (x *localExec) Run(ctx context.Context) error {
 	cmd.Dir = dir
 	cmd.Stderr = &stderr
 
+	log.Debug("running latexmk", zap.Strings("args", args[1:]))
 	if err := cmd.Run(); err != nil {
+		log.Error("compilation failed", zap.Error(err))
 		return tex.CompilationError("compilation failed", err, tex.KV{
 			"cmd":    args[0],
 			"args":   args[1:],

go.mod

@@ -30,6 +30,9 @@ require (
 	github.com/pkg/errors v0.9.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/sirupsen/logrus v1.8.1 // indirect
+	go.uber.org/atomic v1.9.0 // indirect
+	go.uber.org/multierr v1.8.0 // indirect
+	go.uber.org/zap v1.21.0 // indirect
 	golang.org/x/net v0.0.0-20220225172249-27dd8689420f // indirect
 	golang.org/x/sys v0.0.0-20220310020820-b874c991c1a5 // indirect
 	golang.org/x/text v0.3.7 // indirect