From 2287dff298b7d240ac095f7bc2cd9da6a56b472d Mon Sep 17 00:00:00 2001
From: Agniva De Sarker <agnivade@yahoo.co.in>
Date: Tue, 28 Mar 2023 09:04:09 +0530
Subject: [PATCH] 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
```
---
 server/channels/app/platform/web_conn.go | 45 ++++++++++++++++--------
 1 file changed, 30 insertions(+), 15 deletions(-)

diff --git a/server/channels/app/platform/web_conn.go b/server/channels/app/platform/web_conn.go
index 02b8cd8687..ac72c98cdf 100644
--- a/server/channels/app/platform/web_conn.go
+++ b/server/channels/app/platform/web_conn.go
@@ -27,15 +27,16 @@ import (
 )
 
 const (
-	sendQueueSize          = 256
-	sendSlowWarn           = (sendQueueSize * 50) / 100
-	sendFullWarn           = (sendQueueSize * 95) / 100
-	writeWaitTime          = 30 * time.Second
-	pongWaitTime           = 100 * time.Second
-	pingInterval           = (pongWaitTime * 6) / 10
-	authCheckInterval      = 5 * time.Second
-	webConnMemberCacheTime = 1000 * 60 * 30 // 30 minutes
-	deadQueueSize          = 128            // Approximated from /proc/sys/net/core/wmem_default / 2048 (avg msg size)
+	sendQueueSize                  = 256
+	sendSlowWarn                   = (sendQueueSize * 50) / 100
+	sendFullWarn                   = (sendQueueSize * 95) / 100
+	writeWaitTime                  = 30 * time.Second
+	pongWaitTime                   = 100 * time.Second
+	pingInterval                   = (pongWaitTime * 6) / 10
+	authCheckInterval              = 5 * time.Second
+	webConnMemberCacheTime         = 1000 * 60 * 30 // 30 minutes
+	deadQueueSize                  = 128            // Approximated from /proc/sys/net/core/wmem_default / 2048 (avg msg size)
+	websocketSuppressWarnThreshold = time.Minute
 )
 
 const (
@@ -112,6 +113,13 @@ type WebConn struct {
 	endWritePump chan struct{}
 	pumpFinished chan struct{}
 	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.
@@ -215,6 +223,8 @@ func (ps *PlatformService) NewWebConn(cfg *WebConnConfig, suite SuiteIFace, runn
 		endWritePump:       make(chan struct{}),
 		pumpFinished:       make(chan struct{}),
 		pluginPosted:       make(chan pluginWSPostedHook, 10),
+		lastLogTimeSlow:    time.Now(),
+		lastLogTimeFull:    time.Now(),
 	}
 
 	wc.SetSession(&cfg.Session)
@@ -460,7 +470,7 @@ func (wc *WebConn) writePump() {
 				continue
 			}
 
-			if len(wc.send) >= sendFullWarn {
+			if len(wc.send) >= sendFullWarn && time.Since(wc.lastLogTimeFull) > websocketSuppressWarnThreshold {
 				logData := []mlog.Field{
 					mlog.String("user_id", wc.UserId),
 					mlog.String("type", msg.EventType()),
@@ -471,6 +481,7 @@ func (wc *WebConn) writePump() {
 				}
 
 				mlog.Warn("websocket.full", logData...)
+				wc.lastLogTimeFull = time.Now()
 			}
 
 			if evtOk {
@@ -711,11 +722,15 @@ func (wc *WebConn) ShouldSendEvent(msg *model.WebSocketEvent) bool {
 		case model.WebsocketEventTyping,
 			model.WebsocketEventStatusChange,
 			model.WebsocketEventChannelViewed:
-			mlog.Warn(
-				"websocket.slow: dropping message",
-				mlog.String("user_id", wc.UserId),
-				mlog.String("type", msg.EventType()),
-			)
+			if time.Since(wc.lastLogTimeSlow) > websocketSuppressWarnThreshold {
+				mlog.Warn(
+					"websocket.slow: dropping message",
+					mlog.String("user_id", wc.UserId),
+					mlog.String("type", msg.EventType()),
+				)
+				// Reset timer to now.
+				wc.lastLogTimeSlow = time.Now()
+			}
 			return false
 		}
 	}