TLS Validator: Unknown SNI as WARN in Log: merge pull request #579 from telemt/flow

TLS Validator: Unknown SNI as WARN in Log

Cargo.lock

@@ -2793,7 +2793,7 @@ checksum = "7b2093cf4c8eb1e67749a6762251bc9cd836b6fc171623bd0a9d324d37af2417"
 
 [[package]]
 name = "telemt"
-version = "3.3.30"
+version = "3.3.31"
 dependencies = [
  "aes",
  "anyhow",

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "telemt"
-version = "3.3.30"
+version = "3.3.31"
 edition = "2024"
 
 [profile.release]

src/proxy/handshake.rs

@@ -13,7 +13,7 @@ use std::sync::Arc;
 use std::sync::{Mutex, OnceLock};
 use std::time::{Duration, Instant};
 use tokio::io::{AsyncRead, AsyncWrite, AsyncWriteExt};
-use tracing::{debug, trace, warn};
+use tracing::{debug, info, trace, warn};
 use zeroize::{Zeroize, Zeroizing};
 
 use crate::config::{ProxyConfig, UnknownSniAction};
@@ -28,6 +28,8 @@ use rand::RngExt;
 
 const ACCESS_SECRET_BYTES: usize = 16;
 static INVALID_SECRET_WARNED: OnceLock<Mutex<HashSet<(String, String)>>> = OnceLock::new();
+const UNKNOWN_SNI_WARN_COOLDOWN_SECS: u64 = 5;
+static UNKNOWN_SNI_WARN_NEXT_ALLOWED: OnceLock<Mutex<Option<Instant>>> = OnceLock::new();
 #[cfg(test)]
 const WARNED_SECRET_MAX_ENTRIES: usize = 64;
 #[cfg(not(test))]
@@ -86,6 +88,24 @@ fn auth_probe_saturation_state_lock()
         .unwrap_or_else(|poisoned| poisoned.into_inner())
 }
 
+fn unknown_sni_warn_state_lock() -> std::sync::MutexGuard<'static, Option<Instant>> {
+    UNKNOWN_SNI_WARN_NEXT_ALLOWED
+        .get_or_init(|| Mutex::new(None))
+        .lock()
+        .unwrap_or_else(|poisoned| poisoned.into_inner())
+}
+
+fn should_emit_unknown_sni_warn(now: Instant) -> bool {
+    let mut guard = unknown_sni_warn_state_lock();
+    if let Some(next_allowed) = *guard
+        && now < next_allowed
+    {
+        return false;
+    }
+    *guard = Some(now + Duration::from_secs(UNKNOWN_SNI_WARN_COOLDOWN_SECS));
+    true
+}
+
 fn normalize_auth_probe_ip(peer_ip: IpAddr) -> IpAddr {
     match peer_ip {
         IpAddr::V4(ip) => IpAddr::V4(ip),
@@ -412,6 +432,25 @@ fn auth_probe_test_lock() -> &'static Mutex<()> {
     TEST_LOCK.get_or_init(|| Mutex::new(()))
 }
 
+#[cfg(test)]
+fn unknown_sni_warn_test_lock() -> &'static Mutex<()> {
+    static TEST_LOCK: OnceLock<Mutex<()>> = OnceLock::new();
+    TEST_LOCK.get_or_init(|| Mutex::new(()))
+}
+
+#[cfg(test)]
+fn clear_unknown_sni_warn_state_for_testing() {
+    if UNKNOWN_SNI_WARN_NEXT_ALLOWED.get().is_some() {
+        let mut guard = unknown_sni_warn_state_lock();
+        *guard = None;
+    }
+}
+
+#[cfg(test)]
+fn should_emit_unknown_sni_warn_for_testing(now: Instant) -> bool {
+    should_emit_unknown_sni_warn(now)
+}
+
 #[cfg(test)]
 fn clear_warned_secrets_for_testing() {
     if let Some(warned) = INVALID_SECRET_WARNED.get()
@@ -658,12 +697,25 @@ where
     if client_sni.is_some() && matched_tls_domain.is_none() && preferred_user_hint.is_none() {
         auth_probe_record_failure(peer.ip(), Instant::now());
         maybe_apply_server_hello_delay(config).await;
-        debug!(
+        let sni = client_sni.as_deref().unwrap_or_default();
+        let log_now = Instant::now();
+        if should_emit_unknown_sni_warn(log_now) {
+            warn!(
                 peer = %peer,
-            sni = ?client_sni,
-            action = ?config.censorship.unknown_sni_action,
+                sni = %sni,
+                unknown_sni = true,
+                unknown_sni_action = ?config.censorship.unknown_sni_action,
                 "TLS handshake rejected by unknown SNI policy"
             );
+        } else {
+            info!(
+                peer = %peer,
+                sni = %sni,
+                unknown_sni = true,
+                unknown_sni_action = ?config.censorship.unknown_sni_action,
+                "TLS handshake rejected by unknown SNI policy"
+            );
+        }
         return match config.censorship.unknown_sni_action {
             UnknownSniAction::Drop => HandshakeResult::Error(ProxyError::UnknownTlsSni),
             UnknownSniAction::Mask => HandshakeResult::BadClient { reader, writer },

src/proxy/tests/handshake_security_tests.rs

@@ -1643,6 +1643,32 @@ fn auth_probe_capacity_fresh_full_map_still_tracks_newcomer_with_bounded_evictio
     );
 }
 
+#[test]
+fn unknown_sni_warn_cooldown_first_event_is_warn_and_repeated_events_are_info_until_window_expires()
+{
+    let _guard = unknown_sni_warn_test_lock()
+        .lock()
+        .unwrap_or_else(|poisoned| poisoned.into_inner());
+    clear_unknown_sni_warn_state_for_testing();
+
+    let now = Instant::now();
+
+    assert!(
+        should_emit_unknown_sni_warn_for_testing(now),
+        "first unknown SNI event must be eligible for WARN emission"
+    );
+    assert!(
+        !should_emit_unknown_sni_warn_for_testing(now + Duration::from_secs(1)),
+        "events inside cooldown window must be demoted from WARN to INFO"
+    );
+    assert!(
+        should_emit_unknown_sni_warn_for_testing(
+            now + Duration::from_secs(UNKNOWN_SNI_WARN_COOLDOWN_SECS)
+        ),
+        "once cooldown expires, next unknown SNI event must be WARN-eligible again"
+    );
+}
+
 #[test]
 fn stress_auth_probe_full_map_churn_keeps_bound_and_tracks_newcomers() {
     let _guard = auth_probe_test_lock()