Merge pull request #302 from stazio/refactor_logging

Refactored runtime errors to be logged periodically

CMakeLists.txt

@@ -57,6 +57,7 @@ set(LIBDATACHANNEL_SOURCES
 	${CMAKE_CURRENT_SOURCE_DIR}/src/log.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/message.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/peerconnection.cpp
+	${CMAKE_CURRENT_SOURCE_DIR}/src/logcounter.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/rtcp.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/sctptransport.cpp
 	${CMAKE_CURRENT_SOURCE_DIR}/src/threadpool.cpp

src/datachannel.cpp

@@ -20,6 +20,7 @@
 #include "include.hpp"
 #include "peerconnection.hpp"
 #include "sctptransport.hpp"
+#include "logcounter.hpp"
 
 #ifdef _WIN32
 #include <winsock2.h>
@@ -27,6 +28,7 @@
 #include <arpa/inet.h>
 #endif
 
+rtc::LogCounter COUNTER_USERNEG_OPEN_MESSAGE(plog::warning, "Number of open messages for a user-negotiated DataChannel received");
 namespace rtc {
 
 using std::shared_ptr;
@@ -170,7 +172,8 @@ void DataChannel::open(shared_ptr<SctpTransport> transport) {
 }
 
 void DataChannel::processOpenMessage(message_ptr) {
-	PLOG_WARNING << "Received an open message for a user-negotiated DataChannel, ignoring";
+    PLOG_DEBUG << "Received an open message for a user-negotiated DataChannel, ignoring";
+    COUNTER_USERNEG_OPEN_MESSAGE++;
 }
 
 bool DataChannel::outgoing(message_ptr message) {

src/dtlssrtptransport.cpp

@@ -18,6 +18,7 @@
 
 #include "dtlssrtptransport.hpp"
 #include "tls.hpp"
+#include "logcounter.hpp"
 
 #if RTC_ENABLE_MEDIA
 
@@ -28,6 +29,15 @@ using std::shared_ptr;
 using std::to_integer;
 using std::to_string;
 
+static rtc::LogCounter COUNTER_MEDIA_TRUNCATED(plog::warning, "Number of truncated SRT(C)P packets received");
+static rtc::LogCounter COUNTER_UNKNOWN_PACKET_TYPE(plog::warning, "Number of RTP packets received with an unknown packet type");
+static rtc::LogCounter COUNTER_SRTCP_REPLAY(plog::warning, "Number of SRTCP replay packets received");
+static rtc::LogCounter COUNTER_SRTCP_AUTH_FAIL(plog::warning, "Number of SRTCP packets received that failed authentication checks");
+static rtc::LogCounter COUNTER_SRTCP_FAIL(plog::warning, "Number of SRTCP packets received that had an unknown libSRTP failure");
+static rtc::LogCounter COUNTER_SRTP_REPLAY(plog::warning, "Number of SRTP replay packets received");
+static rtc::LogCounter COUNTER_SRTP_AUTH_FAIL(plog::warning, "Number of SRTP packets received that failed authentication checks");
+static rtc::LogCounter COUNTER_SRTP_FAIL(plog::warning, "Number of SRTP packets received that had an unknown libSRTP failure");
+
 namespace rtc {
 
 void DtlsSrtpTransport::Init() { srtp_init(); }
@@ -73,13 +83,14 @@ DtlsSrtpTransport::~DtlsSrtpTransport() {
 	srtp_dealloc(mSrtpOut);
 }
 
+
 bool DtlsSrtpTransport::sendMedia(message_ptr message) {
 	std::lock_guard lock(sendMutex);
 	if (!message)
 		return false;
 
 	if (!mInitDone) {
-		PLOG_WARNING << "SRTP media sent before keys are derived";
+        PLOG_ERROR << "SRTP media sent before keys are derived";
 		return false;
 	}
 
@@ -137,6 +148,7 @@ bool DtlsSrtpTransport::sendMedia(message_ptr message) {
 	return Transport::outgoing(message); // bypass DTLS DSCP marking
 }
 
+
 void DtlsSrtpTransport::incoming(message_ptr message) {
 	if (!mInitDone) {
 		// Bypas
@@ -165,7 +177,8 @@ void DtlsSrtpTransport::incoming(message_ptr message) {
 		// The RTP header has a minimum size of 12 bytes
 		// An RTCP packet can have a minimum size of 8 bytes
 		if (size < 8) {
-			PLOG_WARNING << "Incoming SRTP/SRTCP packet too short, size=" << size;
+            COUNTER_MEDIA_TRUNCATED++;
+			PLOG_VERBOSE << "Incoming SRTP/SRTCP packet too short, size=" << size;
 			return;
 		}
 
@@ -177,12 +190,16 @@ void DtlsSrtpTransport::incoming(message_ptr message) {
 		if (value2 >= 64 && value2 <= 95) { // Range 64-95 (inclusive) MUST be RTCP
 			PLOG_VERBOSE << "Incoming SRTCP packet, size=" << size;
 			if (srtp_err_status_t err = srtp_unprotect_rtcp(mSrtpIn, message->data(), &size)) {
-				if (err == srtp_err_status_replay_fail)
-					PLOG_WARNING << "Incoming SRTCP packet is a replay";
-				else if (err == srtp_err_status_auth_fail)
-					PLOG_WARNING << "Incoming SRTCP packet failed authentication check";
-				else
-					PLOG_WARNING << "SRTCP unprotect error, status=" << err;
+				if (err == srtp_err_status_replay_fail) {
+                    PLOG_VERBOSE << "Incoming SRTCP packet is a replay";
+                    COUNTER_SRTCP_REPLAY++;
+                }else if (err == srtp_err_status_auth_fail) {
+                    PLOG_VERBOSE << "Incoming SRTCP packet failed authentication check";
+                    COUNTER_SRTCP_AUTH_FAIL++;
+                }else {
+                    PLOG_VERBOSE << "SRTCP unprotect error, status=" << err;
+                    COUNTER_SRTCP_FAIL++;
+                }
 
 				return;
 			}
@@ -193,13 +210,16 @@ void DtlsSrtpTransport::incoming(message_ptr message) {
 		} else {
 			PLOG_VERBOSE << "Incoming SRTP packet, size=" << size;
 			if (srtp_err_status_t err = srtp_unprotect(mSrtpIn, message->data(), &size)) {
-				if (err == srtp_err_status_replay_fail)
-					PLOG_WARNING << "Incoming SRTP packet is a replay";
-				else if (err == srtp_err_status_auth_fail)
-					PLOG_WARNING << "Incoming SRTP packet failed authentication check";
-				else
-					PLOG_WARNING << "SRTP unprotect error, status=" << err;
-
+                if (err == srtp_err_status_replay_fail) {
+                    PLOG_VERBOSE << "Incoming SRTP packet is a replay";
+                    COUNTER_SRTP_REPLAY++;
+                } else if (err == srtp_err_status_auth_fail) {
+                    PLOG_VERBOSE << "Incoming SRTP packet failed authentication check";
+                    COUNTER_SRTP_AUTH_FAIL++;
+                } else {
+                    PLOG_VERBOSE << "SRTP unprotect error, status=" << err;
+                    COUNTER_SRTP_FAIL++;
+                }
 				return;
 			}
 			PLOG_VERBOSE << "Unprotected SRTP packet, size=" << size;
@@ -211,7 +231,8 @@ void DtlsSrtpTransport::incoming(message_ptr message) {
 		mSrtpRecvCallback(message);
 
 	} else {
-		PLOG_WARNING << "Unknown packet type, value=" << unsigned(value1) << ", size=" << size;
+	    COUNTER_UNKNOWN_PACKET_TYPE++;
+		PLOG_VERBOSE << "Unknown packet type, value=" << unsigned(value1) << ", size=" << size;
 	}
 }
 

src/logcounter.cpp

@@ -0,0 +1,40 @@
+/**
+ * Copyright (c) 2021 Staz Modrzynski
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 2.1 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
+ */
+
+#include "logcounter.hpp"
+
+rtc::LogCounter::LogCounter(plog::Severity severity, const std::string &text, std::chrono::seconds duration) {
+    mData = std::make_shared<LogData>();
+    mData->mDuration  =duration;
+    mData->mSeverity = severity;
+    mData->mText = text;
+}
+
+rtc::LogCounter& rtc::LogCounter::operator++(int) {
+    if (mData->mCount++ == 0) {
+        ThreadPool::Instance().schedule(mData->mDuration, [](std::weak_ptr<LogData> data) {
+            if (auto ptr = data.lock()) {
+                int countCopy;
+                countCopy = ptr->mCount.exchange(0);
+                PLOG(ptr->mSeverity) << ptr->mText << ": " << countCopy << " (over "
+                               << std::chrono::duration_cast<std::chrono::seconds>(ptr->mDuration).count() << " seconds)";
+            }
+        }, mData);
+    }
+    return *this;
+}

src/logcounter.hpp

@@ -0,0 +1,46 @@
+/**
+ * Copyright (c) 2021 Staz Modrzynski
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 2.1 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA
+ */
+
+#ifndef WEBRTC_SERVER_LOGCOUNTER_HPP
+#define WEBRTC_SERVER_LOGCOUNTER_HPP
+
+#include "threadpool.hpp"
+#include "include.hpp"
+
+namespace rtc {
+class LogCounter {
+private:
+    struct LogData {
+        plog::Severity mSeverity;
+        std::string mText;
+        std::chrono::steady_clock::duration mDuration;
+
+        std::atomic<int> mCount = 0;
+    };
+
+    std::shared_ptr<LogData> mData;
+
+public:
+
+    LogCounter(plog::Severity severity, const std::string& text, std::chrono::seconds duration=std::chrono::seconds(1));
+
+    LogCounter& operator++(int);
+};
+}
+
+#endif //WEBRTC_SERVER_LOGCOUNTER_HPP

src/peerconnection.cpp

@@ -22,6 +22,7 @@
 #include "include.hpp"
 #include "processor.hpp"
 #include "threadpool.hpp"
+#include "logcounter.hpp"
 
 #include "dtlstransport.hpp"
 #include "icetransport.hpp"
@@ -46,6 +47,11 @@ inline std::shared_ptr<To> reinterpret_pointer_cast(std::shared_ptr<From> const
 using std::reinterpret_pointer_cast;
 #endif
 
+static rtc::LogCounter COUNTER_MEDIA_TRUNCATED(plog::warning, "Number of RTP packets truncated over past second");
+static rtc::LogCounter COUNTER_SRTP_DECRYPT_ERROR(plog::warning, "Number of SRTP decryption errors over past second");
+static rtc::LogCounter COUNTER_SRTP_ENCRYPT_ERROR(plog::warning, "Number of SRTP encryption errors over past second");
+static rtc::LogCounter COUNTER_UNKNOWN_PACKET_TYPE(plog::warning, "Number of unknown RTCP packet types over past second");
+
 namespace rtc {
 
 using namespace std::placeholders;
@@ -678,7 +684,7 @@ void PeerConnection::forwardMedia(message_ptr message) {
 		while ((sizeof(rtc::RTCP_HEADER) + offset) <= message->size()) {
 			auto header = reinterpret_cast<rtc::RTCP_HEADER *>(message->data() + offset);
 			if (header->lengthInBytes() > message->size() - offset) {
-				PLOG_WARNING << "RTCP packet is truncated";
+				COUNTER_MEDIA_TRUNCATED++;
 				break;
 			}
 			offset += header->lengthInBytes();
@@ -696,8 +702,7 @@ void PeerConnection::forwardMedia(message_ptr message) {
 				// PT=202 == SDES
 				// PT=207 == Extended Report
 				if (header->payloadType() != 202 && header->payloadType() != 207) {
-					PLOG_WARNING << "Unknown packet type: " << (int)header->version() << " "
-					             << header->payloadType() << "";
+                    COUNTER_UNKNOWN_PACKET_TYPE++;
 				}
 			}
 		}

src/rtcp.cpp

@@ -22,6 +22,7 @@
 #include "track.hpp"
 #include <cmath>
 #include <utility>
+#include "logcounter.hpp"
 
 #ifdef _WIN32
 #include <winsock2.h>
@@ -29,6 +30,11 @@
 #include <arpa/inet.h>
 #endif
 
+static rtc::LogCounter COUNTER_BAD_RTP_HEADER(plog::warning, "Number of malformed RTP headers");
+static rtc::LogCounter COUNTER_UNKNOWN_PPID(plog::warning, "Number of Unknown PPID messages");
+static rtc::LogCounter COUNTER_BAD_NOTIF_LEN(plog::warning, "Number of Bad-Lengthed notifications");
+static rtc::LogCounter COUNTER_BAD_SCTP_STATUS(plog::warning, "Number of unknown SCTP_STATUS errors");
+
 namespace rtc {
 
 rtc::message_ptr RtcpReceivingSession::outgoing(rtc::message_ptr ptr) { return ptr; }
@@ -39,20 +45,19 @@ rtc::message_ptr RtcpReceivingSession::incoming(rtc::message_ptr ptr) {
 
 		// https://tools.ietf.org/html/rfc3550#appendix-A.1
 		if (rtp->version() != 2) {
-			PLOG_WARNING << "RTP packet is not version 2";
+		    COUNTER_BAD_RTP_HEADER++;
+			PLOG_VERBOSE << "RTP packet is not version 2";
 
 			return nullptr;
 		}
 		if (rtp->payloadType() == 201 || rtp->payloadType() == 200) {
-			PLOG_WARNING << "RTP packet has a payload type indicating RR/SR";
+            COUNTER_BAD_RTP_HEADER++;
+            PLOG_VERBOSE << "RTP packet has a payload type indicating RR/SR";
 
 			return nullptr;
 		}
 
-		// TODO Implement the padding bit
-		if (rtp->padding()) {
-			PLOG_WARNING << "Padding processing not implemented";
-		}
+        // Padding-processing is a user-level thing
 
 		mSsrc = rtp->ssrc();
 

src/sctptransport.cpp

@@ -17,6 +17,7 @@
  */
 
 #include "sctptransport.hpp"
+#include "logcounter.hpp"
 
 #include <chrono>
 #include <exception>
@@ -48,6 +49,10 @@ using namespace std::chrono;
 
 using std::shared_ptr;
 
+static rtc::LogCounter COUNTER_UNKNOWN_PPID(plog::warning, "Number of SCTP packets received with an unknown PPID");
+static rtc::LogCounter COUNTER_BAD_NOTIF_LEN(plog::warning, "Number of SCTP packets received with an bad notification length");
+static rtc::LogCounter COUNTER_BAD_SCTP_STATUS(plog::warning, "Number of SCTP packets received with a bad status");
+
 namespace rtc {
 
 std::unordered_set<SctpTransport *> SctpTransport::Instances;
@@ -631,14 +636,15 @@ void SctpTransport::processData(binary &&data, uint16_t sid, PayloadId ppid) {
 
 	default:
 		// Unknown
-		PLOG_WARNING << "Unknown PPID: " << uint32_t(ppid);
+		COUNTER_UNKNOWN_PPID++;
+		PLOG_VERBOSE << "Unknown PPID: " << uint32_t(ppid);
 		return;
 	}
 }
 
 void SctpTransport::processNotification(const union sctp_notification *notify, size_t len) {
 	if (len != size_t(notify->sn_header.sn_length)) {
-		PLOG_WARNING << "Invalid notification length";
+        COUNTER_BAD_NOTIF_LEN++;
 		return;
 	}
 
@@ -738,7 +744,8 @@ std::optional<milliseconds> SctpTransport::rtt() {
 	struct sctp_status status = {};
 	socklen_t len = sizeof(status);
 	if (usrsctp_getsockopt(mSock, IPPROTO_SCTP, SCTP_STATUS, &status, &len)) {
-		PLOG_WARNING << "Could not read SCTP_STATUS";
+		COUNTER_BAD_SCTP_STATUS++;
+
 		return nullopt;
 	}
 	return milliseconds(status.sstat_primary.spinfo_srtt);

src/track.cpp

@@ -19,6 +19,10 @@
 #include "track.hpp"
 #include "dtlssrtptransport.hpp"
 #include "include.hpp"
+#include "logcounter.hpp"
+
+static rtc::LogCounter COUNTER_MEDIA_BAD_DIRECTION(plog::warning, "Number of media packets sent in invalid directions");
+static rtc::LogCounter COUNTER_QUEUE_FULL(plog::warning, "Number of media packets dropped due to a full queue");
 
 namespace rtc {
 
@@ -52,7 +56,7 @@ bool Track::send(message_variant data) {
 	auto direction = mMediaDescription.direction();
 	if ((direction == Description::Direction::RecvOnly ||
 	     direction == Description::Direction::Inactive)) {
-		PLOG_WARNING << "Track media direction does not allow transmission, dropping";
+	    COUNTER_MEDIA_BAD_DIRECTION++;
 		return false;
 	}
 
@@ -114,7 +118,7 @@ void Track::incoming(message_ptr message) {
 	if ((direction == Description::Direction::SendOnly ||
 	     direction == Description::Direction::Inactive) &&
 	    message->type != Message::Control) {
-		PLOG_WARNING << "Track media direction does not allow reception, dropping";
+        COUNTER_MEDIA_BAD_DIRECTION++;
 		return;
 	}
 
@@ -126,7 +130,7 @@ void Track::incoming(message_ptr message) {
 
 	// Tail drop if queue is full
 	if (mRecvQueue.full()) {
-		PLOG_WARNING << "Track incoming queue is full, dropping";
+        COUNTER_QUEUE_FULL++;
 		return;
 	}