local: fix assorted cmd bugs (#4331)

- expose /debug/pprof (this broke during server refactor). Useful for debugging stuck goroutines
- ensure Cmd doesn't assume we're running a server
- ensure ServerCmd doesn't start Cmd while a build command is waiting

integration/local_resource_test.go

@@ -30,7 +30,7 @@ func TestLocalResource(t *testing.T) {
 
 	f.TiltUp()
 
-	const barServeLogMessage = "Running serve cmd: ./hello.sh bar"
+	const barServeLogMessage = "Running cmd: ./hello.sh bar"
 	const readinessProbeSuccessMessage = `[readiness probe: success] fake probe success message`
 
 	require.NoError(t, f.logs.WaitUntilContains("hello! foo #1", 5*time.Second))

internal/controllers/core/cmd/controller.go

@@ -127,6 +127,7 @@ func (c *Controller) reconcile(ctx context.Context, name types.NamespacedName) e
 	}
 
 	proc.spec = cmd.Spec
+	proc.isServer = cmd.ObjectMeta.Annotations[local.AnnotationOwnerKind] == "CmdServer"
 	proc.lastEventTime = lastEventTime
 	ctx, proc.cancelFunc = context.WithCancel(ctx)
 
@@ -295,6 +296,11 @@ func (c *Controller) processStatuses(
 		}
 
 		if sm.status == Error || sm.status == Done {
+			// This is a hack until CmdServer is a real object.
+			if proc.isServer && sm.exitCode == 0 {
+				logger.Get(ctx).Errorf("Server exited with exit code 0")
+			}
+
 			c.updateStatus(name, func(status *CmdStatus) {
 				status.Waiting = nil
 				status.Running = nil
@@ -355,6 +361,7 @@ type currentProcess struct {
 	// closed when the process finishes executing, intentionally or not
 	doneCh      chan struct{}
 	probeWorker *probe.Worker
+	isServer    bool
 
 	// tracks the last RestartOn event
 	lastEventTime time.Time

internal/controllers/core/cmd/controller_test.go

@@ -66,6 +66,38 @@ func TestUpdate(t *testing.T) {
 	f.assertCmdCount(1)
 }
 
+func TestUpdateWithCurrentBuild(t *testing.T) {
+	f := newFixture(t)
+	defer f.teardown()
+
+	t1 := time.Unix(1, 0)
+	f.resource("foo", "true", ".", t1)
+	f.step()
+	f.assertCmdMatches("foo-serve-1", func(cmd *Cmd) bool {
+		return cmd.Status.Running != nil
+	})
+
+	f.st.WithState(func(s *store.EngineState) {
+		c := model.ToHostCmd("false")
+		localTarget := model.NewLocalTarget(model.TargetName("foo"), c, c, nil)
+		s.ManifestTargets["foo"].Manifest.DeployTarget = localTarget
+		s.ManifestTargets["foo"].State.CurrentBuild = model.BuildRecord{StartTime: time.Now()}
+	})
+
+	f.step()
+
+	assert.Never(f.t, func() bool {
+		return f.st.Cmd("foo-serve-2") != nil
+	}, 20*time.Millisecond, 5*time.Millisecond)
+
+	f.st.WithState(func(s *store.EngineState) {
+		s.ManifestTargets["foo"].State.CurrentBuild = model.BuildRecord{}
+	})
+
+	f.step()
+	f.assertCmdDeleted("foo-serve-1")
+}
+
 func TestServe(t *testing.T) {
 	f := newFixture(t)
 	defer f.teardown()
@@ -261,7 +293,7 @@ func (s *testStore) CmdCount() int {
 	defer s.RUnlockState()
 	count := 0
 	for _, cmd := range st.Cmds {
-		if cmd.DeletionTimestamp != nil {
+		if cmd.DeletionTimestamp == nil {
 			count++
 		}
 	}
@@ -383,11 +415,17 @@ func (f *fixture) resourceFromTarget(name string, target model.TargetSpec, lastD
 
 	st := f.st.LockMutableStateForTesting()
 	defer f.st.UnlockMutableState()
+
+	state := &store.ManifestState{
+		LastSuccessfulDeployTime: lastDeploy,
+	}
+	state.AddCompletedBuild(model.BuildRecord{
+		StartTime:  lastDeploy,
+		FinishTime: lastDeploy,
+	})
 	st.UpsertManifestTarget(&store.ManifestTarget{
 		Manifest: m,
-		State: &store.ManifestState{
-			LastSuccessfulDeployTime: lastDeploy,
-		},
+		State:    state,
 	})
 }
 

internal/controllers/core/cmd/execer.go

@@ -144,7 +144,7 @@ func (e *processExecer) Start(ctx context.Context, cmd model.Cmd, w io.Writer, s
 func (e *processExecer) processRun(ctx context.Context, cmd model.Cmd, w io.Writer, statusCh chan statusAndMetadata, spanID model.LogSpanID) {
 	defer close(statusCh)
 
-	logger.Get(ctx).Infof("Running serve cmd: %s", cmd.String())
+	logger.Get(ctx).Infof("Running cmd: %s", cmd.String())
 	c := localexec.ExecCmd(cmd, logger.Get(ctx))
 
 	c.SysProcAttr = &syscall.SysProcAttr{}
@@ -178,18 +178,21 @@ func (e *processExecer) processRun(ctx context.Context, cmd model.Cmd, w io.Writ
 	case err := <-processExitCh:
 		exitCode := 0
 		reason := ""
+		status := Done
 		if err == nil {
-			logger.Get(ctx).Errorf("%s exited with exit code 0", cmd.String())
+			// Use defaults
 		} else if ee, ok := err.(*exec.ExitError); ok {
+			status = Error
 			exitCode = ee.ExitCode()
 			reason = err.Error()
 			logger.Get(ctx).Errorf("%s exited with exit code %d", cmd.String(), ee.ExitCode())
 		} else {
+			status = Error
 			exitCode = 1
 			reason = err.Error()
 			logger.Get(ctx).Errorf("error execing %s: %v", cmd.String(), err)
 		}
-		statusCh <- statusAndMetadata{status: Error, pid: pid, spanID: spanID, exitCode: exitCode, reason: reason}
+		statusCh <- statusAndMetadata{status: status, pid: pid, spanID: spanID, exitCode: exitCode, reason: reason}
 	case <-ctx.Done():
 		e.killProcess(ctx, c, processExitCh)
 		statusCh <- statusAndMetadata{status: Done, pid: pid, spanID: spanID, reason: "killed", exitCode: 137}

internal/controllers/core/cmd/execer_test.go

@@ -248,8 +248,7 @@ func (f *processExecFixture) start(cmd string) {
 }
 
 func (f *processExecFixture) assertCmdSucceeds() {
-	f.waitForStatus(Error)
-	f.assertLogContains("exited with exit code 0")
+	f.waitForStatus(Done)
 }
 
 func (f *processExecFixture) waitForStatus(expectedStatus status) {

internal/engine/local/reducers.go

@@ -3,8 +3,6 @@ package local
 import (
 	"time"
 
-	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
-
 	"github.com/tilt-dev/tilt/internal/store"
 	"github.com/tilt-dev/tilt/pkg/apis/core/v1alpha1"
 	"github.com/tilt-dev/tilt/pkg/model"
@@ -97,13 +95,5 @@ func HandleCmdCreateAction(state *store.EngineState, action CmdCreateAction) {
 
 // Mark the command for deletion.
 func HandleCmdDeleteAction(state *store.EngineState, action CmdDeleteAction) {
-	cmd, ok := state.Cmds[action.Name]
-	if !ok {
-		return
-	}
-
-	updated := cmd.DeepCopy()
-	now := metav1.Now()
-	updated.ObjectMeta.DeletionTimestamp = &now
-	state.Cmds[action.Name] = updated
+	delete(state.Cmds, action.Name)
 }

internal/engine/local/servercontroller.go

@@ -12,12 +12,16 @@ import (
 
 	"github.com/tilt-dev/tilt/internal/store"
 	"github.com/tilt-dev/tilt/pkg/apis/core/v1alpha1"
+	"github.com/tilt-dev/tilt/pkg/model"
 	"github.com/tilt-dev/tilt/pkg/model/logstore"
 )
 
 const AnnotationOwnerName = "tilt.dev/owner-name"
 const AnnotationOwnerKind = "tilt.dev/owner-kind"
 
+// Expresses the status of a build dependency.
+const AnnotationDepStatus = "tilt.dev/dep-status"
+
 // A controller that reads the Tilt data model and creates new Cmd objects.
 //
 // Reads the Cmd Status.
@@ -30,7 +34,7 @@ const AnnotationOwnerKind = "tilt.dev/owner-kind"
 // - We report the Cmd status Terminated as an Error state,
 //   and report it in a standard way.
 type ServerController struct {
-	createdCmds        map[string]*Cmd
+	recentlyCreatedCmd map[string]bool
 	createdTriggerTime map[string]time.Time
 	deletingCmds       map[string]bool
 	client             ctrlclient.Client
@@ -42,7 +46,7 @@ var _ store.Subscriber = &ServerController{}
 
 func NewServerController(client ctrlclient.Client) *ServerController {
 	return &ServerController{
-		createdCmds:        make(map[string]*Cmd),
+		recentlyCreatedCmd: make(map[string]bool),
 		createdTriggerTime: make(map[string]time.Time),
 		deletingCmds:       make(map[string]bool),
 		client:             client,
@@ -54,13 +58,14 @@ func (c *ServerController) OnChange(ctx context.Context, st store.RStore, summar
 		return
 	}
 
-	servers := c.determineServers(ctx, st)
-	for _, server := range servers {
-		c.reconcile(ctx, server, st)
+	servers, owned := c.determineServers(ctx, st)
+	for i, server := range servers {
+		c.reconcile(ctx, server, owned[i], st)
 	}
 }
 
-func (c *ServerController) determineServers(ctx context.Context, st store.RStore) []CmdServer {
+// Returns a list of server objects and the Cmd they own (if any).
+func (c *ServerController) determineServers(ctx context.Context, st store.RStore) ([]CmdServer, []*Cmd) {
 	state := st.RLockState()
 	defer st.RUnlockState()
 
@@ -79,22 +84,25 @@ func (c *ServerController) determineServers(ctx context.Context, st store.RStore
 	}
 
 	var r []CmdServer
+	var cmds []*Cmd
 
 	// Infer all the CmdServer objects from the legacy EngineState
 	for _, mt := range state.Targets() {
 		if !mt.Manifest.IsLocal() {
 			continue
 		}
 		lt := mt.Manifest.LocalTarget()
-		if lt.ServeCmd.Empty() ||
-			mt.State.LastSuccessfulDeployTime.IsZero() {
+		if lt.ServeCmd.Empty() {
 			continue
 		}
 
 		name := mt.Manifest.Name.String()
 		cmdServer := CmdServer{
 			ObjectMeta: ObjectMeta{
 				Name: name,
+				Annotations: map[string]string{
+					AnnotationDepStatus: string(mt.UpdateStatus()),
+				},
 			},
 			Spec: CmdServerSpec{
 				Args:           lt.ServeCmd.Argv,
@@ -114,40 +122,50 @@ func (c *ServerController) determineServers(ctx context.Context, st store.RStore
 		}
 
 		r = append(r, cmdServer)
+		cmds = append(cmds, cmd)
 	}
 
-	return r
+	return r, cmds
 }
 
-func (c *ServerController) reconcile(ctx context.Context, server CmdServer, st store.RStore) {
+func (c *ServerController) reconcile(ctx context.Context, server CmdServer, owned *Cmd, st store.RStore) {
+	// Do not make any changes to the server while the update status is building.
+	// This ensures the old server stays up while any deps are building.
+	depStatus := model.UpdateStatus(server.ObjectMeta.Annotations[AnnotationDepStatus])
+	if depStatus != model.UpdateStatusOK && depStatus != model.UpdateStatusNotApplicable {
+		return
+	}
+
+	// If the command was created recently but hasn't appeared yet, wait until it appears.
+	name := server.Name
+	if c.recentlyCreatedCmd[name] {
+		if owned == nil {
+			return
+		}
+		delete(c.recentlyCreatedCmd, name)
+	}
+
 	cmdSpec := CmdSpec{
 		Args:           server.Spec.Args,
 		Dir:            server.Spec.Dir,
 		Env:            server.Spec.Env,
 		ReadinessProbe: server.Spec.ReadinessProbe,
 	}
 
-	name := server.Name
-	created, isCreated := c.createdCmds[name]
 	triggerTime := c.createdTriggerTime[name]
-	if isCreated && equality.Semantic.DeepEqual(created.Spec, cmdSpec) && triggerTime.Equal(server.Spec.TriggerTime) {
+	if owned != nil && equality.Semantic.DeepEqual(owned.Spec, cmdSpec) && triggerTime.Equal(server.Spec.TriggerTime) {
 		// We're in the correct state! Nothing to do.
 		return
 	}
 
 	// Otherwise, we need to create a new command.
 
-	// If the command hasn't appeared yet, wait until it appears.
-	if isCreated && server.Status.CmdName == "" {
-		return // wait for the command to appear
-	}
-
 	// If the command is running, wait until it's deleted
-	if isCreated && server.Status.CmdStatus.Terminated == nil {
+	if owned != nil && owned.Status.Terminated == nil {
 		if !c.deletingCmds[name] {
 			c.deletingCmds[name] = true
 
-			err := c.client.Delete(ctx, created)
+			err := c.client.Delete(ctx, owned)
 			if err != nil && !apierrors.IsNotFound(err) {
 				st.Dispatch(store.NewErrorAction(fmt.Errorf("syncing to apiserver: %v", err)))
 				return
@@ -181,7 +199,7 @@ func (c *ServerController) reconcile(ctx context.Context, server CmdServer, st s
 		},
 		Spec: cmdSpec,
 	}
-	c.createdCmds[name] = cmd
+	c.recentlyCreatedCmd[name] = true
 
 	err := c.client.Create(ctx, cmd)
 	if err != nil && !apierrors.IsNotFound(err) {

internal/hud/server/controller.go

@@ -102,6 +102,7 @@ func (s *HeadsUpServerController) setUpHelper(ctx context.Context, st store.RSto
 	r.PathPrefix("/readyz").Handler(apiserverHandler)
 	r.PathPrefix("/swagger").Handler(apiserverHandler)
 	r.PathPrefix("/version").Handler(apiserverHandler)
+	r.PathPrefix("/debug").Handler(http.DefaultServeMux) // for /debug/pprof
 	r.PathPrefix("/").Handler(s.hudServer.Router())
 
 	s.apiServer = &http.Server{