From 62f9fdaa5a5ad05e32e614dfd12b774cf3ae065c Mon Sep 17 00:00:00 2001 From: Dominik Menke Date: Thu, 25 Jan 2024 23:32:09 +0100 Subject: [PATCH 1/7] refactor: replace logger This replaces the zap logging engine with Go 1.21's 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 --- cmd/texd/main.go | 87 +++++++++----------- exec/docker.go | 8 +- exec/docker_client.go | 16 ++-- exec/docker_client_test.go | 4 +- exec/docker_test.go | 10 +-- exec/exec.go | 4 +- exec/local.go | 10 +-- exec/local_test.go | 4 +- exec/mock.go | 6 +- exec/mock_test.go | 14 ++-- go.mod | 2 - go.sum | 6 -- refstore/dir/dir_store.go | 14 ++-- refstore/dir/dir_store_test.go | 6 +- refstore/memcached/memcached.go | 38 ++++----- refstore/nop/nop_store.go | 6 +- refstore/reference_store.go | 6 +- service/middleware/logging.go | 20 ++--- service/middleware/logging_test.go | 37 +++------ service/middleware/requestid.go | 9 ++- service/middleware/requestid_test.go | 10 +-- service/renderer.go | 39 +++++---- service/service.go | 20 ++--- service/service_test.go | 10 +-- service/status.go | 4 +- service/status_test.go | 37 ++++----- tex/document.go | 14 ++-- tex/document_test.go | 10 +-- tex/metrics_test.go | 4 +- xlog/attrs.go | 28 +++++++ xlog/log.go | 117 +++++++++++++++++++++++++++ xlog/nop.go | 15 ++++ 32 files changed, 369 insertions(+), 246 deletions(-) create mode 100644 xlog/attrs.go create mode 100644 xlog/log.go create mode 100644 xlog/nop.go diff --git a/cmd/texd/main.go b/cmd/texd/main.go index 609f15f..68a55e3 100644 --- a/cmd/texd/main.go +++ b/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" ) const ( @@ -53,7 +54,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 @@ -119,7 +120,7 @@ func parseFlags(progname string, args ...string) []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`) @@ -148,8 +149,10 @@ func parseFlags(progname string, args ...string) []string { func main() { //nolint:funlen texd.PrintBanner(os.Stdout) images := parseFlags(os.Args[0], os.Args[1:]...) - log, sync := setupLogger() - defer sync() + log, err := setupLogger() + if err != nil { + panic(err) + } if showVersion { printVersion() @@ -158,18 +161,18 @@ func main() { //nolint:funlen 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 maxsz, 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 = maxsz } @@ -177,13 +180,13 @@ func main() { //nolint:funlen 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 } @@ -192,37 +195,39 @@ func main() { //nolint:funlen } 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) } 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) //nolint:mnd // idiomatic 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() @@ -232,7 +237,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) @@ -275,34 +280,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) } diff --git a/exec/docker.go b/exec/docker.go index d33c4dd..0b509f3 100644 --- a/exec/docker.go +++ b/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:], diff --git a/exec/docker_client.go b/exec/docker_client.go index 731ee96..ca6de33 100644 --- a/exec/docker_client.go +++ b/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/container" "github.com/docker/docker/api/types/image" "github.com/docker/docker/api/types/mount" @@ -15,7 +16,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. @@ -26,7 +26,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 @@ -40,14 +40,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, @@ -82,14 +82,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 } @@ -209,8 +209,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 } diff --git a/exec/docker_client_test.go b/exec/docker_client_test.go index 332bf5a..6e1beed 100644 --- a/exec/docker_client_test.go +++ b/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(), } } diff --git a/exec/docker_test.go b/exec/docker_test.go index c13bb57..f2fcbc9 100644 --- a/exec/docker_test.go +++ b/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) } diff --git a/exec/exec.go b/exec/exec.go index 7f98849..2f89a98 100644 --- a/exec/exec.go +++ b/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(ctx context.Context, logger *zap.Logger) error + Run(ctx context.Context, logger xlog.Logger) error } // Document is a sub-set of the tex.Document interface. diff --git a/exec/local.go b/exec/local.go index 465fc55..af7ef7b 100644 --- a/exec/local.go +++ b/exec/local.go @@ -6,7 +6,7 @@ import ( "os/exec" "github.com/digineo/texd/tex" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) type localExec struct { @@ -20,7 +20,7 @@ func LocalExec(doc Document) Exec { } } -func (x *localExec) Run(ctx context.Context, log *zap.Logger) error { +func (x *localExec) Run(ctx context.Context, log xlog.Logger) error { dir, args, err := x.extract() if err != nil { return tex.CompilationError("invalid document", err, nil) @@ -36,11 +36,11 @@ func (x *localExec) Run(ctx context.Context, log *zap.Logger) error { cmd.Dir = dir cmd.Stderr = &stderr - log.Debug("running latexmk", zap.Strings("args", args[1:])) + log.Debug("running latexmk", xlog.Any("args", args[1:])) if err := cmd.Run(); err != nil { log.Error("compilation failed", - zap.String("stderr", stderr.String()), - zap.Error(err)) + xlog.String("stderr", stderr.String()), + xlog.Error(err)) return tex.CompilationError("compilation failed", err, tex.KV{ "cmd": args[0], "args": args[1:], diff --git a/exec/local_test.go b/exec/local_test.go index 2b9563c..7df33ad 100644 --- a/exec/local_test.go +++ b/exec/local_test.go @@ -9,9 +9,9 @@ import ( "testing" "github.com/digineo/texd/tex" + "github.com/digineo/texd/xlog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap" ) func TestLocalExec_Run(t *testing.T) { @@ -58,7 +58,7 @@ func TestLocalExec_Run(t *testing.T) { // create local exec exec := LocalExec(tt.doc).(*localExec) //nolint:forcetypeassert exec.path = tt.path - err := exec.Run(context.Background(), zap.NewNop()) + err := exec.Run(context.Background(), xlog.NewNop()) if tt.expectedErr == "" { assert.NoError(t, err) diff --git a/exec/mock.go b/exec/mock.go index c4146c1..8a1369a 100644 --- a/exec/mock.go +++ b/exec/mock.go @@ -6,7 +6,7 @@ import ( "strings" "github.com/digineo/texd/tex" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) type MockExec struct { @@ -38,13 +38,13 @@ func Mock(shouldFail bool, resultContents string) func(Document) Exec { } } -func (x *MockExec) Run(ctx context.Context, log *zap.Logger) error { +func (x *MockExec) Run(ctx context.Context, log xlog.Logger) error { _, args, err := x.extract() if err != nil { return tex.CompilationError("invalid document", err, nil) } - log.Debug("simlate running latexmk", zap.Strings("args", args[1:])) + log.Debug("simlate running latexmk", xlog.Any("args", args[1:])) main, _ := x.doc.MainInput() // would have failed in x.extract() dot := strings.LastIndexByte(main, '.') if dot < 0 { diff --git a/exec/mock_test.go b/exec/mock_test.go index d4a1e7c..707c5ff 100644 --- a/exec/mock_test.go +++ b/exec/mock_test.go @@ -4,10 +4,10 @@ import ( "io" "testing" + "github.com/digineo/texd/xlog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" - "go.uber.org/zap" ) func TestMock(t *testing.T) { @@ -25,7 +25,7 @@ func TestMock_Run_extractError(t *testing.T) { doc := &mockDocument{"/", io.ErrClosedPipe, "a", nil} subject := Mock(true, "content")(doc) - err := subject.Run(bg, zap.NewNop()) + err := subject.Run(bg, xlog.NewNop()) require.EqualError(t, err, "invalid document: "+io.ErrClosedPipe.Error()) } @@ -34,7 +34,7 @@ func TestMock_Run_invalidMainfilePanics(t *testing.T) { subject := Mock(true, "content")(doc) require.PanicsWithValue(t, "malformed input file: missing extension", - func() { _ = subject.Run(bg, zap.NewNop()) }) + func() { _ = subject.Run(bg, xlog.NewNop()) }) } func TestMock_Run_noAddFilePanics(t *testing.T) { @@ -42,7 +42,7 @@ func TestMock_Run_noAddFilePanics(t *testing.T) { subject := Mock(true, "content")(doc) require.PanicsWithValue(t, "can't add files to document", - func() { _ = subject.Run(bg, zap.NewNop()) }) + func() { _ = subject.Run(bg, xlog.NewNop()) }) } type mockDockumentWithAddFile struct { @@ -64,7 +64,7 @@ func TestMock_Run_errorOnAddFilePanics(t *testing.T) { doc.On("AddFile", "a.log", "content").Return(io.ErrClosedPipe) require.PanicsWithError(t, "failed to store result file: "+io.ErrClosedPipe.Error(), - func() { _ = subject.Run(bg, zap.NewNop()) }) + func() { _ = subject.Run(bg, xlog.NewNop()) }) } func TestMock_Run_shouldFailCapturesLog(t *testing.T) { @@ -75,7 +75,7 @@ func TestMock_Run_shouldFailCapturesLog(t *testing.T) { doc.On("AddFile", "a.log", "content").Return(nil) - err := subject.Run(bg, zap.NewNop()) + err := subject.Run(bg, xlog.NewNop()) require.EqualError(t, err, "compilation failed") } @@ -87,6 +87,6 @@ func TestMock_Run_shouldFailCapturesResult(t *testing.T) { doc.On("AddFile", "a.pdf", "%PDF/1.5").Return(nil) - err := subject.Run(bg, zap.NewNop()) + err := subject.Run(bg, xlog.NewNop()) require.NoError(t, err) } diff --git a/go.mod b/go.mod index f361a22..e32dace 100644 --- a/go.mod +++ b/go.mod @@ -17,7 +17,6 @@ require ( github.com/spf13/pflag v1.0.5 github.com/stretchr/testify v1.9.0 github.com/thediveo/enumflag v0.10.1 - go.uber.org/zap v1.27.0 ) require ( @@ -54,7 +53,6 @@ require ( go.opentelemetry.io/otel/metric v1.31.0 // indirect go.opentelemetry.io/otel/sdk v1.30.0 // indirect go.opentelemetry.io/otel/trace v1.31.0 // indirect - go.uber.org/multierr v1.11.0 // indirect golang.org/x/sys v0.26.0 // indirect golang.org/x/text v0.19.0 // indirect google.golang.org/protobuf v1.35.1 // indirect diff --git a/go.sum b/go.sum index 80a113e..7a20ee1 100644 --- a/go.sum +++ b/go.sum @@ -1617,14 +1617,8 @@ go.opentelemetry.io/proto/otlp v0.19.0/go.mod h1:H7XAot3MsfNsj7EXtrA2q5xSNQ10UqI go.opentelemetry.io/proto/otlp v1.3.1 h1:TrMUixzpM0yuc/znrFTP9MMRh8trP93mkCiDVeXrui0= go.opentelemetry.io/proto/otlp v1.3.1/go.mod h1:0X1WI4de4ZsLrrJNLAQbFeLCm3T7yBkR0XqQ7niQU+8= go.uber.org/atomic v1.4.0/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE= -go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= -go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0= -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.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q= -go.uber.org/zap v1.27.0 h1:aJMhYGrd5QSmlpLMr2MftRKl7t8J8PTZPA732ud/XR8= -go.uber.org/zap v1.27.0/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E= golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= diff --git a/refstore/dir/dir_store.go b/refstore/dir/dir_store.go index 6208806..2e564b9 100644 --- a/refstore/dir/dir_store.go +++ b/refstore/dir/dir_store.go @@ -32,8 +32,8 @@ import ( "github.com/digineo/texd/internal" "github.com/digineo/texd/refstore" + "github.com/digineo/texd/xlog" "github.com/spf13/afero" - "go.uber.org/zap" ) var defaultFs afero.Fs = afero.OsFs{} // swapped in tests @@ -109,7 +109,7 @@ func pathFromURL(config *url.URL) string { return path } -func (d *dir) CopyFile(log *zap.Logger, id refstore.Identifier, dst io.Writer) error { +func (d *dir) CopyFile(log xlog.Logger, id refstore.Identifier, dst io.Writer) error { src, err := d.fs.Open(d.idPath(id)) if err != nil { if errors.Is(err, os.ErrNotExist) { @@ -120,8 +120,8 @@ func (d *dir) CopyFile(log *zap.Logger, id refstore.Identifier, dst io.Writer) e defer src.Close() log.Debug("copy file", - zap.String("refstore", "disk"), - zap.String("id", id.Raw())) + xlog.String("refstore", "disk"), + xlog.String("id", id.Raw())) if _, err := io.Copy(dst, src); err != nil { return fmt.Errorf("failed to copy storage object: %v", err) } @@ -129,7 +129,7 @@ func (d *dir) CopyFile(log *zap.Logger, id refstore.Identifier, dst io.Writer) e return nil } -func (d *dir) Store(log *zap.Logger, r io.Reader) error { +func (d *dir) Store(log xlog.Logger, r io.Reader) error { tmp, err := afero.TempFile(d.fs, d.path, "tmp-*") if err != nil { return fmt.Errorf("failed to create storage object: %v", err) @@ -145,8 +145,8 @@ func (d *dir) Store(log *zap.Logger, r io.Reader) error { } log.Debug("store file", - zap.String("refstore", "disk"), - zap.String("id", id.Raw())) + xlog.String("refstore", "disk"), + xlog.String("id", id.Raw())) dst := d.idPath(id) if err = d.fs.Rename(tmp.Name(), dst); err != nil { diff --git a/refstore/dir/dir_store_test.go b/refstore/dir/dir_store_test.go index fed7997..3737901 100644 --- a/refstore/dir/dir_store_test.go +++ b/refstore/dir/dir_store_test.go @@ -8,10 +8,10 @@ import ( "testing" "github.com/digineo/texd/refstore" + "github.com/digineo/texd/xlog" "github.com/spf13/afero" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap" ) type dummyFile []byte @@ -84,7 +84,7 @@ func TestNew_dirNotWritable(t *testing.T) { func TestDirAdapter_keepFiles(t *testing.T) { require := require.New(t) - log := zap.NewNop() + log := xlog.NewNop() subject, err := NewMemory(nil, &refstore.KeepForever{}) require.NoError(err) @@ -121,7 +121,7 @@ func TestDirAdapter_purgeFiles(t *testing.T) { func TestDirAdapter_accessMap(t *testing.T) { require := require.New(t) - log := zap.NewNop() + log := xlog.NewNop() f := dummyFile("01234567890") for _, q := range []struct{ n, sz int }{ diff --git a/refstore/memcached/memcached.go b/refstore/memcached/memcached.go index 5f312e7..2256af1 100644 --- a/refstore/memcached/memcached.go +++ b/refstore/memcached/memcached.go @@ -31,7 +31,7 @@ import ( "github.com/bradfitz/gomemcache/memcache" "github.com/digineo/texd/internal" "github.com/digineo/texd/refstore" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) // Defaults copied from github.com/bradfitz/gomemcache/memcache for clarity @@ -76,22 +76,22 @@ type store struct { // The following URI parameters are understood (any similarity with // github.com/bradfitz/gomemcache/memcache is intentional): // -// - addr= adds an additional server to the pool. This option can -// be specified multiple times. If an address is specified multiple times, -// it gains a proportional amount of weight. -// Note: you may omit config.Host, and only use addr= URI parameters. -// - timeout= to specify the read/write timeout. The parameter -// value will be parsed with time.ParseDuration(). Values < 0 are invalid -// (New() will return an error) and the zero value is substituted with -// a default (100ms). -// - max_idle_conns= specifies the maximum number of idle connections -// that will be maintained per address. Negative values are invalid, -// and the zero value is substituted with a default (2). -// - expiration= adds a lifetime to reference files. A value <= 0 -// is ignored (no error). The duration must fit into a int32, which -// imposes a maximum duration of just over 68 years. -// - key_prefix= adds a custom prefix to file reference hashes. -// By default, this adapter prefixes reference hashes with "texd/". +// - addr= adds an additional server to the pool. This option can +// be specified multiple times. If an address is specified multiple times, +// it gains a proportional amount of weight. +// Note: you may omit config.Host, and only use addr= URI parameters. +// - timeout= to specify the read/write timeout. The parameter +// value will be parsed with time.ParseDuration(). Values < 0 are invalid +// (New() will return an error) and the zero value is substituted with +// a default (100ms). +// - max_idle_conns= specifies the maximum number of idle connections +// that will be maintained per address. Negative values are invalid, +// and the zero value is substituted with a default (2). +// - expiration= adds a lifetime to reference files. A value <= 0 +// is ignored (no error). The duration must fit into a int32, which +// imposes a maximum duration of just over 68 years. +// - key_prefix= adds a custom prefix to file reference hashes. +// By default, this adapter prefixes reference hashes with "texd/". // // Note that server addresses (whether provided as DNS host name or via query // parameters) should include a port number (by default, Memcached listens @@ -134,7 +134,7 @@ func New(config *url.URL, _ refstore.RetentionPolicy) (refstore.Adapter, error) return adapter, nil } -func (s *store) CopyFile(_ *zap.Logger, id refstore.Identifier, w io.Writer) error { +func (s *store) CopyFile(_ xlog.Logger, id refstore.Identifier, w io.Writer) error { val, err := s.get(s.key(id)) if err != nil { if errors.Is(err, memcache.ErrCacheMiss) { @@ -149,7 +149,7 @@ func (s *store) CopyFile(_ *zap.Logger, id refstore.Identifier, w io.Writer) err return nil } -func (s *store) Store(_ *zap.Logger, r io.Reader) error { +func (s *store) Store(_ xlog.Logger, r io.Reader) error { val, err := io.ReadAll(r) if err != nil { return fmt.Errorf("memcached: failed to read reference file: %w", err) diff --git a/refstore/nop/nop_store.go b/refstore/nop/nop_store.go index 39ade12..1881a92 100644 --- a/refstore/nop/nop_store.go +++ b/refstore/nop/nop_store.go @@ -7,7 +7,7 @@ import ( "net/url" "github.com/digineo/texd/refstore" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) type nop struct{} @@ -16,11 +16,11 @@ func New(_ *url.URL, _ refstore.RetentionPolicy) (refstore.Adapter, error) { return &nop{}, nil } -func (*nop) CopyFile(*zap.Logger, refstore.Identifier, io.Writer) error { +func (*nop) CopyFile(xlog.Logger, refstore.Identifier, io.Writer) error { return refstore.ErrUnknownReference } -func (*nop) Store(_ *zap.Logger, r io.Reader) error { +func (*nop) Store(_ xlog.Logger, r io.Reader) error { _, err := io.Copy(io.Discard, r) return err } diff --git a/refstore/reference_store.go b/refstore/reference_store.go index 1c0ab66..9580eba 100644 --- a/refstore/reference_store.go +++ b/refstore/reference_store.go @@ -4,7 +4,7 @@ import ( "errors" "io" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) // The Adapter interface describes the protocol to interact with different @@ -12,10 +12,10 @@ import ( type Adapter interface { // CopyFile copies a file with the given ID to the target path. It may // return ErrUnknownReference if the ID is unknown. - CopyFile(log *zap.Logger, id Identifier, w io.Writer) error + CopyFile(log xlog.Logger, id Identifier, w io.Writer) error // Store saves the content in the adapter backend. - Store(log *zap.Logger, r io.Reader) error + Store(log xlog.Logger, r io.Reader) error // Exists checks whether the given reference identifier exists in this // storage adapter. diff --git a/service/middleware/logging.go b/service/middleware/logging.go index 6777caa..de8e378 100644 --- a/service/middleware/logging.go +++ b/service/middleware/logging.go @@ -4,7 +4,7 @@ import ( "net" "net/http" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) type responseLogger struct { @@ -25,7 +25,7 @@ func (l *responseLogger) WriteHeader(status int) { // Logging performs request logging. This method takes heavy inspiration // from (github.com/gorilla/handlers).CombinedLoggingHandler. -func WithLogging(log *zap.Logger) func(http.Handler) http.Handler { +func WithLogging(log xlog.Logger) func(http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { rl := &responseLogger{ResponseWriter: w} @@ -33,16 +33,16 @@ func WithLogging(log *zap.Logger) func(http.Handler) http.Handler { next.ServeHTTP(rl, r) - f := []zap.Field{ + logAttrs := []any{ // []slog.Attr RequestIDField(r.Context()), - zap.String("method", r.Method), - zap.Int("status", rl.status), - zap.Int("bytes", rl.n), + xlog.String("method", r.Method), + xlog.Int("status", rl.status), + xlog.Int("bytes", rl.n), } if url.User != nil { if name := url.User.Username(); name != "" { - f = append(f, zap.String("username", name)) + logAttrs = append(logAttrs, xlog.String("username", name)) } } @@ -50,7 +50,7 @@ func WithLogging(log *zap.Logger) func(http.Handler) http.Handler { if err != nil { host = r.RemoteAddr } - f = append(f, zap.String("host", host)) + logAttrs = append(logAttrs, xlog.String("host", host)) // Requests using the CONNECT method over HTTP/2.0 must use // the authority field (aka r.Host) to identify the target. @@ -62,9 +62,9 @@ func WithLogging(log *zap.Logger) func(http.Handler) http.Handler { if uri == "" { uri = url.RequestURI() } - f = append(f, zap.String("url", uri)) + logAttrs = append(logAttrs, xlog.String("url", uri)) - log.Info("", f...) + log.Info("", logAttrs...) }) } } diff --git a/service/middleware/logging_test.go b/service/middleware/logging_test.go index fbe5c94..57e1cfe 100644 --- a/service/middleware/logging_test.go +++ b/service/middleware/logging_test.go @@ -2,23 +2,16 @@ package middleware import ( "bytes" + "log/slog" "net/http" "net/http/httptest" - "strings" "testing" - "time" + "github.com/digineo/texd/xlog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" ) -type mockClock struct{ t time.Time } - -func (m mockClock) Now() time.Time { return m.t } -func (m mockClock) NewTicker(time.Duration) *time.Ticker { return nil } - func TestLogging(t *testing.T) { t.Parallel() @@ -30,26 +23,20 @@ func TestLogging(t *testing.T) { h = RequestID(h) var buf bytes.Buffer - core := zapcore.NewCore( - zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()), - zapcore.AddSync(&buf), - zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { return true }), - ) - clock := &mockClock{time.Unix(1650000000, 0).UTC()} - log := zap.New(core, zap.WithClock(clock)) + log, err := xlog.New(xlog.TypeText, &buf, &slog.HandlerOptions{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + return a + }, + }) + require.NoError(t, err) w := httptest.NewRecorder() WithLogging(log)(h).ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/", nil)) require.Equal(t, http.StatusOK, w.Code) - require.NoError(t, log.Sync()) - - msg := strings.Join([]string{ - "2022-04-15T05:20:00.000Z", - "INFO", - "", - `{"method": "GET", "status": 200, "bytes": 0, "host": "192.0.2.1", "url": "/"}` + "\n", - }, "\t") - + msg := `level=INFO msg="" method=GET status=200 bytes=0 host=192.0.2.1 url=/` + "\n" assert.Equal(t, msg, buf.String()) } diff --git a/service/middleware/requestid.go b/service/middleware/requestid.go index c6548e5..2236dae 100644 --- a/service/middleware/requestid.go +++ b/service/middleware/requestid.go @@ -4,10 +4,11 @@ import ( "context" "crypto/rand" "fmt" + "log/slog" "net/http" + "github.com/digineo/texd/xlog" "github.com/oklog/ulid/v2" - "go.uber.org/zap" ) const HeaderKey = "X-Request-Id" @@ -39,9 +40,9 @@ func GetRequestID(r *http.Request) (string, bool) { return id, ok } -func RequestIDField(ctx context.Context) zap.Field { +func RequestIDField(ctx context.Context) slog.Attr { if id, ok := ctx.Value(ContextKey).(string); ok { - return zap.String("request-id", id) + return xlog.String("request-id", id) } - return zap.Skip() + return slog.Attr{} } diff --git a/service/middleware/requestid_test.go b/service/middleware/requestid_test.go index e5ede5b..0ed7345 100644 --- a/service/middleware/requestid_test.go +++ b/service/middleware/requestid_test.go @@ -1,13 +1,13 @@ package middleware import ( + "log/slog" "net/http" "net/http/httptest" "testing" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap" ) func TestMiddleware(t *testing.T) { @@ -39,7 +39,7 @@ func TestMiddleware(t *testing.T) { func TestRequestIDField(t *testing.T) { t.Parallel() - var ctxIDField zap.Field + var ctxIDField slog.Attr captureContextID := func(w http.ResponseWriter, r *http.Request) { t.Helper() ctxIDField = RequestIDField(r.Context()) @@ -55,13 +55,13 @@ func TestRequestIDField(t *testing.T) { require.NotEmpty(t, headerId) assert.Equal(t, "request-id", ctxIDField.Key) - assert.Equal(t, headerId, ctxIDField.String) + assert.Equal(t, headerId, ctxIDField.Value.String()) } func TestRequestIDField_missing(t *testing.T) { t.Parallel() - var ctxIDField zap.Field + var ctxIDField slog.Attr captureContextID := func(w http.ResponseWriter, r *http.Request) { t.Helper() ctxIDField = RequestIDField(r.Context()) @@ -76,5 +76,5 @@ func TestRequestIDField_missing(t *testing.T) { headerId := w.Header().Get(HeaderKey) require.Empty(t, headerId) - assert.Equal(t, zap.Skip().Type, ctxIDField.Type) + assert.Equal(t, slog.Attr{}, ctxIDField) } diff --git a/service/renderer.go b/service/renderer.go index 4f7920f..3cac939 100644 --- a/service/renderer.go +++ b/service/renderer.go @@ -6,7 +6,6 @@ import ( "context" "errors" "io" - "log" "mime" "mime/multipart" "net/http" @@ -18,7 +17,7 @@ import ( "github.com/digineo/texd/refstore" "github.com/digineo/texd/service/middleware" "github.com/digineo/texd/tex" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) func (svc *service) Close() { @@ -45,7 +44,7 @@ func (svc *service) shouldKeepJobs(err error) bool { return svc.keepJobs == KeepJobsAlways || (svc.keepJobs == KeepJobsOnFailure && err != nil) } -func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.Request) error { //nolint:funlen +func (svc *service) render(log xlog.Logger, res http.ResponseWriter, req *http.Request) error { //nolint:funlen params := req.URL.Query() image, err := svc.validateImageParam(params.Get("image")) if err != nil { @@ -58,7 +57,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R // Add a new job to the queue and bail if we're over capacity. if err = svc.acquire(req.Context()); err != nil { - log.Error("failed enter queue", zap.Error(err)) + log.Error("failed enter queue", xlog.Error(err)) metrics.ProcessedRejected.Inc() return err } @@ -74,7 +73,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R } observeRenderMetrics(doc) if err := doc.Cleanup(); err != nil { - log.Error("cleanup failed", zap.Error(err)) + log.Error("cleanup failed", xlog.Error(err)) } }() @@ -82,7 +81,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R if tex.IsReferenceError(err) { log.Warn("unknown file reference") } else { - log.Error("failed to add files", zap.Error(err)) + log.Error("failed to add files", xlog.Error(err)) } return err } @@ -92,8 +91,8 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R if input := params.Get("input"); input != "" { if err = doc.SetMainInput(input); err != nil { log.Error("invalid main input file", - zap.String("filename", input), - zap.Error(err)) + xlog.String("filename", input), + xlog.Error(err)) return err } } @@ -105,7 +104,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R } if err := req.Context().Err(); err != nil { - log.Error("cancel render job, client is gone", zap.Error(err)) + log.Error("cancel render job, client is gone", xlog.Error(err)) metrics.ProcessedAborted.Inc() return err } @@ -116,7 +115,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R case "full", "condensed": logReader, lerr := doc.GetLogs() if lerr != nil { - log.Error("failed to get logs", zap.Error(lerr)) + log.Error("failed to get logs", xlog.Error(lerr)) return err // not lerr, client gets error from executor.Run() } logfileResponse(log, res, format, logReader) @@ -129,7 +128,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R pdf, err := doc.GetResult() if err != nil { - log.Error("failed to get result", zap.Error(err)) + log.Error("failed to get result", xlog.Error(err)) return err } defer pdf.Close() @@ -139,7 +138,7 @@ func (svc *service) render(log *zap.Logger, res http.ResponseWriter, req *http.R res.WriteHeader(http.StatusOK) n, err := io.Copy(res, pdf) if err != nil { - log.Error("failed to send results", zap.Error(err)) + log.Error("failed to send results", xlog.Error(err)) } metrics.OutputSize.Observe(float64(n)) return nil // header is already written @@ -159,7 +158,7 @@ func (svc *service) validateImageParam(image string) (string, error) { return image, nil } } - log.Printf("forbidden image: %q", image) + svc.log.Error("forbidden image", xlog.String("name", image)) return "", tex.InputError("forbidden image name", nil, tex.KV{"image": image}) } @@ -170,7 +169,7 @@ func (svc *service) validateEngineParam(name string) (engine tex.Engine, err err } engine, err = tex.ParseEngine(name) if err != nil { - log.Printf("invalid engine: %v", err) + svc.log.Error("invalid engine", xlog.Error(err)) err = tex.InputError("unknown engine", err, nil) } return @@ -180,7 +179,7 @@ type errMissingReference struct{ ref string } func (err *errMissingReference) Error() string { return err.ref } -func (svc *service) addFiles(log *zap.Logger, doc tex.Document, req *http.Request) error { +func (svc *service) addFiles(log xlog.Logger, doc tex.Document, req *http.Request) error { ct := req.Header.Get("Content-Type") mt, params, err := mime.ParseMediaType(ct) if err != nil { @@ -216,7 +215,7 @@ func (svc *service) addFiles(log *zap.Logger, doc tex.Document, req *http.Reques return nil } -func (svc *service) addFileFromPart(log *zap.Logger, doc tex.Document, part *multipart.Part, partNum int) error { +func (svc *service) addFileFromPart(log xlog.Logger, doc tex.Document, part *multipart.Part, partNum int) error { name := part.FormName() if name == "" { return tex.InputError("empty name", nil, tex.KV{"part": partNum}) @@ -276,13 +275,13 @@ func (svc *service) addFileFromPart(log *zap.Logger, doc tex.Document, part *mul return nil } -func logfileResponse(log *zap.Logger, res http.ResponseWriter, format string, logs io.ReadCloser) { +func logfileResponse(log xlog.Logger, res http.ResponseWriter, format string, logs io.ReadCloser) { res.Header().Set("Content-Type", mimeTypePlain) res.WriteHeader(http.StatusUnprocessableEntity) if format != "condensed" { if _, err := io.Copy(res, logs); err != nil { - log.Error("failed to send logs", zap.Error(err)) + log.Error("failed to send logs", xlog.Error(err)) } return } @@ -293,13 +292,13 @@ func logfileResponse(log *zap.Logger, res http.ResponseWriter, format string, lo // drop error indicator and add line break line = append(bytes.TrimLeft(line, "! "), '\n') if _, err := res.Write(line); err != nil { - log.Error("failed to send logs", zap.Error(err)) + log.Error("failed to send logs", xlog.Error(err)) return } } } if err := s.Err(); err != nil { - log.Error("failed to read logs", zap.Error(err)) + log.Error("failed to read logs", xlog.Error(err)) } } diff --git a/service/service.go b/service/service.go index 5bf100b..8330ee4 100644 --- a/service/service.go +++ b/service/service.go @@ -15,10 +15,10 @@ import ( "github.com/digineo/texd/refstore/nop" "github.com/digineo/texd/service/middleware" "github.com/digineo/texd/tex" + "github.com/digineo/texd/xlog" "github.com/gorilla/handlers" "github.com/gorilla/mux" "github.com/prometheus/client_golang/prometheus/promhttp" - "go.uber.org/zap" ) const ( @@ -59,10 +59,10 @@ type service struct { maxJobSize int64 // number of bytes keepJobs int - log *zap.Logger + log xlog.Logger } -func newService(opts Options, log *zap.Logger) *service { +func newService(opts Options, log xlog.Logger) *service { svc := &service{ mode: opts.Mode, jobs: make(chan struct{}, opts.QueueLength), @@ -112,7 +112,7 @@ func (svc *service) start(addr string) (func(context.Context) error, error) { Handler: svc.routes(), } - zaddr := zap.String("addr", addr) + zaddr := xlog.String("addr", addr) svc.Logger().Info("starting server", zaddr) l, err := net.Listen("tcp", addr) @@ -123,7 +123,7 @@ func (svc *service) start(addr string) (func(context.Context) error, error) { go func() { if e := srv.Serve(l); !errors.Is(e, http.ErrServerClosed) { - svc.Logger().Error("unexpected HTTP server shutdown", zap.Error(err)) + svc.Logger().Error("unexpected HTTP server shutdown", xlog.Error(err)) } }() @@ -136,13 +136,13 @@ func (svc *service) start(addr string) (func(context.Context) error, error) { }, nil } -func Start(opts Options, log *zap.Logger) (func(context.Context) error, error) { +func Start(opts Options, log xlog.Logger) (func(context.Context) error, error) { return newService(opts, log).start(opts.Addr) } -var discardlog = zap.NewNop() +var discardlog = xlog.NewNop() -func (svc *service) Logger() *zap.Logger { +func (svc *service) Logger() xlog.Logger { if svc.log == nil { return discardlog } @@ -163,7 +163,7 @@ func (svc *service) newMetricsHandler() http.Handler { }) } -func errorResponse(log *zap.Logger, res http.ResponseWriter, err error) { +func errorResponse(log xlog.Logger, res http.ResponseWriter, err error) { res.Header().Set("Content-Type", mimeTypeJSON) res.Header().Set("X-Content-Type-Options", "nosniff") res.WriteHeader(http.StatusUnprocessableEntity) @@ -178,6 +178,6 @@ func errorResponse(log *zap.Logger, res http.ResponseWriter, err error) { }) } if respErr != nil { - log.Error("failed to write response", zap.Error(respErr)) + log.Error("failed to write response", xlog.Error(respErr)) } } diff --git a/service/service_test.go b/service/service_test.go index 3a09917..8b920af 100644 --- a/service/service_test.go +++ b/service/service_test.go @@ -19,16 +19,16 @@ import ( "github.com/digineo/texd/exec" "github.com/digineo/texd/refstore" "github.com/digineo/texd/refstore/dir" + "github.com/digineo/texd/xlog" "github.com/docker/go-units" "github.com/stretchr/testify/suite" - "go.uber.org/zap" ) type testSuite struct { suite.Suite svc *service stop func(context.Context) error - logger *zap.Logger + logger xlog.Logger mock mockParams } @@ -48,7 +48,7 @@ func TestSuite(t *testing.T) { func (suite *testSuite) SetupSuite() { require := suite.Require() - logger, err := zap.NewDevelopment() + logger, err := xlog.New(xlog.TypeText, os.Stderr, nil) suite.Require().NoError(err) suite.logger = logger @@ -260,7 +260,7 @@ func (suite *testSuite) TestService_refstore_useKnownRef() { if err != nil { panic(err) } - if err = refs.Store(zap.NewNop(), contents); err != nil { + if err = refs.Store(xlog.NewNop(), contents); err != nil { panic(err) } contents.Close() @@ -308,7 +308,7 @@ func (suite *testSuite) runServiceTestCase(testCase serviceTestCase) { assert.Equal(testCase.expectedMIME, res.Header.Get("Content-Type")) if !assert.Equal(testCase.statusCode, res.StatusCode) { - suite.logger.Error("unexpected result", zap.ByteString("body", body)) + suite.logger.Error("unexpected result", xlog.String("body", string(body))) } assert.EqualValues( strings.TrimSpace(testCase.expectedBody), diff --git a/service/status.go b/service/status.go index 9a877bd..92f5499 100644 --- a/service/status.go +++ b/service/status.go @@ -7,7 +7,7 @@ import ( "github.com/digineo/texd" "github.com/digineo/texd/service/middleware" "github.com/digineo/texd/tex" - "go.uber.org/zap" + "github.com/digineo/texd/xlog" ) type Status struct { @@ -45,6 +45,6 @@ func (svc *service) HandleStatus(res http.ResponseWriter, req *http.Request) { if err := json.NewEncoder(res).Encode(&status); err != nil { svc.Logger().Error("failed to write response", middleware.RequestIDField(req.Context()), - zap.Error(err)) + xlog.Error(err)) } } diff --git a/service/status_test.go b/service/status_test.go index 58ba6c1..fa5a0f8 100644 --- a/service/status_test.go +++ b/service/status_test.go @@ -4,16 +4,15 @@ import ( "bytes" "encoding/json" "io" + "log/slog" "net/http" "net/http/httptest" - "strings" "testing" "time" + "github.com/digineo/texd/xlog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" ) type failResponseWriter struct { @@ -25,17 +24,12 @@ func (w *failResponseWriter) Header() http.Header { return w.h } func (w *failResponseWriter) WriteHeader(code int) { w.code = code } func (failResponseWriter) Write([]byte) (int, error) { return 0, io.ErrClosedPipe } -type mockClock struct{ t time.Time } - -func (m mockClock) Now() time.Time { return m.t } -func (m mockClock) NewTicker(time.Duration) *time.Ticker { return nil } - func TestHandleStatus(t *testing.T) { svc := &service{ mode: "local", compileTimeout: 3 * time.Second, jobs: make(chan struct{}, 2), - log: zap.NewNop(), + log: xlog.NewNop(), } req := httptest.NewRequest(http.MethodGet, "/status", nil) @@ -66,18 +60,21 @@ func TestHandleStatus(t *testing.T) { func TestHandleStatus_withFailIO(t *testing.T) { var buf bytes.Buffer - core := zapcore.NewCore( - zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()), - zapcore.AddSync(&buf), - zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { return true }), - ) - clock := &mockClock{time.Unix(1650000000, 0).UTC()} + log, err := xlog.New(xlog.TypeText, &buf, &slog.HandlerOptions{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + return a + }, + }) + require.NoError(t, err) svc := &service{ mode: "local", compileTimeout: 3 * time.Second, jobs: make(chan struct{}, 2), - log: zap.New(core, zap.WithClock(clock)), + log: log, } req := httptest.NewRequest(http.MethodGet, "/status", nil) @@ -91,10 +88,6 @@ func TestHandleStatus_withFailIO(t *testing.T) { assert.Equal(t, http.StatusOK, rec.code) assert.Equal(t, mimeTypeJSON, rec.h.Get("Content-Type")) - assert.Equal(t, strings.Join([]string{ - "2022-04-15T05:20:00.000Z", - "ERROR", - "failed to write response", - `{"error": "io: read/write on closed pipe"}` + "\n", - }, "\t"), buf.String()) + msg := `level=ERROR msg="failed to write response" error="io: read/write on closed pipe"` + "\n" + assert.Equal(t, msg, buf.String()) } diff --git a/tex/document.go b/tex/document.go index 4f2a73c..8d41b97 100644 --- a/tex/document.go +++ b/tex/document.go @@ -9,8 +9,8 @@ import ( "strings" "sync" + "github.com/digineo/texd/xlog" "github.com/spf13/afero" - "go.uber.org/zap" ) // Mark is used to help identifying the main input file from a list @@ -57,7 +57,7 @@ func (f *File) hasDocumentClass() bool { return f.flags&flagDocumentClass > 0 } func (f *File) hasTexdMark() bool { return f.flags&flagTexdMark > 0 } type fileWriter struct { - log *zap.Logger + log xlog.Logger buf []byte // the first few bytes written to wc off int // how many bytes were written to buf wc io.WriteCloser @@ -194,7 +194,7 @@ type document struct { files map[string]*File mainInput string // only present after SetMainInput(), otherwise ask MainInput() - log *zap.Logger + log xlog.Logger image string engine Engine @@ -205,7 +205,7 @@ type document struct { var _ Document = (*document)(nil) -func NewDocument(log *zap.Logger, engine Engine, image string) Document { +func NewDocument(log xlog.Logger, engine Engine, image string) Document { return &document{ fs: texFs, files: make(map[string]*File), @@ -251,7 +251,7 @@ func (doc *document) AddFile(name, contents string) error { } defer func() { _ = wc.Close() }() - log := doc.log.With(zap.String("filename", name)) + log := doc.log.With(xlog.String("filename", name)) log.Info("adding file") _, err = wc.Write([]byte(contents)) @@ -310,7 +310,7 @@ func (doc *document) NewWriter(name string) (wc io.WriteCloser, err error) { return wc, err } - log := doc.log.With(zap.String("filename", file.name)) + log := doc.log.With(xlog.String("filename", file.name)) if isMainCandidate(file.name) { log.Debug("mark as candidate") file.flags |= flagCandidate @@ -334,7 +334,7 @@ func (doc *document) SetMainInput(name string) error { return InputError("unknown input file name", nil, nil) } - doc.log.Info("setting main input", zap.String("filename", name)) + doc.log.Info("setting main input", xlog.String("filename", name)) doc.mainInput = name return nil } diff --git a/tex/document_test.go b/tex/document_test.go index 84889da..d5952af 100644 --- a/tex/document_test.go +++ b/tex/document_test.go @@ -10,11 +10,11 @@ import ( "sync" "testing" + "github.com/digineo/texd/xlog" "github.com/spf13/afero" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" - "go.uber.org/zap" ) func TestFile_flags(t *testing.T) { @@ -57,7 +57,7 @@ func testFileWriter(t *testing.T, s string, candidate bool) { } subject := fileWriter{ - log: zap.NewNop(), + log: xlog.NewNop(), file: f, wc: &nopCloser{Writer: &buf}, buf: make([]byte, 4), @@ -224,7 +224,7 @@ func TestDocument(t *testing.T) { subject := documentHelper{ //nolint:forcetypeassert t: t, fs: afero.Afero{Fs: afero.NewMemMapFs()}, - document: NewDocument(zap.NewNop(), DefaultEngine, "").(*document), + document: NewDocument(xlog.NewNop(), DefaultEngine, "").(*document), } subject.document.fs = subject.fs @@ -279,7 +279,7 @@ func TestDocument_MainInput(t *testing.T) { subject := documentHelper{ //nolint:forcetypeassert t: t, fs: afero.Afero{Fs: afero.NewMemMapFs()}, - document: NewDocument(zap.NewNop(), DefaultEngine, "").(*document), + document: NewDocument(xlog.NewNop(), DefaultEngine, "").(*document), } subject.document.fs = subject.fs @@ -335,7 +335,7 @@ func TestNewDocument(t *testing.T) { engine := NewEngine("foo") image := "bar" - subject := NewDocument(zap.NewNop(), engine, image) + subject := NewDocument(xlog.NewNop(), engine, image) require.NotNil(t, subject) assert.Equal(t, engine, subject.Engine()) diff --git a/tex/metrics_test.go b/tex/metrics_test.go index 74d721a..11de58a 100644 --- a/tex/metrics_test.go +++ b/tex/metrics_test.go @@ -5,10 +5,10 @@ import ( "sort" "testing" + "github.com/digineo/texd/xlog" "github.com/spf13/afero" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap" ) func TestFileCategory_FromName(t *testing.T) { @@ -52,7 +52,7 @@ func TestFileCategory_String(t *testing.T) { func TestMetrics(t *testing.T) { assert, require := assert.New(t), require.New(t) - doc := NewDocument(zap.NewNop(), DefaultEngine, "") + doc := NewDocument(xlog.NewNop(), DefaultEngine, "") doc.(*document).fs = afero.NewMemMapFs() for name, size := range map[string]int{ "input.tex": 10, diff --git a/xlog/attrs.go b/xlog/attrs.go new file mode 100644 index 0000000..9aaef8e --- /dev/null +++ b/xlog/attrs.go @@ -0,0 +1,28 @@ +package xlog + +import "log/slog" + +var ( + String = slog.String + Int64 = slog.Int64 + Int = slog.Int + Uint64 = slog.Uint64 + Float64 = slog.Float64 + Bool = slog.Bool + Time = slog.Time + Group = slog.Group + Duration = slog.Duration + Any = slog.Any +) + +const ErrorKey = "error" + +type ErrorValue struct{ error } + +func (err ErrorValue) Value() slog.Value { + return slog.StringValue(err.Error()) +} + +func Error(err error) slog.Attr { + return slog.Any(ErrorKey, ErrorValue{err}) +} diff --git a/xlog/log.go b/xlog/log.go new file mode 100644 index 0000000..a16a550 --- /dev/null +++ b/xlog/log.go @@ -0,0 +1,117 @@ +// Package xlog provides a very thin (and maybe leaky) +// wrapper aroud log/slog. +package xlog + +import ( + "context" + "fmt" + "io" + "log/slog" + "os" + "runtime" + "time" +) + +type Logger interface { + Debug(msg string, args ...any) + Info(msg string, args ...any) + Warn(msg string, args ...any) + Error(msg string, args ...any) + Fatal(msg string, args ...any) + + With(args ...any) Logger +} + +type logger struct { + l *slog.Logger + context []any +} + +type LoggerType int + +const ( + TypeText LoggerType = iota // maps to slog.TextHandler + TypeJSON // maps to slog.JSONHandler + TypeNop // discards log records +) + +func New(typ LoggerType, w io.Writer, o *slog.HandlerOptions) (Logger, error) { + var h slog.Handler + switch typ { + case TypeText: + h = slog.NewTextHandler(w, o) + case TypeJSON: + h = slog.NewTextHandler(w, o) + case TypeNop: + return &nop{}, nil + default: + return nil, fmt.Errorf("unknown LoggerType: %#v", typ) + } + + return &logger{ + l: slog.New(h), + }, nil +} + +// log creates a log record. It is called by Debug, Info, etc. +func (log *logger) log(level slog.Level, msg string, args ...any) { + if !log.l.Enabled(context.Background(), level) { + return + } + var pcs [1]uintptr + runtime.Callers(3, pcs[:]) // skip runtime.Callers, log, and our caller + r := slog.NewRecord(time.Now(), level, msg, pcs[0]) + r.Add(log.context...) + r.Add(args...) + _ = log.l.Handler().Handle(context.Background(), r) +} + +func (log *logger) Debug(msg string, args ...any) { + log.log(slog.LevelDebug, msg, args...) +} + +func (log *logger) Info(msg string, args ...any) { + log.log(slog.LevelInfo, msg, args...) +} + +func (log *logger) Warn(msg string, args ...any) { + log.log(slog.LevelWarn, msg, args...) +} + +func (log *logger) Error(msg string, args ...any) { + log.log(slog.LevelError, msg, args...) +} + +// Fatal is the same as Error, but quits the program via os.Exit(1). +func (log *logger) Fatal(msg string, args ...any) { + log.log(slog.LevelError, msg, args...) + os.Exit(1) +} + +func (log *logger) With(args ...any) Logger { + context := make([]any, 0, len(log.context)+len(args)) + context = append(context, log.context...) + context = append(context, args...) + + return &logger{ + l: log.l, + context: context, + } +} + +func ParseLevel(s string) (l slog.Level, err error) { + switch s { + case "debug", "DEBUG": + l = slog.LevelDebug + case "info", "INFO", "": // make the zero value useful + l = slog.LevelInfo + case "warn", "WARN": + l = slog.LevelWarn + case "error", "ERROR", + "fatal", "FATAL": + l = slog.LevelError + default: + err = fmt.Errorf("unknown log level: %q", s) + } + return +} diff --git a/xlog/nop.go b/xlog/nop.go new file mode 100644 index 0000000..ff478c6 --- /dev/null +++ b/xlog/nop.go @@ -0,0 +1,15 @@ +package xlog + +type nop struct{} + +func NewNop() Logger { + l, _ := New(TypeNop, nil, nil) + return l +} + +func (*nop) Debug(msg string, args ...any) {} +func (*nop) Info(msg string, args ...any) {} +func (*nop) Warn(msg string, args ...any) {} +func (*nop) Error(msg string, args ...any) {} +func (*nop) Fatal(msg string, args ...any) { /* XXX: os.Exit? */ } +func (n *nop) With(args ...any) Logger { return n } From 704fe26afb37c7619ad72b33fd4a755e2aed16d2 Mon Sep 17 00:00:00 2001 From: Dominik Menke Date: Sun, 28 Jan 2024 22:37:55 +0100 Subject: [PATCH 2/7] refactor: change xlog constructor to functional options --- cmd/texd/main.go | 19 +++--- exec/docker_client.go | 2 +- exec/docker_client_test.go | 2 +- exec/docker_test.go | 8 +-- exec/local_test.go | 2 +- exec/mock_test.go | 12 ++-- refstore/dir/dir_store_test.go | 4 +- service/middleware/logging_test.go | 28 +++++---- service/service.go | 2 +- service/service_test.go | 4 +- service/status_test.go | 26 ++++---- tex/document_test.go | 8 +-- tex/metrics_test.go | 2 +- xlog/discard.go | 21 +++++++ xlog/log.go | 62 ++++++++++++------- xlog/nop.go | 15 ----- xlog/options.go | 99 ++++++++++++++++++++++++++++++ 17 files changed, 219 insertions(+), 97 deletions(-) create mode 100644 xlog/discard.go delete mode 100644 xlog/nop.go create mode 100644 xlog/options.go diff --git a/cmd/texd/main.go b/cmd/texd/main.go index 68a55e3..095c6b5 100644 --- a/cmd/texd/main.go +++ b/cmd/texd/main.go @@ -281,19 +281,14 @@ func printVersion() { } func setupLogger() (xlog.Logger, error) { - lvl, err := xlog.ParseLevel(logLevel) - if err != nil { - return nil, err - } - - o := &slog.HandlerOptions{ - AddSource: true, - // XXX: provide ReplaceAttr callback to normalize Source locations? - Level: lvl, + o := []xlog.Option{ + xlog.LeveledString(logLevel), + xlog.WithSource(), } - if texd.Development() { - return xlog.New(xlog.TypeText, os.Stderr, o) + o = append(o, xlog.WriteTo(os.Stderr), xlog.AsText()) + } else { + o = append(o, xlog.WriteTo(os.Stdout), xlog.AsJSON()) } - return xlog.New(xlog.TypeJSON, os.Stdout, o) + return xlog.New(o...) } diff --git a/exec/docker_client.go b/exec/docker_client.go index ca6de33..5fe2c99 100644 --- a/exec/docker_client.go +++ b/exec/docker_client.go @@ -47,7 +47,7 @@ func NewDockerClient(log xlog.Logger, baseDir string) (h *DockerClient, err erro } if log == nil { - log = xlog.NewNop() + log = xlog.NewDiscard() } dc := &DockerClient{ log: log, diff --git a/exec/docker_client_test.go b/exec/docker_client_test.go index 6e1beed..b6bbce4 100644 --- a/exec/docker_client_test.go +++ b/exec/docker_client_test.go @@ -115,7 +115,7 @@ func (s *dockerClientSuite) SetupTest() { s.cli = &apiMock{} s.subject = &DockerClient{ cli: s.cli, - log: xlog.NewNop(), + log: xlog.NewDiscard(), } } diff --git a/exec/docker_test.go b/exec/docker_test.go index f2fcbc9..47ecb0f 100644 --- a/exec/docker_test.go +++ b/exec/docker_test.go @@ -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: xlog.NewNop(), + log: xlog.NewDiscard(), 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, xlog.NewNop()) + err := exec.Run(bg, xlog.NewDiscard()) 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, xlog.NewNop()) + err := exec.Run(bg, xlog.NewDiscard()) 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, xlog.NewNop()) + err := exec.Run(bg, xlog.NewDiscard()) require.NoError(t, err) } diff --git a/exec/local_test.go b/exec/local_test.go index 7df33ad..ca56b13 100644 --- a/exec/local_test.go +++ b/exec/local_test.go @@ -58,7 +58,7 @@ func TestLocalExec_Run(t *testing.T) { // create local exec exec := LocalExec(tt.doc).(*localExec) //nolint:forcetypeassert exec.path = tt.path - err := exec.Run(context.Background(), xlog.NewNop()) + err := exec.Run(context.Background(), xlog.NewDiscard()) if tt.expectedErr == "" { assert.NoError(t, err) diff --git a/exec/mock_test.go b/exec/mock_test.go index 707c5ff..87b1cea 100644 --- a/exec/mock_test.go +++ b/exec/mock_test.go @@ -25,7 +25,7 @@ func TestMock_Run_extractError(t *testing.T) { doc := &mockDocument{"/", io.ErrClosedPipe, "a", nil} subject := Mock(true, "content")(doc) - err := subject.Run(bg, xlog.NewNop()) + err := subject.Run(bg, xlog.NewDiscard()) require.EqualError(t, err, "invalid document: "+io.ErrClosedPipe.Error()) } @@ -34,7 +34,7 @@ func TestMock_Run_invalidMainfilePanics(t *testing.T) { subject := Mock(true, "content")(doc) require.PanicsWithValue(t, "malformed input file: missing extension", - func() { _ = subject.Run(bg, xlog.NewNop()) }) + func() { _ = subject.Run(bg, xlog.NewDiscard()) }) } func TestMock_Run_noAddFilePanics(t *testing.T) { @@ -42,7 +42,7 @@ func TestMock_Run_noAddFilePanics(t *testing.T) { subject := Mock(true, "content")(doc) require.PanicsWithValue(t, "can't add files to document", - func() { _ = subject.Run(bg, xlog.NewNop()) }) + func() { _ = subject.Run(bg, xlog.NewDiscard()) }) } type mockDockumentWithAddFile struct { @@ -64,7 +64,7 @@ func TestMock_Run_errorOnAddFilePanics(t *testing.T) { doc.On("AddFile", "a.log", "content").Return(io.ErrClosedPipe) require.PanicsWithError(t, "failed to store result file: "+io.ErrClosedPipe.Error(), - func() { _ = subject.Run(bg, xlog.NewNop()) }) + func() { _ = subject.Run(bg, xlog.NewDiscard()) }) } func TestMock_Run_shouldFailCapturesLog(t *testing.T) { @@ -75,7 +75,7 @@ func TestMock_Run_shouldFailCapturesLog(t *testing.T) { doc.On("AddFile", "a.log", "content").Return(nil) - err := subject.Run(bg, xlog.NewNop()) + err := subject.Run(bg, xlog.NewDiscard()) require.EqualError(t, err, "compilation failed") } @@ -87,6 +87,6 @@ func TestMock_Run_shouldFailCapturesResult(t *testing.T) { doc.On("AddFile", "a.pdf", "%PDF/1.5").Return(nil) - err := subject.Run(bg, xlog.NewNop()) + err := subject.Run(bg, xlog.NewDiscard()) require.NoError(t, err) } diff --git a/refstore/dir/dir_store_test.go b/refstore/dir/dir_store_test.go index 3737901..eb24d6d 100644 --- a/refstore/dir/dir_store_test.go +++ b/refstore/dir/dir_store_test.go @@ -84,7 +84,7 @@ func TestNew_dirNotWritable(t *testing.T) { func TestDirAdapter_keepFiles(t *testing.T) { require := require.New(t) - log := xlog.NewNop() + log := xlog.NewDiscard() subject, err := NewMemory(nil, &refstore.KeepForever{}) require.NoError(err) @@ -121,7 +121,7 @@ func TestDirAdapter_purgeFiles(t *testing.T) { func TestDirAdapter_accessMap(t *testing.T) { require := require.New(t) - log := xlog.NewNop() + log := xlog.NewDiscard() f := dummyFile("01234567890") for _, q := range []struct{ n, sz int }{ diff --git a/service/middleware/logging_test.go b/service/middleware/logging_test.go index 57e1cfe..0c9bb56 100644 --- a/service/middleware/logging_test.go +++ b/service/middleware/logging_test.go @@ -2,10 +2,11 @@ package middleware import ( "bytes" - "log/slog" "net/http" "net/http/httptest" + "strings" "testing" + "time" "github.com/digineo/texd/xlog" "github.com/stretchr/testify/assert" @@ -23,20 +24,25 @@ func TestLogging(t *testing.T) { h = RequestID(h) var buf bytes.Buffer - log, err := xlog.New(xlog.TypeText, &buf, &slog.HandlerOptions{ - ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { - if a.Key == slog.TimeKey { - return slog.Attr{} - } - return a - }, - }) + log, err := xlog.New( + xlog.AsText(), + xlog.WriteTo(&buf), + xlog.MockClock(time.Unix(1650000000, 0)), + ) require.NoError(t, err) w := httptest.NewRecorder() WithLogging(log)(h).ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/", nil)) require.Equal(t, http.StatusOK, w.Code) - msg := `level=INFO msg="" method=GET status=200 bytes=0 host=192.0.2.1 url=/` + "\n" - assert.Equal(t, msg, buf.String()) + assert.Equal(t, strings.Join([]string{ + "time=2022-04-15T07:20:00.000+02:00", + "level=INFO", + `msg=""`, + "method=GET", + "status=200", + "bytes=0", + "host=192.0.2.1", + "url=/", + }, " ")+"\n", buf.String()) } diff --git a/service/service.go b/service/service.go index 8330ee4..4c14af1 100644 --- a/service/service.go +++ b/service/service.go @@ -140,7 +140,7 @@ func Start(opts Options, log xlog.Logger) (func(context.Context) error, error) { return newService(opts, log).start(opts.Addr) } -var discardlog = xlog.NewNop() +var discardlog = xlog.NewDiscard() func (svc *service) Logger() xlog.Logger { if svc.log == nil { diff --git a/service/service_test.go b/service/service_test.go index 8b920af..5091a7a 100644 --- a/service/service_test.go +++ b/service/service_test.go @@ -48,7 +48,7 @@ func TestSuite(t *testing.T) { func (suite *testSuite) SetupSuite() { require := suite.Require() - logger, err := xlog.New(xlog.TypeText, os.Stderr, nil) + logger, err := xlog.New(xlog.AsText(), xlog.WriteTo(os.Stderr)) suite.Require().NoError(err) suite.logger = logger @@ -260,7 +260,7 @@ func (suite *testSuite) TestService_refstore_useKnownRef() { if err != nil { panic(err) } - if err = refs.Store(xlog.NewNop(), contents); err != nil { + if err = refs.Store(xlog.NewDiscard(), contents); err != nil { panic(err) } contents.Close() diff --git a/service/status_test.go b/service/status_test.go index fa5a0f8..8d65832 100644 --- a/service/status_test.go +++ b/service/status_test.go @@ -4,9 +4,9 @@ import ( "bytes" "encoding/json" "io" - "log/slog" "net/http" "net/http/httptest" + "strings" "testing" "time" @@ -29,7 +29,7 @@ func TestHandleStatus(t *testing.T) { mode: "local", compileTimeout: 3 * time.Second, jobs: make(chan struct{}, 2), - log: xlog.NewNop(), + log: xlog.NewDiscard(), } req := httptest.NewRequest(http.MethodGet, "/status", nil) @@ -60,14 +60,11 @@ func TestHandleStatus(t *testing.T) { func TestHandleStatus_withFailIO(t *testing.T) { var buf bytes.Buffer - log, err := xlog.New(xlog.TypeText, &buf, &slog.HandlerOptions{ - ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { - if a.Key == slog.TimeKey { - return slog.Attr{} - } - return a - }, - }) + log, err := xlog.New( + xlog.AsText(), + xlog.WriteTo(&buf), + xlog.MockClock(time.Unix(1650000000, 0)), + ) require.NoError(t, err) svc := &service{ @@ -87,7 +84,10 @@ func TestHandleStatus_withFailIO(t *testing.T) { assert.Equal(t, http.StatusOK, rec.code) assert.Equal(t, mimeTypeJSON, rec.h.Get("Content-Type")) - - msg := `level=ERROR msg="failed to write response" error="io: read/write on closed pipe"` + "\n" - assert.Equal(t, msg, buf.String()) + assert.Equal(t, strings.Join([]string{ + "time=2022-04-15T07:20:00.000+02:00", + "level=ERROR", + `msg="failed to write response"`, + `error="io: read/write on closed pipe"`, + }, " ")+"\n", buf.String()) } diff --git a/tex/document_test.go b/tex/document_test.go index d5952af..ef33512 100644 --- a/tex/document_test.go +++ b/tex/document_test.go @@ -57,7 +57,7 @@ func testFileWriter(t *testing.T, s string, candidate bool) { } subject := fileWriter{ - log: xlog.NewNop(), + log: xlog.NewDiscard(), file: f, wc: &nopCloser{Writer: &buf}, buf: make([]byte, 4), @@ -224,7 +224,7 @@ func TestDocument(t *testing.T) { subject := documentHelper{ //nolint:forcetypeassert t: t, fs: afero.Afero{Fs: afero.NewMemMapFs()}, - document: NewDocument(xlog.NewNop(), DefaultEngine, "").(*document), + document: NewDocument(xlog.NewDiscard(), DefaultEngine, "").(*document), } subject.document.fs = subject.fs @@ -279,7 +279,7 @@ func TestDocument_MainInput(t *testing.T) { subject := documentHelper{ //nolint:forcetypeassert t: t, fs: afero.Afero{Fs: afero.NewMemMapFs()}, - document: NewDocument(xlog.NewNop(), DefaultEngine, "").(*document), + document: NewDocument(xlog.NewDiscard(), DefaultEngine, "").(*document), } subject.document.fs = subject.fs @@ -335,7 +335,7 @@ func TestNewDocument(t *testing.T) { engine := NewEngine("foo") image := "bar" - subject := NewDocument(xlog.NewNop(), engine, image) + subject := NewDocument(xlog.NewDiscard(), engine, image) require.NotNil(t, subject) assert.Equal(t, engine, subject.Engine()) diff --git a/tex/metrics_test.go b/tex/metrics_test.go index 11de58a..5431272 100644 --- a/tex/metrics_test.go +++ b/tex/metrics_test.go @@ -52,7 +52,7 @@ func TestFileCategory_String(t *testing.T) { func TestMetrics(t *testing.T) { assert, require := assert.New(t), require.New(t) - doc := NewDocument(xlog.NewNop(), DefaultEngine, "") + doc := NewDocument(xlog.NewDiscard(), DefaultEngine, "") doc.(*document).fs = afero.NewMemMapFs() for name, size := range map[string]int{ "input.tex": 10, diff --git a/xlog/discard.go b/xlog/discard.go new file mode 100644 index 0000000..58a674a --- /dev/null +++ b/xlog/discard.go @@ -0,0 +1,21 @@ +package xlog + +import "os" + +type discard struct{} + +// NewDiscard produces basically the same logger as +// +// xlog.New(xlog.Discard(), otheroptions...) +// +// but without the option overhead. +func NewDiscard() Logger { + return &discard{} +} + +func (*discard) Debug(msg string, args ...any) {} +func (*discard) Info(msg string, args ...any) {} +func (*discard) Warn(msg string, args ...any) {} +func (*discard) Error(msg string, args ...any) {} +func (*discard) Fatal(msg string, args ...any) { os.Exit(1) } +func (d *discard) With(args ...any) Logger { return d } diff --git a/xlog/log.go b/xlog/log.go index a16a550..2bcec84 100644 --- a/xlog/log.go +++ b/xlog/log.go @@ -1,55 +1,71 @@ -// Package xlog provides a very thin (and maybe leaky) -// wrapper aroud log/slog. +// Package xlog provides a very thin wrapper aroud log/slog. package xlog import ( "context" "fmt" - "io" "log/slog" "os" "runtime" "time" ) +// A Logger allows writing messages with various severities. type Logger interface { + // Debug writes log messages with DEBUG severity. Debug(msg string, args ...any) + // Info writes log messages with INFO severity. Info(msg string, args ...any) + // Warn writes log messages with WARN severity. Warn(msg string, args ...any) + // Error writes log messages with ERROR severity. Error(msg string, args ...any) + // Fatal writes log messages with ERROR severity, and then + // exits the whole program. Fatal(msg string, args ...any) - + // With creates a child logger, and adds the given arguments + // to each child message output With(args ...any) Logger } type logger struct { - l *slog.Logger + l *slog.Logger + // context holds the arguments received from With(). context []any } -type LoggerType int +func New(opt ...Option) (Logger, error) { + opts := options{ + handlerOpts: &slog.HandlerOptions{}, + } -const ( - TypeText LoggerType = iota // maps to slog.TextHandler - TypeJSON // maps to slog.JSONHandler - TypeNop // discards log records -) + for _, o := range opt { + if err := o(&opts); err != nil { + return nil, err + } + } -func New(typ LoggerType, w io.Writer, o *slog.HandlerOptions) (Logger, error) { - var h slog.Handler - switch typ { - case TypeText: - h = slog.NewTextHandler(w, o) - case TypeJSON: - h = slog.NewTextHandler(w, o) - case TypeNop: - return &nop{}, nil - default: - return nil, fmt.Errorf("unknown LoggerType: %#v", typ) + // the discard logger doesn't require any further setup + if opts.discard { + return &discard{}, nil + } + + // setup mock time + if opts.clock != nil { + repl := opts.handlerOpts.ReplaceAttr + opts.handlerOpts.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { + if len(groups) == 0 && a.Key == slog.TimeKey { + a.Value = slog.TimeValue(opts.clock.Now()) + } + if repl == nil { + return a + } + return repl(groups, a) + } } return &logger{ - l: slog.New(h), + l: slog.New(opts.buildHandler(&opts)), }, nil } diff --git a/xlog/nop.go b/xlog/nop.go deleted file mode 100644 index ff478c6..0000000 --- a/xlog/nop.go +++ /dev/null @@ -1,15 +0,0 @@ -package xlog - -type nop struct{} - -func NewNop() Logger { - l, _ := New(TypeNop, nil, nil) - return l -} - -func (*nop) Debug(msg string, args ...any) {} -func (*nop) Info(msg string, args ...any) {} -func (*nop) Warn(msg string, args ...any) {} -func (*nop) Error(msg string, args ...any) {} -func (*nop) Fatal(msg string, args ...any) { /* XXX: os.Exit? */ } -func (n *nop) With(args ...any) Logger { return n } diff --git a/xlog/options.go b/xlog/options.go new file mode 100644 index 0000000..8dc8c3e --- /dev/null +++ b/xlog/options.go @@ -0,0 +1,99 @@ +package xlog + +import ( + "bytes" + "io" + "log/slog" + "time" + + "github.com/digineo/texd/internal" +) + +type Option func(*options) error + +type options struct { + discard bool + output io.Writer + clock internal.Clock + buildHandler func(o *options) slog.Handler + handlerOpts *slog.HandlerOptions +} + +func Leveled(l slog.Level) Option { + return func(o *options) error { + o.handlerOpts.Level = l + return nil + } +} + +func LeveledString(s string) Option { + return func(o *options) error { + l, err := ParseLevel(s) + if err != nil { + return err + } + o.handlerOpts.Level = l + return nil + } +} + +func WriteTo(w io.Writer) Option { + return func(o *options) error { + o.output = w + return nil + } +} + +func CaptureOutput() (Option, *bytes.Buffer) { + var b bytes.Buffer + return func(o *options) error { + o.output = &b + return nil + }, &b +} + +func MockClock(t time.Time) Option { + return func(o *options) error { + o.clock = internal.MockClock(t) + return nil + } +} + +func WithSource() Option { + return func(o *options) error { + o.handlerOpts.AddSource = true + return nil + } +} + +func WithAttrReplacer(f func(groups []string, a slog.Attr) slog.Attr) Option { + return func(o *options) error { + o.handlerOpts.ReplaceAttr = f + return nil + } +} + +func AsJSON() Option { + return func(o *options) error { + o.buildHandler = func(o *options) slog.Handler { + return slog.NewJSONHandler(o.output, o.handlerOpts) + } + return nil + } +} + +func AsText() Option { + return func(o *options) error { + o.buildHandler = func(o *options) slog.Handler { + return slog.NewTextHandler(o.output, o.handlerOpts) + } + return nil + } +} + +func Discard() Option { + return func(o *options) error { + o.discard = true + return nil + } +} From 03fb12757e8d457e38bbd0e0b929beb6d58e65ac Mon Sep 17 00:00:00 2001 From: Dominik Menke Date: Sun, 28 Jan 2024 22:47:42 +0100 Subject: [PATCH 3/7] fix tests --- service/middleware/logging_test.go | 4 ++-- service/status_test.go | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/service/middleware/logging_test.go b/service/middleware/logging_test.go index 0c9bb56..e61776a 100644 --- a/service/middleware/logging_test.go +++ b/service/middleware/logging_test.go @@ -27,7 +27,7 @@ func TestLogging(t *testing.T) { log, err := xlog.New( xlog.AsText(), xlog.WriteTo(&buf), - xlog.MockClock(time.Unix(1650000000, 0)), + xlog.MockClock(time.Unix(1650000000, 0).UTC()), ) require.NoError(t, err) @@ -36,7 +36,7 @@ func TestLogging(t *testing.T) { require.Equal(t, http.StatusOK, w.Code) assert.Equal(t, strings.Join([]string{ - "time=2022-04-15T07:20:00.000+02:00", + "time=2022-04-15T05:20:00.000Z", "level=INFO", `msg=""`, "method=GET", diff --git a/service/status_test.go b/service/status_test.go index 8d65832..c5724fa 100644 --- a/service/status_test.go +++ b/service/status_test.go @@ -63,7 +63,7 @@ func TestHandleStatus_withFailIO(t *testing.T) { log, err := xlog.New( xlog.AsText(), xlog.WriteTo(&buf), - xlog.MockClock(time.Unix(1650000000, 0)), + xlog.MockClock(time.Unix(1650000000, 0).UTC()), ) require.NoError(t, err) @@ -85,7 +85,7 @@ func TestHandleStatus_withFailIO(t *testing.T) { assert.Equal(t, http.StatusOK, rec.code) assert.Equal(t, mimeTypeJSON, rec.h.Get("Content-Type")) assert.Equal(t, strings.Join([]string{ - "time=2022-04-15T07:20:00.000+02:00", + "time=2022-04-15T05:20:00.000Z", "level=ERROR", `msg="failed to write response"`, `error="io: read/write on closed pipe"`, From 6b7efce8f3d4c2371253d2797b39e201321e61cd Mon Sep 17 00:00:00 2001 From: Dominik Menke Date: Mon, 29 Jan 2024 19:58:32 +0100 Subject: [PATCH 4/7] refactor: change logger to only accept slog.Attrs Y'know, for performance. Logging is intense --- service/middleware/logging.go | 3 +- xlog/discard.go | 17 ++++++----- xlog/{log.go => xlog.go} | 55 ++++++++++++++++------------------- 3 files changed, 37 insertions(+), 38 deletions(-) rename xlog/{log.go => xlog.go} (64%) diff --git a/service/middleware/logging.go b/service/middleware/logging.go index de8e378..160730b 100644 --- a/service/middleware/logging.go +++ b/service/middleware/logging.go @@ -1,6 +1,7 @@ package middleware import ( + "log/slog" "net" "net/http" @@ -33,7 +34,7 @@ func WithLogging(log xlog.Logger) func(http.Handler) http.Handler { next.ServeHTTP(rl, r) - logAttrs := []any{ // []slog.Attr + logAttrs := []slog.Attr{ RequestIDField(r.Context()), xlog.String("method", r.Method), xlog.Int("status", rl.status), diff --git a/xlog/discard.go b/xlog/discard.go index 58a674a..814909d 100644 --- a/xlog/discard.go +++ b/xlog/discard.go @@ -1,6 +1,9 @@ package xlog -import "os" +import ( + "log/slog" + "os" +) type discard struct{} @@ -13,9 +16,9 @@ func NewDiscard() Logger { return &discard{} } -func (*discard) Debug(msg string, args ...any) {} -func (*discard) Info(msg string, args ...any) {} -func (*discard) Warn(msg string, args ...any) {} -func (*discard) Error(msg string, args ...any) {} -func (*discard) Fatal(msg string, args ...any) { os.Exit(1) } -func (d *discard) With(args ...any) Logger { return d } +func (*discard) Debug(string, ...slog.Attr) {} +func (*discard) Info(string, ...slog.Attr) {} +func (*discard) Warn(string, ...slog.Attr) {} +func (*discard) Error(string, ...slog.Attr) {} +func (*discard) Fatal(string, ...slog.Attr) { os.Exit(1) } +func (d *discard) With(...slog.Attr) Logger { return d } diff --git a/xlog/log.go b/xlog/xlog.go similarity index 64% rename from xlog/log.go rename to xlog/xlog.go index 2bcec84..528d1a9 100644 --- a/xlog/log.go +++ b/xlog/xlog.go @@ -13,29 +13,30 @@ import ( // A Logger allows writing messages with various severities. type Logger interface { // Debug writes log messages with DEBUG severity. - Debug(msg string, args ...any) + Debug(msg string, a ...slog.Attr) // Info writes log messages with INFO severity. - Info(msg string, args ...any) + Info(msg string, a ...slog.Attr) // Warn writes log messages with WARN severity. - Warn(msg string, args ...any) + Warn(msg string, a ...slog.Attr) // Error writes log messages with ERROR severity. - Error(msg string, args ...any) + Error(msg string, a ...slog.Attr) // Fatal writes log messages with ERROR severity, and then // exits the whole program. - Fatal(msg string, args ...any) - // With creates a child logger, and adds the given arguments - // to each child message output - With(args ...any) Logger + Fatal(msg string, a ...slog.Attr) + // With returns a Logger that includes the given attributes + // in each output operation. + With(a ...slog.Attr) Logger } type logger struct { l *slog.Logger - // context holds the arguments received from With(). - context []any } +// New creates a new logger instance. By default, log messages are +// written to stdout, and the log level is INFO. func New(opt ...Option) (Logger, error) { opts := options{ + output: os.Stdout, handlerOpts: &slog.HandlerOptions{}, } @@ -70,48 +71,42 @@ func New(opt ...Option) (Logger, error) { } // log creates a log record. It is called by Debug, Info, etc. -func (log *logger) log(level slog.Level, msg string, args ...any) { +func (log *logger) log(level slog.Level, msg string, a ...slog.Attr) { if !log.l.Enabled(context.Background(), level) { return } var pcs [1]uintptr runtime.Callers(3, pcs[:]) // skip runtime.Callers, log, and our caller r := slog.NewRecord(time.Now(), level, msg, pcs[0]) - r.Add(log.context...) - r.Add(args...) + r.AddAttrs(a...) _ = log.l.Handler().Handle(context.Background(), r) } -func (log *logger) Debug(msg string, args ...any) { - log.log(slog.LevelDebug, msg, args...) +func (log *logger) Debug(msg string, a ...slog.Attr) { + log.log(slog.LevelDebug, msg, a...) } -func (log *logger) Info(msg string, args ...any) { - log.log(slog.LevelInfo, msg, args...) +func (log *logger) Info(msg string, a ...slog.Attr) { + log.log(slog.LevelInfo, msg, a...) } -func (log *logger) Warn(msg string, args ...any) { - log.log(slog.LevelWarn, msg, args...) +func (log *logger) Warn(msg string, a ...slog.Attr) { + log.log(slog.LevelWarn, msg, a...) } -func (log *logger) Error(msg string, args ...any) { - log.log(slog.LevelError, msg, args...) +func (log *logger) Error(msg string, a ...slog.Attr) { + log.log(slog.LevelError, msg, a...) } // Fatal is the same as Error, but quits the program via os.Exit(1). -func (log *logger) Fatal(msg string, args ...any) { - log.log(slog.LevelError, msg, args...) +func (log *logger) Fatal(msg string, a ...slog.Attr) { + log.log(slog.LevelError, msg, a...) os.Exit(1) } -func (log *logger) With(args ...any) Logger { - context := make([]any, 0, len(log.context)+len(args)) - context = append(context, log.context...) - context = append(context, args...) - +func (log *logger) With(a ...slog.Attr) Logger { return &logger{ - l: log.l, - context: context, + l: slog.New(log.l.Handler().WithAttrs(a)), } } From c64d20d8035e8c7915c120f817d8c8416686c71a Mon Sep 17 00:00:00 2001 From: Dominik Menke Date: Mon, 29 Jan 2024 20:34:46 +0100 Subject: [PATCH 5/7] add documentation --- xlog/attrs.go | 9 +++++++++ xlog/options.go | 25 ++++++++++++++++--------- xlog/xlog.go | 15 +++++++++------ 3 files changed, 34 insertions(+), 15 deletions(-) diff --git a/xlog/attrs.go b/xlog/attrs.go index 9aaef8e..ca5bbce 100644 --- a/xlog/attrs.go +++ b/xlog/attrs.go @@ -2,6 +2,8 @@ package xlog import "log/slog" +// Convenience slog.Attr generators. Allows cluttering imports (no need +// to import both log/slog and xlog). var ( String = slog.String Int64 = slog.Int64 @@ -15,14 +17,21 @@ var ( Any = slog.Any ) +// Key used to denote error values. const ErrorKey = "error" +// ErrorValue holds an error value. type ErrorValue struct{ error } +// Value extracts the error message. func (err ErrorValue) Value() slog.Value { return slog.StringValue(err.Error()) } +// Error constructs a first-class error log attribute. +// +// Not to be confused with (xlog.Logger).Error() or (log/slog).Error(), +// which produce an error-level log message. func Error(err error) slog.Attr { return slog.Any(ErrorKey, ErrorValue{err}) } diff --git a/xlog/options.go b/xlog/options.go index 8dc8c3e..94a691d 100644 --- a/xlog/options.go +++ b/xlog/options.go @@ -1,7 +1,6 @@ package xlog import ( - "bytes" "io" "log/slog" "time" @@ -9,6 +8,8 @@ import ( "github.com/digineo/texd/internal" ) +// An Option represents a functional configuration option. These are +// used to configure new logger instances. type Option func(*options) error type options struct { @@ -19,6 +20,7 @@ type options struct { handlerOpts *slog.HandlerOptions } +// Leveled sets the log level. func Leveled(l slog.Level) Option { return func(o *options) error { o.handlerOpts.Level = l @@ -26,6 +28,8 @@ func Leveled(l slog.Level) Option { } } +// LeveledString interprets s (see ParseLevel) and sets the log level. +// If s is unknown, the error will be revealed with New(). func LeveledString(s string) Option { return func(o *options) error { l, err := ParseLevel(s) @@ -37,6 +41,7 @@ func LeveledString(s string) Option { } } +// WriteTo sets the output. func WriteTo(w io.Writer) Option { return func(o *options) error { o.output = w @@ -44,14 +49,7 @@ func WriteTo(w io.Writer) Option { } } -func CaptureOutput() (Option, *bytes.Buffer) { - var b bytes.Buffer - return func(o *options) error { - o.output = &b - return nil - }, &b -} - +// MockClock sets up a canned timestamp. func MockClock(t time.Time) Option { return func(o *options) error { o.clock = internal.MockClock(t) @@ -59,6 +57,7 @@ func MockClock(t time.Time) Option { } } +// WithSource enables source code positions in log messages. func WithSource() Option { return func(o *options) error { o.handlerOpts.AddSource = true @@ -66,6 +65,8 @@ func WithSource() Option { } } +// WithAttrReplacer configures an attribute replacer. +// See (slog.HandlerOptions).ReplaceAtrr for details. func WithAttrReplacer(f func(groups []string, a slog.Attr) slog.Attr) Option { return func(o *options) error { o.handlerOpts.ReplaceAttr = f @@ -73,6 +74,8 @@ func WithAttrReplacer(f func(groups []string, a slog.Attr) slog.Attr) Option { } } +// AsJSON configures a JSONHandler, i.e. log messages will be printed +// as JSON string. func AsJSON() Option { return func(o *options) error { o.buildHandler = func(o *options) slog.Handler { @@ -82,6 +85,8 @@ func AsJSON() Option { } } +// AsText configures a TextHandler, i.e. the message output is a +// simple list of key=value pairs with minimal quoting. func AsText() Option { return func(o *options) error { o.buildHandler = func(o *options) slog.Handler { @@ -91,6 +96,8 @@ func AsText() Option { } } +// Discard mutes the logger. See also NewDiscard() for a simpler +// constructor. func Discard() Option { return func(o *options) error { o.discard = true diff --git a/xlog/xlog.go b/xlog/xlog.go index 528d1a9..8824d33 100644 --- a/xlog/xlog.go +++ b/xlog/xlog.go @@ -7,6 +7,7 @@ import ( "log/slog" "os" "runtime" + "strings" "time" ) @@ -110,16 +111,18 @@ func (log *logger) With(a ...slog.Attr) Logger { } } +// ParseLevel tries to convert a (case-insensitive) string into a +// slog.Level. Accepted values are "debug", "info", "warn", "warning", +// "error" and "fatal". Other input will result in err not being nil. func ParseLevel(s string) (l slog.Level, err error) { - switch s { - case "debug", "DEBUG": + switch strings.ToLower(s) { + case "debug": l = slog.LevelDebug - case "info", "INFO", "": // make the zero value useful + case "info", "": // make the zero value useful l = slog.LevelInfo - case "warn", "WARN": + case "warn", "warning": l = slog.LevelWarn - case "error", "ERROR", - "fatal", "FATAL": + case "error", "fatal": l = slog.LevelError default: err = fmt.Errorf("unknown log level: %q", s) From d680742e6cd164ab6cd418d3f5213316edc381c6 Mon Sep 17 00:00:00 2001 From: Dominik Menke Date: Wed, 30 Oct 2024 19:48:48 +0100 Subject: [PATCH 6/7] enable log colorization in development I'm waiting on upstream to merge two merge requests. Merge-Request: https://gitlab.com/greyxor/slogor/-/merge_requests/7 Merge-Request: https://gitlab.com/greyxor/slogor/-/merge_requests/8 --- cmd/texd/main.go | 2 +- go.mod | 4 +++ go.sum | 4 +++ service/middleware/logging_test.go | 5 ++-- service/status_test.go | 5 ++-- xlog/attrs.go | 7 +++++ xlog/options.go | 44 +++++++++++++++++++++--------- xlog/xlog.go | 37 ++++++++++++++----------- 8 files changed, 72 insertions(+), 36 deletions(-) diff --git a/cmd/texd/main.go b/cmd/texd/main.go index 095c6b5..df21ebd 100644 --- a/cmd/texd/main.go +++ b/cmd/texd/main.go @@ -286,7 +286,7 @@ func setupLogger() (xlog.Logger, error) { xlog.WithSource(), } if texd.Development() { - o = append(o, xlog.WriteTo(os.Stderr), xlog.AsText()) + o = append(o, xlog.WriteTo(os.Stderr), xlog.AsText(), xlog.Color()) } else { o = append(o, xlog.WriteTo(os.Stdout), xlog.AsJSON()) } diff --git a/go.mod b/go.mod index e32dace..96e77e6 100644 --- a/go.mod +++ b/go.mod @@ -9,6 +9,7 @@ require ( github.com/docker/go-units v0.5.0 github.com/gorilla/handlers v1.5.2 github.com/gorilla/mux v1.8.1 + github.com/mattn/go-isatty v0.0.20 github.com/moby/term v0.5.0 github.com/oklog/ulid/v2 v2.1.0 github.com/opencontainers/image-spec v1.1.0 @@ -17,6 +18,7 @@ require ( github.com/spf13/pflag v1.0.5 github.com/stretchr/testify v1.9.0 github.com/thediveo/enumflag v0.10.1 + gitlab.com/greyxor/slogor v1.4.1 ) require ( @@ -61,3 +63,5 @@ require ( ) replace github.com/spf13/afero => github.com/digineo/afero v1.11.1-0.20240128222722-ade8094005cb + +replace gitlab.com/greyxor/slogor => gitlab.com/dmke/slogor v1.4.2-0.20241030183918-8885575df1e5 diff --git a/go.sum b/go.sum index 7a20ee1..42ebc2a 100644 --- a/go.sum +++ b/go.sum @@ -1456,6 +1456,8 @@ github.com/magiconair/properties v1.8.0/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czP github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU= github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= github.com/mattn/go-isatty v0.0.17/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= +github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/mattn/go-sqlite3 v1.14.14/go.mod h1:NyWgC/yNuGj7Q9rpYnZvas74GogHl5/Z4A/KQRfk6bU= github.com/mattn/go-sqlite3 v1.14.15/go.mod h1:2eHXhiwb8IkHr+BDWZGa96P6+rkvnG63S2DGjv9HUNg= github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0= @@ -1588,6 +1590,8 @@ github.com/yuin/goldmark v1.4.1/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1 github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY= github.com/zeebo/assert v1.3.0/go.mod h1:Pq9JiuJQpG8JLJdtkwrJESF0Foym2/D9XMU5ciN/wJ0= github.com/zeebo/xxh3 v1.0.2/go.mod h1:5NWz9Sef7zIDm2JHfFlcQvNekmcEl9ekUZQQKCYaDcA= +gitlab.com/dmke/slogor v1.4.2-0.20241030183918-8885575df1e5 h1:oIZBFZcMCiRwi1CdWSf62YF4XKq0GyhKIBsxZo24AWw= +gitlab.com/dmke/slogor v1.4.2-0.20241030183918-8885575df1e5/go.mod h1:RvD/RqmEGpqVhL8tqqfVduuxtcik6uXCnzfikaFCwto= go.etcd.io/bbolt v1.3.2/go.mod h1:IbVyRI1SCnLcuJnV2u8VeU0CEYM7e686BmAb1XKL+uU= go.opencensus.io v0.21.0/go.mod h1:mSImk1erAIZhrmZN+AvHh14ztQfjbGwt4TtuofqLduU= go.opencensus.io v0.22.0/go.mod h1:+kGneAE2xo2IficOXnaByMWTGM9T73dGwxeWcUqIpI8= diff --git a/service/middleware/logging_test.go b/service/middleware/logging_test.go index e61776a..9865c83 100644 --- a/service/middleware/logging_test.go +++ b/service/middleware/logging_test.go @@ -36,9 +36,8 @@ func TestLogging(t *testing.T) { require.Equal(t, http.StatusOK, w.Code) assert.Equal(t, strings.Join([]string{ - "time=2022-04-15T05:20:00.000Z", - "level=INFO", - `msg=""`, + "[05:20:00.000] INFO logging.go:68", + "", "method=GET", "status=200", "bytes=0", diff --git a/service/status_test.go b/service/status_test.go index c5724fa..70584ef 100644 --- a/service/status_test.go +++ b/service/status_test.go @@ -85,9 +85,8 @@ func TestHandleStatus_withFailIO(t *testing.T) { assert.Equal(t, http.StatusOK, rec.code) assert.Equal(t, mimeTypeJSON, rec.h.Get("Content-Type")) assert.Equal(t, strings.Join([]string{ - "time=2022-04-15T05:20:00.000Z", - "level=ERROR", - `msg="failed to write response"`, + "[05:20:00.000] ERROR status.go:46", + "failed to write response", `error="io: read/write on closed pipe"`, }, " ")+"\n", buf.String()) } diff --git a/xlog/attrs.go b/xlog/attrs.go index ca5bbce..481a61e 100644 --- a/xlog/attrs.go +++ b/xlog/attrs.go @@ -23,11 +23,18 @@ const ErrorKey = "error" // ErrorValue holds an error value. type ErrorValue struct{ error } +var _ slog.LogValuer = (*ErrorValue)(nil) + // Value extracts the error message. func (err ErrorValue) Value() slog.Value { return slog.StringValue(err.Error()) } +// LogValue implements [slog.LogValuer]. +func (err ErrorValue) LogValue() slog.Value { + return slog.StringValue(err.Error()) +} + // Error constructs a first-class error log attribute. // // Not to be confused with (xlog.Logger).Error() or (log/slog).Error(), diff --git a/xlog/options.go b/xlog/options.go index 94a691d..25cfe14 100644 --- a/xlog/options.go +++ b/xlog/options.go @@ -3,9 +3,12 @@ package xlog import ( "io" "log/slog" + "os" "time" "github.com/digineo/texd/internal" + "github.com/mattn/go-isatty" + "gitlab.com/greyxor/slogor" ) // An Option represents a functional configuration option. These are @@ -13,17 +16,20 @@ import ( type Option func(*options) error type options struct { - discard bool - output io.Writer - clock internal.Clock + discard bool + output io.Writer + color bool + clock internal.Clock + level slog.Leveler + source bool + buildHandler func(o *options) slog.Handler - handlerOpts *slog.HandlerOptions } // Leveled sets the log level. func Leveled(l slog.Level) Option { return func(o *options) error { - o.handlerOpts.Level = l + o.level = l return nil } } @@ -36,7 +42,7 @@ func LeveledString(s string) Option { if err != nil { return err } - o.handlerOpts.Level = l + o.level = l return nil } } @@ -60,16 +66,17 @@ func MockClock(t time.Time) Option { // WithSource enables source code positions in log messages. func WithSource() Option { return func(o *options) error { - o.handlerOpts.AddSource = true + o.source = true return nil } } -// WithAttrReplacer configures an attribute replacer. -// See (slog.HandlerOptions).ReplaceAtrr for details. -func WithAttrReplacer(f func(groups []string, a slog.Attr) slog.Attr) Option { +// Color enables colorful log output. If the output writer set by +// [WriteTo] isn't a TTY, or messages are output [AsJSON], enabling +// colors won't have an effect. +func Color() Option { return func(o *options) error { - o.handlerOpts.ReplaceAttr = f + o.color = true return nil } } @@ -79,7 +86,10 @@ func WithAttrReplacer(f func(groups []string, a slog.Attr) slog.Attr) Option { func AsJSON() Option { return func(o *options) error { o.buildHandler = func(o *options) slog.Handler { - return slog.NewJSONHandler(o.output, o.handlerOpts) + return slog.NewJSONHandler(o.output, &slog.HandlerOptions{ + AddSource: o.source, + Level: o.level, + }) } return nil } @@ -90,7 +100,15 @@ func AsJSON() Option { func AsText() Option { return func(o *options) error { o.buildHandler = func(o *options) slog.Handler { - return slog.NewTextHandler(o.output, o.handlerOpts) + opts := []slogor.OptionFn{ + slogor.SetLevel(o.level.Level()), + slogor.SetTimeFormat("[15:04:05.000]"), + slogor.ShowSource(), + } + if f, isFile := o.output.(*os.File); !isFile || !isatty.IsTerminal(f.Fd()) { + opts = append(opts, slogor.DisableColor()) + } + return slogor.NewHandler(o.output, opts...) } return nil } diff --git a/xlog/xlog.go b/xlog/xlog.go index 8824d33..8f5cf2a 100644 --- a/xlog/xlog.go +++ b/xlog/xlog.go @@ -1,4 +1,4 @@ -// Package xlog provides a very thin wrapper aroud log/slog. +// Package xlog provides a thin wrapper around [log/slog]. package xlog import ( @@ -9,6 +9,8 @@ import ( "runtime" "strings" "time" + + "github.com/digineo/texd/internal" ) // A Logger allows writing messages with various severities. @@ -37,8 +39,8 @@ type logger struct { // written to stdout, and the log level is INFO. func New(opt ...Option) (Logger, error) { opts := options{ - output: os.Stdout, - handlerOpts: &slog.HandlerOptions{}, + level: slog.LevelInfo, + output: os.Stdout, } for _, o := range opt { @@ -53,22 +55,15 @@ func New(opt ...Option) (Logger, error) { } // setup mock time + h := opts.buildHandler(&opts) if opts.clock != nil { - repl := opts.handlerOpts.ReplaceAttr - opts.handlerOpts.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { - if len(groups) == 0 && a.Key == slog.TimeKey { - a.Value = slog.TimeValue(opts.clock.Now()) - } - if repl == nil { - return a - } - return repl(groups, a) + h = &mockTimeHandler{ + clock: opts.clock, + Handler: h, } } - return &logger{ - l: slog.New(opts.buildHandler(&opts)), - }, nil + return &logger{l: slog.New(h)}, nil } // log creates a log record. It is called by Debug, Info, etc. @@ -77,7 +72,7 @@ func (log *logger) log(level slog.Level, msg string, a ...slog.Attr) { return } var pcs [1]uintptr - runtime.Callers(3, pcs[:]) // skip runtime.Callers, log, and our caller + runtime.Callers(3, pcs[:]) //nolint:mnd // skip runtime.Callers, log, and our caller r := slog.NewRecord(time.Now(), level, msg, pcs[0]) r.AddAttrs(a...) _ = log.l.Handler().Handle(context.Background(), r) @@ -129,3 +124,13 @@ func ParseLevel(s string) (l slog.Level, err error) { } return } + +type mockTimeHandler struct { + clock internal.Clock + slog.Handler +} + +func (h *mockTimeHandler) Handle(ctx context.Context, a slog.Record) error { + a.Time = h.clock.Now() + return h.Handler.Handle(ctx, a) +} From f259c316f495d438c1d6911954145fe9282d6a72 Mon Sep 17 00:00:00 2001 From: Dominik Menke Date: Thu, 31 Oct 2024 01:23:12 +0100 Subject: [PATCH 7/7] add tests for xlog [wip] --- service/middleware/logging_test.go | 1 + service/status_test.go | 1 + xlog/attrs.go | 4 +- xlog/discard.go | 11 +++ xlog/options.go | 27 ++++-- xlog/options_test.go | 140 +++++++++++++++++++++++++++++ xlog/xlog.go | 15 ++-- 7 files changed, 182 insertions(+), 17 deletions(-) create mode 100644 xlog/options_test.go diff --git a/service/middleware/logging_test.go b/service/middleware/logging_test.go index 9865c83..7eca438 100644 --- a/service/middleware/logging_test.go +++ b/service/middleware/logging_test.go @@ -27,6 +27,7 @@ func TestLogging(t *testing.T) { log, err := xlog.New( xlog.AsText(), xlog.WriteTo(&buf), + xlog.WithSource(), xlog.MockClock(time.Unix(1650000000, 0).UTC()), ) require.NoError(t, err) diff --git a/service/status_test.go b/service/status_test.go index 70584ef..6d6fa27 100644 --- a/service/status_test.go +++ b/service/status_test.go @@ -63,6 +63,7 @@ func TestHandleStatus_withFailIO(t *testing.T) { log, err := xlog.New( xlog.AsText(), xlog.WriteTo(&buf), + xlog.WithSource(), xlog.MockClock(time.Unix(1650000000, 0).UTC()), ) require.NoError(t, err) diff --git a/xlog/attrs.go b/xlog/attrs.go index 481a61e..84ca5a2 100644 --- a/xlog/attrs.go +++ b/xlog/attrs.go @@ -32,7 +32,7 @@ func (err ErrorValue) Value() slog.Value { // LogValue implements [slog.LogValuer]. func (err ErrorValue) LogValue() slog.Value { - return slog.StringValue(err.Error()) + return err.Value() } // Error constructs a first-class error log attribute. @@ -40,5 +40,5 @@ func (err ErrorValue) LogValue() slog.Value { // Not to be confused with (xlog.Logger).Error() or (log/slog).Error(), // which produce an error-level log message. func Error(err error) slog.Attr { - return slog.Any(ErrorKey, ErrorValue{err}) + return Any(ErrorKey, ErrorValue{err}) } diff --git a/xlog/discard.go b/xlog/discard.go index 814909d..22d40a6 100644 --- a/xlog/discard.go +++ b/xlog/discard.go @@ -1,6 +1,7 @@ package xlog import ( + "context" "log/slog" "os" ) @@ -16,9 +17,19 @@ func NewDiscard() Logger { return &discard{} } +var ( + _ Logger = (*discard)(nil) + _ slog.Handler = (*discard)(nil) +) + func (*discard) Debug(string, ...slog.Attr) {} func (*discard) Info(string, ...slog.Attr) {} func (*discard) Warn(string, ...slog.Attr) {} func (*discard) Error(string, ...slog.Attr) {} func (*discard) Fatal(string, ...slog.Attr) { os.Exit(1) } func (d *discard) With(...slog.Attr) Logger { return d } + +func (*discard) Enabled(context.Context, slog.Level) bool { return false } +func (*discard) Handle(context.Context, slog.Record) error { return nil } +func (d *discard) WithAttrs(attrs []slog.Attr) slog.Handler { return d } +func (d *discard) WithGroup(name string) slog.Handler { return d } diff --git a/xlog/options.go b/xlog/options.go index 25cfe14..3a65519 100644 --- a/xlog/options.go +++ b/xlog/options.go @@ -1,6 +1,7 @@ package xlog import ( + "errors" "io" "log/slog" "os" @@ -16,12 +17,11 @@ import ( type Option func(*options) error type options struct { - discard bool - output io.Writer - color bool - clock internal.Clock - level slog.Leveler - source bool + output io.Writer + color bool + clock internal.Clock + level slog.Leveler + source bool buildHandler func(o *options) slog.Handler } @@ -47,9 +47,15 @@ func LeveledString(s string) Option { } } +var ErrNilWriter = errors.New("invalid writer: nil") + // WriteTo sets the output. func WriteTo(w io.Writer) Option { return func(o *options) error { + if w == nil { + return ErrNilWriter + } + o.output = w return nil } @@ -103,7 +109,9 @@ func AsText() Option { opts := []slogor.OptionFn{ slogor.SetLevel(o.level.Level()), slogor.SetTimeFormat("[15:04:05.000]"), - slogor.ShowSource(), + } + if o.source { + opts = append(opts, slogor.ShowSource()) } if f, isFile := o.output.(*os.File); !isFile || !isatty.IsTerminal(f.Fd()) { opts = append(opts, slogor.DisableColor()) @@ -118,7 +126,10 @@ func AsText() Option { // constructor. func Discard() Option { return func(o *options) error { - o.discard = true + o.buildHandler = func(o *options) slog.Handler { + // the discard logger doesn't have any options + return &discard{} + } return nil } } diff --git a/xlog/options_test.go b/xlog/options_test.go new file mode 100644 index 0000000..bfd7eca --- /dev/null +++ b/xlog/options_test.go @@ -0,0 +1,140 @@ +package xlog + +import ( + "bytes" + "context" + "fmt" + "log/slog" + "runtime" + "testing" + "time" + + "github.com/stretchr/testify/suite" +) + +func TestOptionSuite(t *testing.T) { + suite.Run(t, new(OptionSuite)) +} + +type OptionSuite struct { + suite.Suite + options +} + +func (o *OptionSuite) SetupTest() { + o.level = slog.LevelDebug +} + +func (o *OptionSuite) TestLeveled() { + err := Leveled(slog.LevelError)(&o.options) + o.Require().NoError(err) + o.Assert().Equal(slog.LevelError, o.level) + + err = Leveled(slog.Level(999))(&o.options) + o.Require().NoError(err) + o.Assert().Equal(slog.Level(999), o.level) +} + +func (o *OptionSuite) TestLeveledString_valid() { + for i, tt := range []struct { + input string + expected slog.Level + }{ + {"dbg", slog.LevelDebug}, + {"debug", slog.LevelDebug}, + + {"", slog.LevelInfo}, + {"info", slog.LevelInfo}, + {"INFO", slog.LevelInfo}, + + {"WARN", slog.LevelWarn}, + {"WARNING", slog.LevelWarn}, + + {"ERR", slog.LevelError}, + {"ERROR", slog.LevelError}, + {"FaTaL", slog.LevelError}, + } { + o.level = slog.Level(100 + i) + err := LeveledString(tt.input)(&o.options) + o.Require().NoError(err) + o.Assert().Equal(tt.expected, o.level) + } +} + +func (o *OptionSuite) TestLeveledString_invalid() { + o.level = slog.Level(100) + err := LeveledString("ifno")(&o.options) + o.Require().Equal(slog.Level(100), o.level) + o.Assert().EqualError(err, `unknown log level: "ifno"`) +} + +func (o *OptionSuite) TestWriteTo() { + var buf bytes.Buffer + err := WriteTo(&buf)(&o.options) + o.Require().NoError(err) + o.Assert().Equal(&buf, o.output) + + err = WriteTo(nil)(&o.options) + o.Assert().EqualError(err, "invalid writer: nil") +} + +func (o *OptionSuite) TestMockClock() { + t := time.Now() + err := MockClock(t)(&o.options) + o.Require().NoError(err) + o.Require().NotNil(o.clock) + o.Assert().EqualValues(t, o.clock.Now()) +} + +func (o *OptionSuite) TestWithSource() { + err := WithSource()(&o.options) + o.Require().NoError(err) + o.Assert().True(o.source) +} + +func (o *OptionSuite) TestColor() { + err := Color()(&o.options) + o.Require().NoError(err) + o.Assert().True(o.color) +} + +func (o *OptionSuite) testBuildHandler(expectedLog string, opts ...Option) { + o.T().Helper() + + var buf bytes.Buffer + o.output = &buf + + for _, opt := range opts { + o.Require().NoError(opt(&o.options)) + } + o.Require().NotNil(o.buildHandler) + h := o.buildHandler(&o.options) + o.Require().NotNil(h) + + o.Assert().False(h.Enabled(context.Background(), -999)) + + pc, _, _, ok := runtime.Caller(1) + o.Require().True(ok) + err := h.Handle(context.Background(), slog.NewRecord( + time.Time{}, slog.LevelInfo, "test", pc, + )) + o.Assert().NoError(err) + o.Assert().EqualValues(expectedLog, buf.String()) +} + +func (o *OptionSuite) TestAsJSON() { + o.testBuildHandler(`{"level":"INFO","msg":"test"}`+"\n", AsJSON()) +} + +func (o *OptionSuite) TestAsText() { + o.testBuildHandler("INFO test\n", AsText()) + + _, _, line, ok := runtime.Caller(0) + o.Require().True(ok) + msg := fmt.Sprintf("INFO options_test.go:%d test\n", line+3) + o.testBuildHandler(msg, WithSource(), AsText()) +} + +func (o *OptionSuite) TestDiscard() { + o.testBuildHandler("", Discard()) +} diff --git a/xlog/xlog.go b/xlog/xlog.go index 8f5cf2a..992629f 100644 --- a/xlog/xlog.go +++ b/xlog/xlog.go @@ -49,13 +49,14 @@ func New(opt ...Option) (Logger, error) { } } - // the discard logger doesn't require any further setup - if opts.discard { - return &discard{}, nil - } - // setup mock time h := opts.buildHandler(&opts) + + // skip a lot of overhead for the discard logger + if d, ok := h.(*discard); ok { + return d, nil + } + if opts.clock != nil { h = &mockTimeHandler{ clock: opts.clock, @@ -111,13 +112,13 @@ func (log *logger) With(a ...slog.Attr) Logger { // "error" and "fatal". Other input will result in err not being nil. func ParseLevel(s string) (l slog.Level, err error) { switch strings.ToLower(s) { - case "debug": + case "dbg", "debug": l = slog.LevelDebug case "info", "": // make the zero value useful l = slog.LevelInfo case "warn", "warning": l = slog.LevelWarn - case "error", "fatal": + case "err", "error", "fatal": l = slog.LevelError default: err = fmt.Errorf("unknown log level: %q", s)