Integrate the new "rephist" [rep(utation) hist(ory)] module to trace

successful/failed connections, successful/failed extends, and
connection uptimes.

It's still not done: more tests are needed, and not everything calls
connection/circuit_mark_for_close properly.  This skews the results.

Also, there needs to be a 'testing' mode for non-OP ORs, where they
periodically build circuits just to test whether extends work.


svn:r1313

8 files changed, 130 insertions, 14 deletions

diff --git a/src/or/Makefile.am b/src/or/Makefile.am
index c056fa20f..38aee6179 100644
--- a/src/or/Makefile.am
+++ b/src/or/Makefile.am
@@ -14,7 +14,7 @@ tor_LDADD = ../common/libor.a
 test_SOURCES = buffers.c circuit.c command.c connection.c \
              connection_or.c config.c dirserv.c \
              onion.c router.c routerlist.c directory.c dns.c connection_edge.c \
-             cpuworker.c main.c test.c
+             rephist.c cpuworker.c main.c test.c
 
 test_LDADD = ../common/libor.a
 
diff --git a/src/or/circuit.c b/src/or/circuit.c
index 9f2d17565..2cadd6d7d 100644
--- a/src/or/circuit.c
+++ b/src/or/circuit.c
@@ -11,6 +11,7 @@ static int relay_crypt(circuit_t *circ, cell_t *cell, int cell_direction,
 static connection_t *relay_lookup_conn(circuit_t *circ, cell_t *cell, int cell_direction);
 static void circuit_free_cpath_node(crypt_path_t *victim);
 static uint16_t get_unique_circ_id_by_conn(connection_t *conn, int circ_id_type);
+static void circuit_rep_hist_note_result(circuit_t *circ);
 
 unsigned long stats_n_relay_cells_relayed = 0;
 unsigned long stats_n_relay_cells_delivered = 0;
@@ -698,6 +699,12 @@ int _circuit_mark_for_close(circuit_t *circ) {
   if(circ->state == CIRCUIT_STATE_ONIONSKIN_PENDING) {
     onion_pending_remove(circ);
   }
+  /* If the circuit ever became OPEN, we sent it to the reputation history
+   * module then.  If it isn't OPEN, we send it there now to remember which
+   * links worked and which didn't.
+   */
+  if (circ->state != CIRCUIT_STATE_OPEN)
+    circuit_rep_hist_note_result(circ);
 
   if(circ->n_conn)
     connection_send_destroy(circ->n_circ_id, circ->n_conn);
@@ -814,6 +821,40 @@ void circuit_log_path(int severity, circuit_t *circ) {
   log_fn(severity,"%s",buf);
 }
 
+/* Tell the rep(utation)hist(ory) module about the status of the links
+ * in circ.  Hops that have become OPEN are marked as successfully
+ * extended; the _first_ hop that isn't open (if any) is marked as
+ * unable to extend.
+ */
+static void
+circuit_rep_hist_note_result(circuit_t *circ)
+{
+  struct crypt_path_t *hop;
+  char *prev_nickname = NULL;
+  routerinfo_t *router;
+  hop = circ->cpath;
+  if (options.ORPort) {
+    prev_nickname = options.Nickname;
+  }
+  do {
+    router = router_get_by_addr_port(hop->addr,hop->port);
+    if (router) {
+      if (prev_nickname) {
+        if (hop->state == CPATH_STATE_OPEN)
+          rep_hist_note_extend_succeeded(prev_nickname, router->nickname);
+        else {
+          rep_hist_note_extend_failed(prev_nickname, router->nickname);
+          break;
+        }
+      }
+      prev_nickname = router->nickname;
+    } else {
+      prev_nickname = NULL;
+    }
+    hop=hop->next;
+  } while (hop!=circ->cpath);
+}
+
 static void
 circuit_dump_details(int severity, circuit_t *circ, int poll_index,
                      char *type, int this_circid, int other_circid) {
@@ -1179,6 +1220,7 @@ int circuit_finish_handshake(circuit_t *circ, char *reply) {
     log_fn(LOG_WARN,"Tor has successfully opened a circuit. Looks like it's working.");
   }
   circuit_log_path(LOG_INFO,circ);
+  circuit_rep_hist_note_result(circ);
   return 0;
 }
 
diff --git a/src/or/connection.c b/src/or/connection.c
index 50903cf36..c5e205ddf 100644
--- a/src/or/connection.c
+++ b/src/or/connection.c
@@ -185,7 +185,15 @@ _connection_mark_for_close(connection_t *conn, char reason)
       /* No special processing needed. */
       break;
     case CONN_TYPE_OR:
-      /* No special processing needed, I think. */
+      /* Remember why we're closing this connection. */
+      if (conn->state != OR_CONN_STATE_OPEN) {
+        rep_hist_note_connect_failed(conn->nickname, time(NULL));
+      } else if (reason == CLOSE_REASON_UNUSED_OR_CONN) {
+        rep_hist_note_disconnect(conn->nickname, time(NULL));
+      } else {
+        rep_hist_note_connection_died(conn->nickname, time(NULL));
+      }
+      /* No special processing needed. */
       break;
     case CONN_TYPE_EXIT:
     case CONN_TYPE_AP:
diff --git a/src/or/connection_edge.c b/src/or/connection_edge.c
index be1a2f750..4d2ce00cc 100644
--- a/src/or/connection_edge.c
+++ b/src/or/connection_edge.c
@@ -977,7 +977,6 @@ void client_dns_init(void) {
   client_dns_size = 0;
 }
 
-/* XXXX NM casei */
 static uint32_t client_dns_lookup_entry(const char *address)
 {
   struct client_dns_entry *ent;
@@ -1057,7 +1056,6 @@ static void* _remove_if_expired(const char *addr,
 
 void client_dns_clean(void)
 {
-  struct client_dns_entry *ent;
   time_t now;
 
   if(!client_dns_size)
diff --git a/src/or/connection_or.c b/src/or/connection_or.c
index 9f0f3b85c..39f3f2755 100644
--- a/src/or/connection_or.c
+++ b/src/or/connection_or.c
@@ -112,6 +112,8 @@ connection_t *connection_or_connect(routerinfo_t *router) {
   /* set up conn so it's got all the data we need to remember */
   connection_or_init_conn_from_router(conn, router);
 
+  /* XXXX Should all this stuff do mark-for-close instead? */
+
   if(connection_add(conn) < 0) { /* no space, forget it */
     connection_free(conn);
     return NULL;
@@ -242,7 +244,12 @@ static int connection_tls_finish_handshake(connection_t *conn) {
   if (!options.ORPort) { /* If I'm an OP... */
     conn->receiver_bucket = conn->bandwidth = DEFAULT_BANDWIDTH_OP;
     circuit_n_conn_open(conn); /* send the pending creates, if any. */
+    /* XXXX ORs may need to send creates for test circuits; "I am an OR"
+     * doesn't mean "I have no pending creates", right?
+     */
   }
+  /* Note the success */
+  rep_hist_note_connect_succeeded(nickname, time(NULL));
   return 0;
 }
 
diff --git a/src/or/main.c b/src/or/main.c
index 4c7be331a..1af6d8981 100644
--- a/src/or/main.c
+++ b/src/or/main.c
@@ -291,7 +291,7 @@ static void run_connection_housekeeping(int i, time_t now) {
       log_fn(LOG_INFO,"Expiring connection to %d (%s:%d).",
              i,conn->address, conn->port);
       /* flush anything waiting, e.g. a destroy for a just-expired circ */
-      connection_mark_for_close(conn,0);
+      connection_mark_for_close(conn,CLOSE_REASON_UNUSED_OR_CONN);
       conn->hold_open_until_flushed = 1;
     } else {
       /* either a full router, or we've got a circuit. send a padding cell. */
@@ -528,6 +528,9 @@ static int do_main_loop(void) {
     return -1;
   }
 
+  /* Initialize the history structures. */
+  rep_hist_init();
+
   /* load the private keys, if we're supposed to have them, and set up the
    * TLS context. */
   if (init_keys() < 0) {
@@ -679,6 +682,8 @@ static void dumpstats(int severity) {
   if (stats_n_seconds_reading)
     log(severity,"Average bandwidth used: %d bytes/sec",
            (int) (stats_n_bytes_read/stats_n_seconds_reading));
+
+  rep_hist_dump_stats(now,severity);
 }
 
 int network_init(void)
diff --git a/src/or/or.h b/src/or/or.h
index 154df4a58..8754e4468 100644
--- a/src/or/or.h
+++ b/src/or/or.h
@@ -209,6 +209,9 @@
 #define END_STREAM_REASON_TIMEOUT 7
 #define _MAX_END_STREAM_REASON 7
 
+/* Reasons used by connection_mark_for_close */
+#define CLOSE_REASON_UNUSED_OR_CONN 100
+
 /* default cipher function */
 #define DEFAULT_CIPHER CRYPTO_CIPHER_AES_CTR
 /* Used to en/decrypt onion skins */
@@ -905,11 +908,12 @@ size_t dirserv_get_directory(const char **cp);
 void rep_hist_init(void);
 void rep_hist_note_connect_failed(const char* nickname, time_t when);
 void rep_hist_note_connect_succeeded(const char* nickname, time_t when);
+void rep_hist_note_disconnect(const char* nickname, time_t when);
 void rep_hist_note_connection_died(const char* nickname, time_t when);
 void rep_hist_note_extend_succeeded(const char *from_name,
 				    const char *to_name);
 void rep_hist_note_extend_failed(const char *from_name, const char *to_name);
-void rep_hist_dump_status(time_t now);
+void rep_hist_dump_stats(time_t now, int severity);
 
 
 #endif
diff --git a/src/or/rephist.c b/src/or/rephist.c
index 7fa5c5a54..ab03fab09 100644
--- a/src/or/rephist.c
+++ b/src/or/rephist.c
@@ -23,6 +23,8 @@ typedef struct or_history_t {
 
 static strmap_t *history_map;
 
+/* Return the or_history_t for the named OR, creating it if necessary.
+ */
 static or_history_t *get_or_history(const char* nickname)
 {
   or_history_t *hist;
@@ -36,6 +38,9 @@ static or_history_t *get_or_history(const char* nickname)
   return hist;
 }
 
+/* Return the link_history_t for the link from the first named OR to
+ * the second, creating it if necessary.
+ */
 static link_history_t *get_link_history(const char *from_name,
 					const char *to_name)
 {
@@ -51,6 +56,9 @@ static link_history_t *get_link_history(const char *from_name,
   return lhist;
 }
 
+/* Update an or_history_t object so that its uptime/downtime count is
+ * up-to-date.
+ */
 static void update_or_history(or_history_t *hist, time_t when)
 {
   assert(hist);
@@ -64,11 +72,16 @@ static void update_or_history(or_history_t *hist, time_t when)
   }
 }
 
+/* Initialize the static data structures for tracking history.
+ */
 void rep_hist_init(void)
 {
   history_map = strmap_new();
 }
 
+/* Remember that an attempt to connect to the OR 'nickname' failed at
+ * 'when'.
+ */
 void rep_hist_note_connect_failed(const char* nickname, time_t when)
 {
   or_history_t *hist;
@@ -82,6 +95,9 @@ void rep_hist_note_connect_failed(const char* nickname, time_t when)
     hist->down_since = when;
 }
 
+/* Remember that an attempt to connect to the OR 'nickname' succeeded
+ * at 'when'.
+ */
 void rep_hist_note_connect_succeeded(const char* nickname, time_t when)
 {
   or_history_t *hist;
@@ -94,6 +110,24 @@ void rep_hist_note_connect_succeeded(const char* nickname, time_t when)
   if (!hist->up_since)
     hist->up_since = when;
 }
+
+/* Remember that we intentionally closed our connection to the OR
+ * 'nickname' at 'when'.
+ */
+void rep_hist_note_disconnect(const char* nickname, time_t when)
+{
+  or_history_t *hist;
+  hist = get_or_history(nickname);
+  ++hist->n_conn_ok;
+  if (hist->up_since) {
+    hist->uptime += (when - hist->up_since);
+    hist->up_since = 0;
+  }
+}
+
+/* Remember that our connection to the OR 'nickname' had an error and
+ * stopped working at 'when'.
+ */
 void rep_hist_note_connection_died(const char* nickname, time_t when)
 {
   or_history_t *hist;
@@ -106,21 +140,33 @@ void rep_hist_note_connection_died(const char* nickname, time_t when)
     hist->down_since = when;
 }
 
+/* Remember that we successfully extended from the OR 'from_name' to
+ * the OR 'to_name'.
+ */
 void rep_hist_note_extend_succeeded(const char *from_name,
 				    const char *to_name)
 {
   link_history_t *hist;
+  /* log_fn(LOG_WARN, "EXTEND SUCCEEDED: %s->%s",from_name,to_name); */
   hist = get_link_history(from_name, to_name);
   ++hist->n_extend_ok;
 }
+
+/* Remember that we tried to extend from the OR 'from_name' to the OR
+ * 'to_name', but failed.
+ */
 void rep_hist_note_extend_failed(const char *from_name, const char *to_name)
 {
   link_history_t *hist;
+  /* log_fn(LOG_WARN, "EXTEND FAILED: %s->%s",from_name,to_name); */
   hist = get_link_history(from_name, to_name);
   ++hist->n_extend_fail;
 }
 
-void rep_hist_dump_status(time_t now)
+/* Log all the reliability data we have rememberred, with the chosen
+ * severity.
+ */
+void rep_hist_dump_stats(time_t now, int severity)
 {
   strmap_iter_t *lhist_it;
   strmap_iter_t *orhist_it;
@@ -129,22 +175,28 @@ void rep_hist_dump_status(time_t now)
   link_history_t *link_history;
   double uptime;
   char buffer[2048];
-  char *cp;
   int len;
+  unsigned long upt, downt;
 
-  log(LOG_WARN, "--------------- Dumping history information:");
+  log(severity, "--------------- Dumping history information:");
 
   for (orhist_it = strmap_iter_init(history_map); !strmap_iter_done(orhist_it);
        orhist_it = strmap_iter_next(history_map,orhist_it)) {
     strmap_iter_get(orhist_it, &name1, (void**)&or_history);
 
     update_or_history(or_history, now);
-
-    uptime = ((double)or_history->uptime) / or_history->downtime;
-    log(LOG_WARN, "OR %s: %ld/%ld good connection attempts; uptime %.2f%%",
+    upt = or_history->uptime;
+    downt = or_history->downtime;
+    if (upt+downt) {
+      uptime = ((double)upt) / (upt+downt);
+    } else {
+      uptime=1.0;
+    }
+    log(severity,
+        "OR %s: %ld/%ld good connections; uptime %ld/%ld sec (%.2f%%)",
 	name1,
 	or_history->n_conn_ok, or_history->n_conn_fail+or_history->n_conn_ok,
-	uptime*100.0);
+        upt, upt+downt, uptime*100.0);
 
     strcpy(buffer, "    Good extend attempts: ");
     len = strlen(buffer);
@@ -160,7 +212,7 @@ void rep_hist_dump_status(time_t now)
 	break;
       }
     }
-    log(LOG_WARN, buffer);
+    log(severity, buffer);
   }
 }