ospf6d: add SPF logs, statistics, and display of SPF parameters

Signed-off-by: Pradosh Mohapatra <pmohapat at cumulusnetworks.com>
Reviewed-by: Scott Feldman <sfeldma at cumulusnetworks.com>
[DL: adapted to rebase / readded randomly lost line]
[DL: killed timeval_subtract]
Signed-off-by: David Lamparter <equinox@opensourcerouting.org>

ospf6d/ospf6_area.c

@@ -67,7 +67,8 @@ ospf6_area_lsdb_hook_add (struct ospf6_lsa *lsa)
           zlog_debug ("Schedule SPF Calculation for %s",
 		      OSPF6_AREA (lsa->lsdb->data)->name);
         }
-      ospf6_spf_schedule (OSPF6_PROCESS(OSPF6_AREA (lsa->lsdb->data)->ospf6));
+      ospf6_spf_schedule (OSPF6_PROCESS(OSPF6_AREA (lsa->lsdb->data)->ospf6),
+			  ospf6_lsadd_to_spf_reason(lsa));
       break;
 
     case OSPF6_LSTYPE_INTRA_PREFIX:
@@ -97,7 +98,8 @@ ospf6_area_lsdb_hook_remove (struct ospf6_lsa *lsa)
           zlog_debug ("Schedule SPF Calculation for %s",
                      OSPF6_AREA (lsa->lsdb->data)->name);
         }
-      ospf6_spf_schedule (OSPF6_PROCESS(OSPF6_AREA (lsa->lsdb->data)->ospf6));
+      ospf6_spf_schedule (OSPF6_PROCESS(OSPF6_AREA (lsa->lsdb->data)->ospf6),
+			  ospf6_lsremove_to_spf_reason(lsa));
       break;
 
     case OSPF6_LSTYPE_INTRA_PREFIX:

ospf6d/ospf6_interface.c

@@ -73,7 +73,7 @@ ospf6_interface_lookup_by_ifindex (int ifindex)
 
 /* schedule routing table recalculation */
 static void
-ospf6_interface_lsdb_hook (struct ospf6_lsa *lsa)
+ospf6_interface_lsdb_hook (struct ospf6_lsa *lsa, unsigned int reason)
 {
   struct ospf6_interface *oi;
 
@@ -86,7 +86,7 @@ ospf6_interface_lsdb_hook (struct ospf6_lsa *lsa)
       case OSPF6_LSTYPE_LINK:
         if (oi->state == OSPF6_INTERFACE_DR)
           OSPF6_INTRA_PREFIX_LSA_SCHEDULE_TRANSIT (oi);
-        ospf6_spf_schedule (oi->area->ospf6);
+        ospf6_spf_schedule (oi->area->ospf6, reason);
         break;
 
       default:
@@ -94,6 +94,18 @@ ospf6_interface_lsdb_hook (struct ospf6_lsa *lsa)
     }
 }
 
+static void
+ospf6_interface_lsdb_hook_add (struct ospf6_lsa *lsa)
+{
+  ospf6_interface_lsdb_hook(lsa, ospf6_lsadd_to_spf_reason(lsa));
+}
+
+static void
+ospf6_interface_lsdb_hook_remove (struct ospf6_lsa *lsa)
+{
+  ospf6_interface_lsdb_hook(lsa, ospf6_lsremove_to_spf_reason(lsa));
+}
+
 static u_char
 ospf6_default_iftype(struct interface *ifp)
 {
@@ -152,8 +164,8 @@ ospf6_interface_create (struct interface *ifp)
   oi->lsupdate_list = ospf6_lsdb_create (oi);
   oi->lsack_list = ospf6_lsdb_create (oi);
   oi->lsdb = ospf6_lsdb_create (oi);
-  oi->lsdb->hook_add = ospf6_interface_lsdb_hook;
+  oi->lsdb->hook_add = ospf6_interface_lsdb_hook_add;
-  oi->lsdb->hook_remove = ospf6_interface_lsdb_hook;
+  oi->lsdb->hook_remove = ospf6_interface_lsdb_hook_remove;
   oi->lsdb_self = ospf6_lsdb_create (oi);
 
   oi->route_connected = OSPF6_ROUTE_TABLE_CREATE (INTERFACE, CONNECTED_ROUTES);

ospf6d/ospf6_intra.c

@@ -46,7 +46,7 @@
 #include "ospf6_abr.h"
 #include "ospf6_flood.h"
 #include "ospf6d.h"
-
+#include "ospf6_spf.h"
 
 unsigned char conf_debug_ospf6_brouter = 0;
 u_int32_t conf_debug_ospf6_brouter_specific_router_id;

ospf6d/ospf6_spf.c

@@ -377,6 +377,36 @@ ospf6_spf_table_finish (struct ospf6_route_table *result_table)
     }
 }
 
