engine: log more readiness probe results (#4183)

When setting up readiness probes, it can be tricky to get them
tuned + passing correctly. Since probe results were only logged
on a status change, and (to mirror K8s) probes start off in the
failing state, there was no way to get any feedback on a
misconfigured probe.

To balance, now _every_ non-success result is logged (assuming it
has output). Successful results are _only_ logged if they're the
result of a status change; otherwise, you would reasonably expect
a chunk of output in the log every ~10 secs that would make verbose
mode pretty much unusable.

This also exposes probe errors, which were previously invisible
within Tilt.

go.mod

@@ -67,7 +67,7 @@ require (
 	github.com/tilt-dev/fsnotify v1.4.8-0.20200727200623-991e307aab7f
 	github.com/tilt-dev/go-get v0.0.0-20200911222649-1acd29546527
 	github.com/tilt-dev/localregistry-go v0.0.0-20200615231835-07e386f4ebd7
-	github.com/tilt-dev/probe v0.1.0
+	github.com/tilt-dev/probe v0.2.0
 	github.com/tilt-dev/wmclient v0.0.0-20201109174454-1839d0355fbc
 	github.com/tonistiigi/units v0.0.0-20180711220420-6950e57a87ea
 	github.com/whilp/git-urls v0.0.0-20160530060445-31bac0d230fa

go.sum

@@ -1159,6 +1159,8 @@ github.com/tilt-dev/opencensus-go v0.22.5-0.20200904175236-275b1754f353 h1:lxM1v
 github.com/tilt-dev/opencensus-go v0.22.5-0.20200904175236-275b1754f353/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
 github.com/tilt-dev/probe v0.1.0 h1:mEQhtV/M1VjV/sY2TZ89FVE3u+rFSWV9gtT8KzHAn54=
 github.com/tilt-dev/probe v0.1.0/go.mod h1:N4FSqESyYQuc9GwIaIoHS5cIUDznIUwDkG6y4kQVXQY=
+github.com/tilt-dev/probe v0.2.0 h1:2kLs+xNjv6OYoR7OLCQELV6+/Ce0gqOC856qKfN/TB4=
+github.com/tilt-dev/probe v0.2.0/go.mod h1:N4FSqESyYQuc9GwIaIoHS5cIUDznIUwDkG6y4kQVXQY=
 github.com/tilt-dev/wmclient v0.0.0-20201109174454-1839d0355fbc h1:wGkAoZhrvnmq93B4W2v+agiPl7xzqUaxXkxmKrwJ6bc=
 github.com/tilt-dev/wmclient v0.0.0-20201109174454-1839d0355fbc/go.mod h1:n01fG3LbImzxBP3GGCTHkgXuPeJusWg6xv0QYGm9HtE=
 github.com/timakin/bodyclose v0.0.0-20190930140734-f7f2e9bca95e/go.mod h1:Qimiffbc6q9tBWlVV6x0P9sat/ao1xEkREYPPj9hphk=

integration/local_resource_test.go

@@ -28,7 +28,7 @@ func TestLocalResource(t *testing.T) {
 	f.TiltWatch()
 
 	const barServeLogMessage = "Running serve cmd: ./hello.sh bar"
-	const readinessProbeSuccessMessage = `[readiness probe] fake probe success message`
+	const readinessProbeSuccessMessage = `[readiness probe: success] fake probe success message`
 
 	require.NoError(t, f.logs.WaitUntilContains("hello! foo #1", 5*time.Second))
 
@@ -44,7 +44,7 @@ func TestLocalResource(t *testing.T) {
 	require.NoError(t, f.logs.WaitUntilContains("hello! bar #1", 5*time.Second))
 
 	require.NoError(t, os.Remove(f.testDirPath("probe-success")))
-	require.NoError(t, f.logs.WaitUntilContains(`[readiness probe] fake probe failure message`, 5*time.Second))
+	require.NoError(t, f.logs.WaitUntilContains(`[readiness probe: failure] fake probe failure message`, 5*time.Second))
 
 	// send a SIGTERM and make sure Tilt propagates it to its local_resource processes
 	require.NoError(t, f.activeTiltUp.process.Signal(syscall.SIGTERM))

internal/engine/local/controller.go

@@ -117,14 +117,12 @@ func (c *Controller) stop(name model.ManifestName) {
 	proc := c.procs[name]
 	// change the process's current number so that any further events received by the existing process will be considered out of date
 	proc.incrProcNum()
-	if proc.probeWorker != nil {
-		proc.probeWorker.Stop()
-	}
 	if proc.cancelFunc == nil {
 		return
 	}
 	proc.cancelFunc()
 	<-proc.doneCh
+	proc.probeWorker = nil
 	proc.cancelFunc = nil
 	proc.doneCh = nil
 }
@@ -163,11 +161,13 @@ func (c *Controller) start(ctx context.Context, spec ServeSpec, st store.RStore)
 
 	spanID := SpanIDForServeLog(proc.procNum)
 	if spec.ReadinessProbe != nil {
-		statusChangeFunc := processReadinessProbeUpdate(ctx, st, spec.ManifestName, proc.stillHasSameProcNum())
+		statusChangeFunc := processReadinessProbeStatusChange(ctx, st, spec.ManifestName, proc.stillHasSameProcNum())
+		resultLoggerFunc := processReadinessProbeResultLogger(ctx, proc.stillHasSameProcNum())
 		probeWorker, err := probeWorkerFromSpec(
 			c.proberManager,
 			spec.ReadinessProbe,
-			statusChangeFunc)
+			statusChangeFunc,
+			resultLoggerFunc)
 		if err != nil {
 			logger.Get(ctx).Errorf("Invalid readiness probe: %v", err)
 			st.Dispatch(LocalServeStatusAction{
@@ -185,28 +185,17 @@ func (c *Controller) start(ctx context.Context, spec ServeSpec, st store.RStore)
 	proc.doneCh = c.execer.Start(ctx, spec.ServeCmd, logger.Get(ctx).Writer(logger.InfoLvl), statusCh, spanID)
 }
 
-func processReadinessProbeUpdate(
-	ctx context.Context,
-	st store.RStore,
-	manifestName model.ManifestName,
-	stillHasSameProcNum func() bool) probe.StatusChangedFunc {
+func processReadinessProbeStatusChange(ctx context.Context, st store.RStore, manifestName model.ManifestName, stillHasSameProcNum func() bool) probe.StatusChangedFunc {
 	return func(status prober.Result, output string) {
 		if !stillHasSameProcNum() {
 			return
 		}
-		if output != "" {
-			w := logger.Get(ctx).Writer(logger.VerboseLvl)
-
-			var logMessage strings.Builder
-			s := bufio.NewScanner(strings.NewReader(output))
-			for s.Scan() {
-				logMessage.WriteString("[readiness probe] ")
-				logMessage.WriteString(s.Text())
-				logMessage.WriteRune('\n')
-			}
 
-			_, _ = io.WriteString(w, logMessage.String())
+		if status == prober.Success {
+			// successful probes are ONLY logged on status change to reduce chattiness
+			logProbeOutput(ctx, status, output, nil)
 		}
+
 		ready := status == prober.Success || status == prober.Warning
 		st.Dispatch(LocalServeReadinessProbeAction{
 			ManifestName: manifestName,
@@ -215,6 +204,42 @@ func processReadinessProbeUpdate(
 	}
 }
 
+func logProbeOutput(ctx context.Context, result prober.Result, output string, err error) {
+	l := logger.Get(ctx)
+	if !l.Level().ShouldDisplay(logger.VerboseLvl) {
+		return
+	}
+
+	if err != nil {
+		l.Verbosef("[readiness probe error] %v", err)
+	} else if output != "" {
+		w := l.Writer(logger.VerboseLvl)
+		var logMessage strings.Builder
+		s := bufio.NewScanner(strings.NewReader(output))
+		for s.Scan() {
+			logMessage.WriteString("[readiness probe: ")
+			logMessage.WriteString(string(result))
+			logMessage.WriteString("] ")
+			logMessage.Write(s.Bytes())
+			logMessage.WriteRune('\n')
+		}
+		_, _ = io.WriteString(w, logMessage.String())
+	}
+}
+
+func processReadinessProbeResultLogger(ctx context.Context, stillHasSameProcNum func() bool) probe.ResultFunc {
+	return func(result prober.Result, output string, err error) {
+		if !stillHasSameProcNum() {
+			return
+		}
+
+		// successful probes are ONLY logged on status change to reduce chattiness
+		if result != prober.Success {
+			logProbeOutput(ctx, result, output, err)
+		}
+	}
+}
+
 func processStatuses(
 	ctx context.Context,
 	statusCh chan statusAndMetadata,

internal/engine/local/controller_test.go

@@ -91,6 +91,7 @@ func TestServeReadinessProbe(t *testing.T) {
 		}
 		return true
 	})
+	f.assertLogMessage("foo", "[readiness probe: success] fake probe succeeded")
 
 	assert.Equal(t, "sleep", f.fpm.execName)
 	assert.Equal(t, []string{"15"}, f.fpm.execArgs)
@@ -181,7 +182,7 @@ type fixture struct {
 func newFixture(t *testing.T) *fixture {
 	ctx, cancel := context.WithCancel(context.Background())
 	out := bufsync.NewThreadSafeBuffer()
-	l := logger.NewLogger(logger.DebugLvl, out)
+	l := logger.NewLogger(logger.VerboseLvl, out)
 	ctx = logger.WithLogger(ctx, l)
 
 	fe := NewFakeExecer()

internal/engine/local/probe.go

@@ -28,7 +28,7 @@ type ProberManager interface {
 	Exec(name string, args ...string) prober.ProberFunc
 }
 
-func probeWorkerFromSpec(manager ProberManager, probeSpec *v1.Probe, changedFunc probe.StatusChangedFunc) (*probe.Worker, error) {
+func probeWorkerFromSpec(manager ProberManager, probeSpec *v1.Probe, changedFunc probe.StatusChangedFunc, resultFunc probe.ResultFunc) (*probe.Worker, error) {
 	probeFunc, err := proberFromSpec(manager, probeSpec)
 	if err != nil {
 		return nil, err
@@ -52,7 +52,12 @@ func probeWorkerFromSpec(manager ProberManager, probeSpec *v1.Probe, changedFunc
 		opts = append(opts, probe.WorkerFailureThreshold(int(probeSpec.FailureThreshold)))
 	}
 
-	opts = append(opts, probe.WorkerOnStatusChange(changedFunc))
+	if changedFunc != nil {
+		opts = append(opts, probe.WorkerOnStatusChange(changedFunc))
+	}
+	if resultFunc != nil {
+		opts = append(opts, probe.WorkerOnProbeResult(resultFunc))
+	}
 
 	w := probe.NewWorker(probeFunc, opts...)
 	return w, nil

internal/engine/local/probe_fake.go

@@ -52,5 +52,5 @@ func (m *FakeProberManager) ProbeCount() int {
 }
 
 func successProbe(_ context.Context) (prober.Result, string, error) {
-	return prober.Success, "", nil
+	return prober.Success, "fake probe succeeded!", nil
 }

vendor/modules.txt

@@ -492,7 +492,7 @@ github.com/tilt-dev/go-get/internal/web
 # github.com/tilt-dev/localregistry-go v0.0.0-20200615231835-07e386f4ebd7
 ## explicit
 github.com/tilt-dev/localregistry-go
-# github.com/tilt-dev/probe v0.1.0
+# github.com/tilt-dev/probe v0.2.0
 ## explicit
 github.com/tilt-dev/probe/pkg/probe
 github.com/tilt-dev/probe/pkg/prober