feat: add coderd_api_websocket_probes_total metric (#25012)

Relates to CODAGT-115

Adds metric `coderd_api_websocket_probes_total`. Every successful
heartbeat for a given path will increment the metric.

Comparing this with `coderd_api_concurrent_websockets` will give an
indication of how many websocket connections are open but in a 'wedged'
state (when heartbeats stopped versus when we closed the connection).
This commit is contained in:
Cian Johnston
2026-06-03 10:46:07 +01:00
committed by GitHub
parent 7703e7a26e
commit 8b058dc949
22 changed files with 596 additions and 171 deletions
+2 -2
View File
@@ -419,7 +419,7 @@ func ServerSentEventSender(rw http.ResponseWriter, r *http.Request) (
// open a workspace in multiple tabs, the entire UI can start to lock up.
// WebSockets have no such limitation, no matter what HTTP protocol was used to
// establish the connection.
func OneWayWebSocketEventSender(log slog.Logger) func(rw http.ResponseWriter, r *http.Request) (
func OneWayWebSocketEventSender(log slog.Logger, watcher *WSWatcher) func(rw http.ResponseWriter, r *http.Request) (
func(event codersdk.ServerSentEvent) error,
<-chan struct{},
error,
@@ -436,7 +436,7 @@ func OneWayWebSocketEventSender(log slog.Logger) func(rw http.ResponseWriter, r
cancel()
return nil, nil, xerrors.Errorf("cannot establish connection: %w", err)
}
go HeartbeatClose(ctx, log, cancel, socket)
ctx = watcher.Watch(ctx, log, socket)
eventC := make(chan codersdk.ServerSentEvent, 64)
socketErrC := make(chan websocket.CloseError, 1)
+13 -6
View File
@@ -22,6 +22,7 @@ import (
"github.com/coder/coder/v2/coderd/httpapi"
"github.com/coder/coder/v2/codersdk"
"github.com/coder/coder/v2/testutil"
"github.com/coder/quartz"
)
func TestInternalServerError(t *testing.T) {
@@ -245,7 +246,7 @@ func TestOneWayWebSocketEventSender(t *testing.T) {
req.Proto = p.proto
writer := newOneWayWriter(t)
_, _, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil))(writer, req)
_, _, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil), nil)(writer, req)
require.ErrorContains(t, err, p.proto)
}
})
@@ -254,9 +255,11 @@ func TestOneWayWebSocketEventSender(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
wsw := httpapi.NewWSWatcher(quartz.NewReal(), nil)
req := newBaseRequest(ctx)
writer := newOneWayWriter(t)
send, _, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil))(writer, req)
send, _, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil), wsw)(writer, req)
require.NoError(t, err)
serverPayload := codersdk.ServerSentEvent{
@@ -280,9 +283,10 @@ func TestOneWayWebSocketEventSender(t *testing.T) {
t.Parallel()
ctx, cancel := context.WithCancel(testutil.Context(t, testutil.WaitShort))
wsw := httpapi.NewWSWatcher(quartz.NewReal(), nil)
req := newBaseRequest(ctx)
writer := newOneWayWriter(t)
_, done, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil))(writer, req)
_, done, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil), wsw)(writer, req)
require.NoError(t, err)
successC := make(chan bool)
@@ -304,9 +308,10 @@ func TestOneWayWebSocketEventSender(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
wsw := httpapi.NewWSWatcher(quartz.NewReal(), nil)
req := newBaseRequest(ctx)
writer := newOneWayWriter(t)
_, done, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil))(writer, req)
_, done, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil), wsw)(writer, req)
require.NoError(t, err)
successC := make(chan bool)
@@ -334,9 +339,10 @@ func TestOneWayWebSocketEventSender(t *testing.T) {
t.Parallel()
ctx, cancel := context.WithCancel(testutil.Context(t, testutil.WaitShort))
wsw := httpapi.NewWSWatcher(quartz.NewReal(), nil)
req := newBaseRequest(ctx)
writer := newOneWayWriter(t)
send, done, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil))(writer, req)
send, done, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil), wsw)(writer, req)
require.NoError(t, err)
successC := make(chan bool)
@@ -375,9 +381,10 @@ func TestOneWayWebSocketEventSender(t *testing.T) {
timeout := hbDuration + (5 * time.Second)
ctx := testutil.Context(t, timeout)
wsw := httpapi.NewWSWatcher(quartz.NewReal(), nil)
req := newBaseRequest(ctx)
writer := newOneWayWriter(t)
_, _, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil))(writer, req)
_, _, err := httpapi.OneWayWebSocketEventSender(slogtest.Make(t, nil), wsw)(writer, req)
require.NoError(t, err)
type Result struct {
+103 -39
View File
@@ -15,20 +15,70 @@ import (
const HeartbeatInterval time.Duration = 15 * time.Second
// HeartbeatClose loops to ping a WebSocket to keep it alive.
// It calls `exit` on ping failure.
func HeartbeatClose(ctx context.Context, logger slog.Logger, exit func(), conn *websocket.Conn) {
heartbeatCloseWith(ctx, logger, exit, conn, quartz.NewReal(), HeartbeatInterval)
// ProbeResult classifies the outcome of a single WebSocket liveness
// probe so that callers (typically a Prometheus recorder) can track
// successes and the various failure modes independently.
type ProbeResult string
const (
ProbeOK ProbeResult = "ok"
ProbeTimeout ProbeResult = "timeout"
ProbePeerClosed ProbeResult = "peer_closed"
ProbeCanceled ProbeResult = "canceled"
ProbeError ProbeResult = "error"
)
// ProbeRecorder is called once per liveness probe with its outcome.
// It may be nil, in which case probes are still run but not recorded.
type ProbeRecorder func(ctx context.Context, result ProbeResult)
// PingCloser is the minimal interface for WebSocket liveness probing.
// *websocket.Conn satisfies this interface.
type PingCloser interface {
Ping(ctx context.Context) error
Close(code websocket.StatusCode, reason string) error
}
// HeartbeatCloseWithClock is like HeartbeatClose, but uses the provided
// clock so tests can drive heartbeat ticks deterministically.
func HeartbeatCloseWithClock(ctx context.Context, logger slog.Logger, exit func(), conn *websocket.Conn, clk quartz.Clock) {
heartbeatCloseWith(ctx, logger, exit, conn, clk, HeartbeatInterval)
// WSWatcher supervises WebSocket connections for liveness by
// periodically sending ping frames. On probe failure, the watcher
// closes the connection with StatusGoingAway and cancels the
// returned context; the caller owns closing the connection on
// normal teardown.
type WSWatcher struct {
rec ProbeRecorder
clk quartz.Clock
interval time.Duration
}
func heartbeatCloseWith(ctx context.Context, logger slog.Logger, exit func(), conn *websocket.Conn, clk quartz.Clock, interval time.Duration) {
ticker := clk.NewTicker(interval, "HeartbeatClose")
// NewWSWatcher creates a WSWatcher. Pass nil for rec when no
// recording is needed (e.g. agent-side code without a Prometheus
// registry).
func NewWSWatcher(clk quartz.Clock, rec ProbeRecorder) *WSWatcher {
return &WSWatcher{
rec: rec,
clk: clk,
interval: HeartbeatInterval,
}
}
// Watch supervises conn for liveness. The returned context is
// canceled when parent is canceled or when conn fails a probe.
// Watch closes conn on probe failure with StatusGoingAway; the
// caller owns close on normal teardown.
func (w *WSWatcher) Watch(parent context.Context, log slog.Logger, conn PingCloser) context.Context {
if w == nil {
panic("developer error: WSWatcher is nil")
}
ctx, cancel := context.WithCancel(parent)
go func() {
defer cancel()
w.supervise(ctx, log, conn)
}()
return ctx
}
func (w *WSWatcher) supervise(ctx context.Context, log slog.Logger, conn PingCloser) {
ticker := w.clk.NewTicker(w.interval, "WSWatcher")
defer ticker.Stop()
for {
@@ -37,39 +87,53 @@ func heartbeatCloseWith(ctx context.Context, logger slog.Logger, exit func(), co
return
case <-ticker.C:
}
err := pingWithTimeout(ctx, conn, interval)
if err != nil {
// These errors are all expected during normal connection
// teardown and should not be logged at error level:
// - context.DeadlineExceeded: client disconnected
// without sending a close frame.
// - context.Canceled: request context was canceled.
// - net.ErrClosed: connection was already closed by
// another goroutine (e.g. handler returned).
// - websocket.CloseError: a close frame was
// received or sent.
if errors.Is(err, context.DeadlineExceeded) ||
errors.Is(err, context.Canceled) ||
errors.Is(err, net.ErrClosed) ||
websocket.CloseStatus(err) != -1 {
logger.Debug(ctx, "heartbeat ping stopped", slog.Error(err))
} else {
logger.Error(ctx, "failed to heartbeat ping", slog.Error(err))
}
_ = conn.Close(websocket.StatusGoingAway, "Ping failed")
exit()
return
result, err := probe(ctx, conn, w.interval)
if w.rec != nil {
w.rec(ctx, result)
}
if result == ProbeOK {
continue
}
if result == ProbeError {
log.Error(ctx, "websocket probe failed", slog.Error(err))
} else {
log.Debug(ctx, "websocket probe stopped",
slog.F("result", string(result)), slog.Error(err))
}
_ = conn.Close(websocket.StatusGoingAway, "liveness probe failed")
return
}
}
func pingWithTimeout(ctx context.Context, conn *websocket.Conn, timeout time.Duration) error {
ctx, cancel := context.WithTimeout(ctx, timeout)
func probe(ctx context.Context, conn PingCloser, timeout time.Duration) (ProbeResult, error) {
pingCtx, cancel := context.WithTimeout(ctx, timeout)
defer cancel()
err := conn.Ping(ctx)
if err != nil {
return xerrors.Errorf("failed to ping: %w", err)
err := conn.Ping(pingCtx)
switch {
case err == nil:
return ProbeOK, nil
case errors.Is(err, context.Canceled):
return ProbeCanceled, err
case errors.Is(err, context.DeadlineExceeded):
return ProbeTimeout, err
case errors.Is(err, net.ErrClosed) || websocket.CloseStatus(err) != -1:
return ProbePeerClosed, err
default:
return ProbeError, xerrors.Errorf("ping: %w", err)
}
}
// HeartbeatClose is a legacy helper that pings conn in a loop and
// calls exit on failure. Callers that need metric recording should
// use WSWatcher directly.
func HeartbeatClose(ctx context.Context, logger slog.Logger, exit func(), conn *websocket.Conn) {
w := NewWSWatcher(quartz.NewReal(), nil)
watchCtx := w.Watch(ctx, logger, conn)
<-watchCtx.Done()
// Only call exit when the probe failed; if the parent context was
// canceled the caller is already shutting down.
if ctx.Err() == nil {
exit()
}
return nil
}
+246 -37
View File
@@ -4,11 +4,14 @@ import (
"context"
"net/http"
"net/http/httptest"
"sync"
"testing"
"time"
"github.com/prometheus/client_golang/prometheus"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"golang.org/x/xerrors"
"cdr.dev/slog/v3"
"github.com/coder/coder/v2/testutil"
@@ -53,7 +56,37 @@ func websocketPair(ctx context.Context, t *testing.T) *websocket.Conn {
}
}
func TestHeartbeatClose(t *testing.T) {
// probeRecords is a thread-safe collector for ProbeResult values.
type probeRecords struct {
mu sync.Mutex
results []ProbeResult
}
func (r *probeRecords) record(_ context.Context, result ProbeResult) {
r.mu.Lock()
defer r.mu.Unlock()
r.results = append(r.results, result)
}
func (r *probeRecords) count(want ProbeResult) int {
r.mu.Lock()
defer r.mu.Unlock()
n := 0
for _, got := range r.results {
if got == want {
n++
}
}
return n
}
func (r *probeRecords) len() int {
r.mu.Lock()
defer r.mu.Unlock()
return len(r.results)
}
func TestWSWatcher(t *testing.T) {
t.Parallel()
t.Run("ServerSideClose", func(t *testing.T) {
@@ -63,33 +96,31 @@ func TestHeartbeatClose(t *testing.T) {
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
rec := &probeRecords{}
// Trap ticker creation so we can synchronize startup.
trap := mClock.Trap().NewTicker("HeartbeatClose")
trap := mClock.Trap().NewTicker("WSWatcher")
defer trap.Close()
serverConn := websocketPair(ctx, t)
exitCalled := make(chan struct{})
go heartbeatCloseWith(ctx, logger, func() {
close(exitCalled)
}, serverConn, mClock, time.Second)
w := &WSWatcher{rec: rec.record, clk: mClock, interval: time.Second}
watchCtx := w.Watch(ctx, logger, serverConn)
// Wait for the ticker to be created, then release.
trap.MustWait(ctx).MustRelease(ctx)
// Close the server-side connection before the tick fires.
// The next ping will get net.ErrClosed.
// The next ping will get a close/net.ErrClosed error.
_ = serverConn.Close(websocket.StatusGoingAway, "simulated teardown")
// Advance clock to trigger the tick.
mClock.Advance(time.Second).MustWait(ctx)
// Wait for heartbeatClose to call exit.
// The watch context should be canceled after probe failure.
select {
case <-exitCalled:
case <-watchCtx.Done():
case <-ctx.Done():
t.Fatal("timed out waiting for heartbeatClose to call exit")
t.Fatal("timed out waiting for watch context to be canceled")
}
// A closed connection is a normal shutdown condition. The
@@ -100,6 +131,9 @@ func TestHeartbeatClose(t *testing.T) {
debugEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelDebug })
assert.NotEmpty(t, debugEntries,
"expected a debug-level log entry for the closed connection")
assert.Zero(t, rec.count(ProbeOK), "expected no successful probes")
assert.Equal(t, 1, rec.len(), "expected exactly one probe recorded")
assert.Equal(t, 1, rec.count(ProbePeerClosed), "expected one peer_closed probe")
})
t.Run("ContextCanceled", func(t *testing.T) {
@@ -109,36 +143,33 @@ func TestHeartbeatClose(t *testing.T) {
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
rec := &probeRecords{}
trap := mClock.Trap().NewTicker("HeartbeatClose")
trap := mClock.Trap().NewTicker("WSWatcher")
defer trap.Close()
serverCtx, serverCancel := context.WithCancel(ctx)
serverConn := websocketPair(ctx, t)
done := make(chan struct{})
go func() {
defer close(done)
heartbeatCloseWith(serverCtx, logger, func() {
t.Error("exit should not be called on context cancel")
}, serverConn, mClock, time.Second)
}()
w := &WSWatcher{rec: rec.record, clk: mClock, interval: time.Second}
watchCtx := w.Watch(serverCtx, logger, serverConn)
trap.MustWait(ctx).MustRelease(ctx)
// Cancel the context. HeartbeatClose should return via
// the <-ctx.Done() branch without calling exit.
// Cancel the parent context. The watcher should exit via
// the <-ctx.Done() branch without closing the conn.
serverCancel()
select {
case <-done:
case <-watchCtx.Done():
case <-ctx.Done():
t.Fatal("timed out waiting for heartbeatClose to return")
t.Fatal("timed out waiting for watch context to be canceled")
}
errorEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelError })
assert.Empty(t, errorEntries,
"context cancellation should not produce error-level logs, got: %+v", errorEntries)
assert.Zero(t, rec.len(), "expected no probes when context is canceled before tick")
})
t.Run("PingSucceeds", func(t *testing.T) {
@@ -148,30 +179,30 @@ func TestHeartbeatClose(t *testing.T) {
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
rec := &probeRecords{}
trap := mClock.Trap().NewTicker("HeartbeatClose")
trap := mClock.Trap().NewTicker("WSWatcher")
defer trap.Close()
serverConn := websocketPair(ctx, t)
exitCalled := make(chan struct{}, 1)
go heartbeatCloseWith(ctx, logger, func() {
exitCalled <- struct{}{}
}, serverConn, mClock, time.Second)
w := &WSWatcher{rec: rec.record, clk: mClock, interval: time.Second}
watchCtx := w.Watch(ctx, logger, serverConn)
trap.MustWait(ctx).MustRelease(ctx)
// Fire several ticks pings should succeed each time.
for range 3 {
// Fire several ticks; pings should succeed each time.
for i := range 3 {
mClock.Advance(time.Second).MustWait(ctx)
// Give the ping round-trip time to complete.
// If exit were called, we'd catch it.
select {
case <-exitCalled:
t.Fatal("exit should not be called when pings succeed")
default:
}
testutil.Eventually(ctx, t, func(context.Context) bool {
select {
case <-watchCtx.Done():
t.Fatal("watch context should not be canceled when pings succeed")
default:
}
return rec.count(ProbeOK) == i+1
}, testutil.IntervalFast, "probe counter not incremented at tick %d", i+1)
}
// No logs should be emitted during normal operation.
@@ -181,5 +212,183 @@ func TestHeartbeatClose(t *testing.T) {
debugEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelDebug })
assert.Empty(t, debugEntries,
"successful pings should not produce debug-level logs, got: %+v", debugEntries)
assert.Equal(t, 3, rec.count(ProbeOK), "expected 3 successful probes")
})
t.Run("RecordsPrometheusCounter", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
// Use a real prometheus registry to verify end-to-end metric recording.
registry := prometheus.NewRegistry()
probes := prometheus.NewCounterVec(prometheus.CounterOpts{
Namespace: "coderd",
Subsystem: "api",
Name: "websocket_probes_total",
Help: "test",
}, []string{"path", "result"})
registry.MustRegister(probes)
recorder := func(ctx context.Context, r ProbeResult) {
probes.WithLabelValues("/test/path", string(r)).Inc()
}
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
trap := mClock.Trap().NewTicker("WSWatcher")
defer trap.Close()
serverConn := websocketPair(ctx, t)
w := &WSWatcher{rec: recorder, clk: mClock, interval: time.Second}
watchCtx := w.Watch(ctx, logger, serverConn)
trap.MustWait(ctx).MustRelease(ctx)
mClock.Advance(time.Second).MustWait(ctx)
testutil.Eventually(ctx, t, func(context.Context) bool {
select {
case <-watchCtx.Done():
t.Fatal("watch context should not be canceled when pings succeed")
default:
}
metrics, err := registry.Gather()
require.NoError(t, err)
return testutil.PromCounterHasValue(t, metrics, 1,
"coderd_api_websocket_probes_total", "/test/path", "ok")
}, testutil.IntervalFast, "probe counter not incremented")
})
t.Run("ProbeTimeout", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
rec := &probeRecords{}
trap := mClock.Trap().NewTicker("WSWatcher")
defer trap.Close()
// Set up a websocket pair manually. Do NOT call CloseRead
// on the client so pong frames are never sent back.
serverConnCh := make(chan *websocket.Conn, 1)
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
conn, err := websocket.Accept(w, r, nil)
if err != nil {
return
}
serverConnCh <- conn
<-ctx.Done()
}))
t.Cleanup(srv.Close)
//nolint:bodyclose
clientConn, _, err := websocket.Dial(ctx, srv.URL, nil)
require.NoError(t, err)
// Intentionally NOT calling clientConn.CloseRead, so pongs won't be processed.
t.Cleanup(func() {
_ = clientConn.Close(websocket.StatusNormalClosure, "test cleanup")
})
var serverConn *websocket.Conn
select {
case sc := <-serverConnCh:
_ = sc.CloseRead(ctx)
serverConn = sc
case <-ctx.Done():
t.Fatal("timed out waiting for server websocket accept")
}
// Use a very short interval so the real context.WithTimeout
// inside probe() expires quickly when pongs aren't coming.
w := &WSWatcher{rec: rec.record, clk: mClock, interval: time.Millisecond}
watchCtx := w.Watch(ctx, logger, serverConn)
trap.MustWait(ctx).MustRelease(ctx)
mClock.Advance(time.Millisecond).MustWait(ctx)
// Wait for the watch context to be canceled (probe failure).
select {
case <-watchCtx.Done():
case <-ctx.Done():
t.Fatal("timed out waiting for watch context to be canceled")
}
assert.Equal(t, 1, rec.count(ProbeTimeout), "expected one timeout probe")
// Timeout is an expected condition, should be Debug not Error.
errorEntries := sink.Entries(func(e slog.SinkEntry) bool { return e.Level == slog.LevelError })
assert.Empty(t, errorEntries,
"probe timeout should not produce error-level logs, got: %+v", errorEntries)
})
t.Run("ProbeError", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitShort)
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
mClock := quartz.NewMock(t)
rec := &probeRecords{}
trap := mClock.Trap().NewTicker("WSWatcher")
defer trap.Close()
fConn := &fakePingCloser{
pingErr: xerrors.New("unexpected internal error"),
}
w := &WSWatcher{rec: rec.record, clk: mClock, interval: time.Second}
watchCtx := w.Watch(ctx, logger, fConn)
trap.MustWait(ctx).MustRelease(ctx)
mClock.Advance(time.Second).MustWait(ctx)
// Wait for the watch context to be canceled (probe failure).
select {
case <-watchCtx.Done():
case <-ctx.Done():
t.Fatal("timed out waiting for watch context to be canceled")
}
assert.Equal(t, 1, rec.count(ProbeError), "expected one error probe")
// ProbeError should log at Error level (unlike other failures).
errorEntries := sink.Entries(func(e slog.SinkEntry) bool {
return e.Level == slog.LevelError
})
assert.NotEmpty(t, errorEntries, "ProbeError should produce error-level log")
// Connection should be closed with StatusGoingAway.
fConn.mu.Lock()
assert.True(t, fConn.closed, "connection should be closed on probe error")
assert.Equal(t, websocket.StatusGoingAway, fConn.code)
fConn.mu.Unlock()
})
}
// fakePingCloser is a test double for the pingCloser interface.
type fakePingCloser struct {
mu sync.Mutex
pingErr error
closed bool
code websocket.StatusCode
reason string
}
func (f *fakePingCloser) Ping(context.Context) error {
f.mu.Lock()
defer f.mu.Unlock()
return f.pingErr
}
func (f *fakePingCloser) Close(code websocket.StatusCode, reason string) error {
f.mu.Lock()
defer f.mu.Unlock()
f.closed = true
f.code = code
f.reason = reason
return nil
}