fix(git): parse git clone progress as log messages

pkg/git/progress.go

@@ -0,0 +1,82 @@
+package git
+
+import (
+	"bytes"
+	"io"
+	"regexp"
+	"strconv"
+
+	"github.com/devsy-org/devsy/pkg/log"
+)
+
+// progressLine matches git's repeating "<label>: NN% (x/y)" progress
+// updates, e.g. "Receiving objects:  47% (156/333)".
+var progressLine = regexp.MustCompile(`^(.+?):\s+(\d+)% \(\d+/\d+\)`)
+
+// progressWriter splits git's --progress output on '\r' as well as '\n'
+// (git overwrites a line with '\r' rather than emitting a new one), passes
+// plain informational lines to next unchanged, and logs percentage updates
+// thinned to one per 10 points instead of forwarding every frame.
+type progressWriter struct {
+	next    io.Writer
+	buf     bytes.Buffer
+	lastPct map[string]int
+}
+
+func newProgressWriter(next io.Writer) *progressWriter {
+	return &progressWriter{next: next, lastPct: map[string]int{}}
+}
+
+func (w *progressWriter) Write(p []byte) (int, error) {
+	for i, b := range p {
+		if b == '\r' || b == '\n' {
+			if err := w.flush(); err != nil {
+				return i + 1, err
+			}
+			continue
+		}
+		w.buf.WriteByte(b)
+	}
+	return len(p), nil
+}
+
+func (w *progressWriter) Close() error {
+	return w.flush()
+}
+
+func (w *progressWriter) flush() error {
+	line := w.buf.String()
+	w.buf.Reset()
+	if line == "" || w.reportProgress(line) {
+		return nil
+	}
+	_, err := w.next.Write(append([]byte(line), '\n'))
+	return err
+}
+
+// reportProgress returns true if line was a percentage update (thinned or
+// not), so the caller knows not to also write it to the log.
+func (w *progressWriter) reportProgress(line string) bool {
+	m := progressLine.FindStringSubmatch(line)
+	if m == nil {
+		return false
+	}
+	label, pct := m[1], atoiOr(m[2], -1)
+	last, seen := w.lastPct[label]
+	w.lastPct[label] = pct
+	if seen && pct == last {
+		return true // exact duplicate frame (e.g. object count didn't change)
+	}
+	if pct%10 == 0 || pct == 100 {
+		log.Infof("%s", line)
+	}
+	return true
+}
+
+func atoiOr(s string, fallback int) int {
+	n, err := strconv.Atoi(s)
+	if err != nil {
+		return fallback
+	}
+	return n
+}

pkg/git/progress_test.go

