Merge branch 'ticket26009'

6 files changed, 101 insertions, 28 deletions

diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c
index 6881e0ebb8..09102d0c4c 100644
--- a/src/or/circuitbuild.c
+++ b/src/or/circuitbuild.c
@@ -1130,19 +1130,29 @@ circuit_send_intermediate_onion_skin(origin_circuit_t *circ,
   return 0;
 }
 
-/** Our clock just jumped by <b>seconds_elapsed</b>. Assume
- * something has also gone wrong with our network: notify the user,
- * and abandon all not-yet-used circuits. */
+/** Our clock just jumped by <b>seconds_elapsed</b>. If <b>was_idle</b> is
+ * true, then the monotonic time matches; otherwise it doesn't. Assume
+ * something has also gone wrong with our network: notify the user, and
+ * abandon all not-yet-used circuits. */
 void
-circuit_note_clock_jumped(int seconds_elapsed)
+circuit_note_clock_jumped(int64_t seconds_elapsed, bool was_idle)
 {
   int severity = server_mode(get_options()) ? LOG_WARN : LOG_NOTICE;
-  tor_log(severity, LD_GENERAL, "Your system clock just jumped %d seconds %s; "
-      "assuming established circuits no longer work.",
-      seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed,
-      seconds_elapsed >=0 ? "forward" : "backward");
-  control_event_general_status(LOG_WARN, "CLOCK_JUMPED TIME=%d",
-                               seconds_elapsed);
+  if (was_idle) {
+    tor_log(severity, LD_GENERAL, "Tor has been idle for "I64_FORMAT
+            " seconds; assuming established circuits no longer work.",
+            I64_PRINTF_ARG(seconds_elapsed));
+  } else {
+    tor_log(severity, LD_GENERAL,
+            "Your system clock just jumped "I64_FORMAT" seconds %s; "
+            "assuming established circuits no longer work.",
+            I64_PRINTF_ARG(
+                 seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed),
+            seconds_elapsed >=0 ? "forward" : "backward");
+  }
+  control_event_general_status(LOG_WARN, "CLOCK_JUMPED TIME="I64_FORMAT
+                               " IDLE=%d",
+                               I64_PRINTF_ARG(seconds_elapsed), was_idle?1:0);
   /* so we log when it works again */
   note_that_we_maybe_cant_complete_circuits();
   control_event_client_status(severity, "CIRCUIT_NOT_ESTABLISHED REASON=%s",
diff --git a/src/or/circuitbuild.h b/src/or/circuitbuild.h
index ae4aef768a..0184898e29 100644
--- a/src/or/circuitbuild.h
+++ b/src/or/circuitbuild.h
@@ -29,7 +29,7 @@ void circuit_n_chan_done(channel_t *chan, int status,
 int inform_testing_reachability(void);
 int circuit_timeout_want_to_count_circ(const origin_circuit_t *circ);
 int circuit_send_next_onion_skin(origin_circuit_t *circ);
-void circuit_note_clock_jumped(int seconds_elapsed);
+void circuit_note_clock_jumped(int64_t seconds_elapsed, bool was_idle);
 int circuit_extend(cell_t *cell, circuit_t *circ);
 int circuit_init_cpath_crypto(crypt_path_t *cpath,
                               const char *key_data, size_t key_data_len,
diff --git a/src/or/connection.c b/src/or/connection.c
index 4361e1ca0c..1b15260801 100644
--- a/src/or/connection.c
+++ b/src/or/connection.c
@@ -3440,7 +3440,7 @@ int
 connection_handle_read(connection_t *conn)
 {
   int res;
-
+  update_current_time(time(NULL));
   res = connection_handle_read_impl(conn);
   return res;
 }
@@ -3983,6 +3983,7 @@ int
 connection_handle_write(connection_t *conn, int force)
 {
     int res;
+    update_current_time(time(NULL));
     conn->in_connection_handle_write = 1;
     res = connection_handle_write_impl(conn, force);
     conn->in_connection_handle_write = 0;
diff --git a/src/or/main.c b/src/or/main.c
index c3505a2d91..2497c277a2 100644
--- a/src/or/main.c
+++ b/src/or/main.c
@@ -2497,8 +2497,71 @@ hs_service_callback(time_t now, const or_options_t *options)
 static periodic_timer_t *second_timer = NULL;
 /** Number of libevent errors in the last second: we die if we get too many. */
 static int n_libevent_errors = 0;
-/** Last time that second_elapsed_callback was called. */
+
+/** Last time that update_current_time was called. */
 static time_t current_second = 0;
+/** Last time that update_current_time updated current_second. */
+static monotime_coarse_t current_second_last_changed;
+
+/**
+ * Set the current time to "now", which should be the value returned by
+ * time().  Check for clock jumps and track the total number of seconds we
+ * have been running.
+ */
+void
+update_current_time(time_t now)
+{
+  if (PREDICT_LIKELY(now == current_second)) {
+    /* We call this function a lot.  Most frequently, the current second
+     * will not have changed, so we just return. */
+    return;
+  }
+
+  const time_t seconds_elapsed = current_second ? (now - current_second) : 0;
+
+  /* Check the wall clock against the monotonic clock, so we can
+   * better tell idleness from clock jumps and/or other shenanigans. */
+  monotime_coarse_t last_updated;
+  memcpy(&last_updated, &current_second_last_changed, sizeof(last_updated));
+  monotime_coarse_get(&current_second_last_changed);
+
+  /** How much clock jumping do we tolerate? */
+#define NUM_JUMPED_SECONDS_BEFORE_WARN 100
+
+  /** How much idleness do we tolerate? */
+#define NUM_IDLE_SECONDS_BEFORE_WARN 3600
+
+  if (seconds_elapsed < -NUM_JUMPED_SECONDS_BEFORE_WARN) {
+    // moving back in time is always a bad sign.
+    circuit_note_clock_jumped(seconds_elapsed, false);
+  } else if (seconds_elapsed >= NUM_JUMPED_SECONDS_BEFORE_WARN) {
+    /* Compare the monotonic clock to the result of time(). */
+    const int32_t monotime_msec_passed =
+      monotime_coarse_diff_msec32(&last_updated,
+                                  &current_second_last_changed);
+    const int monotime_sec_passed = monotime_msec_passed / 1000;
+    const int discrepancy = monotime_sec_passed - (int)seconds_elapsed;
+    /* If the monotonic clock deviates from time(NULL), we have a couple of
+     * possibilities.  On some systems, this means we have been suspended or
+     * sleeping.  Everywhere, it can mean that the wall-clock time has
+     * been changed -- for example, with settimeofday().
+     *
+     * On the other hand, if the monotonic time matches with the wall-clock
+     * time, we've probably just been idle for a while, with no events firing.
+     * we tolerate much more of that.
+     */
+    const bool clock_jumped = abs(discrepancy) > 2;
+
+    if (clock_jumped || seconds_elapsed >= NUM_IDLE_SECONDS_BEFORE_WARN) {
+      circuit_note_clock_jumped(seconds_elapsed, ! clock_jumped);
+    }
+  } else if (seconds_elapsed > 0) {
+    stats_n_seconds_working += seconds_elapsed;
+  }
+
+  update_approx_time(now);
+  current_second = now;
+}
 
 /** Libevent callback: invoked once every second. */
 static void
@@ -2510,18 +2573,21 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg)
   time_t now;
   size_t bytes_written;
   size_t bytes_read;
-  int seconds_elapsed;
   (void)timer;
   (void)arg;
 
   n_libevent_errors = 0;
 
-  /* log_notice(LD_GENERAL, "Tick."); */
   now = time(NULL);
-  update_approx_time(now);
+
+  /* We don't need to do this once-per-second any more: time-updating is
+   * only in this callback _because it is a callback_. It should be fine
+   * to disable this callback, and the time will still get updated.
+   */
+  update_current_time(now);
 
   /* the second has rolled over. check more stuff. */
-  seconds_elapsed = current_second ? (int)(now - current_second) : 0;
+  // remove this once it's unneeded
   bytes_read = (size_t)(stats_n_bytes_read - stats_prev_n_read);
   bytes_written = (size_t)(stats_n_bytes_written - stats_prev_n_written);
   stats_prev_n_read = stats_n_bytes_read;
@@ -2533,18 +2599,7 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg)
   control_event_circ_bandwidth_used();
   control_event_circuit_cell_stats();
 
-/** If more than this many seconds have elapsed, probably the clock
- * jumped: doesn't count. */
-#define NUM_JUMPED_SECONDS_BEFORE_WARN 100
-  if (seconds_elapsed < -NUM_JUMPED_SECONDS_BEFORE_WARN ||
-      seconds_elapsed >= NUM_JUMPED_SECONDS_BEFORE_WARN) {
-    circuit_note_clock_jumped(seconds_elapsed);
-  } else if (seconds_elapsed > 0)
-    stats_n_seconds_working += seconds_elapsed;
-
   run_scheduled_events(now);
-
-  current_second = now; /* remember which second it is, for next time */
 }
 
 #ifdef HAVE_SYSTEMD_209
@@ -3029,6 +3084,7 @@ signal_callback(evutil_socket_t fd, short events, void *arg)
   (void)fd;
   (void)events;
 
+  update_current_time(time(NULL));
   process_signal(sig);
 }
 
@@ -3667,6 +3723,8 @@ tor_free_all(int postfork)
   heartbeat_callback_first_time = 1;
   n_libevent_errors = 0;
   current_second = 0;
+  memset(&current_second_last_changed, 0,
+         sizeof(current_second_last_changed));
 
   if (!postfork) {
     release_lockfile();
diff --git a/src/or/main.h b/src/or/main.h
index a312b51e05..45d6b4478f 100644
--- a/src/or/main.h
+++ b/src/or/main.h
@@ -66,6 +66,8 @@ void reschedule_dirvote(const or_options_t *options);
 void mainloop_schedule_postloop_cleanup(void);
 void rescan_periodic_events(const or_options_t *options);
 
+void update_current_time(time_t now);
+
 MOCK_DECL(long,get_uptime,(void));
 MOCK_DECL(void,reset_uptime,(void));
 
diff --git a/src/or/periodic.c b/src/or/periodic.c
index 76aa418b35..92fa677f8f 100644
--- a/src/or/periodic.c
+++ b/src/or/periodic.c
@@ -14,6 +14,7 @@
 #include "or.h"
 #include "compat_libevent.h"
 #include "config.h"
+#include "main.h"
 #include "periodic.h"
 
 /** We disable any interval greater than this number of seconds, on the
@@ -48,6 +49,7 @@ periodic_event_dispatch(mainloop_event_t *ev, void *data)
   }
 
   time_t now = time(NULL);
+  update_current_time(now);
   const or_options_t *options = get_options();
 //  log_debug(LD_GENERAL, "Dispatching %s", event->name);
   int r = event->fn(now, options);