feat: add logger interface (#17)

* feat: repsect oid batch arguments

Preserve oid batch arguments in requset/response per [specs](https://github.com/git-lfs/git-lfs/blob/main/docs/proposals/ssh_adapter.md#requests-to-transfer-objects)

* fix: error on invalid arguments

* feat: support batch response error message

* feat: support batch response error message

* feat: add logger interface

Pass a custom logger to log messages

* fix: lint

* feat: use structured logging

* fix: merge

.editorconfig

@@ -0,0 +1,5 @@
+root = true
+
+[*.go]
+indent_style = tab
+indent_size = 4

cmd/cmd.go → cmd.go

@@ -1,4 +1,4 @@
-package cmd
+package main
 
 import (
 	"fmt"
@@ -31,7 +31,7 @@ func ensureDirs(path string) error {
 	return nil
 }
 
-func run(r io.Reader, w io.Writer, args []string) error {
+func run(r io.Reader, w io.Writer, args ...string) error {
 	if len(args) != 2 {
 		return fmt.Errorf("expected 2 arguments, got %d", len(args))
 	}
@@ -50,20 +50,20 @@ func run(r io.Reader, w io.Writer, args []string) error {
 		return err
 	}
 	umask := setPermissions(gitdir)
-	handler := transfer.NewPktline(r, w)
+	handler := transfer.NewPktline(r, w, logger)
 	for _, cap := range capabilities {
 		if err := handler.WritePacketText(cap); err != nil {
-			transfer.Logf("error sending capability: %s: %v", cap, err)
+			logger.Log("error sending capability", "cap", cap, "err", err)
 		}
 	}
 	if err := handler.WriteFlush(); err != nil {
-		transfer.Logf("error flushing capabilities: %v", err)
+		logger.Log("error flushing capabilities", "err", err)
 	}
 	now := time.Now()
-	transfer.Logf("umask %o", umask)
+	logger.Log("umask", "umask", umask)
 	backend := local.New(lfsPath, umask, &now)
-	p := transfer.NewProcessor(handler, backend)
-	defer transfer.Log("done processing commands")
+	p := transfer.NewProcessor(handler, backend, logger)
+	defer logger.Log("done processing commands")
 	switch op {
 	case "upload":
 		return p.ProcessCommands(transfer.UploadOperation)
@@ -94,17 +94,17 @@ func Command(stdin io.Reader, stdout io.Writer, stderr io.Writer, args ...string
 	errc := make(chan error, 1)
 
 	setup(done)
-	transfer.Logf("git-lfs-transfer %s", "v1")
-	defer transfer.Log("git-lfs-transfer completed")
+	logger.Log("git-lfs-transfer", "version", "v1")
+	defer logger.Log("git-lfs-transfer completed")
 	go func() {
-		errc <- run(stdin, stdout, args)
+		errc <- run(stdin, stdout, args...)
 	}()
 
 	select {
 	case s := <-done:
-		transfer.Logf("signal %q received", s)
+		logger.Log("signal received", "signal", s)
 	case err := <-errc:
-		transfer.Log("done running")
+		logger.Log("done running")
 		fmt.Fprintln(stderr, Usage())
 		fmt.Fprintln(stderr, err)
 		if err != nil {

cmd/cmd_other.go → cmd_other.go

@@ -1,7 +1,7 @@
 //go:build !(darwin || dragonfly || freebsd || linux || netbsd || openbsd || solaris)
 // +build !darwin,!dragonfly,!freebsd,!linux,!netbsd,!openbsd,!solaris
 
-package cmd
+package main
 
 import (
 	"os"

cmd/cmd_unix.go → cmd_unix.go

@@ -1,7 +1,7 @@
 //go:build darwin || dragonfly || freebsd || linux || netbsd || openbsd || solaris
 // +build darwin dragonfly freebsd linux netbsd openbsd solaris
 
-package cmd
+package main
 
 import (
 	"os"

internal/local/backend.go

@@ -72,7 +72,6 @@ func (l *LocalBackend) FinishUpload(state interface{}, _ transfer.Args) error {
 	case *UploadState:
 		destPath := oidExpectedPath(l.lfsPath, state.Oid)
 		parent := filepath.Dir(destPath)
-		transfer.Logf("finishing upload of %s at %s", destPath, parent)
 		if err := os.MkdirAll(parent, 0777); err != nil {
 			return err
 		}
@@ -106,7 +105,6 @@ func (l *LocalBackend) StartUpload(oid string, r io.Reader, _ transfer.Args) (in
 	if r == nil {
 		return nil, fmt.Errorf("%w: received null data", transfer.ErrMissingData)
 	}
-	transfer.Logf("start uploading %s", oid)
 	tempDir := filepath.Join(l.lfsPath, "incomplete")
 	randBytes := make([]byte, 12)
 	if _, err := rand.Read(randBytes); err != nil {
@@ -142,7 +140,6 @@ func (l *LocalBackend) Verify(oid string, args transfer.Args) (transfer.Status,
 		return nil, err
 	}
 	if stat.Size() != int64(expectedSize) {
-		transfer.Logf("size mismatch, expected %d, got %d", expectedSize, stat.Size())
 		return transfer.NewFailureStatus(transfer.StatusConflict, "size mismatch"), nil
 	}
 	return transfer.SuccessStatus(), nil
@@ -169,7 +166,7 @@ func (l *localLockBackend) Timestamp() *time.Time {
 }
 
 // Create implements main.LockBackend.
-func (l *localLockBackend) Create(path, refname string) (transfer.Lock, error) {
+func (l *localLockBackend) Create(path, _ string) (transfer.Lock, error) {
 	id := localBackendLock{}.HashFor(path)
 	var b bytes.Buffer
 	b.WriteString(fmt.Sprintf("%s:%d:", LocalBackendLockVersion, l.Timestamp().Unix()))
@@ -242,12 +239,10 @@ func (l *localLockBackend) Range(_ string, _ int, f func(l transfer.Lock) error)
 	if err != nil {
 		return "", err
 	}
-	transfer.Logf("found %d locks", len(data))
 	sort.Slice(data, func(i, j int) bool {
 		return data[i].Name() < data[j].Name()
 	})
 	for _, lf := range data {
-		transfer.Logf("found lock %s", lf.Name())
 		var lock transfer.Lock
 		lock, err = l.FromID(lf.Name())
 		if err != nil {

internal/local/backend_unix.go

@@ -19,7 +19,6 @@ func (l *LocalBackend) FixPermissions(path string) (transfer.Status, error) {
 	if err != nil {
 		return nil, err
 	}
-	transfer.Logf("settings permissions of %s to %o", path, 0777&^l.umask)
 	if err := os.Chmod(path, 0777&^l.umask); err != nil {
 		return nil, err
 	}

main.go

@@ -5,19 +5,37 @@ import (
 	"fmt"
 	"os"
 
-	"github.com/charmbracelet/git-lfs-transfer/cmd"
 	"github.com/charmbracelet/git-lfs-transfer/transfer"
+	"github.com/rubyist/tracerx"
 )
 
+type tracerxLogger struct{}
+
+// Log logs the given arguments if Debug is true.
+func (*tracerxLogger) Log(msg string, kv ...interface{}) {
+	format := msg
+	for i := 0; i < len(kv); i += 2 {
+		format += " %s=%v"
+	}
+	tracerx.Printf(format, kv...)
+}
+
+var logger = new(tracerxLogger)
+
+func init() {
+	tracerx.DefaultKey = "GIT"
+	tracerx.Prefix = "trace git-lfs-transfer: "
+}
+
 func main() {
 	args := os.Args
 	if len(args) < 2 {
-		fmt.Fprintln(os.Stderr, cmd.Usage())
+		fmt.Fprintln(os.Stderr, Usage())
 		fmt.Fprintf(os.Stderr, "expected 2 arguments, got %d\n", len(args)-1)
 		os.Exit(1)
 	}
-	if err := cmd.Command(os.Stdin, os.Stdout, os.Stderr, args[1:]...); err != nil {
-		fmt.Fprintf(os.Stderr, cmd.Usage())
+	if err := Command(os.Stdin, os.Stdout, os.Stderr, args[1:]...); err != nil {
+		fmt.Fprintf(os.Stderr, Usage())
 		fmt.Fprintln(os.Stderr)
 		fmt.Fprintln(os.Stderr, err)
 		switch {

transfer/args.go

@@ -29,7 +29,6 @@ func ParseArgs(parts []string) (Args, error) {
 		key, value := parts[0], parts[1]
 		args[key] = value
 	}
-	Logf("args: %d %v", len(args), args)
 	return args, nil
 }
 

transfer/log.go

@@ -1,20 +1,14 @@
 package transfer
 
-import (
-	"github.com/rubyist/tracerx"
-)
+// Logger is a logging interface.
+type Logger interface {
+	// Log logs the given message and structured arguments.
+	Log(msg string, kv ...interface{})
+}
 
-var (
-	// Debug is the debug flag.
-	Debug = false
-)
+type noopLogger struct{}
 
-// Log logs the given arguments if Debug is true.
-func Log(v ...interface{}) {
-	tracerx.Printf("%v", v...)
-}
+var _ Logger = (*noopLogger)(nil)
 
-// Logf logs the given arguments if Debug is true.
-func Logf(format string, v ...interface{}) {
-	tracerx.Printf(format, v...)
-}
+// Log implements Logger.
+func (*noopLogger) Log(string, ...interface{}) {}

transfer/oid.go

@@ -34,7 +34,7 @@ func (p Pointer) IsValid() bool {
 	return true
 }
 
-// RelativePath returns the relative storage path of the pointer
+// RelativePath returns the relative storage path of the pointer.
 func (p Pointer) RelativePath() string {
 	if len(p.Oid) < 5 {
 		return p.Oid

transfer/pktline.go

@@ -30,70 +30,75 @@ const (
 // PktLine is a Git packet line handler.
 type Pktline struct {
 	*pktline.Pktline
-	r io.Reader
-	w io.Writer
+	r      io.Reader
+	w      io.Writer
+	logger Logger
 }
 
 // NewPktline creates a new Git packet line handler.
-func NewPktline(r io.Reader, w io.Writer) *Pktline {
+func NewPktline(r io.Reader, w io.Writer, logger Logger) *Pktline {
+	if logger == nil {
+		logger = new(noopLogger)
+	}
 	return &Pktline{
 		Pktline: pktline.NewPktline(r, w),
 		r:       r,
 		w:       w,
+		logger:  logger,
 	}
 }
 
 // SendError sends an error msg.
 func (p *Pktline) SendError(status uint32, message string) error {
-	Logf("sending error: %d %s", status, message)
+	p.logger.Log("sending error status", "code", status, "msg", message)
 	if err := p.WritePacketText(fmt.Sprintf("status %03d", status)); err != nil {
-		Logf("error writing status: %s", err)
+		p.logger.Log("failed to write packet", "err", err)
 	}
 	if err := p.WriteDelim(); err != nil {
-		Logf("error writing delim: %s", err)
+		p.logger.Log("failed to write delimiter", "err", err)
 	}
 	if err := p.WritePacketText(message); err != nil {
-		Logf("error writing message: %s", err)
+		p.logger.Log("failed to write message", "err", err)
 	}
 	return p.WriteFlush()
 }
 
 // SendStatus sends a status message.
 func (p *Pktline) SendStatus(status Status) error {
-	Logf("sending status: %s", status)
+	p.logger.Log("sending status", "code", status)
 	if err := p.WritePacketText(fmt.Sprintf("status %03d", status.Code())); err != nil {
-		Logf("error writing status: %s", err)
+		p.logger.Log("failed to write status", "err", err)
 	}
 	if args := status.Args(); len(args) > 0 {
 		for _, arg := range args {
 			if err := p.WritePacketText(arg); err != nil {
-				Logf("error writing arg: %s", err)
+				p.logger.Log("failed to write argument", "arg", arg, "err", err)
 			}
 		}
 	}
 	if msgs := status.Messages(); len(msgs) > 0 {
 		if err := p.WriteDelim(); err != nil {
-			Logf("error writing delim: %s", err)
+			p.logger.Log("failed to write delimiter", "err", err)
 		}
 		for _, msg := range msgs {
 			if err := p.WritePacketText(msg); err != nil {
-				Logf("error writing msg: %s", err)
+				p.logger.Log("failed to write message", "err", err)
 			}
 		}
 	} else if r := status.Reader(); r != nil {
-		Logf("sending reader")
+		p.logger.Log("sending reader")
 		// Close reader if it implements io.Closer.
 		if c, ok := r.(io.Closer); ok {
 			defer c.Close() // nolint: errcheck
 		}
 		if err := p.WriteDelim(); err != nil {
-			Logf("error writing delim: %v", err)
+			p.logger.Log("failed to write delimiter", "err", err)
 		}
 		w := p.Writer()
 		if _, err := io.Copy(w, r); err != nil {
-			Logf("error copying reader: %v", err)
+			p.logger.Log("failed to copy reader", "err", err)
 		}
-		defer Logf("done copying")
+		defer p.logger.Log("done copying")
 		return w.Flush()
 	}
 	return p.WriteFlush()