chore(telemetry): track upload phase + per-phase sub-progress

Author: shubham-stepsecurity

internal/detector/nodescan.go

@@ -34,12 +34,23 @@ type NodeScanner struct {
 	exec         executor.Executor
 	log          *progress.Logger
 	loggedInUser string // when non-empty and running as root, commands run as this user
+	// ProgressHook, when non-nil, is invoked from inside ScanProjects /
+	// ScanGlobalPackages with a short human-readable detail string ("project
+	// 12 of 47", "scanning yarn", ...). Telemetry plumbs this into
+	// PhaseTracker.UpdateDetail so heartbeats surface mid-phase progress.
+	ProgressHook func(detail string)
 }
 
 func NewNodeScanner(exec executor.Executor, log *progress.Logger, loggedInUser string) *NodeScanner {
 	return &NodeScanner{exec: exec, log: log, loggedInUser: loggedInUser}
 }
 
+func (s *NodeScanner) emitProgress(detail string) {
+	if s.ProgressHook != nil {
+		s.ProgressHook(detail)
+	}
+}
+
 // shouldRunAsUser returns true when commands should be delegated to the logged-in user.
 // Only applies on Unix — RunAsUser uses sudo which is not available on Windows.
 func (s *NodeScanner) shouldRunAsUser() bool {
@@ -107,16 +118,19 @@ func (s *NodeScanner) checkPath(ctx context.Context, name string) error {
 func (s *NodeScanner) ScanGlobalPackages(ctx context.Context) []model.NodeScanResult {
 	var results []model.NodeScanResult
 
+	s.emitProgress("global: npm")
 	s.log.Progress("  Checking npm global packages...")
 	if r, ok := s.scanNPMGlobal(ctx); ok {
 		results = append(results, r)
 	}
 
+	s.emitProgress("global: yarn")
 	s.log.Progress("  Checking yarn global packages...")
 	if r, ok := s.scanYarnGlobal(ctx); ok {
 		results = append(results, r)
 	}
 
+	s.emitProgress("global: pnpm")
 	s.log.Progress("  Checking pnpm global packages...")
 	if r, ok := s.scanPnpmGlobal(ctx); ok {
 		results = append(results, r)
@@ -288,6 +302,10 @@ func (s *NodeScanner) ScanProjects(ctx context.Context, searchDirs []string) []m
 	var results []model.NodeScanResult
 	totalSize := int64(0)
 
+	totalProjects := len(projects)
+	if totalProjects > maxNodeProjects {
+		totalProjects = maxNodeProjects
+	}
 	for i, p := range projects {
 		if i >= maxNodeProjects {
 			s.log.Progress("  Reached maximum of %d projects, stopping search", maxNodeProjects)
@@ -300,6 +318,11 @@ func (s *NodeScanner) ScanProjects(ctx context.Context, searchDirs []string) []m
 			break
 		}
 
+		// Per-project sub-progress for the heartbeat goroutine. Surfaces
+		// to console as "current_phase_detail: project 12 of 47" so a
+		// stuck scan is visibly so, not just opaque "node_scan in progress".
+		s.emitProgress(fmt.Sprintf("project %d of %d", i+1, totalProjects))
+
 		s.log.Progress("  Found project: %s", p.dir)
 		pm := DetectProjectPM(s.exec, p.dir)
 		s.log.Progress("    Package manager: %s", pm)

internal/detector/pythonscan.go

@@ -15,12 +15,23 @@ import (
 type PythonScanner struct {
 	exec executor.Executor
 	log  *progress.Logger
+	// ProgressHook, when non-nil, is invoked from inside ScanGlobalPackages
+	// with a short human-readable detail string ("scanning pip3", ...).
+	// Telemetry plumbs this into PhaseTracker.UpdateDetail so heartbeats
+	// surface mid-phase progress.
+	ProgressHook func(detail string)
 }
 
 func NewPythonScanner(exec executor.Executor, log *progress.Logger) *PythonScanner {
 	return &PythonScanner{exec: exec, log: log}
 }
 
+func (s *PythonScanner) emitProgress(detail string) {
+	if s.ProgressHook != nil {
+		s.ProgressHook(detail)
+	}
+}
+
 type pythonScanSpec struct {
 	binary     string
 	name       string
@@ -49,6 +60,7 @@ func (s *PythonScanner) ScanGlobalPackages(ctx context.Context) []model.PythonSc
 			continue
 		}
 
+		s.emitProgress("scanning " + spec.name)
 		s.log.Progress("  Checking %s global packages...", spec.name)
 		version := s.getVersion(ctx, spec.binary, spec.versionCmd)
 

internal/telemetry/heartbeat_shutdown_test.go

@@ -0,0 +1,49 @@
+package telemetry
+
+import (
+	"context"
+	"testing"
+	"time"
+)
+
+// TestHeartbeatShutdown_NoDeadlock mirrors the cancel-then-wait pattern
+// Run() uses to shut down its heartbeat goroutine. Two `defer` statements
+// (cancel + wait) would deadlock under LIFO ordering — wait runs first,
+// blocks on the goroutine, and cancel never fires. Combining them into a
+// single deferred function is the fix; this test pins it down.
+func TestHeartbeatShutdown_NoDeadlock(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	done := make(chan struct{})
+
+	go func() {
+		defer close(done)
+		ticker := time.NewTicker(50 * time.Millisecond)
+		defer ticker.Stop()
+		for {
+			select {
+			case <-ctx.Done():
+				return
+			case <-ticker.C:
+				// no-op, mimics postPhase
+			}
+		}
+	}()
+
+	// This is the load-bearing pattern from Run(): cancel first, THEN wait.
+	// If a future refactor splits these into separate `defer` statements at
+	// the top level of Run(), the LIFO ordering will deadlock.
+	shutdownStart := time.Now()
+	func() {
+		defer func() {
+			cancel()
+			<-done
+		}()
+	}()
+	elapsed := time.Since(shutdownStart)
+
+	// 50ms ticker + small scheduler overhead; 1s is generous and signals a
+	// hang clearly if the pattern ever regresses.
+	if elapsed > time.Second {
+		t.Fatalf("heartbeat shutdown took %s — likely deadlocked on defer ordering", elapsed)
+	}
+}

internal/telemetry/phase_tracker.go

@@ -17,6 +17,11 @@ type PhaseCompletion struct {
 // boundary and on every heartbeat tick. The same struct is embedded on the
 // final telemetry Payload so a stored telemetry record is self-describing
 // without joining to the run-status table.
+//
+// In-flight sub-progress (set via PhaseTracker.UpdateDetail) is folded into
+// CurrentPhase as "<phase> (<detail>)" rather than carried in a separate
+// field, so older backends that don't know about phase-detail still surface
+// the string verbatim. Completed phases keep their base name only.
 type RunStatusInfo struct {
 	PhasesCompleted []PhaseCompletion `json:"phases_completed,omitempty"`
 	CurrentPhase    string            `json:"current_phase,omitempty"`
@@ -28,12 +33,13 @@ type RunStatusInfo struct {
 // concurrently — Snapshot returns a defensive copy so the caller never
 // observes a torn slice while a phase is appended.
 type PhaseTracker struct {
-	mu             sync.Mutex
-	startedAt      time.Time
-	phaseStartedAt time.Time
-	currentPhase   string
-	completed      []PhaseCompletion
-	now            func() time.Time // overridable for tests
+	mu                 sync.Mutex
+	startedAt          time.Time
+	phaseStartedAt     time.Time
+	currentPhase       string
+	currentPhaseDetail string
+	completed          []PhaseCompletion
+	now                func() time.Time // overridable for tests
 }
 
 // NewPhaseTracker constructs a tracker anchored at the current time.
@@ -51,7 +57,8 @@ func newPhaseTrackerWithClock(now func() time.Time) *PhaseTracker {
 // Start records the beginning of a new phase. Calling Start while another
 // phase is already in flight implicitly finishes the previous one — this
 // keeps call sites tidy when phases run back-to-back without a Finish in
-// between.
+// between. Detail from the previous phase is cleared so it never leaks
+// into the new one.
 func (t *PhaseTracker) Start(phase string) {
 	t.mu.Lock()
 	defer t.mu.Unlock()
@@ -60,6 +67,7 @@ func (t *PhaseTracker) Start(phase string) {
 		t.finishLocked()
 	}
 	t.currentPhase = phase
+	t.currentPhaseDetail = ""
 	t.phaseStartedAt = t.now()
 }
 
@@ -82,17 +90,42 @@ func (t *PhaseTracker) finishLocked() {
 		DurationMs: finishedAt.Sub(t.phaseStartedAt).Milliseconds(),
 	})
 	t.currentPhase = ""
+	t.currentPhaseDetail = ""
+}
+
+// UpdateDetail sets a free-form sub-progress string for the current
+// phase ("project 12 of 47", "scanning pip3", ...). No-op when no phase
+// is in flight — keeps call sites tidy when a scanner reports progress
+// from inside a goroutine that may outlive its enclosing Start/Finish.
+func (t *PhaseTracker) UpdateDetail(detail string) {
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	if t.currentPhase == "" {
+		return
+	}
+	t.currentPhaseDetail = detail
 }
 
 // Snapshot returns a copy of the tracker state safe for marshalling on
 // another goroutine. The returned slice is independent of the tracker's
 // internal buffer.
+//
+// When the in-flight phase has a detail set, it's folded into CurrentPhase
+// as "<phase> (<detail>)" so the wire format stays flat — older backends
+// without a dedicated detail field still render the progress verbatim.
+// PhasesCompleted entries keep their base name; detail is per-tick state,
+// not a permanent label.
 func (t *PhaseTracker) Snapshot() RunStatusInfo {
 	t.mu.Lock()
 	defer t.mu.Unlock()
 
+	current := t.currentPhase
+	if current != "" && t.currentPhaseDetail != "" {
+		current = current + " (" + t.currentPhaseDetail + ")"
+	}
+
 	out := RunStatusInfo{
-		CurrentPhase: t.currentPhase,
+		CurrentPhase: current,
 		ElapsedMs:    t.now().Sub(t.startedAt).Milliseconds(),
 	}
 	if len(t.completed) > 0 {

internal/telemetry/phase_tracker_test.go

@@ -108,6 +108,74 @@ func TestPhaseTracker_SnapshotIsDefensiveCopy(t *testing.T) {
 	}
 }
 
+func TestPhaseTracker_UpdateDetailFoldsIntoCurrentPhase(t *testing.T) {
+	pt := NewPhaseTracker()
+
+	// Detail before Start is a no-op — keeps callers from leaking stale
+	// per-phase strings into the next phase.
+	pt.UpdateDetail("dropped")
+	if got := pt.Snapshot(); got.CurrentPhase != "" {
+		t.Errorf("detail before Start should be ignored, got %q", got.CurrentPhase)
+	}
+
+	pt.Start("brew_scan")
+	if got := pt.Snapshot(); got.CurrentPhase != "brew_scan" {
+		t.Errorf("no detail yet: current_phase = %q, want %q", got.CurrentPhase, "brew_scan")
+	}
+
+	pt.UpdateDetail("fetching formulae")
+	if got := pt.Snapshot(); got.CurrentPhase != "brew_scan (fetching formulae)" {
+		t.Errorf("with detail: current_phase = %q, want %q",
+			got.CurrentPhase, "brew_scan (fetching formulae)")
+	}
+
+	pt.UpdateDetail("fetching casks")
+	if got := pt.Snapshot(); got.CurrentPhase != "brew_scan (fetching casks)" {
+		t.Errorf("detail should overwrite, got %q", got.CurrentPhase)
+	}
+}
+
+func TestPhaseTracker_StartClearsPreviousDetail(t *testing.T) {
+	pt := NewPhaseTracker()
+
+	pt.Start("a")
+	pt.UpdateDetail("a-detail")
+	pt.Start("b") // implicit finish of a; detail must reset
+	if got := pt.Snapshot(); got.CurrentPhase != "b" {
+		t.Errorf("detail should reset on next phase, got current_phase = %q", got.CurrentPhase)
+	}
+}
+
+func TestPhaseTracker_FinishClearsDetail(t *testing.T) {
+	pt := NewPhaseTracker()
+
+	pt.Start("a")
+	pt.UpdateDetail("in-flight")
+	pt.Finish()
+	if got := pt.Snapshot(); got.CurrentPhase != "" {
+		t.Errorf("detail should clear on Finish, got current_phase = %q", got.CurrentPhase)
+	}
+}
+
+// Completed phases keep their base name only — detail is per-tick state,
+// not a permanent label baked into history.
+func TestPhaseTracker_CompletedPhasesKeepBaseName(t *testing.T) {
+	pt := NewPhaseTracker()
+
+	pt.Start("node_scan")
+	pt.UpdateDetail("project 5 of 10")
+	pt.Finish()
+
+	snap := pt.Snapshot()
+	if len(snap.PhasesCompleted) != 1 {
+		t.Fatalf("phases_completed = %d, want 1", len(snap.PhasesCompleted))
+	}
+	if snap.PhasesCompleted[0].Name != "node_scan" {
+		t.Errorf("completed name = %q, want bare %q without detail",
+			snap.PhasesCompleted[0].Name, "node_scan")
+	}
+}
+
 func TestPhaseTracker_ConcurrentReadDuringWrite(t *testing.T) {
 	// Race detector must report clean. Spawn a writer that flips phases and
 	// a reader (mimicking the heartbeat goroutine) that snapshots repeatedly.

internal/telemetry/progress_hook_test.go

@@ -0,0 +1,33 @@
+package telemetry
+
+import (
+	"testing"
+)
+
+// Verifies the wiring contract telemetry.Run() relies on: a ProgressHook
+// closure that calls tracker.UpdateDetail surfaces the detail through the
+// next Snapshot's CurrentPhase field (folded as "<phase> (<detail>)").
+// Keeps the scanner / tracker integration honest even when the real
+// scanner tests live in package detector.
+func TestProgressHook_PlumbsDetailIntoSnapshot(t *testing.T) {
+	tracker := NewPhaseTracker()
+	tracker.Start("node_scan")
+
+	// Simulate the closure telemetry.Run() installs on NodeScanner.ProgressHook.
+	hook := func(detail string) { tracker.UpdateDetail(detail) }
+
+	hook("project 1 of 47")
+	if got := tracker.Snapshot().CurrentPhase; got != "node_scan (project 1 of 47)" {
+		t.Fatalf("after hook: current_phase = %q, want %q", got, "node_scan (project 1 of 47)")
+	}
+
+	hook("project 47 of 47")
+	if got := tracker.Snapshot().CurrentPhase; got != "node_scan (project 47 of 47)" {
+		t.Fatalf("after second hook call: current_phase = %q", got)
+	}
+
+	tracker.Finish()
+	if got := tracker.Snapshot().CurrentPhase; got != "" {
+		t.Fatalf("after Finish: current_phase = %q, want empty", got)
+	}
+}