From 5fc0e33fe4adcf881fdb4d26745271398c25ff27 Mon Sep 17 00:00:00 2001 From: Samuel K Date: Sun, 26 Apr 2026 10:25:14 -0500 Subject: [PATCH 1/2] feat(obs): add injection pipeline timing logs Add structured timing logs at key injection milestones so slow injection is visible at a glance. Info-level start/complete bookends are always shown; Debug-level intermediate steps (handshake, payload delivery, SSH client/session creation) appear with -v. --- pkg/devcontainer/sshtunnel/sshtunnel.go | 6 +- pkg/devcontainer/sshtunnel/sshtunnel_test.go | 27 ++++++ pkg/inject/inject.go | 14 +++- pkg/inject/inject_test.go | 86 ++++++++++++++++++++ 4 files changed, 131 insertions(+), 2 deletions(-) diff --git a/pkg/devcontainer/sshtunnel/sshtunnel.go b/pkg/devcontainer/sshtunnel/sshtunnel.go index 0ef6f17f9..eea9bdd1b 100644 --- a/pkg/devcontainer/sshtunnel/sshtunnel.go +++ b/pkg/devcontainer/sshtunnel/sshtunnel.go @@ -273,6 +273,9 @@ func runSSHTunnel( ) sshTunnelResult { defer cancel() + start := time.Now() + log.Infof("tunnel: setup start") + log.Debug("creating SSH client") sshClient, err := devssh.StdioClient(ts.sshPipes.stdoutReader, ts.sshPipes.stdinWriter, false) if err != nil { @@ -281,7 +284,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 +294,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") diff --git a/pkg/devcontainer/sshtunnel/sshtunnel_test.go b/pkg/devcontainer/sshtunnel/sshtunnel_test.go index 3c266be78..f9da46f6d 100644 --- a/pkg/devcontainer/sshtunnel/sshtunnel_test.go +++ b/pkg/devcontainer/sshtunnel/sshtunnel_test.go @@ -1,6 +1,7 @@ package sshtunnel import ( + "context" "testing" "github.com/devsy-org/devsy/pkg/log" @@ -179,6 +180,32 @@ 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") +} + func TestNormalizeLevel(t *testing.T) { tests := []struct { input string diff --git a/pkg/inject/inject.go b/pkg/inject/inject.go index f1785fdb8..09e4fd923 100644 --- a/pkg/inject/inject.go +++ b/pkg/inject/inject.go @@ -50,6 +50,9 @@ func Inject(opts InjectOptions) (bool, error) { return false, fmt.Errorf("script params is required") } + start := time.Now() + log.Infof("injection: start") + if opts.ScriptParams.PreferAgentDownload { url := "" if opts.ScriptParams.DownloadURLs != nil { @@ -136,25 +139,31 @@ 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 { + log.Infof("injection: complete elapsed=%s", time.Since(start)) return result.wasExecuted, result.err } else if err != nil { + log.Infof("injection: complete elapsed=%s", time.Since(start)) return result.wasExecuted, err } else if result.wasExecuted || opts.ScriptParams.Command == "" { + log.Infof("injection: complete elapsed=%s", time.Since(start)) return result.wasExecuted, nil } log.Debugf("Rerun command as binary was injected") delayedStderr.Start() - return true, opts.Exec( + rerunErr := opts.Exec( opts.Ctx, opts.ScriptParams.Command, opts.Stdin, opts.Stdout, delayedStderr, ) + log.Infof("injection: complete elapsed=%s", time.Since(start)) + return true, rerunErr } func inject( @@ -166,6 +175,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 +196,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) diff --git a/pkg/inject/inject_test.go b/pkg/inject/inject_test.go index 848254f25..9875b27ab 100644 --- a/pkg/inject/inject_test.go +++ b/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 +} From 06a2fc486f7fa7689507704fec25ef5a5cd336e2 Mon Sep 17 00:00:00 2001 From: Samuel K Date: Sun, 26 Apr 2026 10:30:56 -0500 Subject: [PATCH 2/2] fix(obs): use deferred complete logs to cover all exit paths Replace inline 'injection: complete' logs with a single defer so early error paths (GenerateScript, os.Pipe, context.Canceled) are also covered. Add 'tunnel: setup complete' bookend via defer in runSSHTunnel. --- pkg/devcontainer/sshtunnel/sshtunnel.go | 1 + pkg/devcontainer/sshtunnel/sshtunnel_test.go | 10 ++++++++++ pkg/inject/inject.go | 8 ++------ 3 files changed, 13 insertions(+), 6 deletions(-) diff --git a/pkg/devcontainer/sshtunnel/sshtunnel.go b/pkg/devcontainer/sshtunnel/sshtunnel.go index eea9bdd1b..e5bc4ad93 100644 --- a/pkg/devcontainer/sshtunnel/sshtunnel.go +++ b/pkg/devcontainer/sshtunnel/sshtunnel.go @@ -275,6 +275,7 @@ func runSSHTunnel( 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) diff --git a/pkg/devcontainer/sshtunnel/sshtunnel_test.go b/pkg/devcontainer/sshtunnel/sshtunnel_test.go index f9da46f6d..33567171f 100644 --- a/pkg/devcontainer/sshtunnel/sshtunnel_test.go +++ b/pkg/devcontainer/sshtunnel/sshtunnel_test.go @@ -2,6 +2,7 @@ package sshtunnel import ( "context" + "strings" "testing" "github.com/devsy-org/devsy/pkg/log" @@ -204,6 +205,15 @@ func TestRunSSHTunnel_TimingLogs(t *testing.T) { 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) { diff --git a/pkg/inject/inject.go b/pkg/inject/inject.go index 09e4fd923..7d1cb9c75 100644 --- a/pkg/inject/inject.go +++ b/pkg/inject/inject.go @@ -52,6 +52,7 @@ func Inject(opts InjectOptions) (bool, error) { start := time.Now() log.Infof("injection: start") + defer func() { log.Infof("injection: complete elapsed=%s", time.Since(start)) }() if opts.ScriptParams.PreferAgentDownload { url := "" @@ -143,27 +144,22 @@ func Inject(opts InjectOptions) (bool, error) { // prefer result error if result.err != nil { - log.Infof("injection: complete elapsed=%s", time.Since(start)) return result.wasExecuted, result.err } else if err != nil { - log.Infof("injection: complete elapsed=%s", time.Since(start)) return result.wasExecuted, err } else if result.wasExecuted || opts.ScriptParams.Command == "" { - log.Infof("injection: complete elapsed=%s", time.Since(start)) return result.wasExecuted, nil } log.Debugf("Rerun command as binary was injected") delayedStderr.Start() - rerunErr := opts.Exec( + return true, opts.Exec( opts.Ctx, opts.ScriptParams.Command, opts.Stdin, opts.Stdout, delayedStderr, ) - log.Infof("injection: complete elapsed=%s", time.Since(start)) - return true, rerunErr } func inject(