isisd: add a slight delay to lsp_regenerate_schedule

isisd implements a holdoff interval and will refrain from regenerating
an lsp if the difference between the current time and its last refresh
is less than the holdoff interval. Instead, it will schedule a timer
to regenerate the lsp after the holdoff interval has passed.

This implementation has one disadvantage in the case where there is a
succession of calls to lsp_regenerate_schedule. In such a case, the
first call will trigger an immediate regeneration of the lsp, while the
other calls will only schedule the regeneration timer. This leads to
cases where it takes holdoff interval time for information to propagate,
just because the information was only available e.g. at the second call
of lsp_regenerate_schedule in such a succession of calls.

By not immediately regenerating an lsp if the last generation time
is sufficiently long ago, but instead scheduling the regeneration with a
very small delay, we allow all information from such a succession of
calls to be considered.

Signed-off-by: Christian Franke <chris@opensourcerouting.org>
Acked-by: Donald Sharp <sharpd@cumulusnetworks.com>

5 files changed, 169 insertions, 35 deletions

diff --git a/isisd/isis_circuit.c b/isisd/isis_circuit.c
index 9fe11c29..81c60762 100644
--- a/isisd/isis_circuit.c
+++ b/isisd/isis_circuit.c
@@ -789,6 +789,8 @@ isis_circuit_down (struct isis_circuit *circuit)
       THREAD_TIMER_OFF (circuit->u.bc.t_run_dr[1]);
       THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[0]);
       THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[1]);
+      circuit->lsp_regenerate_pending[0] = 0;
+      circuit->lsp_regenerate_pending[1] = 0;
     }
   else if (circuit->circ_type == CIRCUIT_T_P2P)
     {
diff --git a/isisd/isis_events.c b/isisd/isis_events.c
index 96d5762d..0dee9e6f 100644
--- a/isisd/isis_events.c
+++ b/isisd/isis_events.c
@@ -110,7 +110,10 @@ area_resign_level (struct isis_area *area, int level)
     }
 #endif /* HAVE_IPV6 */
 
+  sched_debug("ISIS (%s): Resigned from L%d - canceling LSP regeneration timer.",
+              area->area_tag, level);
   THREAD_TIMER_OFF (area->t_lsp_refresh[level - 1]);
+  area->lsp_regenerate_pending[level - 1] = 0;
 }
 
 void
@@ -245,6 +248,7 @@ circuit_resign_level (struct isis_circuit *circuit, int level)
       THREAD_TIMER_OFF (circuit->u.bc.t_send_lan_hello[idx]);
       THREAD_TIMER_OFF (circuit->u.bc.t_run_dr[idx]);
       THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[idx]);
+      circuit->lsp_regenerate_pending[idx] = 0;
       circuit->u.bc.run_dr_elect[idx] = 0;
       list_delete (circuit->u.bc.lan_neighs[idx]);
       circuit->u.bc.lan_neighs[idx] = NULL;
diff --git a/isisd/isis_lsp.c b/isisd/isis_lsp.c
index 74a86c89..9ac02214 100644
--- a/isisd/isis_lsp.c
+++ b/isisd/isis_lsp.c
@@ -1681,10 +1681,13 @@ lsp_generate (struct isis_area *area, int level)
   lsp_build (newlsp, area);
   /* time to calculate our checksum */
   lsp_seqnum_update (newlsp);
+  newlsp->last_generated = time(NULL);
   lsp_set_all_srmflags (newlsp);
 
   refresh_time = lsp_refresh_time (newlsp, rem_lifetime);
+
   THREAD_TIMER_OFF (area->t_lsp_refresh[level - 1]);
+  area->lsp_regenerate_pending[level - 1] = 0;
   if (level == IS_LEVEL_1)
     THREAD_TIMER_ON (master, area->t_lsp_refresh[level - 1],
                      lsp_l1_refresh, area, refresh_time);
@@ -1704,6 +1707,8 @@ lsp_generate (struct isis_area *area, int level)
                   ntohs (newlsp->lsp_header->rem_lifetime),
                   refresh_time);
     }