+static const char *ospf6_spf_reason_str[] =
+  {
+    "R+",
+    "R-",
+    "N+",
+    "N-",
+    "L+",
+    "L-",
+    "R*",
+    "N*",
+  };
+
+void ospf6_spf_reason_string (unsigned int reason, char *buf, int size)
+{
+  int bit;
+  int len = 0;
+
+  if (!buf)
+    return;
+
+  for (bit = 0; bit <= (sizeof(ospf6_spf_reason_str) / sizeof(char *)); bit++)
+    {
+      if ((reason & (1 << bit)) && (len < size))
+	{
+	  len += snprintf((buf + len), (size - len), "%s%s",
+			  (len > 0) ? ", " : "", ospf6_spf_reason_str[bit]);
+	}
+    }
+}
+
 /* RFC2328 16.1.  Calculating the shortest-path tree for an area */
 /* RFC2740 3.8.1.  Calculating the shortest path tree for an area */
 void
@@ -515,6 +545,8 @@ ospf6_spf_calculation_thread (struct thread *t)
   struct timeval start, end, runtime;
   struct listnode *node;
   struct ospf6_route *route;
+  int areas_processed = 0;
+  char rbuf[32];
 
   ospf6 = (struct ospf6 *)THREAD_ARG (t);
   ospf6->t_spf_calc = NULL;
@@ -536,6 +568,8 @@ ospf6_spf_calculation_thread (struct thread *t)
       ospf6_spf_calculation (ospf6->router_id, oa->spf_table, oa);
       ospf6_intra_route_calculation (oa);
       ospf6_intra_brouter_calculation (oa);
+
+      areas_processed++;
     }
 
   if (ospf6->backbone)
@@ -550,6 +584,7 @@ ospf6_spf_calculation_thread (struct thread *t)
 			    ospf6->backbone);
       ospf6_intra_route_calculation(ospf6->backbone);
       ospf6_intra_brouter_calculation(ospf6->backbone);
+      areas_processed++;
     }
 
   /* Redo summaries if required */
@@ -562,23 +597,36 @@ ospf6_spf_calculation_thread (struct thread *t)
 
   ospf6->ts_spf_duration = runtime;
 
+  ospf6_spf_reason_string(ospf6->spf_reason, rbuf, sizeof(rbuf));
+
   if (IS_OSPF6_DEBUG_SPF (PROCESS) || IS_OSPF6_DEBUG_SPF (TIME))
     zlog_debug ("SPF runtime: %ld sec %ld usec",
 		runtime.tv_sec, runtime.tv_usec);
 
+  zlog_info("SPF processing: # Areas: %d, SPF runtime: %ld sec %ld usec, "
+	    "Reason: %s\n", areas_processed, runtime.tv_sec, runtime.tv_usec,
+	    rbuf);
+  ospf6->last_spf_reason = ospf6->spf_reason;
+  ospf6_reset_spf_reason(ospf6);
   return 0;
 }
 
 /* Add schedule for SPF calculation.  To avoid frequenst SPF calc, we
    set timer for SPF calc. */
 void
