[or-cvs] Integrate the new "rephist" [rep(utation) hist(ory)] module...

[nickm@seul.org (Nick Mathewson)]

Update of /home/or/cvsroot/src/or
In directory moria.mit.edu:/tmp/cvs-serv9606/src/or

Modified Files:
	Makefile.am circuit.c connection.c connection_edge.c 
	connection_or.c main.c or.h rephist.c 
Log Message:
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.


Index: Makefile.am
===================================================================
RCS file: /home/or/cvsroot/src/or/Makefile.am,v
retrieving revision 1.26
retrieving revision 1.27
diff -u -d -r1.26 -r1.27
--- Makefile.am	20 Mar 2004 01:48:05 -0000	1.26
+++ Makefile.am	20 Mar 2004 04:59:29 -0000	1.27
@@ -14,7 +14,7 @@
 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
 

Index: circuit.c
===================================================================
RCS file: /home/or/cvsroot/src/or/circuit.c,v
retrieving revision 1.152
retrieving revision 1.153
diff -u -d -r1.152 -r1.153
--- circuit.c	18 Mar 2004 19:22:55 -0000	1.152
+++ circuit.c	20 Mar 2004 04:59:29 -0000	1.153
@@ -11,6 +11,7 @@
 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 @@
   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 @@
   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 @@
     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;
 }
 

Index: connection.c
===================================================================
RCS file: /home/or/cvsroot/src/or/connection.c,v
retrieving revision 1.183
retrieving revision 1.184
diff -u -d -r1.183 -r1.184
--- connection.c	14 Mar 2004 17:06:29 -0000	1.183
+++ connection.c	20 Mar 2004 04:59:29 -0000	1.184
@@ -185,7 +185,15 @@
       /* 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:

Index: connection_edge.c
===================================================================
RCS file: /home/or/cvsroot/src/or/connection_edge.c,v
retrieving revision 1.116
retrieving revision 1.117
diff -u -d -r1.116 -r1.117
--- connection_edge.c	20 Mar 2004 01:21:19 -0000	1.116
+++ connection_edge.c	20 Mar 2004 04:59:29 -0000	1.117
@@ -977,7 +977,6 @@
   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 @@
 
 void client_dns_clean(void)
 {
-  struct client_dns_entry *ent;
   time_t now;
 
   if(!client_dns_size)

Index: connection_or.c
===================================================================
RCS file: /home/or/cvsroot/src/or/connection_or.c,v
retrieving revision 1.87
retrieving revision 1.88
diff -u -d -r1.87 -r1.88
--- connection_or.c	9 Mar 2004 14:53:00 -0000	1.87
+++ connection_or.c	20 Mar 2004 04:59:29 -0000	1.88
@@ -112,6 +112,8 @@
   /* 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 @@
   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;
 }
 

Index: main.c
===================================================================
RCS file: /home/or/cvsroot/src/or/main.c,v
retrieving revision 1.204
retrieving revision 1.205
diff -u -d -r1.204 -r1.205
--- main.c	18 Mar 2004 19:22:56 -0000	1.204
+++ main.c	20 Mar 2004 04:59:29 -0000	1.205
@@ -291,7 +291,7 @@
       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 @@
     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 @@
   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)

Index: or.h
===================================================================
RCS file: /home/or/cvsroot/src/or/or.h,v
retrieving revision 1.254
retrieving revision 1.255
diff -u -d -r1.254 -r1.255
--- or.h	20 Mar 2004 01:48:05 -0000	1.254
+++ or.h	20 Mar 2004 04:59:29 -0000	1.255
@@ -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 @@
 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

Index: rephist.c
===================================================================
RCS file: /home/or/cvsroot/src/or/rephist.c,v
retrieving revision 1.1
retrieving revision 1.2
diff -u -d -r1.1 -r1.2
--- rephist.c	20 Mar 2004 01:48:05 -0000	1.1
+++ rephist.c	20 Mar 2004 04:59:29 -0000	1.2
@@ -23,6 +23,8 @@
 
 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 @@
   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 @@
   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 @@
   }
 }
 
+/* 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 @@
     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 @@
   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 @@
     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 @@
   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 @@
 	break;
       }
     }
-    log(LOG_WARN, buffer);
+    log(severity, buffer);
   }
 }