Macro-fu to get DEBUG events working.

svn:r4539

6 files changed, 62 insertions, 22 deletions

diff --git a/doc/control-spec.txt b/doc/control-spec.txt
index b9ba57e65d..17e39a0f6a 100644
--- a/doc/control-spec.txt
+++ b/doc/control-spec.txt
@@ -164,8 +164,6 @@ $Id$
      EventCode = "CIRC" / "STREAM" / "ORCONN" / "BW" / "DEBUG" /
          "INFO" / "NOTICE" / "WARN" / "ERR" / "NEWDESC" / "ADDRMAP"
 
-[XXX DEBUG doesn't work. -NM]
-
   Any events *not* listed in the SETEVENTS line are turned off; thus, sending
   SETEVENTS with an empty body turns off all event reporting.
 
diff --git a/src/or/config.c b/src/or/config.c
index ecf5720926..96439b2cd7 100644
--- a/src/or/config.c
+++ b/src/or/config.c
@@ -332,7 +332,7 @@ options_act(void)
    * gone. */
   close_temp_logs();
   add_callback_log(LOG_ERR, LOG_ERR, control_event_logmsg);
-  adjust_event_log_severity();
+  control_adjust_event_log_severity();
 
   /* Set up libevent. */
   if (!libevent_initialized) {
diff --git a/src/or/connection.c b/src/or/connection.c
index 21cdf2a447..500121de2d 100644
--- a/src/or/connection.c
+++ b/src/or/connection.c
@@ -925,7 +925,7 @@ static void
 connection_consider_empty_buckets(connection_t *conn)
 {
   if (global_read_bucket <= 0) {
-    log_fn(LOG_DEBUG,"global bucket exhausted. Pausing.");
+    LOG_FN_CONN(conn, (LOG_DEBUG,"global bucket exhausted. Pausing."));
     conn->wants_to_read = 1;
     connection_stop_reading(conn);
     return;
@@ -933,7 +933,7 @@ connection_consider_empty_buckets(connection_t *conn)
   if (connection_speaks_cells(conn) &&
       conn->state == OR_CONN_STATE_OPEN &&
       conn->receiver_bucket <= 0) {
-    log_fn(LOG_DEBUG,"receiver bucket exhausted. Pausing.");
+    LOG_FN_CONN(conn, (LOG_DEBUG,"receiver bucket exhausted. Pausing."));
     conn->wants_to_read = 1;
     connection_stop_reading(conn);
   }
@@ -986,7 +986,7 @@ connection_bucket_refill(struct timeval *now)
             conn->state != OR_CONN_STATE_OPEN ||
             conn->receiver_bucket > 0)) {
       /* and either a non-cell conn or a cell conn with non-empty bucket */
-      log_fn(LOG_DEBUG,"waking up conn (fd %d)",conn->s);
+      LOG_FN_CONN(conn, (LOG_DEBUG,"waking up conn (fd %d)",conn->s));
       conn->wants_to_read = 0;
       connection_start_reading(conn);
       if (conn->wants_to_write == 1) {
@@ -1165,8 +1165,9 @@ connection_read_to_buf(connection_t *conn, int *max_to_read)
     }
 
   } else {
-    result = read_to_buf(conn->s, at_most, conn->inbuf,
-                         &conn->inbuf_reached_eof);
+    CONN_LOG_PROTECT(conn,
+        result = read_to_buf(conn->s, at_most, conn->inbuf,
+                             &conn->inbuf_reached_eof));
 
 //  log_fn(LOG_DEBUG,"read_to_buf returned %d.",read_result);
 
@@ -1328,7 +1329,8 @@ connection_handle_write(connection_t *conn)
        */
     }
   } else {
-    result = flush_buf(conn->s, conn->outbuf, &conn->outbuf_flushlen);
+    CONN_LOG_PROTECT(conn,
+             result = flush_buf(conn->s, conn->outbuf, &conn->outbuf_flushlen));
     if (result < 0) {
       if (CONN_IS_EDGE(conn))
         connection_edge_end_errno(conn, conn->cpath_layer);
@@ -1369,7 +1371,8 @@ _connection_controller_force_write(connection_t *conn)
   if (conn->marked_for_close || conn->s < 0)
     return;
 
-  result = flush_buf(conn->s, conn->outbuf, &conn->outbuf_flushlen);
+  CONN_LOG_PROTECT(conn,
+      result = flush_buf(conn->s, conn->outbuf, &conn->outbuf_flushlen));
   if (result < 0) {
     connection_close_immediate(conn); /* Don't flush; connection is dead. */
     connection_mark_for_close(conn);
@@ -1395,13 +1398,15 @@ _connection_controller_force_write(connection_t *conn)
 void
 connection_write_to_buf(const char *string, size_t len, connection_t *conn)
 {
+  int r;
   if (!len)
     return;
   /* if it's marked for close, only allow write if we mean to flush it */
   if (conn->marked_for_close && !conn->hold_open_until_flushed)
     return;
 
-  if (write_to_buf(string, len, conn->outbuf) < 0) {
+  CONN_LOG_PROTECT(conn, r = write_to_buf(string, len, conn->outbuf));
+  if (r < 0) {
     if (CONN_IS_EDGE(conn)) {
       /* if it failed, it means we have our package/delivery windows set
          wrong compared to our max outbuf size. close the whole circuit. */
diff --git a/src/or/control.c b/src/or/control.c
index b8fc7d8f6d..1e776fb817 100644
--- a/src/or/control.c
+++ b/src/or/control.c
@@ -106,6 +106,9 @@ static const char * CONTROL0_COMMANDS[_CONTROL0_CMD_MAX_RECOGNIZED+1] = {
 static uint32_t global_event_mask0 = 0;
 static uint32_t global_event_mask1 = 0;
 
+/** True iff we have disabled log messages from being sent to the controller */
+static int disable_log_messages = 0;
+
 /** Macro: true if any control connection is interested in events of type
  * <b>e</b>. */
 #define EVENT_IS_INTERESTING0(e) (global_event_mask0 & (1<<(e)))
@@ -219,12 +222,12 @@ update_global_event_mask(void)
     }
   }
 
-  adjust_event_log_severity();
+  control_adjust_event_log_severity();
 }
 
 /** DOCDOC */
 void
-adjust_event_log_severity(void)
+control_adjust_event_log_severity(void)
 {
   int i;
   int min_log_event=EVENT_ERR_MSG, max_log_event=EVENT_DEBUG_MSG;
@@ -795,7 +798,7 @@ handle_control_setevents(connection_t *conn, uint32_t len, const char *body)
         else if (!strcasecmp(ev, "BW"))
           event_code = EVENT_BANDWIDTH_USED;
         else if (!strcasecmp(ev, "DEBUG"))
-          continue; /* Don't do debug messages */
+          event_code = EVENT_DEBUG_MSG;
         else if (!strcasecmp(ev, "INFO"))
           event_code = EVENT_INFO_MSG;
         else if (!strcasecmp(ev, "NOTICE"))
@@ -2274,14 +2277,28 @@ control_event_bandwidth_used(uint32_t n_read, uint32_t n_written)
   return 0;
 }
 
+/** DOCDOC */
+void
+disable_control_logging(void)
+{
+  ++disable_log_messages;
+}
+
+/** DOCDOC */
+void
+enable_control_logging(void)
+{
+  if (--disable_log_messages < 0)
+    tor_assert(0);
+}
+
 /** We got a log message: tell any interested control connections. */
 void
 control_event_logmsg(int severity, const char *msg)
 {
-  static int sending_logmsg=0;
   int oldlog, event;
 
-  if (sending_logmsg)
+  if (disable_log_messages)
     return;
 
   oldlog = EVENT_IS_INTERESTING0(EVENT_LOG_OBSOLETE) &&
@@ -2293,12 +2310,12 @@ control_event_logmsg(int severity, const char *msg)
 
   if (oldlog || event) {
     size_t len = strlen(msg);
-    sending_logmsg = 1;
+    disable_log_messages = 1;
     if (event)
       send_control0_event(event, (uint32_t)(len+1), msg);
     if (oldlog)
       send_control0_event(EVENT_LOG_OBSOLETE, (uint32_t)(len+1), msg);
-    sending_logmsg = 0;
+    disable_log_messages = 0;
   }
 
   event = log_severity_to_event(severity);
@@ -2313,13 +2330,16 @@ control_event_logmsg(int severity, const char *msg)
           *cp = ' ';
     }
     switch (severity) {
+      case LOG_DEBUG: s = "DEBUG"; break;
       case LOG_INFO: s = "INFO"; break;
       case LOG_NOTICE: s = "NOTICE"; break;
       case LOG_WARN: s = "WARN"; break;
       case LOG_ERR: s = "ERR"; break;
       default: s = "UnknownLogSeverity"; break;
     }
+    disable_log_messages = 1;
     send_control1_event(event, "650 %s %s\r\n", s, b?b:msg);
+    disable_log_messages = 0;
     tor_free(b);
   }
 }
diff --git a/src/or/main.c b/src/or/main.c
index bf6198a862..4805e26335 100644
--- a/src/or/main.c
+++ b/src/or/main.c
@@ -364,7 +364,7 @@ conn_read_callback(int fd, short event, void *_conn)
 {
   connection_t *conn = _conn;
 
-  log_fn(LOG_DEBUG,"socket %d wants to read.",conn->s);
+  LOG_FN_CONN(conn, (LOG_DEBUG,"socket %d wants to read.",conn->s));
 
   assert_connection_ok(conn, time(NULL));
 
@@ -393,7 +393,7 @@ conn_write_callback(int fd, short events, void *_conn)
 {
   connection_t *conn = _conn;
 
-  log_fn(LOG_DEBUG,"socket %d wants to write.",conn->s);
+  LOG_FN_CONN(conn, (LOG_DEBUG,"socket %d wants to write.",conn->s));
 
   assert_connection_ok(conn, time(NULL));
 
@@ -454,7 +454,8 @@ conn_close_if_marked(int i)
     }
     if (retval >= 0 &&
        conn->hold_open_until_flushed && connection_wants_to_flush(conn)) {
-      log_fn(LOG_INFO,"Holding conn (fd %d) open for more flushing.",conn->s);
+      LOG_FN_CONN(conn,
+             (LOG_INFO,"Holding conn (fd %d) open for more flushing.",conn->s));
       /* XXX should we reset timestamp_lastwritten here? */
       return 0;
     }
diff --git a/src/or/or.h b/src/or/or.h
index e4abc28bad..205a65364d 100644
--- a/src/or/or.h
+++ b/src/or/or.h
@@ -1504,7 +1504,23 @@ typedef enum or_conn_status_event_t {
   OR_CONN_EVENT_CLOSED       = 3,
 } or_conn_status_event_t;
 
-void adjust_event_log_severity(void);
+void control_adjust_event_log_severity(void);
+void disable_control_logging(void);
+void enable_control_logging(void);
+
+#define CONN_LOG_PROTECT(conn, stmt)                                    \
+  do {                                                                  \
+    int _log_conn_is_control = (conn && conn->type == CONN_TYPE_CONTROL); \
+    if (_log_conn_is_control)                                           \
+      disable_control_logging();                                        \
+    do {stmt;} while(0);                                                \
+    if (_log_conn_is_control)                                           \
+      enable_control_logging();                                         \
+  } while (0)
+
+#define LOG_FN_CONN(conn, args)                 \
+  CONN_LOG_PROTECT(conn, log_fn args)
+
 int connection_control_finished_flushing(connection_t *conn);
 int connection_control_reached_eof(connection_t *conn);
 int connection_control_process_inbuf(connection_t *conn);