Merge remote-tracking branch 'public/easy_ratelim'

Conflicts:
	src/or/connection.c

changes/easy.ratelim

@@ -0,0 +1,3 @@
+  o Code simplification and refactoring:
+    - Add a wrapper function for the common "log a message with a rate-limit"
+      case.

src/common/log.c

@@ -140,11 +140,12 @@ static char *domain_to_string(log_domain_mask_t domain,
                              char *buf, size_t buflen);
 static INLINE char *format_msg(char *buf, size_t buf_len,
            log_domain_mask_t domain, int severity, const char *funcname,
+           const char *suffix,
            const char *format, va_list ap, size_t *msg_len_out)
-  CHECK_PRINTF(6,0);
+  CHECK_PRINTF(7,0);
 static void logv(int severity, log_domain_mask_t domain, const char *funcname,
-                 const char *format, va_list ap)
-  CHECK_PRINTF(4,0);
+                 const char *suffix, const char *format, va_list ap)
+  CHECK_PRINTF(5,0);
 
 /** Name of the application: used to generate the message we write at the
  * start of each new log. */
@@ -251,6 +252,7 @@ log_tor_version(logfile_t *lf, int reset)
 static INLINE char *
 format_msg(char *buf, size_t buf_len,
            log_domain_mask_t domain, int severity, const char *funcname,
+           const char *suffix,
            const char *format, va_list ap, size_t *msg_len_out)
 {
   size_t n;
@@ -312,6 +314,13 @@ format_msg(char *buf, size_t buf_len,
     n = buf_len;
   } else {
     n += r;
+    if (suffix) {
+      size_t suffix_len = strlen(suffix);
+      if (buf_len-n >= suffix_len) {
+        memcpy(buf+n, suffix, suffix_len);
+        n += suffix_len;
+      }
+    }
   }
   buf[n]='\n';
   buf[n+1]='\0';
@@ -325,7 +334,7 @@ format_msg(char *buf, size_t buf_len,
  */
 static void
 logv(int severity, log_domain_mask_t domain, const char *funcname,
-     const char *format, va_list ap)
+     const char *suffix, const char *format, va_list ap)
 {
   char buf[10024];
   size_t msg_len = 0;
@@ -361,8 +370,8 @@ logv(int severity, log_domain_mask_t domain, const char *funcname,
 
     if (!formatted) {
       end_of_prefix =
-        format_msg(buf, sizeof(buf), domain, severity, funcname, format, ap,
-                   &msg_len);
+        format_msg(buf, sizeof(buf), domain, severity, funcname, suffix,
+                   format, ap, &msg_len);
       formatted = 1;
     }
 
@@ -426,7 +435,7 @@ tor_log(int severity, log_domain_mask_t domain, const char *format, ...)
   if (severity > log_global_min_severity_)
     return;
   va_start(ap,format);
-  logv(severity, domain, NULL, format, ap);
+  logv(severity, domain, NULL, NULL, format, ap);
   va_end(ap);
 }
 
@@ -443,8 +452,24 @@ log_fn_(int severity, log_domain_mask_t domain, const char *fn,
   if (severity > log_global_min_severity_)
     return;
   va_start(ap,format);
-  logv(severity, domain, fn, format, ap);
+  logv(severity, domain, fn, NULL, format, ap);
+  va_end(ap);
+}
+void
+log_fn_ratelim_(ratelim_t *ratelim, int severity, log_domain_mask_t domain,
+                const char *fn, const char *format, ...)
+{
+  va_list ap;
+  char *m;
+  if (severity > log_global_min_severity_)
+    return;
+  m = rate_limit_log(ratelim, approx_time());
+  if (m == NULL)
+      return;
+  va_start(ap, format);
+  logv(severity, domain, fn, m, format, ap);
   va_end(ap);
+  tor_free(m);
 }
 #else
 /** @{ */
@@ -460,11 +485,27 @@ log_fn_(int severity, log_domain_mask_t domain, const char *format, ...)
   if (severity > log_global_min_severity_)
     return;
   va_start(ap,format);
-  logv(severity, domain, log_fn_function_name_, format, ap);
+  logv(severity, domain, log_fn_function_name_, NULL, format, ap);
   va_end(ap);
   log_fn_function_name_ = NULL;
 }
 void
+log_fn_ratelim_(ratelim_t *ratelim, int severity, log_domain_mask_t domain,
+                const char *format, ...)
+{
+  va_list ap;
+  char *m;
+  if (severity > log_global_min_severity_)
+    return;
+  m = rate_limit_log(ratelim, approx_time());
+  if (m == NULL)
+      return;
+  va_start(ap, format);
+  logv(severity, domain, log_fn_function_name_, m, format, ap);
+  va_end(ap);
+  tor_free(m);
+}
+void
 log_debug_(log_domain_mask_t domain, const char *format, ...)
 {
   va_list ap;
@@ -472,7 +513,7 @@ log_debug_(log_domain_mask_t domain, const char *format, ...)
   if (PREDICT_LIKELY(LOG_DEBUG > log_global_min_severity_))
     return;
   va_start(ap,format);
-  logv(LOG_DEBUG, domain, log_fn_function_name_, format, ap);
+  logv(LOG_DEBUG, domain, log_fn_function_name_, NULL, format, ap);
   va_end(ap);
   log_fn_function_name_ = NULL;
 }
@@ -483,7 +524,7 @@ log_info_(log_domain_mask_t domain, const char *format, ...)
   if (LOG_INFO > log_global_min_severity_)
     return;
   va_start(ap,format);
-  logv(LOG_INFO, domain, log_fn_function_name_, format, ap);
+  logv(LOG_INFO, domain, log_fn_function_name_, NULL, format, ap);
   va_end(ap);
   log_fn_function_name_ = NULL;
 }
