r16279@catbus: nickm | 2007-10-30 11:14:29 -0400

 Improved skew reporting:  "You are 365 days in the duture" is more useful than "You are 525600 minutes in the future".  Also, when we get something that proves we are at least an hour in the past, tell the controller "CLOCK_SKEW MIN_SKEW=-3600" rather than just "CLOCK_SKEW"


svn:r12283

ChangeLog

@@ -37,6 +37,12 @@ Changes in version 0.2.0.10-alpha - 2007-1?-??
       to $PREFIX/share/tor/fallback-consensus) for a consensus.  This way
       we start knowing some directory caches.
     - When we receive a consensus from the future, warn about skew.
+    - Improve skew reporting: try to give the user a better log message about
+      how skewed they are, and how much this matters.
+
+  o Minor features (controller):
+    - When reporting clock skew, and we only have a lower bound on the amount
+      of skew, amount anyway, marked as a lower bound.
 
   - Utilities:
     - Update linux-tor-prio.sh script to allow QoS based on the uid of

doc/TODO

@@ -58,10 +58,10 @@ Things we'd like to do in 0.2.0.x:
         - Revised handshake.
         - Have a 'waiting_for_authentication' state.
         - Only do version negotiation if we use the normalized TLS.
-    . Skew issues:
+    o Skew issues:
       o if you load (nick says receive/set/anything) a consensus that's
         in the future, then log about skew.
-      - should change the "skew complaint" to specify in largest units
+      o should change the "skew complaint" to specify in largest units
         rather than just seconds.
     - Learn new authority IPs from consensus/certs.
     - karsten's patches

doc/spec/control-spec.txt

@@ -1200,14 +1200,16 @@ $Id$
 
      CLOCK_SKEW
        SKEW="+" / "-" SECONDS
+       MIN_SKEW="+" / "-" SECONDS.
        SOURCE="DIRSERV:IP:Port" / "NETWORKSTATUS:IP:PORT" / "CONSENSUS"
          If "SKEW" is present, it's an estimate of how far we are from the
-         time declared in the source.  If the source is a DIRSERV, we got
-         the current time from a connection to a dirserver.  If the source is
-         a NETWORKSTATUS, we decided we're skewed because we got a v2
-         networkstatus from far in the future.  If the source is
-         CONSENSUS, we decided we're skewed because we got a networkstatus
-         consensus from the future.
+         time declared in the source.  (In other words, if we're an hour in
+         the past, the value is -3600.)  "MIN_SKEW" is present, it's a lower
+         bound.  If the source is a DIRSERV, we got the current time from a
+         connection to a dirserver.  If the source is a NETWORKSTATUS, we
+         decided we're skewed because we got a v2 networkstatus from far in
+         the future.  If the source is CONSENSUS, we decided we're skewed
+         because we got a networkstatus consensus from the future.
 
          {Controllers may want to warn the user if the skew is high, or if
          multiple skew messages appear at severity WARN.  Controllers

src/common/util.c

@@ -1250,6 +1250,41 @@ parse_http_time(const char *date, struct tm *tm)
   return 0;
 }
 
+/** DOCDOC */
+int
+format_time_interval(char *out, size_t out_len, long interval)
+{
+  /* We only report seconds if there's no hours. */
+  long sec = 0, min = 0, hour = 0, day = 0;
+  if (interval < 0)
+    interval = -interval;
+
+  if (interval >= 86400) {
+    day = interval / 86400;
+    interval %= 86400;
+  }
+  if (interval >= 3600) {
+    hour = interval / 3600;
+    interval %= 3600;
+  }
+  if (interval >= 60) {
+    min = interval / 60;
+    interval %= 60;
+  }
+  sec = interval;
+
+  if (day) {
+    return tor_snprintf(out, out_len, "%ld days, %ld hours, %ld minutes",
+                        day, hour, min);
+  } else if (hour) {
+    return tor_snprintf(out, out_len, "%ld hours, %ld minutes", hour, min);
+  } else if (min) {
+    return tor_snprintf(out, out_len, "%ld minutes, %ld seconds", min, sec);
+  } else {
+    return tor_snprintf(out, out_len, "%ld seconds", sec);
+  }
+}
+
 /* =====
  * Fuzzy time
  * ===== */

src/common/util.h