+  sched_debug("ISIS (%s): Built L%d LSP. Set triggered regenerate to non-pending.",
+              area->area_tag, level);
 
   return ISIS_OK;
 }
@@ -1766,6 +1771,7 @@ lsp_regenerate (struct isis_area *area, int level)
   else if (level == IS_LEVEL_2)
     THREAD_TIMER_ON (master, area->t_lsp_refresh[level - 1],
                      lsp_l2_refresh, area, refresh_time);
+  area->lsp_regenerate_pending[level - 1] = 0;
 
   if (isis->debugs & DEBUG_UPDATE_PACKETS)
     {
@@ -1779,6 +1785,8 @@ lsp_regenerate (struct isis_area *area, int level)
                   ntohs (lsp->lsp_header->rem_lifetime),
                   refresh_time);
     }
+  sched_debug("ISIS (%s): Rebuilt L%d LSP. Set triggered regenerate to non-pending.",
+              area->area_tag, level);
 
   return ISIS_OK;
 }
@@ -1800,6 +1808,7 @@ lsp_l1_refresh (struct thread *thread)
   if ((area->is_type & IS_LEVEL_1) == 0)
     return ISIS_ERROR;
 
+  sched_debug("ISIS (%s): LSP L1 refresh timer expired. Refreshing LSP...", area->area_tag);
   return lsp_regenerate (area, IS_LEVEL_1);
 }
 
@@ -1817,6 +1826,7 @@ lsp_l2_refresh (struct thread *thread)
   if ((area->is_type & IS_LEVEL_2) == 0)
     return ISIS_ERROR;
 
+  sched_debug("ISIS (%s): LSP L2 refresh timer expired. Refreshing LSP...", area->area_tag);
   return lsp_regenerate (area, IS_LEVEL_2);
 }
 
@@ -1826,6 +1836,7 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo)
   struct isis_lsp *lsp;
   u_char id[ISIS_SYS_ID_LEN + 2];
   time_t now, diff;
+  long timeout;
   struct listnode *cnode;
   struct isis_circuit *circuit;
   int lvl;
@@ -1833,6 +1844,9 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo)
   if (area == NULL)
     return ISIS_ERROR;
 
+  sched_debug("ISIS (%s): Scheduling regeneration of %s LSPs, %sincluding PSNs",
+            area->area_tag, circuit_t2string(level), all_pseudo ? "" : "not ");
+
   memcpy (id, isis->sysid, ISIS_SYS_ID_LEN);
   LSP_PSEUDO_ID (id) = LSP_FRAGMENT (id) = 0;
   now = time (NULL);
@@ -1842,29 +1856,38 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo)
       if (!((level & lvl) && (area->is_type & lvl)))
         continue;
 
+      sched_debug("ISIS (%s): Checking whether L%d needs to be scheduled",
+                  area->area_tag, lvl);
+
       if (area->lsp_regenerate_pending[lvl - 1])
-        continue;
+        {
+          struct timeval remain = thread_timer_remain(area->t_lsp_refresh[lvl - 1]);
+          sched_debug("ISIS (%s): Regeneration is already pending, nothing todo."
+                      " (Due in %lld.%03lld seconds)", area->area_tag,
+                      (long long)remain.tv_sec, (long long)remain.tv_usec / 1000);
+          continue;
+        }
 
       lsp = lsp_search (id, area->lspdb[lvl - 1]);
       if (!lsp)
-        continue;
+        {
+          sched_debug("ISIS (%s): We do not have any LSPs to regenerate, nothing todo.",
+                      area->area_tag);
+          continue;
+        }
 
       /*
        * Throttle avoidance
        */