@@ -494,7 +535,7 @@ log_notice_(log_domain_mask_t domain, const char *format, ...)
   if (LOG_NOTICE > log_global_min_severity_)
     return;
   va_start(ap,format);
-  logv(LOG_NOTICE, domain, log_fn_function_name_, format, ap);
+  logv(LOG_NOTICE, domain, log_fn_function_name_, NULL, format, ap);
   va_end(ap);
   log_fn_function_name_ = NULL;
 }
@@ -505,7 +546,7 @@ log_warn_(log_domain_mask_t domain, const char *format, ...)
   if (LOG_WARN > log_global_min_severity_)
     return;
   va_start(ap,format);
-  logv(LOG_WARN, domain, log_fn_function_name_, format, ap);
+  logv(LOG_WARN, domain, log_fn_function_name_, NULL, format, ap);
   va_end(ap);
   log_fn_function_name_ = NULL;
 }
@@ -516,7 +557,7 @@ log_err_(log_domain_mask_t domain, const char *format, ...)
   if (LOG_ERR > log_global_min_severity_)
     return;
   va_start(ap,format);
-  logv(LOG_ERR, domain, log_fn_function_name_, format, ap);
+  logv(LOG_ERR, domain, log_fn_function_name_, NULL, format, ap);
   va_end(ap);
   log_fn_function_name_ = NULL;
 }

src/common/torlog.h

@@ -160,10 +160,20 @@ extern int log_global_min_severity_;
 void log_fn_(int severity, log_domain_mask_t domain,
              const char *funcname, const char *format, ...)
   CHECK_PRINTF(4,5);
+struct ratelim_t;
+void log_fn_ratelim_(struct ratelim_t *ratelim, int severity,
+                     log_domain_mask_t domain, const char *funcname,
+                     const char *format, ...)
+  CHECK_PRINTF(5,6);
 /** Log a message at level <b>severity</b>, using a pretty-printed version
  * of the current function name. */
 #define log_fn(severity, domain, args...)               \
   log_fn_(severity, domain, __PRETTY_FUNCTION__, args)
+/** As log_fn, but use <b>ratelim</b> (an instance of ratelim_t) to control
+ * the frequency at which messages can appear.
+ */
+#define log_fn_ratelim(ratelim, severity, domain, args...)      \
+  log_fn_ratelim_(ratelim, severity, domain, __PRETTY_FUNCTION__, args)
 #define log_debug(domain, args...)                                      \
   STMT_BEGIN                                                            \
     if (PREDICT_UNLIKELY(log_global_min_severity_ == LOG_DEBUG))        \
@@ -181,6 +191,9 @@ void log_fn_(int severity, log_domain_mask_t domain,
 #else /* ! defined(__GNUC__) */
 
 void log_fn_(int severity, log_domain_mask_t domain, const char *format, ...);
+struct ratelim_t;
+void log_fn_ratelim_(struct ratelim_t *ratelim, int severity,
+             log_domain_mask_t domain, const char *format, ...);
 void log_debug_(log_domain_mask_t domain, const char *format, ...);
 void log_info_(log_domain_mask_t domain, const char *format, ...);
 void log_notice_(log_domain_mask_t domain, const char *format, ...);
@@ -190,6 +203,7 @@ void log_err_(log_domain_mask_t domain, const char *format, ...);
 #if defined(_MSC_VER) && _MSC_VER < 1300
 /* MSVC 6 and earlier don't have __func__, or even __LINE__. */
 #define log_fn log_fn_
+#define log_fn_ratelim log_fn_ratelim_
 #define log_debug log_debug_
 #define log_info log_info_
 #define log_notice log_notice_
@@ -203,6 +217,7 @@ extern const char *log_fn_function_name_;
  * do {...} while (0) trick to wrap this macro, since the macro can't take
  * arguments. */
 #define log_fn (log_fn_function_name_=__func__),log_fn_
+#define log_fn_ratelim (log_fn_function_name_=__func__),log_fn_ratelim_
 #define log_debug (log_fn_function_name_=__func__),log_debug_
 #define log_info (log_fn_function_name_=__func__),log_info_
 #define log_notice (log_fn_function_name_=__func__),log_notice_

src/common/util.h

@@ -284,6 +284,15 @@ void update_approx_time(time_t now);
       }
     }
    </pre>
