From 70e212754c4bd907f581666fb784d7ecf11cb200 Mon Sep 17 00:00:00 2001
From: Maxim Sharabayko <maxlovic@gmail.com>
Date: Fri, 16 Aug 2024 11:03:22 +0200
Subject: [PATCH] [core] Slowdown 'ACKACK out of order' log frequency (#3007).

---
 srtcore/core.cpp | 27 +++++++++++++++++++--------
 srtcore/core.h   | 14 ++++++++------
 2 files changed, 27 insertions(+), 14 deletions(-)

diff --git a/srtcore/core.cpp b/srtcore/core.cpp
index 7067e195c..bae245392 100644
--- a/srtcore/core.cpp
+++ b/srtcore/core.cpp
@@ -5965,7 +5965,7 @@ bool srt::CUDT::frequentLogAllowed(size_t logid, const time_point& tnow, std::st
 #endif
 
     bool is_suppressed = IsSet(m_LogSlowDownExpired, BIT(logid));
-    bool isnow = (m_tsLogSlowDown.load() + milliseconds_from(SRT_LOG_SLOWDOWN_FREQ_MS)) <= tnow;
+    const bool isnow = (m_tsLogSlowDown[logid].load() + milliseconds_from(SRT_LOG_SLOWDOWN_FREQ_MS)) <= tnow;
     if (isnow)
     {
         // Theoretically this should prevent other calls of this function to take
@@ -5977,11 +5977,11 @@ bool srt::CUDT::frequentLogAllowed(size_t logid, const time_point& tnow, std::st
         // Note: it may happen that two threads could intermix one another between
         // the check and setting up, but this will at worst case set the slightly
         // later time again.
-        m_tsLogSlowDown.store(tnow);
+        m_tsLogSlowDown[logid].store(tnow);
 
         is_suppressed = false;
 
-        int supr = m_aSuppressedMsg[logid];
+        const int supr = m_aSuppressedMsg[logid];
 
         if (supr > 0)
             w_why = Sprint("++SUPPRESSED: ", supr);
@@ -5989,7 +5989,7 @@ bool srt::CUDT::frequentLogAllowed(size_t logid, const time_point& tnow, std::st
     }
     else
     {
-        w_why = Sprint("Too early - last one was ", FormatDuration<DUNIT_MS>(tnow - m_tsLogSlowDown.load()));
+        w_why = Sprint("Too early - last one was ", FormatDuration<DUNIT_MS>(tnow - m_tsLogSlowDown[logid].load()));
         // Set YOUR OWN bit, atomically.
         m_LogSlowDownExpired |= uint8_t(BIT(logid));
         ++m_aSuppressedMsg[logid];
@@ -8688,10 +8688,21 @@ void srt::CUDT::processCtrlAckAck(const CPacket& ctrlpkt, const time_point& tsAr
     {
         if (ctrlpkt.getAckSeqNo() > (m_iAckSeqNo - static_cast<int>(ACK_WND_SIZE)) && ctrlpkt.getAckSeqNo() <= m_iAckSeqNo)
         {
-            LOGC(inlog.Note,
-                log << CONID() << "ACKACK out of order, skipping RTT calculation "
-                << "(ACK number: " << ctrlpkt.getAckSeqNo() << ", last ACK sent: " << m_iAckSeqNo
-                << ", RTT (EWMA): " << m_iSRTT << ")");
+            string why;
+            if (frequentLogAllowed(FREQLOGFA_ACKACK_OUTOFORDER, tsArrival, (why)))
+            {
+                LOGC(inlog.Note,
+                    log << CONID() << "ACKACK out of order, skipping RTT calculation "
+                    << "(ACK number: " << ctrlpkt.getAckSeqNo() << ", last ACK sent: " << m_iAckSeqNo
+                    << ", RTT (EWMA): " << m_iSRTT << ")." << why);
+            }
+#if SRT_ENABLE_FREQUENT_LOG_TRACE
+            else
+            {
+                LOGC(qrlog.Note, log << "SUPPRESSED: ACKACK out of order LOG: " << why);
+            }
+#endif
+
             return;
         }
 
diff --git a/srtcore/core.h b/srtcore/core.h
index 3d5314281..ed250c641 100644
--- a/srtcore/core.h
+++ b/srtcore/core.h
@@ -948,13 +948,15 @@ class CUDT
     int32_t m_iReXmitCount;                      // Re-Transmit Count since last ACK
 
     static const size_t
-                MAX_FREQLOGFA = 2,
                 FREQLOGFA_ENCRYPTION_FAILURE = 0,
-                FREQLOGFA_RCV_DROPPED = 1;
-    atomic_time_point m_tsLogSlowDown;                  // The last time a log message from the "slow down" group was shown.
-                                                 // The "slow down" group of logs are those that can be printed too often otherwise, but can't be turned off (warnings and errors).
-                                                 // Currently only used by decryption failure message, therefore no mutex protection needed.
-    sync::atomic<uint8_t> m_LogSlowDownExpired; // Can't use bitset because atomic
+                FREQLOGFA_RCV_DROPPED = 1,
+                FREQLOGFA_ACKACK_OUTOFORDER = 2,
+                MAX_FREQLOGFA = 3;
+
+    atomic_time_point m_tsLogSlowDown[MAX_FREQLOGFA]; // The last time a log message from the "slow down" group was shown.
+                                                      // The "slow down" group of logs are those that can be printed too often otherwise, but can't be turned off (warnings and errors).
+                                                      // Currently only used by decryption failure message, therefore no mutex protection needed.
+    sync::atomic<uint8_t> m_LogSlowDownExpired;       // Can't use bitset because atomic
     sync::atomic<int> m_aSuppressedMsg[MAX_FREQLOGFA];
 
     /// @brief Check if a frequent log can be shown.