Add detailed peer closure logging in reader loop.

This commit is contained in:
Jay
2026-04-16 18:29:21 -04:00
parent 00c79d2170
commit 431aa4791c
2 changed files with 79 additions and 12 deletions

View File

@@ -1,6 +1,7 @@
package honeybee
import (
stderrors "errors"
"fmt"
"log/slog"
"net/url"
@@ -175,7 +176,23 @@ func (c *Connection) startReader() {
messageType, data, err := c.socket.ReadMessage()
if err != nil {
if c.logger != nil {
c.logger.Error("read error", "error", err)
var closeErr *websocket.CloseError
if stderrors.As(err, &closeErr) {
switch closeErr.Code {
case websocket.CloseNormalClosure, websocket.CloseGoingAway:
c.logger.Info("connection closed by peer",
"code", closeErr.Code,
"text", closeErr.Text,
)
default:
c.logger.Error("unexpected close",
"code", closeErr.Code,
"text", closeErr.Text,
)
}
} else {
c.logger.Error("read error", "error", err)
}
}
select {
case c.errors <- err:

View File

@@ -2,12 +2,14 @@ package honeybee
import (
"fmt"
"io"
"log/slog"
"net/http"
"strings"
"testing"
"time"
"github.com/gorilla/websocket"
"github.com/stretchr/testify/assert"
)
@@ -315,31 +317,79 @@ func TestCloseLogging(t *testing.T) {
}
func TestReaderLogging(t *testing.T) {
t.Run("read message error", func(t *testing.T) {
t.Run("clean close by peer", func(t *testing.T) {
mockHandler := newMockSlogHandler()
logger := slog.New(mockHandler)
readErr := fmt.Errorf("read error")
mockSocket := NewMockSocket()
mockSocket.ReadMessageFunc = func() (int, []byte, error) {
return 0, nil, readErr
return 0, nil, &websocket.CloseError{
Code: websocket.CloseNormalClosure,
Text: "goodbye",
}
}
conn, err := NewConnectionFromSocket(mockSocket, nil, logger)
assert.NoError(t, err)
defer conn.Close()
assert.Eventually(t, func() bool {
return findLogRecord(
mockHandler.GetRecords(), slog.LevelInfo, "connection closed by peer") != nil
}, testTimeout, testTick)
record := findLogRecord(mockHandler.GetRecords(), slog.LevelInfo, "connection closed by peer")
assert.NotNil(t, record)
assertAttributePresent(t, *record, "code", websocket.CloseNormalClosure)
assertAttributePresent(t, *record, "text", "goodbye")
})
t.Run("unexpected close", func(t *testing.T) {
mockHandler := newMockSlogHandler()
logger := slog.New(mockHandler)
mockSocket := NewMockSocket()
mockSocket.ReadMessageFunc = func() (int, []byte, error) {
return 0, nil, &websocket.CloseError{
Code: websocket.CloseProtocolError,
Text: "bad protocol",
}
}
conn, err := NewConnectionFromSocket(mockSocket, nil, logger)
assert.NoError(t, err)
defer conn.Close()
assert.Eventually(t, func() bool {
return findLogRecord(
mockHandler.GetRecords(), slog.LevelError, "unexpected close") != nil
}, testTimeout, testTick)
record := findLogRecord(mockHandler.GetRecords(), slog.LevelError, "unexpected close")
assert.NotNil(t, record)
assertAttributePresent(t, *record, "code", websocket.CloseProtocolError)
assertAttributePresent(t, *record, "text", "bad protocol")
})
t.Run("read error", func(t *testing.T) {
mockHandler := newMockSlogHandler()
logger := slog.New(mockHandler)
mockSocket := NewMockSocket()
mockSocket.ReadMessageFunc = func() (int, []byte, error) {
return 0, nil, io.EOF
}
conn, err := NewConnectionFromSocket(mockSocket, nil, logger)
assert.NoError(t, err)
defer conn.Close()
assert.Eventually(t, func() bool {
return findLogRecord(
mockHandler.GetRecords(), slog.LevelError, "read error") != nil
}, testTimeout, testTick)
records := mockHandler.GetRecords()
record := findLogRecord(records, slog.LevelError, "read error")
assert.NotNil(t, record)
assertAttributePresent(t, *record, "error", readErr)
conn.Close()
})
}