From 8c5ba9388bd372316cc18f23dcb6d41b4c1e9546 Mon Sep 17 00:00:00 2001 From: Karsten Loesing Date: Fri, 27 Aug 2010 08:13:54 +0200 Subject: [PATCH 1/3] Make logging resolution configurable. Implements enhancement 1668. --- changes/enhancement1668 | 4 +++ doc/spec/control-spec.txt | 6 ++-- doc/tor.1.txt | 4 +++ src/common/log.c | 25 ++++++++++++-- src/common/torlog.h | 1 + src/or/config.c | 69 +++++++++++++++++++++++++++++++++++++++ src/or/or.h | 1 + 7 files changed, 104 insertions(+), 6 deletions(-) create mode 100644 changes/enhancement1668 diff --git a/changes/enhancement1668 b/changes/enhancement1668 new file mode 100644 index 0000000000..0d9f88fa06 --- /dev/null +++ b/changes/enhancement1668 @@ -0,0 +1,4 @@ + o Minor features: + - Make logging resolution configurable and change default from 1 + millisecond to 1 second. Implements enhancement 1668. + diff --git a/doc/spec/control-spec.txt b/doc/spec/control-spec.txt index 1864666047..2bbcfaec4c 100644 --- a/doc/spec/control-spec.txt +++ b/doc/spec/control-spec.txt @@ -525,9 +525,9 @@ of the form: OptionName SP OptionType [ SP Documentation ] CRLF OptionName = Keyword - OptionType = "Integer" / "TimeInterval" / "DataSize" / "Float" / - "Boolean" / "Time" / "CommaList" / "Dependant" / "Virtual" / - "String" / "LineList" + OptionType = "Integer" / "TimeInterval" / "TimeMsecInterval" / + "DataSize" / "Float" / "Boolean" / "Time" / "CommaList" / + "Dependant" / "Virtual" / "String" / "LineList" Documentation = Text "info/names" diff --git a/doc/tor.1.txt b/doc/tor.1.txt index 42eed6e3dd..5d6a959bea 100644 --- a/doc/tor.1.txt +++ b/doc/tor.1.txt @@ -343,6 +343,10 @@ Other options can be specified either on the command-line (--option on Windows; instead you should use the --service command-line option. (Default: 0) +**LogTimeGranularity** __NUM__:: + Set the resolution of timestamps in Tor's logs to NUM milliseconds. + NUM must be positive and either a divisor or a multiple of 1 second. + (Default: 1 second) **SafeLogging** **0**|**1**|**relay**:: Tor can scrub potentially sensitive strings from log messages (e.g. diff --git a/src/common/log.c b/src/common/log.c index b639e7a781..e507275830 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -131,6 +131,17 @@ log_set_application_name(const char *name) appname = name ? tor_strdup(name) : NULL; } +/** Log time granularity in milliseconds. */ +static int log_time_granularity = 1; + +/** Define log time granularity for all logs to be granularity_msec + * milliseconds. */ +void +set_log_time_granularity(int granularity_msec) +{ + log_time_granularity = granularity_msec; +} + /** Helper: Write the standard prefix for log lines to a * buf_len character buffer in buf. */ @@ -141,14 +152,22 @@ _log_prefix(char *buf, size_t buf_len, int severity) struct timeval now; struct tm tm; size_t n; - int r; + int r, ms; tor_gettimeofday(&now); t = (time_t)now.tv_sec; + ms = (int)now.tv_usec / 1000; + if (log_time_granularity >= 1000) { + t -= t % (log_time_granularity / 1000); + ms = 0; + } else { + ms -= ((int)now.tv_usec / 1000) % log_time_granularity; + } n = strftime(buf, buf_len, "%b %d %H:%M:%S", tor_localtime_r(&t, &tm)); - r = tor_snprintf(buf+n, buf_len-n, ".%.3i [%s] ", - (int)now.tv_usec / 1000, sev_to_string(severity)); + r = tor_snprintf(buf+n, buf_len-n, ".%.3i [%s] ", ms, + sev_to_string(severity)); + if (r<0) return buf_len-1; else diff --git a/src/common/torlog.h b/src/common/torlog.h index 21219569e3..d119993e87 100644 --- a/src/common/torlog.h +++ b/src/common/torlog.h @@ -138,6 +138,7 @@ void mark_logs_temp(void); void change_callback_log_severity(int loglevelMin, int loglevelMax, log_callback cb); void log_set_application_name(const char *name); +void set_log_time_granularity(int granularity_msec); /* Outputs a message to stdout */ void tor_log(int severity, log_domain_mask_t domain, const char *format, ...) diff --git a/src/or/config.c b/src/or/config.c index 4f7077153d..1112478946 100644 --- a/src/or/config.c +++ b/src/or/config.c @@ -44,6 +44,8 @@ typedef enum config_type_t { CONFIG_TYPE_FILENAME, /**< A filename: some prefixes get expanded. */ CONFIG_TYPE_UINT, /**< A non-negative integer less than MAX_INT */ CONFIG_TYPE_INTERVAL, /**< A number of seconds, with optional units*/ + CONFIG_TYPE_MSEC_INTERVAL,/**< A number of milliseconds, with optional + * units */ CONFIG_TYPE_MEMUNIT, /**< A number of bytes, with optional units*/ CONFIG_TYPE_DOUBLE, /**< A floating-point value */ CONFIG_TYPE_BOOL, /**< A boolean value, expressed as 0 or 1. */ @@ -291,6 +293,7 @@ static config_var_t _option_vars[] = { OBSOLETE("LinkPadding"), OBSOLETE("LogLevel"), OBSOLETE("LogFile"), + V(LogTimeGranularity, MSEC_INTERVAL, "1 second"), V(LongLivedPorts, CSV, "21,22,706,1863,5050,5190,5222,5223,6667,6697,8300"), VAR("MapAddress", LINELIST, AddressMap, NULL), @@ -556,6 +559,7 @@ static int is_listening_on_low_port(uint16_t port_option, const config_line_t *listen_options); static uint64_t config_parse_memunit(const char *s, int *ok); +static int config_parse_msec_interval(const char *s, int *ok); static int config_parse_interval(const char *s, int *ok); static void init_libevent(const or_options_t *options); static int opt_streq(const char *s1, const char *s2); @@ -1716,6 +1720,18 @@ config_assign_value(config_format_t *fmt, or_options_t *options, break; } + case CONFIG_TYPE_MSEC_INTERVAL: { + i = config_parse_msec_interval(c->value, &ok); + if (!ok) { + tor_asprintf(msg, + "Msec interval '%s %s' is malformed or out of bounds.", + c->key, c->value); + return -1; + } + *(int *)lvalue = i; + break; + } + case CONFIG_TYPE_MEMUNIT: { uint64_t u64 = config_parse_memunit(c->value, &ok); if (!ok) { @@ -2003,6 +2019,7 @@ get_assigned_option(config_format_t *fmt, void *options, escape_val = 0; /* Can't need escape. */ break; case CONFIG_TYPE_INTERVAL: + case CONFIG_TYPE_MSEC_INTERVAL: case CONFIG_TYPE_UINT: /* This means every or_options_t uint or bool element * needs to be an int. Not, say, a uint16_t or char. */ @@ -2230,6 +2247,7 @@ option_clear(config_format_t *fmt, or_options_t *options, config_var_t *var) *(time_t*)lvalue = 0; break; case CONFIG_TYPE_INTERVAL: + case CONFIG_TYPE_MSEC_INTERVAL: case CONFIG_TYPE_UINT: case CONFIG_TYPE_BOOL: *(int*)lvalue = 0; @@ -4324,6 +4342,17 @@ options_init_logs(or_options_t *options, int validate_only) options->RunAsDaemon; #endif + if (options->LogTimeGranularity > 0 && + (1000 % options->LogTimeGranularity == 0 || + options->LogTimeGranularity % 1000 == 0)) { + set_log_time_granularity(options->LogTimeGranularity); + } else { + log_warn(LD_CONFIG, "Log time granularity '%d' has to be positive " + "and either a divisor or a multiple of 1 second.", + options->LogTimeGranularity); + return -1; + } + ok = 1; elts = smartlist_create(); @@ -4812,6 +4841,26 @@ static struct unit_table_t time_units[] = { { NULL, 0 }, }; +/** Table to map the names of time units to the number of milliseconds + * they contain. */ +static struct unit_table_t time_msec_units[] = { + { "", 1 }, + { "msec", 1 }, + { "millisecond", 1 }, + { "milliseconds", 1 }, + { "second", 1000 }, + { "seconds", 1000 }, + { "minute", 60*1000 }, + { "minutes", 60*1000 }, + { "hour", 60*60*1000 }, + { "hours", 60*60*1000 }, + { "day", 24*60*60*1000 }, + { "days", 24*60*60*1000 }, + { "week", 7*24*60*60*1000 }, + { "weeks", 7*24*60*60*1000 }, + { NULL, 0 }, +}; + /** Parse a string val containing a number, zero or more * spaces, and an optional unit string. If the unit appears in the * table u, then multiply the number by the unit multiplier. @@ -4875,6 +4924,25 @@ config_parse_memunit(const char *s, int *ok) return u; } +/** Parse a string in the format "number unit", where unit is a unit of + * time in milliseconds. On success, set *ok to true and return + * the number of milliseconds in the provided interval. Otherwise, set + * *ok to 0 and return -1. */ +static int +config_parse_msec_interval(const char *s, int *ok) +{ + uint64_t r; + r = config_parse_units(s, time_msec_units, ok); + if (!ok) + return -1; + if (r > INT_MAX) { + log_warn(LD_CONFIG, "Msec interval '%s' is too long", s); + *ok = 0; + return -1; + } + return (int)r; +} + /** Parse a string in the format "number unit", where unit is a unit of time. * On success, set *ok to true and return the number of seconds in * the provided interval. Otherwise, set *ok to 0 and return -1. @@ -5264,6 +5332,7 @@ getinfo_helper_config(control_connection_t *conn, case CONFIG_TYPE_FILENAME: type = "Filename"; break; case CONFIG_TYPE_UINT: type = "Integer"; break; case CONFIG_TYPE_INTERVAL: type = "TimeInterval"; break; + case CONFIG_TYPE_MSEC_INTERVAL: type = "TimeMsecInterval"; break; case CONFIG_TYPE_MEMUNIT: type = "DataSize"; break; case CONFIG_TYPE_DOUBLE: type = "Float"; break; case CONFIG_TYPE_BOOL: type = "Boolean"; break; diff --git a/src/or/or.h b/src/or/or.h index 673a3920cf..01365381fc 100644 --- a/src/or/or.h +++ b/src/or/or.h @@ -2409,6 +2409,7 @@ typedef struct { config_line_t *Logs; /**< New-style list of configuration lines * for logs */ + int LogTimeGranularity; /**< Log resolution in milliseconds. */ char *DebugLogFile; /**< Where to send verbose log messages. */ char *DataDirectory; /**< OR only: where to store long-term data. */ From ed45bc198f10f5ea3dbd40514bb5b443802b50aa Mon Sep 17 00:00:00 2001 From: Karsten Loesing Date: Mon, 8 Nov 2010 16:37:20 +0100 Subject: [PATCH 2/3] Fix log granularity based on Nick's comments. Instead of rejecting a value that doesn't divide into 1 second, round to the nearest divisor of 1 second and warn. Document that the option only controls the granularity written by Tor to a file or console log. It does not (for example) "batch up" log messages to affect times logged by a controller, times attached to syslog messages, or the mtime fields on log files. --- doc/tor.1.txt | 5 ++++- src/or/config.c | 30 +++++++++++++++++++++++------- 2 files changed, 27 insertions(+), 8 deletions(-) diff --git a/doc/tor.1.txt b/doc/tor.1.txt index 5d6a959bea..f6662771dc 100644 --- a/doc/tor.1.txt +++ b/doc/tor.1.txt @@ -346,7 +346,10 @@ Other options can be specified either on the command-line (--option **LogTimeGranularity** __NUM__:: Set the resolution of timestamps in Tor's logs to NUM milliseconds. NUM must be positive and either a divisor or a multiple of 1 second. - (Default: 1 second) + Note that this option only controls the granularity written by Tor to + a file or console log. Tor does not (for example) "batch up" log + messages to affect times logged by a controller, times attached to + syslog messages, or the mtime fields on log files. (Default: 1 second) **SafeLogging** **0**|**1**|**relay**:: Tor can scrub potentially sensitive strings from log messages (e.g. diff --git a/src/or/config.c b/src/or/config.c index 1112478946..0251ef49db 100644 --- a/src/or/config.c +++ b/src/or/config.c @@ -4342,15 +4342,31 @@ options_init_logs(or_options_t *options, int validate_only) options->RunAsDaemon; #endif - if (options->LogTimeGranularity > 0 && - (1000 % options->LogTimeGranularity == 0 || - options->LogTimeGranularity % 1000 == 0)) { - set_log_time_granularity(options->LogTimeGranularity); - } else { - log_warn(LD_CONFIG, "Log time granularity '%d' has to be positive " - "and either a divisor or a multiple of 1 second.", + if (options->LogTimeGranularity <= 0) { + log_warn(LD_CONFIG, "Log time granularity '%d' has to be positive.", options->LogTimeGranularity); return -1; + } else if (1000 % options->LogTimeGranularity != 0 && + options->LogTimeGranularity % 1000 != 0) { + int granularity = options->LogTimeGranularity; + if (granularity < 40) { + do granularity++; + while (1000 % granularity != 0); + } else if (granularity < 1000) { + granularity = 1000 / granularity; + while (1000 % granularity != 0) + granularity--; + granularity = 1000 / granularity; + } else { + granularity = 1000 * ((granularity / 1000) + 1); + } + log_warn(LD_CONFIG, "Log time granularity '%d' has to be either a " + "divisor or a multiple of 1 second. Changing to " + "'%d'.", + options->LogTimeGranularity, granularity); + set_log_time_granularity(granularity); + } else { + set_log_time_granularity(options->LogTimeGranularity); } ok = 1; From 152c9cba65b85fb034f10b3485b5011ecff06f36 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Mon, 8 Nov 2010 12:40:26 -0500 Subject: [PATCH 3/3] Make LogTimeGranularity respect validate_only --- src/or/config.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/or/config.c b/src/or/config.c index 0251ef49db..25f07edcef 100644 --- a/src/or/config.c +++ b/src/or/config.c @@ -4364,9 +4364,11 @@ options_init_logs(or_options_t *options, int validate_only) "divisor or a multiple of 1 second. Changing to " "'%d'.", options->LogTimeGranularity, granularity); - set_log_time_granularity(granularity); + if (!validate_only) + set_log_time_granularity(granularity); } else { - set_log_time_granularity(options->LogTimeGranularity); + if (!validate_only) + set_log_time_granularity(options->LogTimeGranularity); } ok = 1;