@@ -206,6 +206,7 @@ void format_local_iso_time(char *buf, time_t t);
 void format_iso_time(char *buf, time_t t);
 int parse_iso_time(const char *buf, time_t *t);
 int parse_http_time(const char *buf, struct tm *tm);
+int format_time_interval(char *out, size_t out_len, long interval);
 /* Fuzzy time. */
 void ftime_set_maximum_sloppiness(int seconds);
 void ftime_set_estimated_skew(int seconds);

src/or/directory.c

@@ -1250,14 +1250,18 @@ connection_dir_client_reached_eof(dir_connection_t *conn)
      */
     delta = conn->_base.timestamp_lastwritten - date_header;
     if (abs(delta)>ALLOW_DIRECTORY_TIME_SKEW) {
+      char dbuf[64];
       int trusted = router_digest_is_trusted_dir(conn->identity_digest);
+      format_time_interval(dbuf, sizeof(dbuf), delta);
       log_fn(trusted ? LOG_WARN : LOG_INFO,
              LD_HTTP,
              "Received directory with skewed time (server '%s:%d'): "
-             "we are %d minutes %s, or the directory is %d minutes %s.",
+             "It seems that our clock is %s by %s, or that theirs is %s. "
+             "Tor requires an accurate clock to work: please check your time "
+             "and date settings.",
              conn->_base.address, conn->_base.port,
-             abs(delta)/60, delta>0 ? "ahead" : "behind",
-             abs(delta)/60, delta>0 ? "behind" : "ahead");
+             delta>0 ? "ahead" : "behind", dbuf,
+             delta>0 ? "behind" : "ahead");
       skewed = 1; /* don't check the recommended-versions line */
       control_event_general_status(trusted ? LOG_WARN : LOG_NOTICE,
                                "CLOCK_SKEW SKEW=%d SOURCE=DIRSERV:%s:%d",

src/or/networkstatus.c

@@ -559,13 +559,16 @@ router_set_networkstatus_v2(const char *s, time_t arrived_at,
   format_iso_time(published, ns->published_on);
 
   if (ns->published_on > now + NETWORKSTATUS_ALLOW_SKEW) {
-    log_warn(LD_GENERAL, "Network status from %s was published in the future "
-             "(%s GMT). Check your system clock! "
+    char dbuf[64];
+    long delta = now - ns->published_on;
+    format_time_interval(dbuf, sizeof(dbuf), delta);
+    log_warn(LD_GENERAL, "Network status from %s was published %s in the "
+             "future (%s GMT). Check your time and date settings! "
              "Not caching.",
-             source_desc, published);
+             source_desc, dbuf, published);
     control_event_general_status(LOG_WARN,
-                                 "CLOCK_SKEW SOURCE=NETWORKSTATUS:%s:%d",
-                                 ns->source_address, ns->source_dirport);
+                       "CLOCK_SKEW MIN_SKEW=%ld SOURCE=NETWORKSTATUS:%s:%d",
+                       delta, ns->source_address, ns->source_dirport);
     skewed = 1;
   }
 
@@ -1329,12 +1332,17 @@ networkstatus_set_current_consensus(const char *consensus, int from_cache,
                                         current_consensus->valid_after);
 
   if (ftime_definitely_before(now, current_consensus->valid_after)) {
-    char buf[ISO_TIME_LEN+1];
-    format_iso_time(buf, current_consensus->valid_after);
-    log_warn(LD_GENERAL, "Consensus network status document was published "
-             "at some time in the future (%s GMT).  Check your time and date "
-             "settings!", buf);
-    control_event_general_status(LOG_WARN, "CLOCK_SKEW SOURCE=CONSENSUS");
+    char tbuf[ISO_TIME_LEN+1];
+    char dbuf[64];
+    long delta = now - current_consensus->valid_after;
+    format_iso_time(tbuf, current_consensus->valid_after);
+    format_time_interval(dbuf, sizeof(dbuf), delta);
+    log_warn(LD_GENERAL, "Our clock is %s behind the time published in the "
+             "consensus network status document (%s GMT).  Tor needs an "
+             "accurate clock to work correctly. Please check your time and "
+             "date settings!", dbuf, tbuf);
+    control_event_general_status(LOG_WARN,
+                    "CLOCK_SKEW MIN_SKEW=%ld SOURCE=CONSENSUS", delta);
   }
 
   router_dir_info_changed();