Merge branch 'feature3457-v4-nm-squashed'

Conflicts:
	src/or/rendclient.c

changes/feature3457

@@ -0,0 +1,12 @@
+  o Minor features:
+
+    - Log (at debug level) whenever a circuit's purpose is changed.
+
+    - Allow controllers to request an event notification whenever a
+      circuit is cannibalized or its purpose is changed.  Implements
+      part of ticket 3457.
+
+    - Include the creation time of a circuit in CIRC and CIRC2
+      control-port events and the list produced by the 'GETINFO
+      circuit-status' control-port command.
+

src/common/util.c

@@ -1430,6 +1430,26 @@ format_iso_time(char *buf, time_t t)
   strftime(buf, ISO_TIME_LEN+1, "%Y-%m-%d %H:%M:%S", tor_gmtime_r(&t, &tm));
 }
 
+/** As format_iso_time, but use the yyyy-mm-ddThh:mm:ss format to avoid
+ * embedding an internal space. */
+void
+format_iso_time_nospace(char *buf, time_t t)
+{
+  format_iso_time(buf, t);
+  buf[10] = 'T';
+}
+
+/** As format_iso_time_nospace, but include microseconds in decimal
+ * fixed-point format.  Requires that buf be at least ISO_TIME_USEC_LEN+1
+ * bytes long. */
+void
+format_iso_time_nospace_usec(char *buf, const struct timeval *tv)
+{
+  tor_assert(tv);
+  format_iso_time_nospace(buf, tv->tv_sec);
+  tor_snprintf(buf+ISO_TIME_LEN, 8, ".%06d", (int)tv->tv_usec);
+}
+
 /** Given an ISO-formatted UTC time value (after the epoch) in <b>cp</b>,
  * parse it and store its value in *<b>t</b>.  Return 0 on success, -1 on
  * failure.  Ignore extraneous stuff in <b>cp</b> separated by whitespace from

src/common/util.h

@@ -238,8 +238,11 @@ time_t tor_timegm(struct tm *tm);
 void format_rfc1123_time(char *buf, time_t t);
 int parse_rfc1123_time(const char *buf, time_t *t);
 #define ISO_TIME_LEN 19
+#define ISO_TIME_USEC_LEN (ISO_TIME_LEN+7)
 void format_local_iso_time(char *buf, time_t t);
 void format_iso_time(char *buf, time_t t);
+void format_iso_time_nospace(char *buf, time_t t);
+void format_iso_time_nospace_usec(char *buf, const struct timeval *tv);
 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);

src/or/circuituse.c

@@ -481,7 +481,7 @@ circuit_expire_building(void)
           control_event_circuit_status(TO_ORIGIN_CIRCUIT(victim),
                                        CIRC_EVENT_FAILED,
                                        END_CIRC_REASON_TIMEOUT);
-          victim->purpose = CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT;
+          circuit_change_purpose(victim, CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT);
           /* Record this failure to check for too many timeouts
            * in a row. This function does not record a time value yet
            * (we do that later); it only counts the fact that we did
@@ -1309,14 +1309,22 @@ circuit_launch_by_extend_info(uint8_t purpose,
      * internal circs rather than exit circs? -RD */
     circ = circuit_find_to_cannibalize(purpose, extend_info, flags);
     if (circ) {
+      uint8_t old_purpose = circ->_base.purpose;
+      struct timeval old_timestamp_created;
+
       log_info(LD_CIRC,"Cannibalizing circ '%s' for purpose %d (%s)",
                build_state_get_exit_nickname(circ->build_state), purpose,
                circuit_purpose_to_string(purpose));
-      circ->_base.purpose = purpose;
+
+      circuit_change_purpose(TO_CIRCUIT(circ), purpose);
       /* reset the birth date of this circ, else expire_building
        * will see it and think it's been trying to build since it
        * began. */
       tor_gettimeofday(&circ->_base.timestamp_created);
+
+      control_event_circuit_cannibalized(circ, old_purpose,
+                                         &old_timestamp_created);
+
       switch (purpose) {
         case CIRCUIT_PURPOSE_C_ESTABLISH_REND:
         case CIRCUIT_PURPOSE_S_ESTABLISH_INTRO:
@@ -2028,3 +2036,39 @@ connection_ap_handshake_attach_circuit(entry_connection_t *conn)
   }
 }
 
