MM-51700: Suppress websocket warnings with a threshold (#22637)

We log warnings whenever our websocket buffer sizes exceed
certain thresholds. The problem with that is, when this happens,
the logs are completely spammed with these lines
making it annoying for the customer.

To improve the situation, we use a timer that only gets reset
every minute.

https://mattermost.atlassian.net/browse/MM-51700

```release-note
NONE
```
Этот коммит содержится в:
Agniva De Sarker
2023-03-28 09:04:09 +05:30
коммит произвёл GitHub
родитель dc4e7bf2ec
Коммит 2287dff298

Просмотреть файл

@@ -27,15 +27,16 @@ import (
) )
const ( const (
sendQueueSize = 256 sendQueueSize = 256
sendSlowWarn = (sendQueueSize * 50) / 100 sendSlowWarn = (sendQueueSize * 50) / 100
sendFullWarn = (sendQueueSize * 95) / 100 sendFullWarn = (sendQueueSize * 95) / 100
writeWaitTime = 30 * time.Second writeWaitTime = 30 * time.Second
pongWaitTime = 100 * time.Second pongWaitTime = 100 * time.Second
pingInterval = (pongWaitTime * 6) / 10 pingInterval = (pongWaitTime * 6) / 10
authCheckInterval = 5 * time.Second authCheckInterval = 5 * time.Second
webConnMemberCacheTime = 1000 * 60 * 30 // 30 minutes webConnMemberCacheTime = 1000 * 60 * 30 // 30 minutes
deadQueueSize = 128 // Approximated from /proc/sys/net/core/wmem_default / 2048 (avg msg size) deadQueueSize = 128 // Approximated from /proc/sys/net/core/wmem_default / 2048 (avg msg size)
websocketSuppressWarnThreshold = time.Minute
) )
const ( const (
@@ -112,6 +113,13 @@ type WebConn struct {
endWritePump chan struct{} endWritePump chan struct{}
pumpFinished chan struct{} pumpFinished chan struct{}
pluginPosted chan pluginWSPostedHook pluginPosted chan pluginWSPostedHook
// These counters are to suppress spammy websocket.slow
// and websocket.full logs which happen continuously, if they
// do happen. To improve the situation, we log them only once
// per minute.
lastLogTimeSlow time.Time
lastLogTimeFull time.Time
} }
// CheckConnResult indicates whether a connectionID was present in the hub or not. // CheckConnResult indicates whether a connectionID was present in the hub or not.
@@ -215,6 +223,8 @@ func (ps *PlatformService) NewWebConn(cfg *WebConnConfig, suite SuiteIFace, runn
endWritePump: make(chan struct{}), endWritePump: make(chan struct{}),
pumpFinished: make(chan struct{}), pumpFinished: make(chan struct{}),
pluginPosted: make(chan pluginWSPostedHook, 10), pluginPosted: make(chan pluginWSPostedHook, 10),
lastLogTimeSlow: time.Now(),
lastLogTimeFull: time.Now(),
} }
wc.SetSession(&cfg.Session) wc.SetSession(&cfg.Session)
@@ -460,7 +470,7 @@ func (wc *WebConn) writePump() {
continue continue
} }
if len(wc.send) >= sendFullWarn { if len(wc.send) >= sendFullWarn && time.Since(wc.lastLogTimeFull) > websocketSuppressWarnThreshold {
logData := []mlog.Field{ logData := []mlog.Field{
mlog.String("user_id", wc.UserId), mlog.String("user_id", wc.UserId),
mlog.String("type", msg.EventType()), mlog.String("type", msg.EventType()),
@@ -471,6 +481,7 @@ func (wc *WebConn) writePump() {
} }
mlog.Warn("websocket.full", logData...) mlog.Warn("websocket.full", logData...)
wc.lastLogTimeFull = time.Now()
} }
if evtOk { if evtOk {
@@ -711,11 +722,15 @@ func (wc *WebConn) ShouldSendEvent(msg *model.WebSocketEvent) bool {
case model.WebsocketEventTyping, case model.WebsocketEventTyping,
model.WebsocketEventStatusChange, model.WebsocketEventStatusChange,
model.WebsocketEventChannelViewed: model.WebsocketEventChannelViewed:
mlog.Warn( if time.Since(wc.lastLogTimeSlow) > websocketSuppressWarnThreshold {
"websocket.slow: dropping message", mlog.Warn(
mlog.String("user_id", wc.UserId), "websocket.slow: dropping message",
mlog.String("type", msg.EventType()), mlog.String("user_id", wc.UserId),
) mlog.String("type", msg.EventType()),
)
// Reset timer to now.
wc.lastLogTimeSlow = time.Now()
}
return false return false
} }
} }