+      sched_debug("ISIS (%s): Will schedule regen timer. Last run was: %lld, Now is: %lld",
+                  area->area_tag, (long long)lsp->last_generated, (long long)now);
       THREAD_TIMER_OFF (area->t_lsp_refresh[lvl - 1]);
       diff = now - lsp->last_generated;
       if (diff < area->lsp_gen_interval[lvl - 1])
         {
-          area->lsp_regenerate_pending[lvl - 1] = 1;
-          if (lvl == IS_LEVEL_1)
-            THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1],
-                             lsp_l1_refresh, area,
-                             area->lsp_gen_interval[lvl - 1] - diff);
-          else if (lvl == IS_LEVEL_2)
-            THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1],
-                             lsp_l2_refresh, area,
-                             area->lsp_gen_interval[lvl - 1] - diff);
+          timeout = 1000 * (area->lsp_gen_interval[lvl - 1] - diff);
+          sched_debug("ISIS (%s): Scheduling in %ld ms to match configured lsp_gen_interval",
+                      area->area_tag, timeout);
         }
       else
         {
@@ -1873,13 +1896,21 @@ lsp_regenerate_schedule (struct isis_area *area, int level, int all_pseudo)
            * directly. However if the lsp_regenerate call is queued for
            * later execution it works.
            */
-          area->lsp_regenerate_pending[lvl - 1] = 1;
-          if (lvl == IS_LEVEL_1)
-            THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1],
-                             lsp_l1_refresh, area, 0);
-          else if (lvl == IS_LEVEL_2)
-            THREAD_TIMER_ON (master, area->t_lsp_refresh[lvl - 1],
-                             lsp_l2_refresh, area, 0);
+          timeout = 100;
+          sched_debug("ISIS (%s): Last generation was more than lsp_gen_interval ago."
+                      " Scheduling for execution in %ld ms.", area->area_tag, timeout);
+        }
+
+      area->lsp_regenerate_pending[lvl - 1] = 1;
+      if (lvl == IS_LEVEL_1)
+        {
+          THREAD_TIMER_MSEC_ON(master, area->t_lsp_refresh[lvl - 1],
+                               lsp_l1_refresh, area, timeout);
+        }
+      else if (lvl == IS_LEVEL_2)
+        {
+          THREAD_TIMER_MSEC_ON(master, area->t_lsp_refresh[lvl - 1],
+                               lsp_l2_refresh, area, timeout);
         }
     }
 
@@ -2231,13 +2262,18 @@ lsp_regenerate_schedule_pseudo (struct isis_circuit *circuit, int level)
   struct isis_lsp *lsp;
   u_char lsp_id[ISIS_SYS_ID_LEN + 2];
   time_t now, diff;
+  long timeout;
   int lvl;
+  struct isis_area *area = circuit->area;
 
   if (circuit == NULL ||
       circuit->circ_type != CIRCUIT_T_BROADCAST ||
       circuit->state != C_STATE_UP)
     return ISIS_OK;
 
+  sched_debug("ISIS (%s): Scheduling regeneration of %s pseudo LSP for interface %s",
+              area->area_tag, circuit_t2string(level), circuit->interface->name);
+
   memcpy (lsp_id, isis->sysid, ISIS_SYS_ID_LEN);
   LSP_PSEUDO_ID (lsp_id) = circuit->circuit_id;
   LSP_FRAGMENT (lsp_id) = 0;
@@ -2245,39 +2281,74 @@ lsp_regenerate_schedule_pseudo (struct isis_circuit *circuit, int level)
 
   for (lvl = IS_LEVEL_1; lvl <= IS_LEVEL_2; lvl++)
     {
+      sched_debug("ISIS (%s): Checking whether L%d pseudo LSP needs to be scheduled",
+                  area->area_tag, lvl);
+
       if (!((level & lvl) && (circuit->is_type & lvl)))
-        continue;
+        {
+          sched_debug("ISIS (%s): Level is not active on circuit",
+                      area->area_tag);
+          continue;
+        }
 
-      if (circuit->u.bc.is_dr[lvl - 1] == 0 ||
-          circuit->lsp_regenerate_pending[lvl - 1])
-        continue;
+      if (circuit->u.bc.is_dr[lvl - 1] == 0)
+        {
+          sched_debug("ISIS (%s): This IS is not DR, nothing to do.",
+                      area->area_tag);
+          continue;
+        }
+
+      if (circuit->lsp_regenerate_pending[lvl - 1])
+        {
+          struct timeval remain =
+                  thread_timer_remain(circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1]);
+          sched_debug("ISIS (%s): Regenerate is already pending, nothing todo."
+                      " (Due in %lld.%03lld seconds)", area->area_tag,
+                      (long long)remain.tv_sec, (long long)remain.tv_usec/1000);
+          continue;
+        }
 
       lsp = lsp_search (lsp_id, circuit->area->lspdb[lvl - 1]);
       if (!lsp)
