Merge remote-tracking branch 'pastly2/ticket24531_033_01'

5 files changed, 61 insertions, 73 deletions

diff --git a/changes/ticket24531 b/changes/ticket24531
new file mode 100644
index 0000000000..96a8eea5c3
--- /dev/null
+++ b/changes/ticket24531
@@ -0,0 +1,3 @@
+  o Code simplification and refactoring:
+    Add a function to log channels' scheduler state changes to aide debugging 
+    efforts. Closes ticket 24531.
diff --git a/src/or/scheduler.c b/src/or/scheduler.c
index cd047d5a75..058efc7bee 100644
--- a/src/or/scheduler.c
+++ b/src/or/scheduler.c
@@ -362,6 +362,36 @@ set_scheduler(void)
  * Functions that can only be accessed from scheduler*.c
  *****************************************************************************/
 
+/** Returns human readable string for the given channel scheduler state. */
+const char *
+get_scheduler_state_string(int scheduler_state)
+{
+  switch (scheduler_state) {
+  case SCHED_CHAN_IDLE:
+    return "IDLE";
+  case SCHED_CHAN_WAITING_FOR_CELLS:
+    return "WAITING_FOR_CELLS";
+  case SCHED_CHAN_WAITING_TO_WRITE:
+    return "WAITING_TO_WRITE";
+  case SCHED_CHAN_PENDING:
+    return "PENDING";
+  default:
+    return "(invalid)";
+  }
+}
+
+/** Helper that logs channel scheduler_state changes. Use this instead of
+ * setting scheduler_state directly. */
+void
+scheduler_set_channel_state(channel_t *chan, int new_state)
+{
+  log_debug(LD_SCHED, "chan %" PRIu64 " changed from scheduler state %s to %s",
+      chan->global_identifier,
+      get_scheduler_state_string(chan->scheduler_state),
+      get_scheduler_state_string(new_state));
+  chan->scheduler_state = new_state;
+}
+
 /** Return the pending channel list. */
 smartlist_t *
 get_channels_pending(void)
@@ -499,11 +529,7 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan))
                             scheduler_compare_channels,
                             offsetof(channel_t, sched_heap_idx),
                             chan);
-    chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
-    log_debug(LD_SCHED,
-              "Channel " U64_FORMAT " at %p went from pending "
-              "to waiting_to_write",
-              U64_PRINTF_ARG(chan->global_identifier), chan);
+    scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
   } else {
     /*
      * It's not in pending, so it can't become waiting_to_write; it's
@@ -511,10 +537,7 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan))
      * waiting_for_cells (remove it, can't write any more).
      */
     if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS) {
-      chan->scheduler_state = SCHED_CHAN_IDLE;
-      log_debug(LD_SCHED,
-                "Channel " U64_FORMAT " at %p left waiting_for_cells",
-                U64_PRINTF_ARG(chan->global_identifier), chan);
+      scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
     }
   }
 }
@@ -537,15 +560,11 @@ scheduler_channel_has_waiting_cells,(channel_t *chan))
      * the other lists.  It has waiting cells now, so it goes to
      * channels_pending.
      */
-    chan->scheduler_state = SCHED_CHAN_PENDING;
+    scheduler_set_channel_state(chan, SCHED_CHAN_PENDING);
     smartlist_pqueue_add(channels_pending,
                          scheduler_compare_channels,
                          offsetof(channel_t, sched_heap_idx),
                          chan);
-    log_debug(LD_SCHED,
-              "Channel " U64_FORMAT " at %p went from waiting_for_cells "
-              "to pending",
-              U64_PRINTF_ARG(chan->global_identifier), chan);
     /* If we made a channel pending, we potentially have scheduling work to
      * do. */
     the_scheduler->schedule();
@@ -557,10 +576,7 @@ scheduler_channel_has_waiting_cells,(channel_t *chan))
      */
     if (!(chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE ||
           chan->scheduler_state == SCHED_CHAN_PENDING)) {
-      chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
-      log_debug(LD_SCHED,
-                "Channel " U64_FORMAT " at %p entered waiting_to_write",
-                U64_PRINTF_ARG(chan->global_identifier), chan);
+      scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
     }
   }
 }
@@ -643,7 +659,7 @@ scheduler_release_channel,(channel_t *chan))
   if (the_scheduler->on_channel_free) {
     the_scheduler->on_channel_free(chan);
   }
-  chan->scheduler_state = SCHED_CHAN_IDLE;
+  scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
 }
 
 /** Mark a channel as ready to accept writes */
