feat(obs): add injection pipeline timing logs

pkg/devcontainer/sshtunnel/sshtunnel.go

@@ -273,6 +273,10 @@ func runSSHTunnel(
 ) sshTunnelResult {
 	defer cancel()
 
+	start := time.Now()
+	log.Infof("tunnel: setup start")
+	defer func() { log.Infof("tunnel: setup complete elapsed=%s", time.Since(start)) }()
+
 	log.Debug("creating SSH client")
 	sshClient, err := devssh.StdioClient(ts.sshPipes.stdoutReader, ts.sshPipes.stdinWriter, false)
 	if err != nil {
@@ -281,7 +285,7 @@ func runSSHTunnel(
 			err:    fmt.Errorf("failed to create SSH client: %w", err),
 		}
 	}
-	log.Debug("SSH client created")
+	log.Debugf("tunnel: ssh client created elapsed=%s", time.Since(start))
 	defer func() {
 		_ = sshClient.Close()
 		log.Debug("SSH client closed")
@@ -291,6 +295,7 @@ func runSSHTunnel(
 	if err != nil {
 		return sshTunnelResult{source: "tunnel", err: err}
 	}
+	log.Debugf("tunnel: ssh session established elapsed=%s", time.Since(start))
 	defer func() {
 		_ = sess.Close()
 		log.Debug("SSH session closed")

pkg/devcontainer/sshtunnel/sshtunnel_test.go

@@ -1,6 +1,8 @@
 package sshtunnel
 
 import (
+	"context"
+	"strings"
 	"testing"
 
 	"github.com/devsy-org/devsy/pkg/log"
@@ -179,6 +181,41 @@ func TestExtractLogLevel(t *testing.T) {
 	}
 }
 
+func TestRunSSHTunnel_TimingLogs(t *testing.T) {
+	logs := log.InitTestObserved(t, zapcore.DebugLevel)
+
+	pipes, err := createPipes()
+	require.NoError(t, err)
+	// Close the read side so StdioClient fails immediately.
+	_ = pipes.stdoutReader.Close()
+
+	ts := &sshSessionTunnel{
+		sshPipes:  pipes,
+		grpcPipes: &pipePair{},
+	}
+
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	result := runSSHTunnel(ctx, cancel, ts)
+	require.Error(t, result.err)
+
+	messages := make([]string, 0, len(logs.All()))
+	for _, entry := range logs.All() {
+		messages = append(messages, entry.Message)
+	}
+	assert.Contains(t, messages, "tunnel: setup start")
+
+	foundComplete := false
+	for _, msg := range messages {
+		if strings.HasPrefix(msg, "tunnel: setup complete elapsed=") {
+			foundComplete = true
+			break
+		}
+	}
+	assert.True(t, foundComplete, "missing 'tunnel: setup complete' log: %v", messages)
+}
+
 func TestNormalizeLevel(t *testing.T) {
 	tests := []struct {
 		input string

pkg/inject/inject.go

@@ -50,6 +50,10 @@ func Inject(opts InjectOptions) (bool, error) {
 		return false, fmt.Errorf("script params is required")
 	}
 
+	start := time.Now()
+	log.Infof("injection: start")
+	defer func() { log.Infof("injection: complete elapsed=%s", time.Since(start)) }()
+
 	if opts.ScriptParams.PreferAgentDownload {
 		url := ""
 		if opts.ScriptParams.DownloadURLs != nil {
@@ -136,6 +140,7 @@ func Inject(opts InjectOptions) (bool, error) {
 	case result = <-injectChan:
 		// we don't wait for the command termination here and will just retry on error
 	}
+	log.Debugf("injection: payload delivered elapsed=%s", time.Since(start))
 
 	// prefer result error
 	if result.err != nil {
@@ -166,6 +171,8 @@ func inject(
 	delayedStderr *delayedWriter,
 	timeout time.Duration,
 ) (bool, error) {
+	injectStart := time.Now()
+
 	// wait until we read start
 	var line string
 	errChan := make(chan error)
@@ -185,6 +192,7 @@ func inject(
 	if err != nil {
 		return false, err
 	}
+	log.Debugf("injection: handshake complete elapsed=%s", time.Since(injectStart))
 
 	// wait until we read something
 	line, err = readLine(stdout)

pkg/inject/inject_test.go

@@ -12,7 +12,9 @@ import (
 	"testing"
 	"time"
 
+	"github.com/devsy-org/devsy/pkg/log"
 	"github.com/stretchr/testify/suite"
+	"go.uber.org/zap/zapcore"
 )
 
 // errWriter is an io.Writer that always returns a configured error.
@@ -283,3 +285,87 @@ func (s *PerformMutualHandshakeTestSuite) TestPerformMutualHandshake_InvalidInpu
 func TestPerformMutualHandshakeSuite(t *testing.T) {
 	suite.Run(t, new(PerformMutualHandshakeTestSuite))
 }
+
+// --- InjectTimingLogTestSuite ---
+
+type InjectTimingLogTestSuite struct {
+	suite.Suite
+}
+
+func (s *InjectTimingLogTestSuite) TestInject_TimingLogs() {
+	logs := log.InitTestObserved(s.T(), zapcore.DebugLevel)
+
+	ctx := context.Background()
+
+	execFunc := func(_ context.Context, _ string, stdin io.Reader, stdout io.Writer, _ io.Writer) error {
+		// Simulate the inject.sh protocol: send ping, read pong, send done.
+		if _, err := stdout.Write([]byte("ping\n")); err != nil {
+			return err
+		}
+
+		buf := make([]byte, 64)
+		n, err := stdin.Read(buf)
+		if err != nil {
+			return err
+		}
+		if strings.TrimSpace(string(buf[:n])) != "pong" {
+			return fmt.Errorf("expected pong, got %q", string(buf[:n]))
+		}
+
+		if _, err := stdout.Write([]byte("done\n")); err != nil {
+			return err
+		}
+
+		// Return immediately so stdout pipe closes and pipe() completes quickly.
+		return nil
+	}
+
+	wasExecuted, err := Inject(InjectOptions{
+		Ctx:  ctx,
+		Exec: execFunc,
+		ScriptParams: &Params{
+			Command:         "test-cmd",
+			AgentRemotePath: "/tmp/agent",
+			DownloadURLs:    &DownloadURLs{},
+		},
+		Stdin:   strings.NewReader(""),
+		Stdout:  io.Discard,
+		Stderr:  io.Discard,
+		Timeout: 5 * time.Second,
+	})
+
+	s.NoError(err)
+	s.True(wasExecuted)
+
+	messages := make([]string, 0, len(logs.All()))
+	for _, entry := range logs.All() {
+		messages = append(messages, entry.Message)
+	}
+
+	s.Contains(messages, "injection: start")
+	s.True(
+		containsPrefix(messages, "injection: payload delivered elapsed="),
+		"missing payload log: %v", messages,
+	)
+	s.True(
+		containsPrefix(messages, "injection: complete elapsed="),
+		"missing complete log: %v", messages,
+	)
+	s.True(
+		containsPrefix(messages, "injection: handshake complete elapsed="),
+		"missing handshake log: %v", messages,
+	)
+}
+
+func TestInjectTimingLogSuite(t *testing.T) {
+	suite.Run(t, new(InjectTimingLogTestSuite))
+}
+
+func containsPrefix(messages []string, prefix string) bool {
+	for _, msg := range messages {
+		if strings.HasPrefix(msg, prefix) {
+			return true
+		}
+	}
+	return false
+}