From c83c31ba1cea357ae036e5850947af1a5e064454 Mon Sep 17 00:00:00 2001 From: Maxim Sharabayko Date: Thu, 9 Feb 2023 18:06:54 +0100 Subject: [PATCH] [core] Reduce frequency of the decryption failure log (#2602). Added `SRT_LOG_SLOWDOWN_FREQ_MS` build option. --- CMakeLists.txt | 12 ++++++++++++ docs/build/build-options.md | 11 ++++++++++- srtcore/core.cpp | 18 ++++++++++++++++-- srtcore/core.h | 9 +++++++++ srtcore/crypto.cpp | 6 +++--- 5 files changed, 50 insertions(+), 6 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index 305f4be37..fe32f1fec 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -204,6 +204,16 @@ else() message(STATUS "USE_BUSY_WAITING: OFF (default)") endif() +# Reduce the frequency of some frequent logs, milliseconds +set(SRT_LOG_SLOWDOWN_FREQ_MS_DEFAULT 1000) # 1s +if (NOT DEFINED SRT_LOG_SLOWDOWN_FREQ_MS) + if (ENABLE_HEAVY_LOGGING) + set(SRT_LOG_SLOWDOWN_FREQ_MS 0) # Just show every log message. + else() + set(SRT_LOG_SLOWDOWN_FREQ_MS ${SRT_LOG_SLOWDOWN_FREQ_MS_DEFAULT}) + endif() +endif() + if ( CYGWIN AND NOT CYGWIN_USE_POSIX ) set(WIN32 1) set(CMAKE_LEGACY_CYGWIN_WIN32 1) @@ -1067,6 +1077,8 @@ if (ENABLE_SHARED) target_compile_definitions(srt_virtual PUBLIC -DSRT_DYNAMIC) endif() +target_compile_definitions(srt_virtual PRIVATE -DSRT_LOG_SLOWDOWN_FREQ_MS=${SRT_LOG_SLOWDOWN_FREQ_MS}) + if (srt_libspec_shared) if (MICROSOFT) target_link_libraries(${TARGET_srt}_shared PUBLIC Ws2_32.lib) diff --git a/docs/build/build-options.md b/docs/build/build-options.md index 9c3b4471e..a2fcd20cd 100644 --- a/docs/build/build-options.md +++ b/docs/build/build-options.md @@ -40,7 +40,7 @@ Option details are given further below. | [`ENABLE_HEAVY_LOGGING`](#enable_heavy_logging) | 1.3.0 | `BOOL` | OFF | Enables heavy logging instructions in the code that occur often and cover many detailed aspects of library behavior. Default: OFF in release mode. | | [`ENABLE_INET_PTON`](#enable_inet_pton) | 1.3.2 | `BOOL` | ON | Enables usage of the `inet_pton` function used to resolve the network endpoint name into an IP address. | | [`ENABLE_LOGGING`](#enable_logging) | 1.2.0 | `BOOL` | ON | Enables normal logging, including errors. | -| [`ENABLE_MONOTONIC_CLOCK`](#enable_monotonic_clock) | 1.4.0 | `BOOL` | ON\* | Enforces the use of `clock_gettime` with a monotonic clock that is independent of the currently set time in the system. | +| [`ENABLE_MONOTONIC_CLOCK`](#enable_monotonic_clock) | 1.4.0 | `BOOL` | ON\* | Enforces the use of `clock_gettime` with a monotonic clock that is independent of the currently set time in the system. | | [`ENABLE_PROFILE`](#enable_profile) | 1.2.0 | `BOOL` | OFF | Enables code instrumentation for profiling (only for GNU-compatible compilers). | | [`ENABLE_RELATIVE_LIBPATH`](#enable_relative_libpath) | 1.3.2 | `BOOL` | OFF | Enables adding a relative path to a library for linking against a shared SRT library by reaching out to a sibling directory. | | [`ENABLE_SHARED`](#enable_shared--enable_static) | 1.2.0 | `BOOL` | ON | Enables building SRT as a shared library. | @@ -57,6 +57,7 @@ Option details are given further below. | [`PKG_CONFIG_EXECUTABLE`](#pkg_config_executable) | 1.3.0 | `BOOL` | OFF | Configures the path to the `pkg-config` tool. | | [`PTHREAD_INCLUDE_DIR`](#pthread_include_dir) | 1.3.0 | `STRING` | OFF | Configures the path to include files for a `pthread` library. | | [`PTHREAD_LIBRARY`](#pthread_library) | 1.3.0 | `STRING` | OFF | Configures the path to a `pthread` library. | +| [`SRT_LOG_SLOWDOWN_FREQ_MS`](#SRT_LOG_SLOWDOWN_FREQ_MS) | 1.5.2 | `INT` | 1000\* | Reduce the frequency of some frequent logs, milliseconds. | | [`USE_BUSY_WAITING`](#use_busy_waiting) | 1.3.3 | `BOOL` | OFF | Enables more accurate sending times at the cost of potentially higher CPU load. | | [`USE_CXX_STD`](#use_cxx_std) | 1.4.2 | `STRING` | OFF | Enforces using a particular C++ standard (11, 14, 17, etc.) when compiling. | | [`USE_ENCLIB`](#use_enclib) | 1.3.3 | `STRING` | openssl | Encryption library to be used (`openssl`, `openssl-evp` (since 1.5.1), `gnutls`, `mbedtls`). | @@ -547,6 +548,14 @@ in the system. Used to configure the path to a `pthread` library. +#### SRT_LOG_SLOWDOWN_FREQ_MS +**`--srt-log-slowdown-freq-ms=`** (DEFAULT 1000 ms; or 0 ms if `ENABLE_HEAVY_LOGGING`) + +Reduce the frequency of some frequent logs, milliseconds. + +- Decryption failure warning message (`SRT_LOGFA_QUE_RECV`). + + #### USE_BUSY_WAITING **`--use-busy-waiting`** (default: OFF) diff --git a/srtcore/core.cpp b/srtcore/core.cpp index 540416f8c..f9e8a06b4 100644 --- a/srtcore/core.cpp +++ b/srtcore/core.cpp @@ -5743,6 +5743,15 @@ void srt::CUDT::acceptAndRespond(const sockaddr_any& agent, const sockaddr_any& addressAndSend((response)); } +bool srt::CUDT::frequentLogAllowed(const time_point& tnow) const +{ +#ifndef SRT_LOG_SLOWDOWN_FREQ_MS +#define SRT_LOG_SLOWDOWN_FREQ_MS 1000 +#endif + + return (m_tsLogSlowDown + milliseconds_from(SRT_LOG_SLOWDOWN_FREQ_MS)) <= tnow; +} + // This function is required to be called when a caller receives an INDUCTION // response from the listener and would like to create a CONCLUSION that includes // the SRT handshake extension. This extension requires that the crypter object @@ -9892,11 +9901,16 @@ int srt::CUDT::handleSocketPacketReception(const vector& incoming, bool& // A drawback is that it would prevent a valid packet with the same sequence number, if it happens to arrive later, to end up in the buffer. const int iDropCnt = m_pRcvBuffer->dropMessage(u->m_Packet.getSeqNo(), u->m_Packet.getSeqNo(), SRT_MSGNO_NONE); - LOGC(qrlog.Warn, log << CONID() << "Decryption failed. Seqno %" << u->m_Packet.getSeqNo() - << ", msgno " << u->m_Packet.getMsgSeq(m_bPeerRexmitFlag) << ". Dropping " << iDropCnt << "."); + const steady_clock::time_point tnow = steady_clock::now(); ScopedLock lg(m_StatsLock); m_stats.rcvr.dropped.count(stats::BytesPackets(iDropCnt * rpkt.getLength(), iDropCnt)); m_stats.rcvr.undecrypted.count(stats::BytesPackets(rpkt.getLength(), 1)); + if (frequentLogAllowed(tnow)) + { + LOGC(qrlog.Warn, log << CONID() << "Decryption failed (seqno %" << u->m_Packet.getSeqNo() << "), dropped " + << iDropCnt << ". pktRcvUndecryptTotal=" << m_stats.rcvr.undecrypted.total.count() << "."); + m_tsLogSlowDown = tnow; + } } } } diff --git a/srtcore/core.h b/srtcore/core.h index 77350b072..9698a203e 100644 --- a/srtcore/core.h +++ b/srtcore/core.h @@ -897,6 +897,15 @@ class CUDT SRT_ATTR_GUARDED_BY(m_RecvAckLock) int32_t m_iReXmitCount; // Re-Transmit Count since last ACK + 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. + + /// @brief Check if a frequent log can be shown. + /// @param tnow current time + /// @return true if it is ok to print a frequent log message. + bool frequentLogAllowed(const time_point& tnow) const; + private: // Receiving related data CRcvBuffer* m_pRcvBuffer; //< Receiver buffer SRT_ATTR_GUARDED_BY(m_RcvLossLock) diff --git a/srtcore/crypto.cpp b/srtcore/crypto.cpp index 223989199..eec141ed4 100644 --- a/srtcore/crypto.cpp +++ b/srtcore/crypto.cpp @@ -871,10 +871,10 @@ srt::EncryptionStatus srt::CCryptoControl::decrypt(CPacket& w_packet SRT_ATR_UNU return ENCS_FAILED; } - int rc = HaiCrypt_Rx_Data(m_hRcvCrypto, ((uint8_t *)w_packet.getHeader()), ((uint8_t *)w_packet.m_pcData), w_packet.getLength()); - if ( rc <= 0 ) + const int rc = HaiCrypt_Rx_Data(m_hRcvCrypto, ((uint8_t *)w_packet.getHeader()), ((uint8_t *)w_packet.m_pcData), w_packet.getLength()); + if (rc <= 0) { - LOGC(cnlog.Error, log << "decrypt ERROR (IPE): HaiCrypt_Rx_Data failure=" << rc << " - returning failed decryption"); + LOGC(cnlog.Note, log << "decrypt ERROR: HaiCrypt_Rx_Data failure=" << rc << " - returning failed decryption"); // -1: decryption failure // 0: key not received yet return ENCS_FAILED;