From 317bfca75432a2c67014f21ea60f7abf8cb5f702 Mon Sep 17 00:00:00 2001
From: Maxim Sharabayko <maxlovic@gmail.com>
Date: Fri, 7 May 2021 13:59:12 +0200
Subject: [PATCH] [core] Improved 'no room to store' log message

---
 srtcore/buffer.cpp | 41 +++++++++++++++++++++++++++++++++++++++++
 srtcore/buffer.h   | 12 ++++++++++++
 srtcore/core.cpp   | 39 +++++++++++++++++++++++++++++++++------
 3 files changed, 86 insertions(+), 6 deletions(-)

diff --git a/srtcore/buffer.cpp b/srtcore/buffer.cpp
index 660f2b335..611ea2eb9 100644
--- a/srtcore/buffer.cpp
+++ b/srtcore/buffer.cpp
@@ -1722,6 +1722,47 @@ unsigned CRcvBuffer::getRcvAvgPayloadSize() const
     return m_uAvgPayloadSz;
 }
 
+CRcvBuffer::ReadingState CRcvBuffer::debugGetReadingState() const
+{
+    ReadingState readstate;
+
+    readstate.numAcknowledged = 0;
+    readstate.numUnacknowledged = m_iMaxPos;
+
+    if ((NULL != m_pUnit[m_iStartPos]) && (m_pUnit[m_iStartPos]->m_iFlag == CUnit::GOOD))
+    {
+        if (m_tsbpd.isEnabled())
+            readstate.tsStart = m_tsbpd.getPktTsbPdTime(m_pUnit[m_iStartPos]->m_Packet.getMsgTimeStamp());
+
+        readstate.numAcknowledged = m_iLastAckPos > m_iStartPos
+            ? m_iLastAckPos - m_iStartPos
+            : m_iLastAckPos + (m_iSize - m_iStartPos);
+    }
+
+    // All further stats are valid if TSBPD is enabled.
+    if (!m_tsbpd.isEnabled())
+        return readstate;
+
+    // m_iLastAckPos points to the first unacknowledged packet
+    const int iLastAckPos = (m_iLastAckPos - 1) % m_iSize;
+    if (m_iLastAckPos != m_iStartPos && (NULL != m_pUnit[iLastAckPos]) && (m_pUnit[iLastAckPos]->m_iFlag == CUnit::GOOD))
+    {
+        readstate.tsLastAck = m_tsbpd.getPktTsbPdTime(m_pUnit[iLastAckPos]->m_Packet.getMsgTimeStamp());
+    }
+
+    const int iEndPos = (m_iLastAckPos + m_iMaxPos - 1) % m_iSize;
+    if (m_iMaxPos == 0)
+    {
+        readstate.tsEnd = readstate.tsLastAck;
+    }
+    else if ((NULL != m_pUnit[iEndPos]) && (m_pUnit[iEndPos]->m_iFlag == CUnit::GOOD))
+    {
+        readstate.tsEnd = m_tsbpd.getPktTsbPdTime(m_pUnit[iEndPos]->m_Packet.getMsgTimeStamp());
+    }
+
+    return readstate;
+}
+
 void CRcvBuffer::dropMsg(int32_t msgno, bool using_rexmit_flag)
 {
     for (int i = m_iStartPos, n = shift(m_iLastAckPos, m_iMaxPos); i != n; i = shiftFwd(i))
diff --git a/srtcore/buffer.h b/srtcore/buffer.h
index 6a21df1ce..6b213d3e3 100644
--- a/srtcore/buffer.h
+++ b/srtcore/buffer.h
@@ -348,6 +348,18 @@ class CRcvBuffer
     /// @return size (bytes) of payload size
     unsigned getRcvAvgPayloadSize() const;
 
+
+    struct ReadingState
+    {
+        time_point tsStart;
+        time_point tsLastAck;
+        time_point tsEnd;
+        int numAcknowledged;
+        int numUnacknowledged;
+    };
+
+    ReadingState debugGetReadingState() const;
+
     /// Mark the message to be dropped from the message list.
     /// @param [in] msgno message number.
     /// @param [in] using_rexmit_flag whether the MSGNO field uses rexmit flag (if not, one more bit is part of the
diff --git a/srtcore/core.cpp b/srtcore/core.cpp
index 35db04142..046a956d8 100644
--- a/srtcore/core.cpp
+++ b/srtcore/core.cpp
@@ -9622,12 +9622,39 @@ int CUDT::processData(CUnit* in_unit)
                 }
                 else
                 {
-                    LOGC(qrlog.Warn, log << CONID() << "No room to store incoming packet: offset="
-                            << offset << " avail=" << avail_bufsize
-                            << " ack.seq=" << m_iRcvLastSkipAck << " pkt.seq=" << rpkt.m_iSeqNo
-                            << " rcv-remain=" << m_pRcvBuffer->debugGetSize()
-                            << " drift=" << m_pRcvBuffer->getDrift()
-                        );
+#if ENABLE_LOGGING
+                    const time_point curtime = steady_clock::now();
+                    const CRcvBuffer::ReadingState bufstate = m_pRcvBuffer->debugGetReadingState();
+                    stringstream ss;
+
+                    ss << "Packets ACKed: " << bufstate.numAcknowledged;
+                    if (!is_zero(bufstate.tsStart) && !is_zero(bufstate.tsLastAck))
+                    {
+                        ss << " (TSBPD ready in ";
+                        ss << count_milliseconds(bufstate.tsStart - curtime);
+                        ss << " : ";
+                        ss << count_milliseconds(bufstate.tsLastAck - curtime);
+                        ss << " ms)";
+                    }
+
+                    ss << ", not ACKed: " << bufstate.numUnacknowledged;
+                    if (!is_zero(bufstate.tsStart) && !is_zero(bufstate.tsEnd))
+                    {
+                        ss << ", timespan ";
+                        ss << count_milliseconds(bufstate.tsEnd - bufstate.tsStart);
+                        ss << " ms. ";
+                    }
+
+                    LOGC(qrlog.Warn, log << CONID() << "No room to store incoming packet: insert offset " << offset
+                        << ", space avail " << avail_bufsize
+                        << " (pkt.seq=" << rpkt.m_iSeqNo
+                        << ", ack.seq=" << m_iRcvLastSkipAck
+                        << "). " << ss.str()
+                        << SRT_SYNC_CLOCK_STR
+                        << " drift=" << m_pRcvBuffer->getDrift()
+                    );
+#endif
+
                     return -1;
                 }
             }