Logging / Channel padding delay

Reduce the amount of messages being logged related to
channel padding delay when log level is "notice".
Log the channel padding delay as "info" as soon as the
delay occurs. Log "notice" on each heartbeat only
containing the average channel padding delay and the
amount of delays (that exceeded the allowed time window)
occurring between heartbeats or, if first heartbeat
since startup, between startup and heartbeat.

diff --git a/src/core/or/channelpadding.c b/src/core/or/channelpadding.c
index 1f559f6c420d6cce246082bafef9451a65c93483..6a6780f6fbb1c74b82cbbb51a31e2126acd66293 100644 (file)
--- a/src/core/or/channelpadding.c
+++ b/src/core/or/channelpadding.c
@@ -1,7 +1,7 @@
 /* Copyright (c) 2001 Matej Pfajfar.
  * Copyright (c) 2001-2004, Roger Dingledine.
  * Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson.
- * Copyright (c) 2007-2021, The Tor Project, Inc. */
+ * Copyright (c) 2007-2025, The Tor Project, Inc. */
 /* See LICENSE for licensing information */
 
 /**
@@ -38,6 +38,13 @@ STATIC int32_t channelpadding_get_netflow_inactive_timeout_ms(
 STATIC int channelpadding_send_disable_command(channel_t *);
 STATIC int64_t channelpadding_compute_time_until_pad_for_netflow(channel_t *);
 
+/** Total channel padding delay of delays that exceeded the allowed time
+ *  window since last heartbeat or, if no heartbeat yet, since startup */
+static uint64_t channel_padding_delayed_ms = 0;
+/** Amount of delays that exceeded the allowed time window since
+ *  last heartbeat or, if no heartbeat yet, since startup */
+static uint64_t channel_padding_delayed_count = 0;
+
 /** The total number of pending channelpadding timers */
 static uint64_t total_timers_pending;
 
@@ -565,11 +572,14 @@ channelpadding_compute_time_until_pad_for_netflow(channel_t *chan)
      * about it entirely.. */
 #define NETFLOW_MISSED_WINDOW (150000 - DFLT_NETFLOW_INACTIVE_KEEPALIVE_HIGH)
     if (ms_till_pad < 0) {
-      int severity = (ms_till_pad < -NETFLOW_MISSED_WINDOW)
-                      ? LOG_NOTICE : LOG_INFO;
-      log_fn(severity, LD_OR,
-              "Channel padding timeout scheduled %"PRId64"ms in the past. ",
-             (-ms_till_pad));
+      if (ms_till_pad < -NETFLOW_MISSED_WINDOW) {
+        log_info(LD_OR,
+                "Channel padding delay of %"PRIu64"ms occurred in the past "
+                "that exceeded the allowed time window.",
+               (-ms_till_pad));
+        channel_padding_delayed_ms -= ms_till_pad;
+        channel_padding_delayed_count += 1;
+      }
       return 0; /* Clock jumped: Send padding now */
     }
 
@@ -797,3 +807,28 @@ channelpadding_decide_to_pad_channel(channel_t *chan)
     return CHANNELPADDING_PADLATER;
   }
 }
+
+/* Log a heartbeat message with the average channel padding delay and
+ * the number of occurred delays (that exceeded the allowed time window)
+ * since the previous heartbeat or, if we didn't have a heartbeat yet,
+ * since startup. */
+void
+channelpadding_log_heartbeat(void)
+{
+  /* Whether we had a heartbeat since startup */
+  static uint8_t heartbeat = 0;
+
+  if (channel_padding_delayed_count > 0) {
+    log_notice(LD_OR,
+               "Average channel padding delay of delays that exceeded "
+               "the allowed time window since %s: %"PRIu64"ms "
+               "(Number of delays: %"PRIu64")",
+               heartbeat ? "previous heartbeat" : "startup",
+               (uint64_t)((double)channel_padding_delayed_ms /
+                          channel_padding_delayed_count),
+               channel_padding_delayed_count);
+    channel_padding_delayed_count = 0;
+    channel_padding_delayed_ms = 0;
+  }
+  heartbeat = 1;
+}

diff --git a/src/core/or/channelpadding.h b/src/core/or/channelpadding.h
index 23f4210ab77083d8263d0c4ca5d449d2ada2fe2e..7d085fd63c03735907e467948b09face7345ee63 100644 (file)
--- a/src/core/or/channelpadding.h
+++ b/src/core/or/channelpadding.h
@@ -1,7 +1,7 @@
 /* Copyright (c) 2001 Matej Pfajfar.
  * Copyright (c) 2001-2004, Roger Dingledine.
  * Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson.
- * Copyright (c) 2007-2021, The Tor Project, Inc. */
+ * Copyright (c) 2007-2025, The Tor Project, Inc. */
 /* See LICENSE for licensing information */
 
 /**
@@ -39,4 +39,6 @@ int channelpadding_get_circuits_available_timeout(void);
 unsigned int channelpadding_get_channel_idle_timeout(const channel_t *, int);
 void channelpadding_new_consensus_params(const networkstatus_t *ns);
 
+void channelpadding_log_heartbeat(void);
+
 #endif /* !defined(TOR_CHANNELPADDING_H) */

diff --git a/src/core/or/status.c b/src/core/or/status.c
index 11912ffc25c24f4f68d601281face26d5dbfd281..3ab0393b10ff36a9f7bb3b870f4b62a6edd7e8e3 100644 (file)
--- a/src/core/or/status.c
+++ b/src/core/or/status.c
@@ -1,4 +1,4 @@
-/* Copyright (c) 2010-2021, The Tor Project, Inc. */
+/* Copyright (c) 2010-2025, The Tor Project, Inc. */
 /* See LICENSE for licensing information */
 
 /**
@@ -24,6 +24,7 @@
 #include "feature/relay/router.h"
 #include "feature/relay/routermode.h"
 #include "core/or/circuitlist.h"
+#include "core/or/channelpadding.h"
 #include "core/mainloop/mainloop.h"
 #include "feature/stats/rephist.h"
 #include "feature/hibernate/hibernate.h"
@@ -243,6 +244,7 @@ log_heartbeat(time_t now)
     rep_hist_log_circuit_handshake_stats(now);
     rep_hist_log_link_protocol_counts();
     dos_log_heartbeat();
+    channelpadding_log_heartbeat();
   }
 
   circuit_log_ancient_one_hop_circuits(1800);