From f269e0f9a51ecc7f22e62bde302afd8574d2f96f Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 26 Dec 2012 10:51:58 -0500 Subject: Wrapper function for the common rate-limited-log pattern. --- changes/easy.ratelim | 3 +++ src/common/log.c | 69 +++++++++++++++++++++++++++++++++++++++++----------- src/common/torlog.h | 15 ++++++++++++ src/common/util.h | 9 +++++++ 4 files changed, 82 insertions(+), 14 deletions(-) create mode 100644 changes/easy.ratelim diff --git a/changes/easy.ratelim b/changes/easy.ratelim new file mode 100644 index 0000000000..cadd1e4f5e --- /dev/null +++ b/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. diff --git a/src/common/log.c b/src/common/log.c index 5bf12cfe9c..15df2e02f0 100644 --- a/src/common/log.c +++ b/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; } diff --git a/src/common/torlog.h b/src/common/torlog.h index ab97f9c9a7..cc1fa64071 100644 --- a/src/common/torlog.h +++ b/src/common/torlog.h @@ -161,10 +161,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 severity, 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 ratelim (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)) \ @@ -182,6 +192,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, ...); @@ -191,6 +204,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_ @@ -204,6 +218,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_ diff --git a/src/common/util.h b/src/common/util.h index fabfdb19fd..005a3f37cd 100644 --- a/src/common/util.h +++ b/src/common/util.h @@ -284,6 +284,15 @@ void update_approx_time(time_t now); } } + + As a convenience wrapper for logging, you can replace the above with: + 
+   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!");
+   }
+
*/ typedef struct ratelim_t { int rate; -- cgit v1.2.3-54-g00ecf From a7334f5122046b55a5eff425cdaaa3e56c5defed Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 26 Dec 2012 11:07:15 -0500 Subject: Use log_fn_ratelim in a few places. --- src/or/buffers.c | 11 ++++------- src/or/circuituse.c | 10 +++------- src/or/connection.c | 7 ++----- src/or/router.c | 9 +++------ 4 files changed, 12 insertions(+), 25 deletions(-) diff --git a/src/or/buffers.c b/src/or/buffers.c index 3a1b4d54f8..4d4c879627 100644 --- a/src/or/buffers.c +++ b/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", diff --git a/src/or/circuituse.c b/src/or/circuituse.c index c3495b4402..2ffffa8423 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -479,17 +479,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)); } } diff --git a/src/or/connection.c b/src/or/connection.c index 740462e7c6..5da4d39ba5 100644 --- a/src/or/connection.c +++ b/src/or/connection.c @@ -1441,16 +1441,13 @@ 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; #ifdef _WIN32 *socket_error = WSAENETUNREACH; #else *socket_error = ENETUNREACH; #endif - 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; } diff --git a/src/or/router.c b/src/or/router.c index c7380cb444..1a4cee943d 100644 --- a/src/or/router.c +++ b/src/or/router.c @@ -936,14 +936,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; } -- cgit v1.2.3-54-g00ecf