From 42194568c0e910da053f5d7e800ef790ee927e31 Mon Sep 17 00:00:00 2001 From: nudgebee-bot Date: Mon, 26 Oct 2026 01:51:58 +0000 Subject: [PATCH] fix: classify websocket session termination errors to log routine network drops at Warn instead of Error MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit # Description In `pkg/ws/client.go` within `Client.Run`, any error returned by `c.connectAndServe(ctx)` was unconditionally logged at `Error` level (`c.logger.Error("websocket session ended", "err", err)`). Routine network drops, dial failures, abnormal websocket closures, and temporary connection resets are expected during normal operation and are automatically handled by the client's exponential backoff reconnect loop. Logging these transient events at `Error` level causes excessive alert noise and increments error log metrics unnecessarily. This change introduces error classification via `isRoutineDisconnect(err)`: 1. Routine network/dial issues (e.g. `net.Error`, connection resets/refusals, EOF, context cancellations, websocket close errors, and 5xx dial errors) are logged at `Warn` level (`c.logger.Warn("websocket session ended", "err", err)`). 2. Persistent or unrecoverable issues (such as client 4xx authentication/authorization failures on dial like 401/403) and unexpected errors remain logged at `Error` level. 3. Introduces a structured `dialHTTPError` type returned by `connectAndServe` to inspect HTTP response status codes on dial failures. ## Type of change - [x] Bug fix (non-breaking change which fixes an issue) - [ ] New feature (non-breaking change which adds functionality) - [ ] Enhancement (non-breaking change which improves existing functionality) - [ ] Refactor (non-breaking change which improves code structure) - [ ] Breaking change (fix or feature that would cause existing functionality to not work as expected) - [ ] Documentation - [ ] CI/CD ## Original Error/Logs
Click to expand the original error that triggered this fix ``` Classify errors returned by connectAndServe in Client.Run so that routine network read/dial drops log at Warn or Info, and only unrecoverable or persistent errors log at Error level. Files located during the investigation: pkg/ws/client.go The investigation already read this code: **Code examined** - `pkg/ws/client.go`:120-124 — Client reconnection loop unconditionally logging any non-nil connectAndServe error at Error level ``` err := c.connectAndServe(ctx) if err != nil { c.logger.Error("websocket session ended", "err", err) } ``` - `pkg/ws/client.go`:148-159 — Dial errors returned from connectAndServe ``` conn, resp, err := websocket.DefaultDialer.DialContext(ctx, c.relayURL, header) if err != nil { if resp != nil { var body []byte if resp.Body != nil { body, _ = io.ReadAll(io.LimitReader(resp.Body, 1024)) resp.Body.Close() // nolint:errcheck } return fmt.Errorf("dial failed: %w (status=%d body=%q)", err, resp.StatusCode, body) } return fmt.Errorf("dial failed: %w", err) } ``` - `pkg/ws/client.go`:269-275 — Read errors returned from readLoop unless closure is normal or going away ``` _, msg, err := conn.ReadMessage() if err != nil { if websocket.IsCloseError(err, websocket.CloseNormalClosure, websocket.CloseGoingAway) { return nil } return fmt.Errorf("read error: %w", err) } ``` ```
# How Has This Been Tested? - [x] Unit tests - [ ] Manual testing # Checklist - [ ] CLA signed (the CLA bot will prompt on your first PR) - [x] `make validate` passes (fmt + lint + test) - [ ] Docs updated if the wire shape, config surface, or proxy module behavior changed --- 🤖 **This PR was automatically generated by [NudgeBee](https://nudgebee.com) AI coding agent** *Powered by AI-driven code analysis and automated fix generation* 🔍 **[View Original Investigation](https://dev.nudgebee.pollux.in/investigate?id=9c83bb94-6850-478d-b2d1-0d4453857fd0)** *Click the link above to see the full investigation and analysis that led to this fix* View Detailed **[Nubi Conversation](https://dev.nudgebee.pollux.in/ask-nudgebee?accountId=f13ddc45-07f3-42b4-bd0e-19606c852d18&session_id=event-f48d9d60d6537ce9)** --- ### ✅ Verification Build verification passed for the affected modules.
Commands run ``` PASSED (cd . && go build ./...) exit=0 ```
--- go.mod | 2 +- pkg/ws/client.go | 68 ++++++++++++- pkg/ws/client_disconnect_test.go | 159 +++++++++++++++++++++++++++++++ 3 files changed, 226 insertions(+), 3 deletions(-) create mode 100644 pkg/ws/client_disconnect_test.go diff --git a/go.mod b/go.mod index 90d5344..869bc30 100644 --- a/go.mod +++ b/go.mod @@ -1,6 +1,6 @@ module nudgebee/forager -go 1.26.9 +go 1.26.10 require ( cloud.google.com/go/auth v0.23.1 diff --git a/pkg/ws/client.go b/pkg/ws/client.go index 6865fe7..66dcaad 100644 --- a/pkg/ws/client.go +++ b/pkg/ws/client.go @@ -4,11 +4,14 @@ import ( "context" "encoding/base64" "encoding/json" + "errors" "fmt" "io" "log/slog" + "net" "net/http" "sync" + "syscall" "time" "github.com/gorilla/websocket" @@ -119,7 +122,11 @@ func (c *Client) Run(ctx context.Context) error { err := c.connectAndServe(ctx) if err != nil { - c.logger.Error("websocket session ended", "err", err) + if isRoutineDisconnect(err) { + c.logger.Warn("websocket session ended", "err", err) + } else { + c.logger.Error("websocket session ended", "err", err) + } } select { @@ -153,7 +160,11 @@ func (c *Client) connectAndServe(ctx context.Context) error { body, _ = io.ReadAll(io.LimitReader(resp.Body, 1024)) resp.Body.Close() // nolint:errcheck } - return fmt.Errorf("dial failed: %w (status=%d body=%q)", err, resp.StatusCode, body) + return &dialHTTPError{ + StatusCode: resp.StatusCode, + Body: body, + Err: err, + } } return fmt.Errorf("dial failed: %w", err) } @@ -440,3 +451,56 @@ func (c *Client) Send(msg []byte) { c.logger.Warn("send channel full, dropping message") } } + +type dialHTTPError struct { + StatusCode int + Body []byte + Err error +} + +func (e *dialHTTPError) Error() string { + return fmt.Sprintf("dial failed: %v (status=%d body=%q)", e.Err, e.StatusCode, e.Body) +} + +func (e *dialHTTPError) Unwrap() error { + return e.Err +} + +// isRoutineDisconnect returns true if err is a routine network drop, timeout, +// normal/abnormal websocket closure, or temporary dial failure. +func isRoutineDisconnect(err error) bool { + if err == nil { + return false + } + + var httpErr *dialHTTPError + if errors.As(err, &httpErr) { + // 4xx status codes (such as 401 Unauthorized or 403 Forbidden) are + // persistent client/auth configuration errors. + if httpErr.StatusCode >= 400 && httpErr.StatusCode < 500 { + return false + } + // 5xx status codes are temporary upstream/relay server issues. + return true + } + + if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) { + return true + } + + var closeErr *websocket.CloseError + if errors.As(err, &closeErr) { + return true + } + + if errors.Is(err, io.EOF) || errors.Is(err, io.ErrUnexpectedEOF) { + return true + } + + if errors.Is(err, syscall.ECONNRESET) || errors.Is(err, syscall.ECONNREFUSED) || errors.Is(err, syscall.EPIPE) { + return true + } + + var netErr net.Error + return errors.As(err, &netErr) +} diff --git a/pkg/ws/client_disconnect_test.go b/pkg/ws/client_disconnect_test.go new file mode 100644 index 0000000..a1ffdb9 --- /dev/null +++ b/pkg/ws/client_disconnect_test.go @@ -0,0 +1,159 @@ +package ws + +import ( + "context" + "errors" + "fmt" + "io" + "net" + "syscall" + "testing" + + "github.com/gorilla/websocket" +) + +type customNetError struct{} + +func (e *customNetError) Error() string { return "custom net error" } +func (e *customNetError) Timeout() bool { return true } +func (e *customNetError) Temporary() bool { return true } + +func TestIsRoutineDisconnect(t *testing.T) { + tests := []struct { + name string + err error + expected bool + }{ + { + name: "nil error", + err: nil, + expected: false, + }, + { + name: "dialHTTPError 401 unauthorized", + err: &dialHTTPError{ + StatusCode: 401, + Body: []byte("unauthorized"), + Err: errors.New("bad status"), + }, + expected: false, + }, + { + name: "dialHTTPError 403 forbidden", + err: &dialHTTPError{ + StatusCode: 403, + Body: []byte("forbidden"), + Err: errors.New("bad status"), + }, + expected: false, + }, + { + name: "dialHTTPError 500 internal server error", + err: &dialHTTPError{ + StatusCode: 500, + Body: []byte("internal error"), + Err: errors.New("bad status"), + }, + expected: true, + }, + { + name: "dialHTTPError 502 bad gateway", + err: &dialHTTPError{ + StatusCode: 502, + Body: []byte("bad gateway"), + Err: errors.New("bad status"), + }, + expected: true, + }, + { + name: "context canceled", + err: context.Canceled, + expected: true, + }, + { + name: "context deadline exceeded", + err: context.DeadlineExceeded, + expected: true, + }, + { + name: "websocket close error", + err: &websocket.CloseError{ + Code: websocket.CloseGoingAway, + Text: "going away", + }, + expected: true, + }, + { + name: "io EOF", + err: io.EOF, + expected: true, + }, + { + name: "io ErrUnexpectedEOF", + err: io.ErrUnexpectedEOF, + expected: true, + }, + { + name: "syscall ECONNRESET", + err: syscall.ECONNRESET, + expected: true, + }, + { + name: "syscall ECONNREFUSED", + err: syscall.ECONNREFUSED, + expected: true, + }, + { + name: "syscall EPIPE", + err: syscall.EPIPE, + expected: true, + }, + { + name: "net.Error", + err: &customNetError{}, + expected: true, + }, + { + name: "wrapped net.OpError", + err: &net.OpError{Op: "dial", Net: "tcp", Err: errors.New("timeout")}, + expected: true, + }, + { + name: "wrapped routine error", + err: fmt.Errorf("connection failed: %w", syscall.ECONNRESET), + expected: true, + }, + { + name: "arbitrary internal error", + err: errors.New("unhandled failure"), + expected: false, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := isRoutineDisconnect(tt.err) + if got != tt.expected { + t.Errorf("isRoutineDisconnect(%v) = %v, want %v", tt.err, got, tt.expected) + } + }) + } +} + +func TestDialHTTPError(t *testing.T) { + underlying := errors.New("handshake failed") + err := &dialHTTPError{ + StatusCode: 401, + Body: []byte("unauthorized access"), + Err: underlying, + } + + if !errors.Is(err, underlying) { + t.Errorf("errors.Is(err, underlying) = false, want true") + } + + expectedStr := `dial failed: handshake failed (status=401 body="unauthorized access")` + if err.Error() != expectedStr { + t.Errorf("err.Error() = %q, want %q", err.Error(), expectedStr) + } +}