analyze: address review comments and add tests

Addresses F1bonacc1's review on #462:

- app/process.go: in handleOutput() replace the direct Health/ReadyTime
  mutation with a call to setProcHealth(Ready) so the update runs under
  stateMtx, fixing the data race flagged in the review.

- cmd/analyze.go: remove the Run function; Cobra auto-prints help when
  a parent command with no Run is invoked without a subcommand.

- cmd/analyze_critical_chain.go:
  * extract `unreadySortOrder = time.Duration(math.MaxInt64)` and use it
    consistently in readyOffsetForSort.
  * when a positional argument names a process that is not part of the
    dependency graph but is still known to the project (isolated
    process), synthesize a DependencyNode so its timings are still
    rendered, instead of erroring out.
  * replace the manual string-join loop in formatNodeLine with
    strings.Join.
  * small refactor: renderCriticalChain(w io.Writer, ...) and
    sortRootsByReadyTime(...) are now factored out so they can be
    unit-tested without a running server.

New tests:

- cmd/analyze_critical_chain_test.go covers formatDuration,
  formatOffset, readyOffsetForSort (including the unreadySortOrder
  sentinel), formatNodeLine for all branches (nil state, ready with/
  without readiness gap, not-ready, not-started, status annotations),
  sibling ordering, and a full renderCriticalChain tree walk.
- app/process_timing_test.go covers setProcHealth -- asserts that
  ProcessReadyTime is set on the first Ready transition, is not
  overwritten on subsequent Ready calls, is not set for NotReady, and
  a concurrent-Ready test that is intended to be exercised under the
  race detector.

Verified locally:
- `go build ./...`
- `go vet ./...`
- `go test ./...` (all packages pass)
- `go test -race ./...` (equivalent to `make testrace`, all pass)
- `golangci-lint run -c .golangci.yaml` (0 issues)

Author: ryantm

src/app/process.go

