From 52e1a834e9cae111f10d5ab6fd9a88d196e5ea1b Mon Sep 17 00:00:00 2001 From: Phil Leggetter Date: Wed, 9 Sep 2026 17:42:43 +0100 Subject: [PATCH 1/3] fix: say "Connected" even when there is no terminal to spin on MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `listen` connected, forwarded events, and never said it was ready. The readiness line — documented in README for both compact and quiet — lived inside `if r.spinner != nil`, and ansi.StartNewSpinner returns nil whenever the writer is not a TTY or colors are off. So every piped, redirected, CI or `--color off` run went silent at exactly the moment it succeeded, and callers waiting for the documented signal could only time out. The writer is the log stream, i.e. stderr. Nothing sets it, so whether a line reached *stdout* was decided by whether *stderr* was a terminal — a harness that gave stdout a PTY and piped stderr lost the line too. #333 then steers non-interactive callers onto this very renderer. Connection state is not decoration. It now prints unconditionally, and it prints to stdout, next to the banner and the event log, so one stream carries the whole state machine. With a terminal the spinner behaves exactly as before. OnDisconnected had the same shape — the message went to stderr while stdout got a bare newline — and is fixed the same way. ansi.CanSpin makes the condition askable, so the next caller does not have to read nil as "nothing to say". Tests cover the no-spinner path directly: readiness in compact and quiet, readiness under `--color off`, the drop notice reaching stdout, silence when the very first attempt fails, and no duplicate notice across a reconnect. All five fail on the unfixed renderer. Closes #376 Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01BnrKWZQASV7bFJ4oGWwmo9 --- KNOWN_ISSUES.md | 22 ++++ pkg/ansi/ansi.go | 10 +- pkg/listen/proxy/renderer_simple.go | 96 ++++++++++------- pkg/listen/proxy/renderer_simple_test.go | 132 +++++++++++++++++++++++ 4 files changed, 222 insertions(+), 38 deletions(-) create mode 100644 pkg/listen/proxy/renderer_simple_test.go diff --git a/KNOWN_ISSUES.md b/KNOWN_ISSUES.md index c1ec9156..7ef34683 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.5.1 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/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") + }) +} From f0899cf180ddd9911b9e53e686c6b0fa457eb6a1 Mon Sep 17 00:00:00 2001 From: Phil Leggetter Date: Wed, 9 Sep 2026 21:04:55 +0100 Subject: [PATCH 2/3] docs: point the known issue at v2.6.0, not a patch that is not happening The entry named v2.5.1 because this was scoped as a patch release. It now ships in v2.6.0, and a workaround telling people to upgrade to a version that will never be published is worse than no workaround at all. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01BnrKWZQASV7bFJ4oGWwmo9 --- KNOWN_ISSUES.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/KNOWN_ISSUES.md b/KNOWN_ISSUES.md index 7ef34683..6bc7e5da 100644 --- a/KNOWN_ISSUES.md +++ b/KNOWN_ISSUES.md @@ -11,7 +11,7 @@ when the output stream is not a terminal or when colors are disabled. **Affected:** v2.5.0 and earlier. -**Recommended fix:** Update to **v2.5.1 or later**. +**Recommended fix:** Update to **v2.6.0 or later**. - npm: `npm install -g hookdeck-cli@latest` - Homebrew: `brew upgrade hookdeck` From d9d092143436b960e3af38e5fa3b705855716be7 Mon Sep 17 00:00:00 2001 From: Phil Leggetter Date: Thu, 10 Sep 2026 11:38:19 +0100 Subject: [PATCH 3/3] fix: say why the connection failed, not just that it did `listen` gave up with "Could not connect. Terminating after 10 failed attempts to establish a connection." and no reason. The reason existed - the dial error is right there in connect() - but it was logged at debug, so at the default log level the user was told the CLI had stopped trying and nothing about whether it was DNS, a refused connection, a proxy, or a rejected session. That is the other half of the report this branch already addresses. The readiness line tells you when the tunnel came up; this tells you why when it did not. A caller who saw neither had no way to tell a healthy tunnel from a broken one, which is exactly how a working connection got filed as a failure. The websocket client now keeps the last connect error and the proxy appends it to the terminating message: Could not connect. Terminating after 10 failed attempts to establish a connection. Last error: dial tcp [::1]:39999: connect: connection refused Held back earlier as too broad for a patch release. That reasoning expired when the patch was dropped in favour of shipping in v2.6.0. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01BnrKWZQASV7bFJ4oGWwmo9 --- pkg/listen/proxy/proxy.go | 7 +++++++ pkg/websocket/client.go | 20 ++++++++++++++++++++ pkg/websocket/client_test.go | 33 +++++++++++++++++++++++++++++++++ 3 files changed, 60 insertions(+) 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/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) + } + }) +}