@@ -663,17 +679,11 @@ scheduler_channel_wants_writes(channel_t *chan)
     /*
      * It can write now, so it goes to channels_pending.
      */
-    log_debug(LD_SCHED, "chan=%" PRIu64 " became pending",
-        chan->global_identifier);
     smartlist_pqueue_add(channels_pending,
                          scheduler_compare_channels,
                          offsetof(channel_t, sched_heap_idx),
                          chan);
-    chan->scheduler_state = SCHED_CHAN_PENDING;
-    log_debug(LD_SCHED,
-              "Channel " U64_FORMAT " at %p went from waiting_to_write "
-              "to pending",
-              U64_PRINTF_ARG(chan->global_identifier), chan);
+    scheduler_set_channel_state(chan, SCHED_CHAN_PENDING);
     /* We just made a channel pending, we have scheduling work to do. */
     the_scheduler->schedule();
   } else {
@@ -683,10 +693,7 @@ scheduler_channel_wants_writes(channel_t *chan)
      */
     if (!(chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS ||
           chan->scheduler_state == SCHED_CHAN_PENDING)) {
-      chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
-      log_debug(LD_SCHED,
-                "Channel " U64_FORMAT " at %p entered waiting_for_cells",
-                U64_PRINTF_ARG(chan->global_identifier), chan);
+      scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
     }
   }
 }
@@ -703,11 +710,12 @@ scheduler_bug_occurred(const channel_t *chan)
     const size_t outbuf_len =
       buf_datalen(TO_CONN(BASE_CHAN_TO_TLS((channel_t *) chan)->conn)->outbuf);
     tor_snprintf(buf, sizeof(buf),
-                 "Channel %" PRIu64 " in state %s and scheduler state %d."
+                 "Channel %" PRIu64 " in state %s and scheduler state %s."
                  " Num cells on cmux: %d. Connection outbuf len: %lu.",
                  chan->global_identifier,
                  channel_state_to_string(chan->state),
-                 chan->scheduler_state, circuitmux_num_cells(chan->cmux),
+                 get_scheduler_state_string(chan->scheduler_state),
+                 circuitmux_num_cells(chan->cmux),
                  (unsigned long)outbuf_len);
   }
 
diff --git a/src/or/scheduler.h b/src/or/scheduler.h
index 47c98f096a..ac405c21b7 100644
--- a/src/or/scheduler.h
+++ b/src/or/scheduler.h
@@ -144,6 +144,9 @@ MOCK_DECL(void, scheduler_channel_has_waiting_cells, (channel_t *chan));
  * Defined in scheduler.c
  *********************************/
 
+void scheduler_set_channel_state(channel_t *chan, int new_state);
+const char *get_scheduler_state_string(int scheduler_state);
+
 /* Triggers a BUG() and extra information with chan if available. */
 #define SCHED_BUG(cond, chan) \
   (PREDICT_UNLIKELY(cond) ? \
diff --git a/src/or/scheduler_kist.c b/src/or/scheduler_kist.c
index a707ab2758..246c73009a 100644
--- a/src/or/scheduler_kist.c
+++ b/src/or/scheduler_kist.c
@@ -624,7 +624,7 @@ kist_scheduler_run(void)
       if (!CHANNEL_IS_OPEN(chan)) {
         /* Channel isn't open so we put it back in IDLE mode. It is either
          * renegotiating its TLS session or about to be released. */
-        chan->scheduler_state = SCHED_CHAN_IDLE;
+        scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
         continue;
       }
       /* flush_result has the # cells flushed */
@@ -640,12 +640,12 @@ kist_scheduler_run(void)
         log_debug(LD_SCHED,
                  "We didn't flush anything on a chan that we think "
                  "can write and wants to write. The channel's state is '%s' "
-                 "and in scheduler state %d. We're going to mark it as "
+                 "and in scheduler state '%s'. We're going to mark it as "
                  "waiting_for_cells (as that's most likely the issue) and "
                  "stop scheduling it this round.",
                  channel_state_to_string(chan->state),
-                 chan->scheduler_state);
-        chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
+                 get_scheduler_state_string(chan->scheduler_state));
+        scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
         continue;
       }
     }
@@ -672,16 +672,12 @@ kist_scheduler_run(void)
        * SCHED_CHAN_WAITING_FOR_CELLS to SCHED_CHAN_IDLE and seeing if Tor
        * starts having serious throughput issues. Best done in shadow/chutney.
        */
