From 023a5296cf547d9091ce9f1e361f62610f31e8e6 Mon Sep 17 00:00:00 2001 From: nudgebee-bot Date: Tue, 27 Oct 2026 03:30:03 +0000 Subject: [PATCH] fix: log expected websocket session terminations at Warn level in Client.Run MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit # Description In `pkg/ws/client.go`, `Client.Run` unconditionally logs all errors returned by `c.connectAndServe(ctx)` at `Error` level using `c.logger.Error("websocket session ended", "err", err)`. During normal client shutdown or expected network reconnect cycles (such as normal disconnects, abnormal close 1006, `net.ErrClosed`, `io.EOF`, or context cancellation), this causes false error alerts in log monitors. To resolve this, this change: 1. Adds helper function `isExpectedDisconnect(err error) bool` to check if an error matches `context.Canceled`, `net.ErrClosed`, `io.EOF`, or WebSocket close codes `CloseNormalClosure`, `CloseGoingAway`, or `CloseAbnormalClosure` (1006) using `errors.Is` and `errors.As`. 2. Updates `Client.Run` to log expected disconnections at `Warn` level (`c.logger.Warn("websocket session ended", "err", err)`) while continuing to log unexpected or unrecoverable errors at `Error` level. ## 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 ``` In `pkg/ws/client.go`, modify `Client.Run` to log session terminations at `Info` or `Warn` level rather than `Error` when the error is a normal disconnect, abnormal close (1006), `net.ErrClosed`, `io.EOF`, or context cancellation. This prevents expected reconnect cycles from tripping log error alerts. Files located during the investigation: pkg/ws/client.go The investigation already read this code: **Code examined** - `pkg/ws/client.go`:120-123 — Unconditional error-level logging in the auto-reconnection loop ``` err := c.connectAndServe(ctx) if err != nil { c.logger.Error("websocket session ended", "err", err) } ``` - `pkg/ws/client.go`:218-224 — Closing the connection on context cancellation triggers a read error on the blocking ReadMessage call ``` wg.Add(1) go func() { defer wg.Done() <-ctx.Done() _ = conn.WriteMessage(websocket.CloseMessage, websocket.FormatCloseMessage(websocket.CloseNormalClosure, "")) _ = conn.Close() }() ``` - `pkg/ws/client.go`:269-275 — Only CloseNormalClosure and CloseGoingAway are ignored; all other disconnections return an error ``` _, 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=e899cb94-8e78-46b2-b90f-584f609be0d7)** *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: downloading github.com/spf13/viper v1.21.0 go: downloading gopkg.in/yaml.v3 v3.0.1 go: downloading github.com/ClickHouse/clickhouse-go/v2 v2.48.0 go: downloading github.com/go-sql-driver/mysql v1.10.0 go: downloading github.com/jackc/pgx/v5 v5.10.0 go: downloading github.com/microsoft/go-mssqldb v1.10.0 go: downloading github.com/sijms/go-ora/v2 v2.9.0 go: downloading github.com/go-ldap/ldap/v3 v3.4.14 go: downloading golang.org/x/crypto v0.57.0 go: downloading golang.org/x/time v0.15.0 go: downloading github.com/IBM/sarama v1.60.1 go: downloading github.com/xdg-go/scram v1.2.0 go: downloading go.mongodb.org/mongo-driver/v2 v2.8.0 go: downloading github.com/redis/go-redis/v9 v9.22.0 go: downloading github.com/pkg/sftp v1.13.11 go: downloading cloud.google.com/go/auth v0.23.1 go: downloading cloud.google.com/go/secretmanager v1.21.0 go: downloading github.com/Azure/azure-sdk-for-go/sdk/azcore v1.23.0 go: downloading github.com/Azure/azure-sdk-for-go/sdk/azidentity v1.14.0 go: downloading github.com/Azure/azure-sdk-for-go/sdk/security/keyvault/azsecrets v1.5.0 go: downloading github.com/aws/aws-sdk-go-v2/config v1.32.37 go: downloading github.com/aws/aws-sdk-go-v2/service/secretsmanager v1.44.6 go: downloading github.com/aws/aws-sdk-go-v2 v1.43.6 go: downloading github.com/google/uuid v1.6.0 go: downloading google.golang.org/api v0.293.0 go: downloading github.com/fsnotify/fsnotify v1.9.0 go: downloading github.com/go-viper/mapstructur… ```
--- go.mod | 2 +- pkg/ws/client.go | 27 ++++++++++- pkg/ws/client_test.go | 110 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 137 insertions(+), 2 deletions(-) create mode 100644 pkg/ws/client_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..2a567e5 100644 --- a/pkg/ws/client.go +++ b/pkg/ws/client.go @@ -4,9 +4,11 @@ import ( "context" "encoding/base64" "encoding/json" + "errors" "fmt" "io" "log/slog" + "net" "net/http" "sync" "time" @@ -119,7 +121,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 isExpectedDisconnect(err) { + c.logger.Warn("websocket session ended", "err", err) + } else { + c.logger.Error("websocket session ended", "err", err) + } } select { @@ -137,6 +143,25 @@ func (c *Client) Run(ctx context.Context) error { } } +func isExpectedDisconnect(err error) bool { + if errors.Is(err, context.Canceled) || errors.Is(err, net.ErrClosed) || errors.Is(err, io.EOF) { + return true + } + var closeErr *websocket.CloseError + if errors.As(err, &closeErr) { + return websocket.IsCloseError(closeErr, + websocket.CloseNormalClosure, + websocket.CloseGoingAway, + websocket.CloseAbnormalClosure, + ) + } + return websocket.IsCloseError(err, + websocket.CloseNormalClosure, + websocket.CloseGoingAway, + websocket.CloseAbnormalClosure, + ) +} + func (c *Client) connectAndServe(ctx context.Context) error { // Build auth header auth := base64.StdEncoding.EncodeToString([]byte(c.accessKey + ":" + c.accessSecret)) diff --git a/pkg/ws/client_test.go b/pkg/ws/client_test.go new file mode 100644 index 0000000..05d5277 --- /dev/null +++ b/pkg/ws/client_test.go @@ -0,0 +1,110 @@ +package ws + +import ( + "context" + "errors" + "fmt" + "io" + "net" + "testing" + + "github.com/gorilla/websocket" +) + +func TestIsExpectedDisconnect(t *testing.T) { + tests := []struct { + name string + err error + expected bool + }{ + { + name: "nil error", + err: nil, + expected: false, + }, + { + name: "context.Canceled", + err: context.Canceled, + expected: true, + }, + { + name: "wrapped context.Canceled", + err: fmt.Errorf("connection context done: %w", context.Canceled), + expected: true, + }, + { + name: "net.ErrClosed", + err: net.ErrClosed, + expected: true, + }, + { + name: "wrapped net.ErrClosed", + err: fmt.Errorf("socket closed: %w", net.ErrClosed), + expected: true, + }, + { + name: "io.EOF", + err: io.EOF, + expected: true, + }, + { + name: "wrapped io.EOF", + err: fmt.Errorf("read error: %w", io.EOF), + expected: true, + }, + { + name: "websocket CloseNormalClosure", + err: &websocket.CloseError{ + Code: websocket.CloseNormalClosure, + Text: "normal closure", + }, + expected: true, + }, + { + name: "websocket CloseGoingAway", + err: &websocket.CloseError{ + Code: websocket.CloseGoingAway, + Text: "going away", + }, + expected: true, + }, + { + name: "websocket CloseAbnormalClosure", + err: &websocket.CloseError{ + Code: websocket.CloseAbnormalClosure, + Text: "abnormal closure", + }, + expected: true, + }, + { + name: "wrapped CloseAbnormalClosure", + err: fmt.Errorf("read error: %w", &websocket.CloseError{ + Code: websocket.CloseAbnormalClosure, + Text: "unexpected EOF", + }), + expected: true, + }, + { + name: "websocket CloseProtocolError", + err: &websocket.CloseError{ + Code: websocket.CloseProtocolError, + Text: "protocol error", + }, + expected: false, + }, + { + name: "generic unexpected error", + err: errors.New("unexpected database error"), + expected: false, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + actual := isExpectedDisconnect(tc.err) + if actual != tc.expected { + t.Errorf("isExpectedDisconnect(%v) = %v, want %v", tc.err, actual, tc.expected) + } + }) + } +}