-ospf6_spf_schedule (struct ospf6 *ospf6)
+ospf6_spf_schedule (struct ospf6 *ospf6, unsigned int reason)
 {
   unsigned long delay, elapsed, ht;
   struct timeval now, result;
 
+  ospf6_set_spf_reason(ospf6, reason);
+
   if (IS_OSPF6_DEBUG_SPF(PROCESS) || IS_OSPF6_DEBUG_SPF (TIME))
-    zlog_debug ("SPF: calculation timer scheduled");
+    {
+      char rbuf[32];
+      ospf6_spf_reason_string(reason, rbuf, sizeof(rbuf));
+      zlog_debug ("SPF: calculation timer scheduled (reason %s)", rbuf);
+    }
 
   /* OSPF instance does not exist. */
   if (ospf6 == NULL)

ospf6d/ospf6_spf.h

@@ -79,11 +79,77 @@ struct ospf6_vertex
 #define VERTEX_IS_TYPE(t, v) \
   ((v)->type == OSPF6_VERTEX_TYPE_ ## t ? 1 : 0)
 
+/* What triggered the SPF? */
+#define OSPF6_SPF_FLAGS_ROUTER_LSA_ADDED         (1 << 0)
+#define OSPF6_SPF_FLAGS_ROUTER_LSA_REMOVED       (1 << 1)
+#define OSPF6_SPF_FLAGS_NETWORK_LSA_ADDED        (1 << 2)
+#define OSPF6_SPF_FLAGS_NETWORK_LSA_REMOVED      (1 << 3)
+#define OSPF6_SPF_FLAGS_LINK_LSA_ADDED           (1 << 4)
+#define OSPF6_SPF_FLAGS_LINK_LSA_REMOVED         (1 << 5)
+#define OSPF6_SPF_FLAGS_ROUTER_LSA_ORIGINATED    (1 << 6)
+#define OSPF6_SPF_FLAGS_NETWORK_LSA_ORIGINATED   (1 << 7)
+
+static inline void
+ospf6_set_spf_reason (struct ospf6* ospf, unsigned int reason)
+{
+  ospf->spf_reason |= reason;
+}
+
+static inline void
+ospf6_reset_spf_reason (struct ospf6 *ospf)
+{
+  ospf->spf_reason = 0;
+}
+
+static inline unsigned int
+ospf6_lsadd_to_spf_reason (struct ospf6_lsa *lsa)
+{
+  unsigned int reason = 0;
+
+  switch (ntohs (lsa->header->type))
+    {
+    case OSPF6_LSTYPE_ROUTER:
+      reason = OSPF6_SPF_FLAGS_ROUTER_LSA_ADDED;
+      break;
+    case OSPF6_LSTYPE_NETWORK:
+      reason = OSPF6_SPF_FLAGS_NETWORK_LSA_ADDED;
+      break;
+    case OSPF6_LSTYPE_LINK:
+      reason = OSPF6_SPF_FLAGS_LINK_LSA_ADDED;
+      break;
+    default:
+      break;
+    }
+  return (reason);
+}
+
+static inline unsigned int
+ospf6_lsremove_to_spf_reason (struct ospf6_lsa *lsa)
+{
+  unsigned int reason = 0;
+
+  switch (ntohs (lsa->header->type))
+    {
+    case OSPF6_LSTYPE_ROUTER:
+      reason = OSPF6_SPF_FLAGS_ROUTER_LSA_REMOVED;
+      break;
+    case OSPF6_LSTYPE_NETWORK:
+      reason = OSPF6_SPF_FLAGS_NETWORK_LSA_REMOVED;
+      break;
+    case OSPF6_LSTYPE_LINK:
+      reason = OSPF6_SPF_FLAGS_LINK_LSA_REMOVED;
+      break;
+    default:
+      break;
+    }
+  return (reason);
+}
+
 extern void ospf6_spf_table_finish (struct ospf6_route_table *result_table);
 extern void ospf6_spf_calculation (u_int32_t router_id,
                                    struct ospf6_route_table *result_table,
                                    struct ospf6_area *oa);
-extern void ospf6_spf_schedule (struct ospf6 *ospf);
+extern void ospf6_spf_schedule (struct ospf6 *ospf, unsigned int reason);
 
 extern void ospf6_spf_display_subtree (struct vty *vty, const char *prefix,
                                        int rest, struct ospf6_vertex *v);
@@ -92,6 +158,7 @@ extern void ospf6_spf_config_write (struct vty *vty);
 extern int config_write_ospf6_debug_spf (struct vty *vty);
 extern void install_element_ospf6_debug_spf (void);
 extern void ospf6_spf_init (void);
+extern void ospf6_spf_reason_string (unsigned int reason, char *buf, int size);
 
 #endif /* OSPF6_SPF_H */
 

ospf6d/ospf6_top.c

@@ -615,7 +615,8 @@ ospf6_show (struct vty *vty, struct ospf6 *o)
   struct listnode *n;
   struct ospf6_area *oa;
   char router_id[16], duration[32];
-  struct timeval now, running;
+  struct timeval now, running, result;
+  char buf[32], rbuf[32];
 
   /* process id, router id */
   inet_ntop (AF_INET, &o->router_id, router_id, sizeof (router_id));
@@ -631,6 +632,32 @@ ospf6_show (struct vty *vty, struct ospf6 *o)
   /* Redistribute configuration */
   /* XXX */
 
+  /* Show SPF parameters */
+  vty_out(vty, " Initial SPF scheduling delay %d millisec(s)%s"
+	  " Minimum hold time between consecutive SPFs %d millsecond(s)%s"
+	  " Maximum hold time between consecutive SPFs %d millsecond(s)%s"
+	  " Hold time multiplier is currently %d%s",
+	  o->spf_delay, VNL,
+	  o->spf_holdtime, VNL,
+	  o->spf_max_holdtime, VNL,
+	  o->spf_hold_multiplier, VNL);
+
+  vty_out(vty, " SPF algorithm ");
+  if (o->ts_spf.tv_sec || o->ts_spf.tv_usec)
+    {
+      timersub(&now, &o->ts_spf, &result);
+      timerstring(&result, buf, sizeof(buf));
+      ospf6_spf_reason_string(o->last_spf_reason, rbuf, sizeof(rbuf));
+      vty_out(vty, "last executed %s ago, reason %s%s", buf, rbuf, VNL);
+      vty_out (vty, " Last SPF duration %ld sec %ld usec%s",
+	       o->ts_spf_duration.tv_sec, o->ts_spf_duration.tv_usec, VNL);
+    }
+  else
+    vty_out(vty, "has not been run$%s", VNL);
+  threadtimer_string(now, o->t_spf_calc, buf, sizeof(buf));
+  vty_out (vty, " SPF timer %s%s%s",
+	   (o->t_spf_calc ? "due in " : "is "), buf, VNL);
+
   if (CHECK_FLAG (o->flag, OSPF6_STUB_ROUTER))
     vty_out (vty, " Router Is Stub Router%s", VNL);
 

ospf6d/ospf6_top.h

@@ -70,9 +70,11 @@ struct ospf6
   unsigned int spf_holdtime;		/* SPF hold time. */
   unsigned int spf_max_holdtime;	/* SPF maximum-holdtime */
   unsigned int spf_hold_multiplier;	/* Adaptive multiplier for hold time */
+  unsigned int spf_reason;              /* reason bits while scheduling SPF */
 
   struct timeval ts_spf;		/* SPF calculation time stamp. */
   struct timeval ts_spf_duration;	/* Execution time of last SPF */
+  unsigned int last_spf_reason;         /* Last SPF reason */
 
   /* Threads */
   struct thread *t_spf_calc;	        /* SPF calculation timer. */

ospf6d/ospf6d.h

@@ -101,6 +101,17 @@ extern struct thread_master *master;
       zlog_warn ("strftime error");                       \
   } while (0)
 
+#define threadtimer_string(now, t, buf, size)                         \
+  do {                                                                \
+    struct timeval result;                                            \
+    if (!t)                                                           \
+      snprintf(buf, size, "inactive");				      \
+    else {                                                            \
+      timersub(&t->u.sands, &now, &result);                           \
+      timerstring(&result, buf, size);                                \
+    }                                                                 \
+} while (0)
+
 /* for commands */
 #define OSPF6_AREA_STR      "Area information\n"
 #define OSPF6_AREA_ID_STR   "Area ID (as an IPv4 notation)\n"