-      chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
-      log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells",
-                chan->global_identifier);
+      scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
     } else if (!channel_more_to_flush(chan)) {
 
       /* Case 2: no more cells to send, but still open for writes */
 
-      chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
-      log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells",
-                chan->global_identifier);
+      scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
     } else if (!socket_can_write(&socket_table, chan)) {
 
       /* Case 3: cells to send, but cannot write */
@@ -693,18 +689,16 @@ kist_scheduler_run(void)
        * after the scheduling loop is over. They can hopefully be taken care of
        * in the next scheduling round.
        */
-      chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
+      scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
       if (!to_readd) {
         to_readd = smartlist_new();
       }
       smartlist_add(to_readd, chan);
-      log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_to_write",
-                chan->global_identifier);
     } else {
 
       /* Case 4: cells to send, and still open for writes */
 
-      chan->scheduler_state = SCHED_CHAN_PENDING;
+      scheduler_set_channel_state(chan, SCHED_CHAN_PENDING);
       smartlist_pqueue_add(cp, scheduler_compare_channels,
                            offsetof(channel_t, sched_heap_idx), chan);
     }
@@ -724,7 +718,7 @@ kist_scheduler_run(void)
   /* Re-add any channels we need to */
   if (to_readd) {
     SMARTLIST_FOREACH_BEGIN(to_readd, channel_t *, readd_chan) {
-      readd_chan->scheduler_state = SCHED_CHAN_PENDING;
+      scheduler_set_channel_state(readd_chan, SCHED_CHAN_PENDING);
       if (!smartlist_contains(cp, readd_chan)) {
         smartlist_pqueue_add(cp, scheduler_compare_channels,
                              offsetof(channel_t, sched_heap_idx), readd_chan);
diff --git a/src/or/scheduler_vanilla.c b/src/or/scheduler_vanilla.c
index 303b3dbba8..7a83b9da18 100644
--- a/src/or/scheduler_vanilla.c
+++ b/src/or/scheduler_vanilla.c
@@ -89,12 +89,7 @@ vanilla_scheduler_run(void)
 
       if (flushed < n_cells) {
         /* We ran out of cells to flush */
-        chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
-        log_debug(LD_SCHED,
-                  "Channel " U64_FORMAT " at %p "
-                  "entered waiting_for_cells from pending",
-                  U64_PRINTF_ARG(chan->global_identifier),
-                  chan);
+        scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
       } else {
         /* The channel may still have some cells */
         if (channel_more_to_flush(chan)) {
@@ -110,12 +105,7 @@ vanilla_scheduler_run(void)
                       chan);
           } else {
             /* It's waiting to be able to write more */
-            chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
-            log_debug(LD_SCHED,
-                      "Channel " U64_FORMAT " at %p "
-                      "entered waiting_to_write from pending",
-                      U64_PRINTF_ARG(chan->global_identifier),
-                      chan);
+            scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
           }
         } else {
           /* No cells left; it can go to idle or waiting_for_cells */
@@ -124,23 +114,13 @@ vanilla_scheduler_run(void)
              * It can still accept writes, so it goes to
              * waiting_for_cells
              */
-            chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
-            log_debug(LD_SCHED,
-                      "Channel " U64_FORMAT " at %p "
-                      "entered waiting_for_cells from pending",
-                      U64_PRINTF_ARG(chan->global_identifier),
-                      chan);
+            scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
           } else {
             /*
              * We exactly filled up the output queue with all available
              * cells; go to idle.
              */
-            chan->scheduler_state = SCHED_CHAN_IDLE;
-            log_debug(LD_SCHED,
-                      "Channel " U64_FORMAT " at %p "
-                      "become idle from pending",
-                      U64_PRINTF_ARG(chan->global_identifier),
-                      chan);
+            scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
           }
         }
       }
@@ -156,14 +136,14 @@ vanilla_scheduler_run(void)
                "no cells writeable",
                U64_PRINTF_ARG(chan->global_identifier), chan);
       /* Put it back to WAITING_TO_WRITE */
-      chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
+      scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
     }
   }
 
   /* Readd any channels we need to */
   if (to_readd) {
     SMARTLIST_FOREACH_BEGIN(to_readd, channel_t *, readd_chan) {
-      readd_chan->scheduler_state = SCHED_CHAN_PENDING;
+      scheduler_set_channel_state(readd_chan, SCHED_CHAN_PENDING);
       smartlist_pqueue_add(cp,
                            scheduler_compare_channels,
                            offsetof(channel_t, sched_heap_idx),