Merge branch 'loggranularity'

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.
+

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"

doc/tor.1.txt

@@ -343,6 +343,13 @@ 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.
+    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.

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 <b>granularity_msec</b>
+ * milliseconds. */
+void
+set_log_time_granularity(int granularity_msec)
+{
+  log_time_granularity = granularity_msec;
+}
+
 /** Helper: Write the standard prefix for log lines to a
  * <b>buf_len</b> character buffer in <b>buf</b>.
  */
@@ -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

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, ...)

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),
@@ -557,6 +560,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);
@@ -1722,6 +1726,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) {
@@ -2009,6 +2025,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. */
@@ -2236,6 +2253,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;
@@ -4338,6 +4356,35 @@ options_init_logs(or_options_t *options, int validate_only)
                options->RunAsDaemon;
 #endif
 
+  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);
+    if (!validate_only)
+      set_log_time_granularity(granularity);
+  } else {
+    if (!validate_only)
+      set_log_time_granularity(options->LogTimeGranularity);
+  }
+
   ok = 1;
   elts = smartlist_create();
 
@@ -4826,6 +4873,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 <b>val</b> containing a number, zero or more
  * spaces, and an optional unit string.  If the unit appears in the
  * table <b>u</b>, then multiply the number by the unit multiplier.
@@ -4889,6 +4956,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 *<b>ok</b> to true and return
+ * the number of milliseconds in the provided interval.  Otherwise, set
+ * *<b>ok</b> 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 *<b>ok</b> to true and return the number of seconds in
  * the provided interval.  Otherwise, set *<b>ok</b> to 0 and return -1.
@@ -5278,6 +5364,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;

src/or/or.h

@@ -2490,6 +2490,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. */