+
+   As a convenience wrapper for logging, you can replace the above with:
+   <pre>
+   if (possibly_very_frequent_event()) {
+     static ratelim_t warning_limit = RATELIM_INIT(300);
+     log_fn_ratelim(&warning_limit, LOG_WARN, LD_GENERAL,
+                    "The event occurred!");
+   }
+   </pre>
  */
 typedef struct ratelim_t {
   int rate;

src/or/buffers.c

@@ -1505,22 +1505,19 @@ log_unsafe_socks_warning(int socks_protocol, const char *address,
   static ratelim_t socks_ratelim = RATELIM_INIT(SOCKS_WARN_INTERVAL);
 
   const or_options_t *options = get_options();
-  char *m = NULL;
   if (! options->WarnUnsafeSocks)
     return;
-  if (safe_socks || (m = rate_limit_log(&socks_ratelim, approx_time()))) {
-    log_warn(LD_APP,
+  if (safe_socks) {
+    log_fn_ratelim(&socks_ratelim, LOG_WARN, LD_APP,
              "Your application (using socks%d to port %d) is giving "
              "Tor only an IP address. Applications that do DNS resolves "
              "themselves may leak information. Consider using Socks4A "
              "(e.g. via privoxy or socat) instead. For more information, "
              "please see https://wiki.torproject.org/TheOnionRouter/"
-             "TorFAQ#SOCKSAndDNS.%s%s",
+             "TorFAQ#SOCKSAndDNS.%s",
              socks_protocol,
              (int)port,
-             safe_socks ? " Rejecting." : "",
-             m ? m : "");
-    tor_free(m);
+             safe_socks ? " Rejecting." : "");
   }
   control_event_client_status(LOG_WARN,
                               "DANGEROUS_SOCKS PROTOCOL=SOCKS%d ADDRESS=%s:%d",

src/or/circuituse.c

@@ -540,17 +540,13 @@ circuit_expire_building(void)
         continue;
       } else {
         static ratelim_t relax_timeout_limit = RATELIM_INIT(3600);
-        char *m;
-        if ((m = rate_limit_log(&relax_timeout_limit, approx_time()))) {
-          log_notice(LD_CIRC,
+        log_fn_ratelim(&relax_timeout_limit, LOG_NOTICE, LD_CIRC,
                  "No circuits are opened. Relaxed timeout for "
                  "a circuit with channel state %s to %ldms. "
                  "However, it appears the circuit has timed out anyway. "
-                 "%d guards are live. %s",
+                 "%d guards are live.",
                  channel_state_to_string(victim->n_chan->state),
-                     (long)circ_times.close_ms, num_live_entry_guards(0), m);
-          tor_free(m);
-        }
+                 (long)circ_times.close_ms, num_live_entry_guards(0));
       }
     }
 

src/or/connection.c

@@ -1444,12 +1444,9 @@ connection_connect(connection_t *conn, const char *address,
     /* We should never even try to connect anyplace if DisableNetwork is set.
      * Warn if we do, and refuse to make the connection. */
     static ratelim_t disablenet_violated = RATELIM_INIT(30*60);
-    char *m;
     *socket_error = SOCK_ERRNO(ENETUNREACH);
-    if ((m = rate_limit_log(&disablenet_violated, approx_time()))) {
-      log_warn(LD_BUG, "Tried to open a socket with DisableNetwork set.%s", m);
-      tor_free(m);
-    }
+    log_fn_ratelim(&disablenet_violated, LOG_WARN, LD_BUG,
+                   "Tried to open a socket with DisableNetwork set.");
     tor_fragile_assert();
     return -1;
   }

src/or/router.c

@@ -1117,14 +1117,11 @@ consider_testing_reachability(int test_or, int test_dir)
     if (test_or || test_dir) {
 #define SELF_EXCLUDED_WARN_INTERVAL 3600
       static ratelim_t warning_limit=RATELIM_INIT(SELF_EXCLUDED_WARN_INTERVAL);
-      char *msg;
-      if ((msg = rate_limit_log(&warning_limit, approx_time()))) {
-        log_warn(LD_CIRC, "Can't peform self-tests for this relay: we have "
+      log_fn_ratelim(&warning_limit, LOG_WARN, LD_CIRC,
+                 "Can't peform self-tests for this relay: we have "
                  "listed ourself in ExcludeNodes, and StrictNodes is set. "
                  "We cannot learn whether we are usable, and will not "
-                 "be able to advertise ourself.%s", msg);
-        tor_free(msg);
-      }
+                 "be able to advertise ourself.");
     }
     return;
   }