-        continue;
+        {
+          sched_debug("ISIS (%s): Pseudonode LSP does not exist yet, nothing to regenerate.",
+                      area->area_tag);
+          continue;
+        }
 
       /*
        * Throttle avoidance
        */
+      sched_debug("ISIS (%s): Will schedule PSN regen timer. Last run was: %lld, Now is: %lld",
+                  area->area_tag, (long long)lsp->last_generated, (long long) now);
       THREAD_TIMER_OFF (circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1]);
       diff = now - lsp->last_generated;
       if (diff < circuit->area->lsp_gen_interval[lvl - 1])
         {
-          circuit->lsp_regenerate_pending[lvl - 1] = 1;
-          if (lvl == IS_LEVEL_1)
-            THREAD_TIMER_ON (master,
-                             circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1],
-                             lsp_l1_refresh_pseudo, circuit,
-                             circuit->area->lsp_gen_interval[lvl - 1] - diff);
-          else if (lvl == IS_LEVEL_2)
-            THREAD_TIMER_ON (master,
-                             circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1],
-                             lsp_l2_refresh_pseudo, circuit,
-                             circuit->area->lsp_gen_interval[lvl - 1] - diff);
+          timeout = 1000 * (circuit->area->lsp_gen_interval[lvl - 1] - diff);
+          sched_debug("ISIS (%s): Sechduling in %ld ms to match configured lsp_gen_interval",
+                      area->area_tag, timeout);
         }
       else
         {
-          lsp_regenerate_pseudo (circuit, lvl);
+          timeout = 100;
+          sched_debug("ISIS (%s): Last generation was more than lsp_gen_interval ago."
+                      " Scheduling for execution in %ld ms.", area->area_tag, timeout);
+        }
+
+      circuit->lsp_regenerate_pending[lvl - 1] = 1;
+
+      if (lvl == IS_LEVEL_1)
+        {
+          THREAD_TIMER_MSEC_ON(master,
+                               circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1],
+                               lsp_l1_refresh_pseudo, circuit, timeout);
+        }
+      else if (lvl == IS_LEVEL_2)
+        {
+          THREAD_TIMER_MSEC_ON(master,
+                               circuit->u.bc.t_refresh_pseudo_lsp[lvl - 1],
+                               lsp_l2_refresh_pseudo, circuit, timeout);
         }
     }
 
diff --git a/isisd/isisd.c b/isisd/isisd.c
index b601032a..0a5286e3 100644
--- a/isisd/isisd.c
+++ b/isisd/isisd.c
@@ -774,6 +774,8 @@ print_debug (struct vty *vty, int flags, int onoff)
     vty_out (vty, "IS-IS Packet dump debugging is %s%s", onoffs, VTY_NEWLINE);
   if (flags & DEBUG_LSP_GEN)
     vty_out (vty, "IS-IS LSP generation debugging is %s%s", onoffs, VTY_NEWLINE);
+  if (flags & DEBUG_LSP_SCHED)
+    vty_out (vty, "IS-IS LSP scheduling debugging is %s%s", onoffs, VTY_NEWLINE);
 }
 
 DEFUN (show_debugging,
@@ -865,6 +867,11 @@ config_write_debug (struct vty *vty)
       vty_out (vty, "debug isis lsp-gen%s", VTY_NEWLINE);
       write++;
     }
+  if (flags & DEBUG_LSP_SCHED)
+    {
+      vty_out (vty, "debug isis lsp-sched%s", VTY_NEWLINE);
+      write++;
+    }
 
   return write;
 }
@@ -1207,6 +1214,32 @@ DEFUN (no_debug_isis_lsp_gen,
   return CMD_SUCCESS;
 }
 
