diff --git a/KNOWN_ISSUES.md b/KNOWN_ISSUES.md index c1ec9156..6bc7e5da 100644 --- a/KNOWN_ISSUES.md +++ b/KNOWN_ISSUES.md @@ -1,5 +1,27 @@ # Known Issues +## `hookdeck listen` never prints "Connected" when output is piped or `--color off` is set + +**Symptom:** `hookdeck listen` prints the connection banner and then nothing. The documented +`Connected. Waiting for events...` line never appears, so scripts, CI jobs and agent harnesses +waiting for it time out — even though the tunnel is connected and forwarding events. + +**Why:** The readiness line was printed only when a spinner was drawn, and no spinner is drawn +when the output stream is not a terminal or when colors are disabled. + +**Affected:** v2.5.0 and earlier. + +**Recommended fix:** Update to **v2.6.0 or later**. + +- npm: `npm install -g hookdeck-cli@latest` +- Homebrew: `brew upgrade hookdeck` + +**Workaround (until you update):** Drop `--color off` and run on a terminal, or treat the first +forwarded event rather than the readiness line as your ready signal. To confirm the tunnel is up +without waiting for traffic, run with `--log-level debug` and look for `Connected!`. + +**Tracking:** #376 + ## `hookdeck listen` can stop delivering events after an extended disconnect **Symptom:** `hookdeck listen` appears connected but events stop arriving; the Hookdeck diff --git a/pkg/ansi/ansi.go b/pkg/ansi/ansi.go index 7b6a7549..d5116d23 100644 --- a/pkg/ansi/ansi.go +++ b/pkg/ansi/ansi.go @@ -128,10 +128,18 @@ func getCharset() charset { const duration = time.Duration(100) * time.Millisecond +// CanSpin reports whether a live spinner can be drawn on w. Callers that print +// status through a spinner must check this first: StartNewSpinner returns nil +// when it is false, and a caller that treats nil as "nothing to say" silently +// drops the status entirely. +func CanSpin(w io.Writer) bool { + return isTerminal(w) && shouldUseColors(w) +} + // StartNewSpinner starts a new spinner with the given message. If the writer is not // a terminal or doesn't support colors, it simply prints the message. func StartNewSpinner(msg string, w io.Writer) *spinner.Spinner { - if !isTerminal(w) || !shouldUseColors(w) { + if !CanSpin(w) { fmt.Fprintln(w, msg) return nil } diff --git a/pkg/listen/proxy/proxy.go b/pkg/listen/proxy/proxy.go index 6ba3f6b2..62d616fb 100644 --- a/pkg/listen/proxy/proxy.go +++ b/pkg/listen/proxy/proxy.go @@ -275,6 +275,13 @@ func (p *Proxy) Run(parentCtx context.Context) error { } if !canConnect() { p.renderer.Cleanup() + // Report the reason, not just the count. Without this the user is + // told the CLI gave up but not whether it was DNS, a refused + // connection, a proxy, or a rejected session — and the reason is + // only logged at debug level. + if connectErr := wsClient.LastConnectErr(); connectErr != nil { + return fmt.Errorf("Could not connect. Terminating after %d failed attempts to establish a connection. Last error: %v", nAttempts, connectErr) + } return fmt.Errorf("Could not connect. Terminating after %d failed attempts to establish a connection.", nAttempts) } } diff --git a/pkg/listen/proxy/renderer_simple.go b/pkg/listen/proxy/renderer_simple.go index 6611a5b3..59783766 100644 --- a/pkg/listen/proxy/renderer_simple.go +++ b/pkg/listen/proxy/renderer_simple.go @@ -37,41 +37,67 @@ func NewSimpleRenderer(cfg *RendererConfig, quietMode bool) *SimpleRenderer { // OnConnecting is called when starting to connect func (r *SimpleRenderer) OnConnecting() { - r.spinner = ansi.StartNewSpinner("Getting ready...", log.StandardLogger().Out) + r.showStatus("Getting ready...") +} + +// showStatus reports a connection-state change. With a terminal it animates a +// spinner on the log stream, as before. Without one it writes a plain line to +// stdout, next to the connection banner and the event log, so a caller reading +// stdout sees the whole state machine on one stream. +func (r *SimpleRenderer) showStatus(msg string) { + if ansi.CanSpin(log.StandardLogger().Out) { + r.spinner = ansi.StartNewSpinner(msg, log.StandardLogger().Out) + return + } + + r.spinner = nil + fmt.Println(msg) +} + +// stopStatus clears any running spinner. Safe when there is none. +func (r *SimpleRenderer) stopStatus() { + if r.spinner != nil { + ansi.StopSpinner(r.spinner, "", log.StandardLogger().Out) + r.spinner = nil + } } // OnConnected is called when websocket connects func (r *SimpleRenderer) OnConnected() { r.hasConnected = true r.isReconnecting = false // Reset reconnection state - if r.spinner != nil { - ansi.StopSpinner(r.spinner, "", log.StandardLogger().Out) - r.spinner = nil - color := ansi.Color(os.Stdout) - - // Display filter warning if filters are active - if r.cfg.Filters != nil { - fmt.Printf("\n%s Filters provided, only events matching the filter will be forwarded for this session\n", color.Yellow("⏺")) - if r.cfg.Filters.Body != nil { - fmt.Printf(" • Body: %s\n", color.Faint(string(*r.cfg.Filters.Body))) - } - if r.cfg.Filters.Headers != nil { - fmt.Printf(" • Headers: %s\n", color.Faint(string(*r.cfg.Filters.Headers))) - } - if r.cfg.Filters.Query != nil { - fmt.Printf(" • Query: %s\n", color.Faint(string(*r.cfg.Filters.Query))) - } - if r.cfg.Filters.Path != nil { - fmt.Printf(" • Path: %s\n", color.Faint(string(*r.cfg.Filters.Path))) - } - fmt.Println() - } - if r.quietMode { - fmt.Printf("%s\n\n", color.Faint("Connected. Quiet mode: only errors and warnings will be shown.")) - } else { - fmt.Printf("%s\n\n", color.Faint("Connected. Waiting for events...")) + // Ready is the one line every non-interactive caller waits for, so it must not + // depend on how the terminal is dressed. This used to sit inside `if r.spinner + // != nil`, which is false whenever the log stream is not a TTY or --color=off + // is set: `listen` connected, forwarded events, and never said it was ready, so + // scripts and CI could only conclude "connection timed out". + r.stopStatus() + + color := ansi.Color(os.Stdout) + + // Display filter warning if filters are active + if r.cfg.Filters != nil { + fmt.Printf("\n%s Filters provided, only events matching the filter will be forwarded for this session\n", color.Yellow("⏺")) + if r.cfg.Filters.Body != nil { + fmt.Printf(" • Body: %s\n", color.Faint(string(*r.cfg.Filters.Body))) + } + if r.cfg.Filters.Headers != nil { + fmt.Printf(" • Headers: %s\n", color.Faint(string(*r.cfg.Filters.Headers))) + } + if r.cfg.Filters.Query != nil { + fmt.Printf(" • Query: %s\n", color.Faint(string(*r.cfg.Filters.Query))) } + if r.cfg.Filters.Path != nil { + fmt.Printf(" • Path: %s\n", color.Faint(string(*r.cfg.Filters.Path))) + } + fmt.Println() + } + + if r.quietMode { + fmt.Printf("%s\n\n", color.Faint("Connected. Quiet mode: only errors and warnings will be shown.")) + } else { + fmt.Printf("%s\n\n", color.Faint("Connected. Waiting for events...")) } } @@ -81,12 +107,11 @@ func (r *SimpleRenderer) OnDisconnected() { if r.hasConnected && !r.isReconnecting { // First disconnection - print newline for visual separation fmt.Println() - // Stop any existing spinner first - if r.spinner != nil { - ansi.StopSpinner(r.spinner, "", log.StandardLogger().Out) - } - // Start new spinner with reconnection message - r.spinner = ansi.StartNewSpinner("Connection lost, reconnecting...", log.StandardLogger().Out) + r.stopStatus() + // Announce the drop the same way readiness is announced: a spinner on a + // terminal, a plain stdout line otherwise. Routing this to the log stream + // only left stdout with a bare blank line and no reason for it. + r.showStatus("Connection lost, reconnecting...") r.isReconnecting = true } // If we haven't connected yet, the "Getting ready..." spinner is still showing @@ -200,10 +225,7 @@ func (r *SimpleRenderer) OnServerHealthChanged(healthy bool, err error) { // Cleanup stops the spinner and cleans up resources func (r *SimpleRenderer) Cleanup() { - if r.spinner != nil { - ansi.StopSpinner(r.spinner, "", log.StandardLogger().Out) - r.spinner = nil - } + r.stopStatus() } // Done returns a channel that is closed when the renderer wants to quit diff --git a/pkg/listen/proxy/renderer_simple_test.go b/pkg/listen/proxy/renderer_simple_test.go new file mode 100644 index 00000000..4e6368d3 --- /dev/null +++ b/pkg/listen/proxy/renderer_simple_test.go @@ -0,0 +1,132 @@ +package proxy + +import ( + "io" + "net/url" + "os" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/hookdeck/hookdeck-cli/pkg/ansi" +) + +// captureStdout runs fn with os.Stdout redirected and returns what it wrote. +// The renderer prints with fmt.Printf, so stdout is the only place to look — +// which is the point: these tests assert on the stream a caller actually reads. +func captureStdout(t *testing.T, fn func()) string { + t.Helper() + + original := os.Stdout + r, w, err := os.Pipe() + require.NoError(t, err) + os.Stdout = w + + done := make(chan string, 1) + go func() { + out, _ := io.ReadAll(r) + done <- string(out) + }() + + fn() + + require.NoError(t, w.Close()) + os.Stdout = original + + return <-done +} + +// TestSimpleRendererAnnouncesReadinessWithoutASpinner covers the regression where +// `listen` connected but never said so. The readiness line lived inside `if +// r.spinner != nil`, and ansi.StartNewSpinner returns nil whenever the log stream +// is not a TTY or colors are disabled — so every piped, redirected, CI, or +// --color=off run forwarded events in silence and callers timed out waiting for a +// state the CLI had already reached. +func TestSimpleRendererAnnouncesReadinessWithoutASpinner(t *testing.T) { + target, err := url.Parse("http://localhost:3000") + require.NoError(t, err) + + // go test never gives the log stream a TTY, so the spinner is always nil in + // these subtests — exactly the configuration that used to swallow the output. + + t.Run("compact mode says it is ready", func(t *testing.T) { + r := NewSimpleRenderer(&RendererConfig{TargetURL: target}, false) + + out := captureStdout(t, func() { + r.OnConnecting() + r.OnConnected() + }) + + assert.Nil(t, r.spinner, "no TTY means no spinner: the case that regressed") + assert.Contains(t, out, "Connected. Waiting for events...") + }) + + t.Run("quiet mode says it is ready", func(t *testing.T) { + r := NewSimpleRenderer(&RendererConfig{TargetURL: target}, true) + + out := captureStdout(t, func() { + r.OnConnecting() + r.OnConnected() + }) + + assert.Contains(t, out, "Connected. Quiet mode: only errors and warnings will be shown.") + }) + + t.Run("--color off does not remove the readiness line", func(t *testing.T) { + ansi.DisableColors = true + t.Cleanup(func() { ansi.DisableColors = false }) + + r := NewSimpleRenderer(&RendererConfig{TargetURL: target}, false) + + out := captureStdout(t, func() { + r.OnConnecting() + r.OnConnected() + }) + + assert.Contains(t, out, "Connected. Waiting for events...", + "--color controls decoration, not whether the CLI reports its state") + }) + + t.Run("a dropped connection is reported on stdout too", func(t *testing.T) { + r := NewSimpleRenderer(&RendererConfig{TargetURL: target}, false) + + out := captureStdout(t, func() { + r.OnConnecting() + r.OnConnected() + r.OnDisconnected() + }) + + assert.Contains(t, out, "Connection lost, reconnecting...") + }) + + t.Run("a drop before the first connect stays quiet", func(t *testing.T) { + r := NewSimpleRenderer(&RendererConfig{TargetURL: target}, false) + + out := captureStdout(t, func() { + r.OnConnecting() + r.OnDisconnected() + }) + + assert.NotContains(t, out, "Connection lost", + "a failed first attempt is retried, not announced as a lost connection") + }) + + t.Run("reconnecting is announced once, then readiness again", func(t *testing.T) { + r := NewSimpleRenderer(&RendererConfig{TargetURL: target}, false) + + out := captureStdout(t, func() { + r.OnConnecting() + r.OnConnected() + r.OnDisconnected() + r.OnDisconnected() + r.OnConnected() + }) + + assert.Equal(t, 1, strings.Count(out, "Connection lost, reconnecting..."), + "repeated retries must not repeat the notice") + assert.Equal(t, 2, strings.Count(out, "Connected. Waiting for events..."), + "a recovered connection is a state change worth reporting") + }) +} diff --git a/pkg/websocket/client.go b/pkg/websocket/client.go index 505e1611..9d84429a 100644 --- a/pkg/websocket/client.go +++ b/pkg/websocket/client.go @@ -100,6 +100,10 @@ type Client struct { // read by Stop(), which can run on the signal-handler goroutine. stateMu sync.Mutex + // lastConnectErr is why the most recent connect attempt failed. Guarded by + // stateMu: written by Run, read by LastConnectErr from the proxy goroutine. + lastConnectErr error + NotifyExpired chan struct{} notifyClose chan error send chan *OutgoingMessage @@ -129,6 +133,21 @@ func (c *Client) connected() bool { return c.isConnected } +// LastConnectErr returns why the most recent connect attempt failed, or nil if +// none has. The reason is otherwise only visible at debug level, which left the +// CLI able to say it had given up but not why. +func (c *Client) LastConnectErr() error { + c.stateMu.Lock() + defer c.stateMu.Unlock() + return c.lastConnectErr +} + +func (c *Client) setLastConnectErr(err error) { + c.stateMu.Lock() + c.lastConnectErr = err + c.stateMu.Unlock() +} + // HasConnected reports whether this client successfully established its // websocket connection at some point. It stays true after a disconnect, so // callers can distinguish "connected then dropped" from "never connected". @@ -151,6 +170,7 @@ func (c *Client) Run(ctx context.Context) { err := c.connect(ctx) if err != nil { + c.setLastConnectErr(err) c.cfg.Log.WithFields(log.Fields{ "prefix": "websocket.client.Run", }).Debug(err) diff --git a/pkg/websocket/client_test.go b/pkg/websocket/client_test.go index 2381e6c7..6cb87c20 100644 --- a/pkg/websocket/client_test.go +++ b/pkg/websocket/client_test.go @@ -256,3 +256,36 @@ func TestStopConcurrentWithConnect(t *testing.T) { }() wg.Wait() } + +// TestLastConnectErr covers the reason a connect attempt failed being readable +// by the caller. It was previously logged at debug level only, so `listen` could +// report that it had given up after ten attempts without saying whether the +// cause was DNS, a refused connection, a proxy, or a rejected session. +func TestLastConnectErr(t *testing.T) { + t.Run("nil before any attempt", func(t *testing.T) { + c := NewClient("ws://localhost:1", "cses_x", "key", "tm_x", nil, "", &Config{}) + if err := c.LastConnectErr(); err != nil { + t.Fatalf("expected no error before connecting, got %v", err) + } + }) + + t.Run("records why the dial failed", func(t *testing.T) { + // Port 1 is reserved and nothing listens on it, so the dial fails fast. + c := NewClient("ws://127.0.0.1:1", "cses_x", "key", "tm_x", nil, "", &Config{}) + + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + + // Run signals ConnectionLost on failure; drain it so Run can return. + go func() { <-c.NotifyExpired }() + c.Run(ctx) + + err := c.LastConnectErr() + if err == nil { + t.Fatal("a failed dial must leave a reason behind") + } + if !strings.Contains(err.Error(), "connect") { + t.Errorf("expected the reason to name the transport failure, got %q", err) + } + }) +}