+/** Change <b>circ</b>'s purpose to <b>new_purpose</b>. */
+void
+circuit_change_purpose(circuit_t *circ, uint8_t new_purpose)
+{
+  uint8_t old_purpose;
+  /* Don't allow an OR circ to become an origin circ or vice versa. */
+  tor_assert(!!(CIRCUIT_IS_ORIGIN(circ)) ==
+             !!(CIRCUIT_PURPOSE_IS_ORIGIN(new_purpose)));
+
+  if (circ->purpose == new_purpose) return;
+
+  if (CIRCUIT_IS_ORIGIN(circ)) {
+    char old_purpose_desc[80] = "";
+
+    strncpy(old_purpose_desc, circuit_purpose_to_string(circ->purpose), 80-1);
+    old_purpose_desc[80-1] = '\0';
+
+    log_debug(LD_CIRC,
+              "changing purpose of origin circ %d "
+              "from \"%s\" (%d) to \"%s\" (%d)",
+              TO_ORIGIN_CIRCUIT(circ)->global_identifier,
+              old_purpose_desc,
+              circ->purpose,
+              circuit_purpose_to_string(new_purpose),
+              new_purpose);
+  }
+
+  old_purpose = circ->purpose;
+  circ->purpose = new_purpose;
+
+  if (CIRCUIT_IS_ORIGIN(circ)) {
+    control_event_circuit_purpose_changed(TO_ORIGIN_CIRCUIT(circ),
+                                          old_purpose);
+  }
+}
+

src/or/circuituse.h

@@ -51,6 +51,8 @@ int connection_ap_handshake_attach_chosen_circuit(entry_connection_t *conn,
                                                   crypt_path_t *cpath);
 int connection_ap_handshake_attach_circuit(entry_connection_t *conn);
 
+void circuit_change_purpose(circuit_t *circ, uint8_t new_purpose);
+
 int hostname_in_track_host_exits(const or_options_t *options,
                                  const char *address);
 

src/or/control.c

@@ -54,7 +54,7 @@
 #define EVENT_STREAM_STATUS    0x0002
 #define EVENT_OR_CONN_STATUS   0x0003
 #define EVENT_BANDWIDTH_USED   0x0004
-#define EVENT_LOG_OBSOLETE     0x0005 /* Can reclaim this. */
+#define EVENT_CIRCUIT_STATUS_MINOR 0x0005
 #define EVENT_NEW_DESC         0x0006
 #define EVENT_DEBUG_MSG        0x0007
 #define EVENT_INFO_MSG         0x0008
@@ -272,8 +272,7 @@ control_adjust_event_log_severity(void)
       break;
     }
   }
-  if (EVENT_IS_INTERESTING(EVENT_LOG_OBSOLETE) ||
-      EVENT_IS_INTERESTING(EVENT_STATUS_GENERAL)) {
+  if (EVENT_IS_INTERESTING(EVENT_STATUS_GENERAL)) {
     if (min_log_event > EVENT_NOTICE_MSG)
       min_log_event = EVENT_NOTICE_MSG;
     if (max_log_event < EVENT_ERR_MSG)
@@ -925,6 +924,7 @@ struct control_event_t {
 };
 static const struct control_event_t control_event_table[] = {
   { EVENT_CIRCUIT_STATUS, "CIRC" },
+  { EVENT_CIRCUIT_STATUS_MINOR, "CIRC_MINOR" },
   { EVENT_STREAM_STATUS, "STREAM" },
   { EVENT_OR_CONN_STATUS, "ORCONN" },
   { EVENT_BANDWIDTH_USED, "BW" },
@@ -1854,6 +1854,16 @@ circuit_describe_status_for_controller(origin_circuit_t *circ)
     smartlist_add(descparts, rend_query_arg);
   }
 
+  {
+    char *time_created_arg = NULL;
+    char tbuf[ISO_TIME_USEC_LEN+1];
+    format_iso_time_nospace_usec(tbuf, &circ->_base.timestamp_created);
+
+    tor_asprintf(&time_created_arg, "TIME_CREATED=%s", tbuf);
+
+    smartlist_add(descparts, time_created_arg);
+  }
+
   rv = smartlist_join_strings(descparts, " ", 0, NULL);
 
   SMARTLIST_FOREACH(descparts, char *, cp, tor_free(cp));
@@ -2554,7 +2564,7 @@ handle_control_setcircuitpurpose(control_connection_t *conn,
     }
   }
 
-  circ->_base.purpose = new_purpose;
+  circuit_change_purpose(TO_CIRCUIT(circ), new_purpose);
   connection_write_str_to_buf("250 OK\r\n", conn);
 
  done:
@@ -3316,8 +3326,8 @@ connection_control_process_inbuf(control_connection_t *conn)
   goto again;
 }
 
