diff --git a/pkg/devcontainer/sshtunnel/sshtunnel.go b/pkg/devcontainer/sshtunnel/sshtunnel.go index 0ef6f17f9..e5bc4ad93 100644 --- a/pkg/devcontainer/sshtunnel/sshtunnel.go +++ b/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") diff --git a/pkg/devcontainer/sshtunnel/sshtunnel_test.go b/pkg/devcontainer/sshtunnel/sshtunnel_test.go index 3c266be78..33567171f 100644 --- a/pkg/devcontainer/sshtunnel/sshtunnel_test.go +++ b/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 diff --git a/pkg/inject/inject.go b/pkg/inject/inject.go index f1785fdb8..7d1cb9c75 100644 --- a/pkg/inject/inject.go +++ b/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) 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 +}