@@ -0,0 +1,157 @@
+package git
+
+import (
+	"bytes"
+	"fmt"
+	"strings"
+	"testing"
+
+	"github.com/devsy-org/devsy/pkg/log"
+)
+
+const testLogFormatText = "text"
+
+func TestProgressWriter_SplitsOnCarriageReturn(t *testing.T) {
+	var out bytes.Buffer
+	w := newProgressWriter(&out)
+
+	_, err := w.Write([]byte(
+		"Cloning into 'repo'...\n" +
+			"Receiving objects:   0% (1/333)\r" +
+			"Receiving objects:  10% (34/333)\r" +
+			"Receiving objects: 100% (333/333), done.\n",
+	))
+	if err != nil {
+		t.Fatalf("Write: %v", err)
+	}
+	if err := w.Close(); err != nil {
+		t.Fatalf("Close: %v", err)
+	}
+
+	// Only the plain informational line reaches the log; percentage frames
+	// are logged separately (via pkg/log, not through `out`).
+	if got := strings.TrimRight(out.String(), "\n"); got != "Cloning into 'repo'..." {
+		t.Errorf("log output = %q", got)
+	}
+}
+
+func TestProgressWriter_ThinsIntermediatePercentages(t *testing.T) {
+	log.Init(log.Config{Verbosity: 2, Format: testLogFormatText})
+	var sink bytes.Buffer
+	remove := log.AddSink(&sink)
+	defer remove()
+
+	var out bytes.Buffer
+	w := newProgressWriter(&out)
+
+	for pct := 0; pct <= 100; pct++ {
+		_, _ = w.Write(fmt.Appendf(nil, "Receiving objects: %3d%% (1/1)\r", pct))
+	}
+	_ = w.Close()
+	_ = log.Sync()
+
+	// Percentage frames never reach `next`, regardless of thinning.
+	if out.Len() != 0 {
+		t.Errorf("expected no log output via next, got %q", out.String())
+	}
+
+	// Only 0, 10, 20, ..., 100 should have been logged, in that order.
+	lines := strings.Split(strings.TrimSpace(sink.String()), "\n")
+	if len(lines) != 11 {
+		t.Fatalf("got %d progress log lines, want 11: %q", len(lines), sink.String())
+	}
+	for i, want := range []int{0, 10, 20, 30, 40, 50, 60, 70, 80, 90, 100} {
+		wantSub := fmt.Sprintf("%d%%", want)
+		if !strings.Contains(lines[i], wantSub) {
+			t.Errorf("line %d = %q, want to contain %q", i, lines[i], wantSub)
+		}
+	}
+}
+
+func TestProgressWriter_DropsExactDuplicateFrame(t *testing.T) {
+	log.Init(log.Config{Verbosity: 2, Format: testLogFormatText})
+	var sink bytes.Buffer
+	remove := log.AddSink(&sink)
+	defer remove()
+
+	var out bytes.Buffer
+	w := newProgressWriter(&out)
+
+	_, _ = w.Write([]byte(
+		"Receiving objects:  10% (34/333)\r" +
+			"Receiving objects:  10% (34/333)\r",
+	))
+	_ = w.Close()
+	_ = log.Sync()
+
+	lines := strings.Split(strings.TrimSpace(sink.String()), "\n")
+	if len(lines) != 1 {
+		t.Fatalf(
+			"got %d progress log lines, want 1 (duplicate dropped): %q",
+			len(lines), sink.String(),
+		)
+	}
+}
+
+func TestProgressWriter_TracksLabelsIndependently(t *testing.T) {
+	log.Init(log.Config{Verbosity: 2, Format: testLogFormatText})
+	var sink bytes.Buffer
+	remove := log.AddSink(&sink)
+	defer remove()
+
+	var out bytes.Buffer
+	w := newProgressWriter(&out)
+
+	_, _ = w.Write([]byte(
+		"Receiving objects:  10% (34/333)\r" +
+			"Resolving deltas:  10% (10/100)\r",
+	))
+	_ = w.Close()
+	_ = log.Sync()
+
+	got := sink.String()
+	lines := strings.Split(strings.TrimSpace(got), "\n")
+	if len(lines) != 2 {
+		t.Fatalf(
+			"got %d progress log lines, want 2 (independent labels): %q",
+			len(lines), got,
+		)
+	}
+	if !strings.Contains(lines[0], "Receiving objects") {
+		t.Errorf("line 0 = %q, want to contain %q", lines[0], "Receiving objects")
+	}
+	if !strings.Contains(lines[1], "Resolving deltas") {
+		t.Errorf("line 1 = %q, want to contain %q", lines[1], "Resolving deltas")
+	}
+}
+
+func TestProgressWriter_PassesThroughNonProgressLines(t *testing.T) {
+	var out bytes.Buffer
+	w := newProgressWriter(&out)
+
+	_, _ = w.Write([]byte(
+		"Cloning into 'repo'...\n" +
+			"remote: Enumerating objects: 333, done.\n",
+	))
+	_ = w.Close()
+
+	got := out.String()
+	if !strings.Contains(got, "Cloning into 'repo'...") ||
+		!strings.Contains(got, "remote: Enumerating objects: 333, done.") {
+		t.Errorf("expected both lines passed through unchanged, got %q", got)
+	}
+}
+
+func TestProgressWriter_FlushesTrailingPartialLineOnClose(t *testing.T) {
+	var out bytes.Buffer
+	w := newProgressWriter(&out)
+
+	_, _ = w.Write([]byte("no trailing newline"))
+	if out.Len() != 0 {
+		t.Errorf("expected nothing forwarded before close, got %q", out.String())
+	}
+	_ = w.Close()
+	if got := strings.TrimRight(out.String(), "\n"); got != "no trailing newline" {
+		t.Errorf("got %q", got)
+	}
+}

pkg/git/repo.go

@@ -262,6 +262,8 @@ func (r *Repo) cloneWith(ctx context.Context, repository string, c cloneConfig)
 	w := log.Writer(log.LevelInfo)
 	defer func() { _ = w.Close() }()
 
+	pw := newProgressWriter(w)
+
 	env := append([]string{}, r.env...)
 	if smudgeSkippedForClone(c.lfsMode) {
 		env = append(env, "GIT_LFS_SKIP_SMUDGE=1")
@@ -270,9 +272,12 @@ func (r *Repo) cloneWith(ctx context.Context, repository string, c cloneConfig)
 	_, err := r.runner.Run(ctx, RunOptions{
 		Env:    env,
 		Args:   c.args(repository, r.path),
-		Stdout: w,
-		Stderr: w,
+		Stdout: pw,
+		Stderr: pw,
 	})
+	if closeErr := pw.Close(); err == nil {
+		err = closeErr
+	}
 	return err
 }