-/** Something has happened to circuit <b>circ</b>: tell any interested
- * control connections. */
+/** Something major has happened to circuit <b>circ</b>: tell any
+ * interested control connections. */
 int
 control_event_circuit_status(origin_circuit_t *circ, circuit_status_event_t tp,
                              int reason_code)
@@ -3337,6 +3347,7 @@ control_event_circuit_status(origin_circuit_t *circ, circuit_status_event_t tp,
     case CIRC_EVENT_CLOSED: status = "CLOSED"; break;
     default:
       log_warn(LD_BUG, "Unrecognized status code %d", (int)tp);
+      tor_fragile_assert();
       return 0;
     }
 
@@ -3371,6 +3382,106 @@ control_event_circuit_status(origin_circuit_t *circ, circuit_status_event_t tp,
   return 0;
 }
 
+/** Something minor has happened to circuit <b>circ</b>: tell any
+ * interested control connections. */
+static int
+control_event_circuit_status_minor(origin_circuit_t *circ,
+                                   circuit_status_minor_event_t e,
+                                   int purpose, const struct timeval *tv)
+{
+  const char *event_desc;
+  char event_tail[160] = "";
+  if (!EVENT_IS_INTERESTING(EVENT_CIRCUIT_STATUS_MINOR))
+    return 0;
+  tor_assert(circ);
+
+  switch (e)
+    {
+    case CIRC_MINOR_EVENT_PURPOSE_CHANGED:
+      event_desc = "PURPOSE_CHANGED";
+
+      {
+        /* event_tail can currently be up to 68 chars long */
+        const char *hs_state_str =
+          circuit_purpose_to_controller_hs_state_string(purpose);
+        tor_snprintf(event_tail, sizeof(event_tail),
+                     " OLD_PURPOSE=%s%s%s",
+                     circuit_purpose_to_controller_string(purpose),
+                     (hs_state_str != NULL) ? " OLD_HS_STATE=" : "",
+                     (hs_state_str != NULL) ? hs_state_str : "");
+      }
+
+      break;
+    case CIRC_MINOR_EVENT_CANNIBALIZED:
+      event_desc = "CANNIBALIZED";
+
+      {
+        /* event_tail can currently be up to 130 chars long */
+        const char *hs_state_str =
+          circuit_purpose_to_controller_hs_state_string(purpose);
+        const struct timeval *old_timestamp_created = tv;
+
+        tor_snprintf(event_tail, sizeof(event_tail),
+                     " OLD_PURPOSE=%s%s%s OLD_TIME_CREATED=%ld,%ld",
+                     circuit_purpose_to_controller_string(purpose),
+                     (hs_state_str != NULL) ? " OLD_HS_STATE=" : "",
+                     (hs_state_str != NULL) ? hs_state_str : "",
+                     old_timestamp_created->tv_sec,
+                     old_timestamp_created->tv_usec);
+      }
+
+      break;
+    default:
+      log_warn(LD_BUG, "Unrecognized status code %d", (int)e);
+      tor_fragile_assert();
+      return 0;
+    }
+
+  {
+    char *circdesc = circuit_describe_status_for_controller(circ);
+    const char *sp = strlen(circdesc) ? " " : "";
+    send_control_event(EVENT_CIRCUIT_STATUS_MINOR, ALL_FORMATS,
+                       "650 CIRC_MINOR %lu %s%s%s%s\r\n",
+                       (unsigned long)circ->global_identifier,
+                       event_desc, sp,
+                       circdesc,
+                       event_tail);
+    tor_free(circdesc);
+  }
+
+  return 0;
+}
+
+/**
+ * <b>circ</b> has changed its purpose from <b>old_purpose</b>: tell any
+ * interested controllers.
+ */
+int
+control_event_circuit_purpose_changed(origin_circuit_t *circ,
+                                      int old_purpose)
+{
+  return control_event_circuit_status_minor(circ,
+                                            CIRC_MINOR_EVENT_PURPOSE_CHANGED,
+                                            old_purpose,
+                                            NULL);
+}
+
+/**
+ * <b>circ</b> has changed its purpose from <b>old_purpose</b>, and its
+ * created-time from <b>old_tv_created</b>: tell any interested controllers.
+ */
+int
+control_event_circuit_cannibalized(origin_circuit_t *circ,
+                                   int old_purpose,
+                                   const struct timeval *old_tv_created)
+{
+  return control_event_circuit_status_minor(circ,
+                                            CIRC_MINOR_EVENT_CANNIBALIZED,
+                                            old_purpose,
+                                            old_tv_created);
+}
+
+
 /** Given an AP connection <b>conn</b> and a <b>len</b>-character buffer
  * <b>buf</b>, determine the address:port combination requested on
  * <b>conn</b>, and write it to <b>buf</b>.  Return 0 on success, -1 on

src/or/control.h

@@ -37,6 +37,11 @@ int control_event_is_interesting(int event);
 
 int control_event_circuit_status(origin_circuit_t *circ,
                                  circuit_status_event_t e, int reason);
+int control_event_circuit_purpose_changed(origin_circuit_t *circ,
+                                          int old_purpose);
+int control_event_circuit_cannibalized(origin_circuit_t *circ,
+                                       int old_purpose,
+                                       const struct timeval *old_tv_created);
 int control_event_stream_status(entry_connection_t *conn,
                                 stream_status_event_t e,
                                 int reason);

src/or/or.h

@@ -3852,6 +3852,13 @@ typedef enum circuit_status_event_t {
   CIRC_EVENT_CLOSED   = 4,
 } circuit_status_event_t;
 
+/** Used to indicate the type of a CIRC_MINOR event passed to the controller.
+ * The various types are defined in control-spec.txt . */
+typedef enum circuit_status_minor_event_t {
+  CIRC_MINOR_EVENT_PURPOSE_CHANGED,
+  CIRC_MINOR_EVENT_CANNIBALIZED,
+} circuit_status_minor_event_t;
+
 /** Used to indicate the type of a stream event passed to the controller.
  * The various types are defined in control-spec.txt */
 typedef enum stream_status_event_t {

src/or/rendclient.c

@@ -292,7 +292,8 @@ rend_client_send_introduction(origin_circuit_t *introcirc,
   }
 
   /* Now, we wait for an ACK or NAK on this circuit. */
-  introcirc->_base.purpose = CIRCUIT_PURPOSE_C_INTRODUCE_ACK_WAIT;
+  circuit_change_purpose(TO_CIRCUIT(introcirc),
+                         CIRCUIT_PURPOSE_C_INTRODUCE_ACK_WAIT);
   /* Set timestamp_dirty, because circuit_expire_building expects it
    * to specify when a circuit entered the _C_INTRODUCE_ACK_WAIT
    * state. */
@@ -355,7 +356,8 @@ rend_client_introduction_acked(origin_circuit_t *circ,
 #ifndef NON_ANONYMOUS_MODE_ENABLED
       tor_assert(!(rendcirc->build_state->onehop_tunnel));
 #endif
-      rendcirc->_base.purpose = CIRCUIT_PURPOSE_C_REND_READY_INTRO_ACKED;
+      circuit_change_purpose(TO_CIRCUIT(rendcirc),
+                             CIRCUIT_PURPOSE_C_REND_READY_INTRO_ACKED);
       /* Set timestamp_dirty, because circuit_expire_building expects
        * it to specify when a circuit entered the
        * _C_REND_READY_INTRO_ACKED state. */
@@ -364,11 +366,12 @@ rend_client_introduction_acked(origin_circuit_t *circ,
       log_info(LD_REND,"...Found no rend circ. Dropping on the floor.");
     }
     /* close the circuit: we won't need it anymore. */
-    circ->_base.purpose = CIRCUIT_PURPOSE_C_INTRODUCE_ACKED;
+    circuit_change_purpose(TO_CIRCUIT(circ),
+                           CIRCUIT_PURPOSE_C_INTRODUCE_ACKED);
     circuit_mark_for_close(TO_CIRCUIT(circ), END_CIRC_REASON_FINISHED);
   } else {
     /* It's a NAK; the introduction point didn't relay our request. */
-    circ->_base.purpose = CIRCUIT_PURPOSE_C_INTRODUCING;
+    circuit_change_purpose(TO_CIRCUIT(circ), CIRCUIT_PURPOSE_C_INTRODUCING);
     /* Remove this intro point from the set of viable introduction
      * points. If any remain, extend to a new one and try again.
      * If none remain, refetch the service descriptor.
@@ -823,7 +826,7 @@ rend_client_rendezvous_acked(origin_circuit_t *circ, const uint8_t *request,
   }
   log_info(LD_REND,"Got rendezvous ack. This circuit is now ready for "
            "rendezvous.");
-  circ->_base.purpose = CIRCUIT_PURPOSE_C_REND_READY;
+  circuit_change_purpose(TO_CIRCUIT(circ), CIRCUIT_PURPOSE_C_REND_READY);
   /* Set timestamp_dirty, because circuit_expire_building expects it
    * to specify when a circuit entered the _C_REND_READY state. */
   circ->_base.timestamp_dirty = time(NULL);
@@ -887,7 +890,7 @@ rend_client_receive_rendezvous(origin_circuit_t *circ, const uint8_t *request,
   hop->dh_handshake_state = NULL;
 
   /* All is well. Extend the circuit. */
-  circ->_base.purpose = CIRCUIT_PURPOSE_C_REND_JOINED;
+  circuit_change_purpose(TO_CIRCUIT(circ), CIRCUIT_PURPOSE_C_REND_JOINED);
   hop->state = CPATH_STATE_OPEN;
   /* set the windows to default. these are the windows
    * that alice thinks bob has.

src/or/rendmid.c

@@ -9,6 +9,7 @@
 
 #include "or.h"
 #include "circuitlist.h"
+#include "circuituse.h"
 #include "config.h"
 #include "relay.h"
 #include "rendmid.h"
@@ -109,7 +110,7 @@ rend_mid_establish_intro(or_circuit_t *circ, const uint8_t *request,
   }
 
   /* Now, set up this circuit. */
-  circ->_base.purpose = CIRCUIT_PURPOSE_INTRO_POINT;
+  circuit_change_purpose(TO_CIRCUIT(circ), CIRCUIT_PURPOSE_INTRO_POINT);
   memcpy(circ->rend_token, pk_digest, DIGEST_LEN);
 
   log_info(LD_REND,
@@ -249,7 +250,7 @@ rend_mid_establish_rendezvous(or_circuit_t *circ, const uint8_t *request,
     goto err;
   }
 
-  circ->_base.purpose = CIRCUIT_PURPOSE_REND_POINT_WAITING;
+  circuit_change_purpose(TO_CIRCUIT(circ), CIRCUIT_PURPOSE_REND_POINT_WAITING);
   memcpy(circ->rend_token, request, REND_COOKIE_LEN);
 
   base16_encode(hexid,9,(char*)request,4);
@@ -324,8 +325,9 @@ rend_mid_rendezvous(or_circuit_t *circ, const uint8_t *request,
            "Completing rendezvous: circuit %d joins circuit %d (cookie %s)",
            circ->p_circ_id, rend_circ->p_circ_id, hexid);
 
-  circ->_base.purpose = CIRCUIT_PURPOSE_REND_ESTABLISHED;
-  rend_circ->_base.purpose = CIRCUIT_PURPOSE_REND_ESTABLISHED;
+  circuit_change_purpose(TO_CIRCUIT(circ), CIRCUIT_PURPOSE_REND_ESTABLISHED);
+  circuit_change_purpose(TO_CIRCUIT(rend_circ),
+                         CIRCUIT_PURPOSE_REND_ESTABLISHED);
   memset(circ->rend_token, 0, REND_COOKIE_LEN);
 
   rend_circ->rend_splice = circ;

src/or/rendservice.c

@@ -1608,7 +1608,7 @@ rend_service_intro_has_opened(origin_circuit_t *circuit)
                "circuit, but we already have enough. Redefining purpose to "
                "general; leaving as internal.");
 
-      TO_CIRCUIT(circuit)->purpose = CIRCUIT_PURPOSE_C_GENERAL;
+      circuit_change_purpose(TO_CIRCUIT(circuit), CIRCUIT_PURPOSE_C_GENERAL);
 
       {
         rend_data_t *rend_data = circuit->rend_data;
@@ -1700,7 +1700,7 @@ rend_service_intro_established(origin_circuit_t *circuit,
     goto err;
   }
   service->desc_is_dirty = time(NULL);
-  circuit->_base.purpose = CIRCUIT_PURPOSE_S_INTRO;
+  circuit_change_purpose(TO_CIRCUIT(circuit), CIRCUIT_PURPOSE_S_INTRO);
 
   base32_encode(serviceid, REND_SERVICE_ID_LEN_BASE32 + 1,
                 circuit->rend_data->rend_pk_digest, REND_SERVICE_ID_LEN);
@@ -1811,7 +1811,7 @@ rend_service_rendezvous_has_opened(origin_circuit_t *circuit)
   circuit->build_state->pending_final_cpath = NULL; /* prevent double-free */
 
   /* Change the circuit purpose. */
-  circuit->_base.purpose = CIRCUIT_PURPOSE_S_REND_JOINED;
+  circuit_change_purpose(TO_CIRCUIT(circuit), CIRCUIT_PURPOSE_S_REND_JOINED);
 
   return;
  err:

src/test/test_util.c

@@ -19,9 +19,10 @@ test_util_time(void)
 {
   struct timeval start, end;
   struct tm a_time;
-  char timestr[RFC1123_TIME_LEN+1];
+  char timestr[128];
   time_t t_res;
   int i;
+  struct timeval tv;
 
   start.tv_sec = 5;
   start.tv_usec = 5000;
@@ -83,6 +84,24 @@ test_util_time(void)
   /* We might've timewarped a little. */
   tt_int_op(tv_udiff(&start, &end), >=, -5000);
 
+  /* Now let's check some format_iso_time variants */
+  tv.tv_sec = (time_t)1326296338;
+  tv.tv_usec = 3060;
+  format_iso_time(timestr, tv.tv_sec);
+  test_streq("2012-01-11 15:38:58", timestr);
+  /* The output of format_local_iso_time will vary by timezone, and setting
+     our timezone for testing purposes would be a nontrivial flaky pain.
+     Skip this test for now.
+  format_local_iso_time(timestr, tv.tv_sec);
+  test_streq("2012-01-11 10:38:58", timestr);
+  */
+  format_iso_time_nospace(timestr, tv.tv_sec);
+  test_streq("2012-01-11T15:38:58", timestr);
+  test_eq(strlen(timestr), ISO_TIME_LEN);
+  format_iso_time_nospace_usec(timestr, &tv);
+  test_streq("2012-01-11T15:38:58.003060", timestr);
+  test_eq(strlen(timestr), ISO_TIME_USEC_LEN);
+
  done:
   ;
 }