+DEFUN (debug_isis_lsp_sched,
+       debug_isis_lsp_sched_cmd,
+       "debug isis lsp-sched",
+       DEBUG_STR
+       "IS-IS information\n"
+       "IS-IS scheduling of LSP generation\n")
+{
+  isis->debugs |= DEBUG_LSP_SCHED;
+  print_debug (vty, DEBUG_LSP_SCHED, 1);
+
+  return CMD_SUCCESS;
+}
+
+DEFUN (no_debug_isis_lsp_sched,
+       no_debug_isis_lsp_sched_cmd,
+       "no debug isis lsp-gen",
+       UNDEBUG_STR
+       "IS-IS information\n"
+       "IS-IS scheduling of LSP generation\n")
+{
+  isis->debugs &= ~DEBUG_LSP_SCHED;
+  print_debug (vty, DEBUG_LSP_SCHED, 0);
+
+  return CMD_SUCCESS;
+}
+
 DEFUN (show_hostname,
        show_hostname_cmd,
        "show isis hostname",
@@ -3295,6 +3328,8 @@ isis_init ()
   install_element (ENABLE_NODE, &no_debug_isis_packet_dump_cmd);
   install_element (ENABLE_NODE, &debug_isis_lsp_gen_cmd);
   install_element (ENABLE_NODE, &no_debug_isis_lsp_gen_cmd);
+  install_element (ENABLE_NODE, &debug_isis_lsp_sched_cmd);
+  install_element (ENABLE_NODE, &no_debug_isis_lsp_sched_cmd);
 
   install_element (CONFIG_NODE, &debug_isis_adj_cmd);
   install_element (CONFIG_NODE, &no_debug_isis_adj_cmd);
@@ -3322,6 +3357,8 @@ isis_init ()
   install_element (CONFIG_NODE, &no_debug_isis_packet_dump_cmd);
   install_element (CONFIG_NODE, &debug_isis_lsp_gen_cmd);
   install_element (CONFIG_NODE, &no_debug_isis_lsp_gen_cmd);
+  install_element (CONFIG_NODE, &debug_isis_lsp_sched_cmd);
+  install_element (CONFIG_NODE, &no_debug_isis_lsp_sched_cmd);
 
   install_element (CONFIG_NODE, &router_isis_cmd);
   install_element (CONFIG_NODE, &no_router_isis_cmd);
diff --git a/isisd/isisd.h b/isisd/isisd.h
index 51a72abd..96c3ba3e 100644
--- a/isisd/isisd.h
+++ b/isisd/isisd.h
@@ -97,6 +97,17 @@ struct isis_area
   struct flags flags;
   struct thread *t_tick;	/* LSP walker */
   struct thread *t_lsp_refresh[ISIS_LEVELS];
+  /* t_lsp_refresh is used in two ways:
+   * a) regular refresh of LSPs
+   * b) (possibly throttled) updates to LSPs
+   *
+   * The lsp_regenerate_pending flag tracks whether the timer is active
+   * for the a) or the b) case.
+   *
+   * It is of utmost importance to clear this flag when the timer is
+   * rescheduled for normal refresh, because otherwise, updates will
+   * be delayed until the next regular refresh.
+   */
   int lsp_regenerate_pending[ISIS_LEVELS];
 
   /*
@@ -167,6 +178,7 @@ extern struct thread_master *master;
 #define DEBUG_ZEBRA                      (1<<11)
 #define DEBUG_PACKET_DUMP                (1<<12)
 #define DEBUG_LSP_GEN                    (1<<13)
+#define DEBUG_LSP_SCHED                  (1<<14)
 
 #define lsp_debug(...) \
   do \
@@ -176,4 +188,12 @@ extern struct thread_master *master;
     } \
   while (0)
 
+#define sched_debug(...) \
+  do \
+    { \
+      if (isis->debugs & DEBUG_LSP_SCHED) \
+        zlog_debug(__VA_ARGS__); \
+    } \
+  while (0)
+
 #endif /* ISISD_H */