From: Waldemar Zimpel <w.zimpel@dev.utilizer.de>
Date: Mon, 9 Jun 2025 12:07:33 +0000 (+0200)
Subject: Logging / Channel padding delay
X-Git-Url: http://git.ipfire.org/gitweb/gitweb.cgi?a=commitdiff_plain;h=refs%2Fmerge-requests%2F908%2Fhead;p=thirdparty%2Ftor.git

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 1f559f6c42..6a6780f6fb 100644
--- 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 23f4210ab7..7d085fd63c 100644
--- 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 11912ffc25..3ab0393b10 100644
--- 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);