@@ -747,11 +747,9 @@ func (p *Process) handleOutput(pipe io.ReadCloser, output string, handler func(m
 			break
 		}
 		if p.procConf.ReadyLogLine != "" && p.procState.Health == types.ProcessHealthUnknown && strings.Contains(line, p.procConf.ReadyLogLine) {
-			p.procState.Health = types.ProcessHealthReady
-			if p.procState.ProcessReadyTime == nil {
-				now := time.Now()
-				p.procState.ProcessReadyTime = &now
-			}
+			// setProcHealth takes stateMtx, updates Health and (for Ready)
+			// records ProcessReadyTime atomically.
+			p.setProcHealth(types.ProcessHealthReady)
 			p.cancelReadyLogFunc(nil)
 		}
 		p.checkElevatedProcOutput(line)

src/app/process_timing_test.go

@@ -0,0 +1,81 @@
+package app
+
+import (
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/f1bonacc1/process-compose/src/types"
+)
+
+// newBareProcessForTimingTests builds the minimum Process needed to exercise
+// the timing-tracking paths (setProcHealth, onProcessEnd bookkeeping) in
+// isolation -- i.e. without actually spawning a child or starting probes.
+func newBareProcessForTimingTests() *Process {
+	return &Process{
+		procConf:  &types.ProcessConfig{Name: "p", ReplicaName: "p"},
+		procState: &types.ProcessState{},
+	}
+}
+
+func TestSetProcHealth_SetsReadyTimeOnce(t *testing.T) {
+	p := newBareProcessForTimingTests()
+
+	before := time.Now()
+	p.setProcHealth(types.ProcessHealthReady)
+	after := time.Now()
+
+	if p.procState.Health != types.ProcessHealthReady {
+		t.Fatalf("Health = %q, want %q", p.procState.Health, types.ProcessHealthReady)
+	}
+	if p.procState.ProcessReadyTime == nil {
+		t.Fatal("ProcessReadyTime was not set")
+	}
+	got := *p.procState.ProcessReadyTime
+	if got.Before(before) || got.After(after) {
+		t.Errorf("ProcessReadyTime = %v, want between %v and %v", got, before, after)
+	}
+
+	// Calling setProcHealth(Ready) again must not overwrite the first timestamp.
+	first := *p.procState.ProcessReadyTime
+	time.Sleep(2 * time.Millisecond)
+	p.setProcHealth(types.ProcessHealthReady)
+	if !p.procState.ProcessReadyTime.Equal(first) {
+		t.Errorf("ProcessReadyTime changed on second Ready call: first=%v second=%v",
+			first, *p.procState.ProcessReadyTime)
+	}
+}
+
+func TestSetProcHealth_NotReadyDoesNotSetTime(t *testing.T) {
+	p := newBareProcessForTimingTests()
+	p.setProcHealth(types.ProcessHealthNotReady)
+	if p.procState.ProcessReadyTime != nil {
+		t.Errorf("ProcessReadyTime unexpectedly set for NotReady: %v",
+			*p.procState.ProcessReadyTime)
+	}
+}
+
+// TestSetProcHealth_ConcurrentReadyNoRace exercises the mutex protection the
+// maintainer asked for. Running under `go test -race` / `make testrace` should
+// flag any unsynchronised access to procState.
+func TestSetProcHealth_ConcurrentReadyNoRace(t *testing.T) {
+	p := newBareProcessForTimingTests()
+
+	const workers = 32
+	var wg sync.WaitGroup
+	wg.Add(workers)
+	for i := 0; i < workers; i++ {
+		go func() {
+			defer wg.Done()
+			p.setProcHealth(types.ProcessHealthReady)
+		}()
+	}
+	wg.Wait()
+
+	if p.procState.ProcessReadyTime == nil {
+		t.Fatal("ProcessReadyTime not set after concurrent Ready calls")
+	}
+	if p.procState.Health != types.ProcessHealthReady {
+		t.Errorf("Health = %q, want Ready", p.procState.Health)
+	}
+}

src/cmd/analyze.go

@@ -1,12 +1,12 @@
 package cmd
 
 import (
-	"os"
-
 	"github.com/spf13/cobra"
 )
 
-// analyzeCmd represents the analyze command group.
+// analyzeCmd represents the analyze command group. It has no Run of its own;
+// Cobra auto-prints help when a parent command with no Run is invoked without
+// a subcommand.
 var analyzeCmd = &cobra.Command{
 	Use:   "analyze",
 	Short: "Analyze startup timing and dependency information",
@@ -16,12 +16,6 @@ through the dependency graph.
 
 Available subcommands:
   critical-chain    Print the dependency chains ordered by startup time.`,
-	Run: func(cmd *cobra.Command, args []string) {
-		if len(args) == 0 {
-			_ = cmd.Help()
-			os.Exit(0)
-		}
-	},
 }
 
 func init() {

src/cmd/analyze_critical_chain.go

@@ -2,15 +2,24 @@ package cmd
 
 import (
 	"fmt"
+	"io"
+	"math"
 	"os"
 	"sort"
+	"strings"
 	"time"
 
 	"github.com/f1bonacc1/process-compose/src/types"
 	"github.com/fatih/color"
 	"github.com/spf13/cobra"
 )
 
+// unreadySortOrder is the sort-key returned for processes that never became
+// ready (or have no recorded state). Using the maximum duration means these
+// processes float to the top of the critical-chain listing, mirroring
+// systemd-analyze which puts the slowest/stuck paths first.
+const unreadySortOrder = time.Duration(math.MaxInt64)
+
 var analyzeCriticalChainCmd = &cobra.Command{
 	Use:   "critical-chain [process...]",
 	Short: "Print the critical process startup chain",
@@ -71,8 +80,16 @@ func runAnalyzeCriticalChain(cmd *cobra.Command, args []string) {
 		for _, name := range args {
 			node, ok := graph.AllNodes[name]
 			if !ok {
-				fmt.Fprintf(os.Stderr, "unknown process (or process has no dependencies): %s\n", name)
-				os.Exit(1)
+				// The graph only contains processes that participate in a
+				// dependency edge. If the name refers to an isolated process
+				// that is still known to the project, synthesize a bare node
+				// so its timings are still rendered.
+				if _, exists := stateByName[name]; exists {
+					node = &types.DependencyNode{Name: name}
+				} else {
+					fmt.Fprintf(os.Stderr, "unknown process: %s\n", name)
+					os.Exit(1)
+				}
 			}
 			roots = append(roots, node)
 		}
@@ -95,48 +112,70 @@ func runAnalyzeCriticalChain(cmd *cobra.Command, args []string) {
 		}
 	}
 
-	sort.Slice(roots, func(i, j int) bool {
-		ai := readyOffsetForSort(stateByName[roots[i].Name], projectState.StartTime)
-		aj := readyOffsetForSort(stateByName[roots[j].Name], projectState.StartTime)
-		if ai == aj {
-			return roots[i].Name < roots[j].Name
-		}
-		return ai > aj
-	})
+	renderCriticalChain(os.Stdout, projectState, roots, stateByName)
+}
 
-	// Header
+// renderCriticalChain writes the critical-chain report for the given roots to
+// w. Split out from runAnalyzeCriticalChain so it can be unit-tested without a
+// running server.
+func renderCriticalChain(
+	w io.Writer,
+	projectState *types.ProjectState,
+	roots []*types.DependencyNode,
+	stateByName map[string]*types.ProcessState,
+) {
 	green := color.New(color.FgGreen).SprintFunc()
-	fmt.Println("The time when unit became ready is printed after the \"@\" character.")
-	fmt.Println("The time the unit took to become ready is printed after the \"+\" character.")
-	fmt.Println()
-	fmt.Printf("%s: %s\n", green("Project"), projectState.ProjectName)
-	fmt.Printf("%s: %s\n", green("Started"), projectState.StartTime.Format(time.RFC3339))
-	fmt.Printf("%s: %s\n", green("Up time"), projectState.UpTime.Round(time.Millisecond))
-	fmt.Println()
+	fmt.Fprintln(w, "The time when unit became ready is printed after the \"@\" character.")
+	fmt.Fprintln(w, "The time the unit took to become ready is printed after the \"+\" character.")
+	fmt.Fprintln(w)
+	fmt.Fprintf(w, "%s: %s\n", green("Project"), projectState.ProjectName)
+	fmt.Fprintf(w, "%s: %s\n", green("Started"), projectState.StartTime.Format(time.RFC3339))
+	fmt.Fprintf(w, "%s: %s\n", green("Up time"), projectState.UpTime.Round(time.Millisecond))
+	fmt.Fprintln(w)
+
+	sortRootsByReadyTime(roots, stateByName, projectState.StartTime)
 
 	for i, root := range roots {
 		last := i == len(roots)-1
-		printCriticalChain(root, stateByName, projectState.StartTime, "", true, last)
+		printCriticalChain(w, root, stateByName, projectState.StartTime, "", true, last)
 	}
 }
 
+// sortRootsByReadyTime sorts nodes in-place by descending ready-time (slowest
+// first); ties are broken by ascending name.
+func sortRootsByReadyTime(
+	nodes []*types.DependencyNode,
+	stateByName map[string]*types.ProcessState,
+	projectStart time.Time,
+) {
+	sort.Slice(nodes, func(i, j int) bool {
+		ai := readyOffsetForSort(stateByName[nodes[i].Name], projectStart)
+		aj := readyOffsetForSort(stateByName[nodes[j].Name], projectStart)
+		if ai == aj {
+			return nodes[i].Name < nodes[j].Name
+		}
+		return ai > aj
+	})
+}
+
 // readyOffsetForSort returns the duration from project start until the process
-// became ready. Processes that never became ready sort to the top (return
-// max duration) so the "slowest" chain is printed first.
+// became ready. Processes that never became ready return unreadySortOrder so
+// the "slowest" / stuck chain is printed first.
 func readyOffsetForSort(s *types.ProcessState, projectStart time.Time) time.Duration {
 	if s == nil {
-		return time.Duration(1<<62 - 1)
+		return unreadySortOrder
 	}
 	if s.ProcessReadyTime != nil {
 		return s.ProcessReadyTime.Sub(projectStart)
 	}
 	if s.ProcessStartTime != nil {
 		return s.ProcessStartTime.Sub(projectStart)
 	}
-	return time.Duration(1<<62 - 1)
+	return unreadySortOrder
 }
 
 func printCriticalChain(
+	w io.Writer,
 	node *types.DependencyNode,
 	stateByName map[string]*types.ProcessState,
 	projectStart time.Time,
@@ -158,7 +197,7 @@ func printCriticalChain(
 	}
 
 	line := formatNodeLine(node, stateByName[node.Name], projectStart)
-	fmt.Printf("%s%s%s\n", prefix, branch, line)
+	fmt.Fprintf(w, "%s%s%s\n", prefix, branch, line)
 
 	// Sort dependencies by when they became ready (latest first), mirroring
 	// systemd-analyze critical-chain.
@@ -168,17 +207,10 @@ func printCriticalChain(
 			deps = append(deps, link.DependencyNode)
 		}
 	}
-	sort.Slice(deps, func(i, j int) bool {
-		ai := readyOffsetForSort(stateByName[deps[i].Name], projectStart)
-		aj := readyOffsetForSort(stateByName[deps[j].Name], projectStart)
-		if ai == aj {
-			return deps[i].Name < deps[j].Name
-		}
-		return ai > aj
-	})
+	sortRootsByReadyTime(deps, stateByName, projectStart)
 
 	for i, dep := range deps {
-		printCriticalChain(dep, stateByName, projectStart, nextPrefix, false, i == len(deps)-1)
+		printCriticalChain(w, dep, stateByName, projectStart, nextPrefix, false, i == len(deps)-1)
 	}
 }
 
@@ -233,15 +265,7 @@ func formatNodeLine(
 		}
 	}
 
-	// Join with spaces.
-	out := ""
-	for i, p := range parts {
-		if i > 0 {
-			out += " "
-		}
-		out += p
-	}
-	return out
+	return strings.Join(parts, " ")
 }
 
 // formatOffset formats a duration representing "time since project start".