Distinguish true clock jumps from idleness

Since we're going to be disabling the second-elapsed callback, we're
going to sometimes have long periods when no events file, and so the
current second is not updated.  Handle that by having a better means
to detect "clock jumps" as opposed to "being idle for a while".
Tolerate far more of the latter.

Part of #26009.

src/or/circuitbuild.c

@@ -1133,19 +1133,27 @@ 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(int 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 %d seconds; "
+            "assuming established circuits no longer work.",
+            seconds_elapsed);
+  } else {
+    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 IDLE=%d",
+                               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",

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(int 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,

src/or/main.c

@@ -2498,6 +2498,8 @@ static int n_libevent_errors = 0;
 
 /** 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
@@ -2515,13 +2517,42 @@ update_current_time(time_t now)
 
   const time_t seconds_elapsed = current_second ? (now - current_second) : 0;
 
-/** If more than this many seconds have elapsed, probably the clock
- * jumped: doesn't count. */
+  /* 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
 
-  if (seconds_elapsed < -NUM_JUMPED_SECONDS_BEFORE_WARN ||
-      seconds_elapsed >= NUM_JUMPED_SECONDS_BEFORE_WARN) {
-    circuit_note_clock_jumped(seconds_elapsed);
+  /** 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 discrepency = monotime_sec_passed - 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(discrepency) > 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;
   }
@@ -3686,6 +3717,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();

src/test/test_mainloop.c

@@ -12,13 +12,19 @@
 #include "or.h"
 #include "main.h"
 
+static const uint64_t BILLION = 1000000000;
+
 static void
 test_mainloop_update_time_normal(void *arg)
 {
   (void)arg;
 
+  monotime_enable_test_mocking();
+  /* This is arbitrary */
+  uint64_t mt_now = U64_LITERAL(7493289274986);
   /* This time is in the past as of when this test was written. */
   time_t now = 1525272090;
+  monotime_coarse_set_mock_time_nsec(mt_now);
   reset_uptime();
   update_current_time(now);
   tt_int_op(approx_time(), OP_EQ, now);
@@ -28,12 +34,16 @@ test_mainloop_update_time_normal(void *arg)
   tt_int_op(get_uptime(), OP_EQ, 0);
 
   now += 1;
+  mt_now += BILLION;
+  monotime_coarse_set_mock_time_nsec(mt_now);
   update_current_time(now);
   tt_int_op(approx_time(), OP_EQ, now);
   tt_int_op(get_uptime(), OP_EQ, 1);
 
   now += 2; // two-second jump is unremarkable.
+  mt_now += 2*BILLION;
   update_current_time(now);
+  monotime_coarse_set_mock_time_nsec(mt_now);
   tt_int_op(approx_time(), OP_EQ, now);
   tt_int_op(get_uptime(), OP_EQ, 3);
 
@@ -43,7 +53,7 @@ test_mainloop_update_time_normal(void *arg)
   tt_int_op(get_uptime(), OP_EQ, 3); // but it doesn't roll back our uptime
 
  done:
-  ;
+  monotime_disable_test_mocking();
 }
 
 static void
@@ -51,8 +61,12 @@ test_mainloop_update_time_jumps(void *arg)
 {
   (void)arg;
 
+  monotime_enable_test_mocking();
+  /* This is arbitrary */
+  uint64_t mt_now = U64_LITERAL(7493289274986);
   /* This time is in the past as of when this test was written. */
   time_t now = 220897152;
+  monotime_coarse_set_mock_time_nsec(mt_now);
   reset_uptime();
   update_current_time(now);
   tt_int_op(approx_time(), OP_EQ, now);
@@ -60,16 +74,19 @@ test_mainloop_update_time_jumps(void *arg)
 
   /* Put some uptime on the clock.. */
   now += 3;
+  mt_now += 3*BILLION;
+  monotime_coarse_set_mock_time_nsec(mt_now);
   update_current_time(now);
   tt_int_op(approx_time(), OP_EQ, now);
   tt_int_op(get_uptime(), OP_EQ, 3);
 
-  /* Now try jumping forward. */
+  /* Now try jumping forward and backward, without updating the monotonic
+   * clock.  */
   setup_capture_of_logs(LOG_NOTICE);
-  now += 3600;
+  now += 1800;
   update_current_time(now);
   expect_single_log_msg_containing(
-               "Your system clock just jumped 3600 seconds forward");
+               "Your system clock just jumped 1800 seconds forward");
   tt_int_op(approx_time(), OP_EQ, now);
   tt_int_op(get_uptime(), OP_EQ, 3); // no uptime change.
   mock_clean_saved_logs();
@@ -80,15 +97,38 @@ test_mainloop_update_time_jumps(void *arg)
                "Your system clock just jumped 600 seconds backward");
   tt_int_op(approx_time(), OP_EQ, now);
   tt_int_op(get_uptime(), OP_EQ, 3); // no uptime change.
+  mock_clean_saved_logs();
 
   /* uptime tracking should go normally now if the clock moves sensibly. */
   now += 2;
+  mt_now += 2*BILLION;
   update_current_time(now);
   tt_int_op(approx_time(), OP_EQ, now);
   tt_int_op(get_uptime(), OP_EQ, 5);
 
+  /* If we skip forward by a few minutes but the monotonic clock agrees,
+   * we've just been idle: that counts as not worth warning about. */
+  now += 1800;
+  mt_now += 1800*BILLION;
+  monotime_coarse_set_mock_time_nsec(mt_now);
+  update_current_time(now);
+  expect_no_log_entry();
+  tt_int_op(approx_time(), OP_EQ, now);
+  tt_int_op(get_uptime(), OP_EQ, 5); // this doesn't count to uptime, though.
+
+  /* If we skip forward by a long time, even if the clock agrees, it's
+   * idnless that counts. */
+  now += 4000;
+  mt_now += 4000*BILLION;
+  monotime_coarse_set_mock_time_nsec(mt_now);
+  update_current_time(now);
+  expect_single_log_msg_containing("Tor has been idle for 4000 seconds");
+  tt_int_op(approx_time(), OP_EQ, now);
+  tt_int_op(get_uptime(), OP_EQ, 5);
+
  done:
   teardown_capture_of_logs();
+  monotime_disable_test_mocking();
 }
 
 #define MAINLOOP_TEST(name) \