Merged own patch for the bug #391 (debugging and comments mostly).

8 files changed, 418 insertions, 48 deletions

diff --git a/lib/ChangeLog b/lib/ChangeLog
index ee329114..55ddfff8 100644
--- a/lib/ChangeLog
+++ b/lib/ChangeLog
@@ -1,3 +1,7 @@
+2007-08-13 Denis Ovsienko
+
+	* zebra.h: introduce ZEBRA_ERR_KERNEL and ZEBRA_ERR_NOERROR
+
 2007-07-06 Atis Elsts <atis@mikrotik.com>
 
 	* pqueue.{c,h}: Export trickle_up
diff --git a/lib/zebra.h b/lib/zebra.h
index 2c7edd92..150aa2c5 100644
--- a/lib/zebra.h
+++ b/lib/zebra.h
@@ -454,10 +454,12 @@ extern const char *zserv_command_string (unsigned int command);
 #define ZEBRA_FAMILY_MAX                 3
 
 /* Error codes of zebra. */
+#define ZEBRA_ERR_NOERROR                0
 #define ZEBRA_ERR_RTEXIST               -1
 #define ZEBRA_ERR_RTUNREACH             -2
 #define ZEBRA_ERR_EPERM                 -3
 #define ZEBRA_ERR_RTNOEXIST             -4
+#define ZEBRA_ERR_KERNEL                -5
 
 /* Zebra message flags */
 #define ZEBRA_FLAG_INTERNAL           0x01
diff --git a/zebra/ChangeLog b/zebra/ChangeLog
index f6dea442..17e929ee 100644
--- a/zebra/ChangeLog
+++ b/zebra/ChangeLog
@@ -1,3 +1,19 @@
+2007-08-13 Denis Ovsienko
+
+	* kernel_socket.c: normalize rtm_type_str so it can be handled
+	  by LOOKUP macro
+	* kernel_socket.c: (rtm_read) don't ignore self-generated
+	  routing messages, so we can debug them; make use of
+	  ZEBRA_ERR_RTNOEXIST; output more details in debug log.
+	* kernel_socket.c: (rtmsg_debug) make use of LOOKUP macro
+	* kernel_socket.h: let the world know about rtm_type_str[_max]
+	* rib.h: 3 more debugging functions and 5 return codes
+	* rt_socket.c: (kernel_rtm_ipv4) dump IP prefix and masklen;
+	  complain about strange rtm_write() return values
+	* zebra_rib.c: (rib_lookup_ipv4_route, rib_dump,
+	  rib_lookup_and_dump) --- new functions; more comments;
+	  more debug logging
+
 2007-08-10  Emmanuel Vize <emmanuel.vize@6wind.com>
 
 	* rt_netlink.c: (netlink_interface_addr) Use the appropriate field length for the address
diff --git a/zebra/kernel_socket.c b/zebra/kernel_socket.c
index 7bc1b0f9..9d33dd44 100644
--- a/zebra/kernel_socket.c
+++ b/zebra/kernel_socket.c
@@ -160,6 +160,7 @@ struct message rtm_type_str[] =
 #endif /* RTM_IFANNOUNCE */
   {0,            NULL}
 };
+int rtm_type_str_max = sizeof (rtm_type_str) / sizeof (struct message) - 1;
 
 struct message rtm_flag_str[] =
 {
@@ -737,14 +738,12 @@ rtm_read (struct rt_msghdr *rtm)
 
   zebra_flags = 0;
 
-  /* Discard self send message. */
-  if (rtm->rtm_type != RTM_GET 
-      && (rtm->rtm_pid == pid || rtm->rtm_pid == old_pid))
-    return;
-
   /* Read destination and netmask and gateway from rtm message
      structure. */
   flags = rtm_read_mesg (rtm, &dest, &mask, &gate, ifname, &ifnlen);
+  if (IS_ZEBRA_DEBUG_KERNEL)
+    zlog_debug ("%s: got rtm of type %d (%s)", __func__, rtm->rtm_type,
+      LOOKUP (rtm_type_str, rtm->rtm_type));
 
 #ifdef RTF_CLONED	/*bsdi, netbsd 1.6*/
   if (flags & RTF_CLONED)
@@ -786,6 +785,79 @@ rtm_read (struct rt_msghdr *rtm)
       else
 	p.prefixlen = ip_masklen (mask.sin.sin_addr);
       
+      /* Catch self originated messages and match them against our current RIB.
+       * At the same time, ignore unconfirmed messages, they should be tracked
+       * by rtm_write() and kernel_rtm_ipv4().
+       */
+      if (rtm->rtm_type != RTM_GET
+          && (rtm->rtm_pid == pid || rtm->rtm_pid == old_pid))
+      {
+        char buf[INET_ADDRSTRLEN], gate_buf[INET_ADDRSTRLEN];
+        int ret;
+        if (!(flags & RTF_DONE))
+          return;
+        if (! IS_ZEBRA_DEBUG_RIB)
+          return;
+        ret = rib_lookup_ipv4_route (&p, &gate); 
+        inet_ntop (AF_INET, &p.prefix, buf, INET_ADDRSTRLEN);
+        switch (rtm->rtm_type)
+        {
+          case RTM_ADD:
+          case RTM_GET:
+          case RTM_CHANGE:
+            /* The kernel notifies us about a new route in FIB created by us.
+               Do we have a correspondent entry in our RIB? */
+            switch (ret)
+            {
+              case ZEBRA_RIB_NOTFOUND:
+                zlog_debug ("%s: %s %s/%d: desync: RR isn't yet in RIB, while already in FIB",
+                  __func__, LOOKUP (rtm_type_str, rtm->rtm_type), buf, p.prefixlen);
+                break;
+              case ZEBRA_RIB_FOUND_CONNECTED:
+              case ZEBRA_RIB_FOUND_NOGATE:
+                inet_ntop (AF_INET, &gate.sin.sin_addr, gate_buf, INET_ADDRSTRLEN);
+                zlog_debug ("%s: %s %s/%d: desync: RR is in RIB, but gate differs (ours is %s)",
+                  __func__, LOOKUP (rtm_type_str, rtm->rtm_type), buf, p.prefixlen, gate_buf);
+                break;
+              case ZEBRA_RIB_FOUND_EXACT: /* RIB RR == FIB RR */
+                zlog_debug ("%s: %s %s/%d: done Ok",
+                  __func__, LOOKUP (rtm_type_str, rtm->rtm_type), buf, p.prefixlen);
+                rib_lookup_and_dump (&p);
+                return;
+                break;
+            }
+            break;
+          case RTM_DELETE:
+            /* The kernel notifies us about a route deleted by us. Do we still
+               have it in the RIB? Do we have anything instead? */
+            switch (ret)
+            {
+              case ZEBRA_RIB_FOUND_EXACT:
+                zlog_debug ("%s: %s %s/%d: desync: RR is still in RIB, while already not in FIB",
+                  __func__, LOOKUP (rtm_type_str, rtm->rtm_type), buf, p.prefixlen);
+                rib_lookup_and_dump (&p);
+                break;
+              case ZEBRA_RIB_FOUND_CONNECTED:
+              case ZEBRA_RIB_FOUND_NOGATE:
+                zlog_debug ("%s: %s %s/%d: desync: RR is still in RIB, plus gate differs",
+                  __func__, LOOKUP (rtm_type_str, rtm->rtm_type), buf, p.prefixlen);
+                rib_lookup_and_dump (&p);
+                break;
+              case ZEBRA_RIB_NOTFOUND: /* RIB RR == FIB RR */
+                zlog_debug ("%s: %s %s/%d: done Ok",
+                  __func__, LOOKUP (rtm_type_str, rtm->rtm_type), buf, p.prefixlen);
+                rib_lookup_and_dump (&p);
+                return;
+                break;
+            }
+            break;
+          default:
+            zlog_debug ("%s: %s/%d: warning: loopback RTM of type %s received",
+              __func__, buf, p.prefixlen, LOOKUP (rtm_type_str, rtm->rtm_type));
+        }
+        return;
+      }
+
       /* Change, delete the old prefix, we have no further information
        * to specify the route really
        */
@@ -903,7 +975,13 @@ rtm_write (int message,
     {
       if (!ifp)
         {
-          zlog_warn ("no gateway found for interface index %d", index);
+          char dest_buf[INET_ADDRSTRLEN] = "NULL", mask_buf[INET_ADDRSTRLEN] = "255.255.255.255";
+          if (dest)
+            inet_ntop (AF_INET, &dest->sin.sin_addr, dest_buf, INET_ADDRSTRLEN);
+          if (mask)
+            inet_ntop (AF_INET, &mask->sin.sin_addr, mask_buf, INET_ADDRSTRLEN);
+          zlog_warn ("%s: %s/%s: gate == NULL and no gateway found for ifindex %d",
+            __func__, dest_buf, mask_buf, index);
           return -1;
         }
       gate = (union sockunion *) & ifp->sdl;
@@ -959,11 +1037,13 @@ rtm_write (int message,
 	return ZEBRA_ERR_RTEXIST;
       if (errno == ENETUNREACH)
 	return ZEBRA_ERR_RTUNREACH;
+      if (errno == ESRCH)
+	return ZEBRA_ERR_RTNOEXIST;
       
-      zlog_warn ("write : %s (%d)", safe_strerror (errno), errno);
-      return -1;
+      zlog_warn ("%s: write : %s (%d)", __func__, safe_strerror (errno), errno);
+      return ZEBRA_ERR_KERNEL;
     }
-  return 0;
+  return ZEBRA_ERR_NOERROR;
 }
 
 
@@ -974,17 +1054,7 @@ rtm_write (int message,
 static void
 rtmsg_debug (struct rt_msghdr *rtm)
 {
-  const char *type = "Unknown";
-  struct message *mes;
-
-  for (mes = rtm_type_str; mes->str; mes++)
-    if (mes->key == rtm->rtm_type)
-      {
-	type = mes->str;
-	break;
-      }
-
-  zlog_debug ("Kernel: Len: %d Type: %s", rtm->rtm_msglen, type);
+  zlog_debug ("Kernel: Len: %d Type: %s", rtm->rtm_msglen, LOOKUP (rtm_type_str, rtm->rtm_type));
   rtm_flag_dump (rtm->rtm_flags);
   zlog_debug ("Kernel: message seq %d", rtm->rtm_seq);
   zlog_debug ("Kernel: pid %d, rtm_addrs 0x%x", rtm->rtm_pid, rtm->rtm_addrs);
diff --git a/zebra/kernel_socket.h b/zebra/kernel_socket.h
index a3923c5e..c903786b 100644
--- a/zebra/kernel_socket.h
+++ b/zebra/kernel_socket.h
@@ -28,5 +28,7 @@ extern int ifam_read (struct ifa_msghdr *);
 extern int ifm_read (struct if_msghdr *);
 extern int rtm_write (int, union sockunion *, union sockunion *,
                       union sockunion *, unsigned int, int, int);
+extern struct message rtm_type_str[];
+extern int rtm_type_str_max;
 
 #endif /* __ZEBRA_KERNEL_SOCKET_H */
diff --git a/zebra/rib.h b/zebra/rib.h
index 7b2bd426..796a30eb 100644
--- a/zebra/rib.h
+++ b/zebra/rib.h
@@ -211,6 +211,15 @@ extern struct nexthop *nexthop_ifname_add (struct rib *, char *);
 extern struct nexthop *nexthop_blackhole_add (struct rib *);
 extern struct nexthop *nexthop_ipv4_add (struct rib *, struct in_addr *,
 					 struct in_addr *);
+extern void rib_lookup_and_dump (struct prefix_ipv4 *);
+extern void rib_dump (const char *, const struct prefix_ipv4 *, const struct rib *);
+extern int rib_lookup_ipv4_route (struct prefix_ipv4 *, union sockunion *);
+#define ZEBRA_RIB_LOOKUP_ERROR -1
+#define ZEBRA_RIB_FOUND_EXACT 0
+#define ZEBRA_RIB_FOUND_NOGATE 1
+#define ZEBRA_RIB_FOUND_CONNECTED 2
+#define ZEBRA_RIB_NOTFOUND 3
+
 #ifdef HAVE_IPV6
 extern struct nexthop *nexthop_ipv6_add (struct rib *, struct in6_addr *);
 #endif /* HAVE_IPV6 */
diff --git a/zebra/rt_socket.c b/zebra/rt_socket.c
index b06c586a..e8668a1d 100644
--- a/zebra/rt_socket.c
+++ b/zebra/rt_socket.c
@@ -32,6 +32,7 @@
 #include "zebra/debug.h"
 #include "zebra/rib.h"
 #include "zebra/rt.h"
+#include "zebra/kernel_socket.h"
 
 extern struct zebra_privs_t zserv_privs;
 
@@ -75,7 +76,10 @@ kernel_rtm_ipv4 (int cmd, struct prefix *p, struct rib *rib, int family)
   unsigned int ifindex = 0;
   int gate = 0;
   int error;
+  char prefix_buf[INET_ADDRSTRLEN];
 
+  if (IS_ZEBRA_DEBUG_RIB)
+    inet_ntop (AF_INET, &p->u.prefix, prefix_buf, INET_ADDRSTRLEN);
   memset (&sin_dest, 0, sizeof (struct sockaddr_in));
   sin_dest.sin_family = AF_INET;
 #ifdef HAVE_STRUCT_SOCKADDR_IN_SIN_LEN
@@ -95,6 +99,7 @@ kernel_rtm_ipv4 (int cmd, struct prefix *p, struct rib *rib, int family)
   for (nexthop = rib->nexthop; nexthop; nexthop = nexthop->next)
     {
       gate = 0;
+      char gate_buf[INET_ADDRSTRLEN] = "NULL";
 
       /*
        * XXX We need to refrain from kernel operations in some cases,
@@ -161,29 +166,61 @@ kernel_rtm_ipv4 (int cmd, struct prefix *p, struct rib *rib, int family)
 			     rib->flags,
 			     rib->metric);
 
-#if 0
-	  if (error)
-	    {
-	      zlog_info ("kernel_rtm_ipv4(): nexthop %d add error=%d.",
-			 nexthop_num, error);
-	    }
-#endif
-	  if (error == 0)
-	    {
-	      nexthop_num++;
-	      if (cmd == RTM_ADD)
-		SET_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB);
-	    }
-	}
-    }
-
-  /* If there is no useful nexthop then return. */
-  if (nexthop_num == 0)
-    {
-      if (IS_ZEBRA_DEBUG_KERNEL)
-	zlog_debug ("kernel_rtm_ipv4(): No useful nexthop.");
-      return 0;
-    }
+           if (IS_ZEBRA_DEBUG_RIB)
+           {
+             if (!gate)
+             {
+               zlog_debug ("%s: %s/%d: attention! gate not found for rib %p",
+                 __func__, prefix_buf, p->prefixlen, rib);
+               rib_dump (__func__, (struct prefix_ipv4 *)p, rib);
+             }
+             else
+               inet_ntop (AF_INET, &sin_gate.sin_addr, gate_buf, INET_ADDRSTRLEN);
+           }
+ 
+           switch (error)
+           {
+             /* We only flag nexthops as being in FIB if rtm_write() did its work. */
+             case ZEBRA_ERR_NOERROR:
+               nexthop_num++;
+               if (IS_ZEBRA_DEBUG_RIB)
+                 zlog_debug ("%s: %s/%d: successfully did NH %s",
+                   __func__, prefix_buf, p->prefixlen, gate_buf);
+               if (cmd == RTM_ADD)
+                 SET_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB);
+               break;
+ 
+             /* The only valid case for this error is kernel's failure to install
+              * a multipath route, which is common for FreeBSD. This should be
+              * ignored silently, but logged as an error otherwise.
+              */
+             case ZEBRA_ERR_RTEXIST:
+               if (cmd != RTM_ADD)
+                 zlog_err ("%s: rtm_write() returned %d for command %d",
+                   __func__, error, cmd);
+               continue;
+               break;
+ 
+             /* Given that our NEXTHOP_FLAG_FIB matches real kernel FIB, it isn't
+              * normal to get any other messages in ANY case.
+              */
+             case ZEBRA_ERR_RTNOEXIST:
+             case ZEBRA_ERR_RTUNREACH:
+             default:
+               zlog_err ("%s: %s/%d: rtm_write() unexpectedly returned %d for command %s",
+                 __func__, prefix_buf, p->prefixlen, error, LOOKUP (rtm_type_str, cmd));
+               break;
+           }
+         } /* if (cmd and flags make sense) */
+       else
+         if (IS_ZEBRA_DEBUG_RIB)
+           zlog_debug ("%s: odd command %s for flags %d",
+             __func__, LOOKUP (rtm_type_str, cmd), nexthop->flags);
+     } /* for (nexthop = ... */
+ 
+   /* If there was no useful nexthop, then complain. */
+   if (nexthop_num == 0 && IS_ZEBRA_DEBUG_KERNEL)
+     zlog_debug ("%s: No useful nexthops were found in RIB entry %p", __func__, rib);
 
   return 0; /*XXX*/
 }
diff --git a/zebra/zebra_rib.c b/zebra/zebra_rib.c
index 7a63c1c1..f61cbe31 100644
--- a/zebra/zebra_rib.c
+++ b/zebra/zebra_rib.c
@@ -631,6 +631,82 @@ rib_lookup_ipv4 (struct prefix_ipv4 *p)
   return NULL;
 }
 
+/*
+ * This clone function, unlike its original rib_lookup_ipv4(), checks
+ * if specified IPv4 route record (prefix/mask -> gate) exists in
+ * the whole RIB and has ZEBRA_FLAG_SELECTED set.
+ *
+ * Return values:
+ * -1: error
+ * 0: exact match found
+ * 1: a match was found with a different gate
+ * 2: connected route found
+ * 3: no matches found
+ */
+int
+rib_lookup_ipv4_route (struct prefix_ipv4 *p, union sockunion * qgate)
+{
+  struct route_table *table;
+  struct route_node *rn;
+  struct rib *match;
+  struct nexthop *nexthop;
+
+  /* Lookup table.  */
+  table = vrf_table (AFI_IP, SAFI_UNICAST, 0);
+  if (! table)
+    return ZEBRA_RIB_LOOKUP_ERROR;
+
+  /* Scan the RIB table for exactly matching RIB entry. */
+  rn = route_node_lookup (table, (struct prefix *) p);
+
+  /* No route for this prefix. */
+  if (! rn)
+    return ZEBRA_RIB_NOTFOUND;
+
+  /* Unlock node. */
+  route_unlock_node (rn);
+
+  /* Find out if a "selected" RR for the discovered RIB entry exists ever. */
+  for (match = rn->info; match; match = match->next)
+  {
+    if (CHECK_FLAG (match->status, RIB_ENTRY_REMOVED))
+      continue;
+    if (CHECK_FLAG (match->flags, ZEBRA_FLAG_SELECTED))
+      break;
+  }
+
+  /* None such found :( */
+  if (!match)
+    return ZEBRA_RIB_NOTFOUND;
+
+  if (match->type == ZEBRA_ROUTE_CONNECT)
+    return ZEBRA_RIB_FOUND_CONNECTED;
+  
+  /* Ok, we have a cood candidate, let's check it's nexthop list... */
+  for (nexthop = match->nexthop; nexthop; nexthop = nexthop->next)
+    if (CHECK_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB))
+    {
+      /* We are happy with either direct or recursive hexthop */
+      if (nexthop->gate.ipv4.s_addr == qgate->sin.sin_addr.s_addr ||
+          nexthop->rgate.ipv4.s_addr == qgate->sin.sin_addr.s_addr)
+        return ZEBRA_RIB_FOUND_EXACT;
+      else
+      {
+        if (IS_ZEBRA_DEBUG_RIB)
+        {
+          char gate_buf[INET_ADDRSTRLEN], rgate_buf[INET_ADDRSTRLEN], qgate_buf[INET_ADDRSTRLEN];
+          inet_ntop (AF_INET, &nexthop->gate.ipv4.s_addr, gate_buf, INET_ADDRSTRLEN);
+          inet_ntop (AF_INET, &nexthop->rgate.ipv4.s_addr, rgate_buf, INET_ADDRSTRLEN);
+          inet_ntop (AF_INET, &qgate->sin.sin_addr.s_addr, qgate_buf, INET_ADDRSTRLEN);
+          zlog_debug ("%s: qgate == %s, gate == %s, rgate == %s", __func__, qgate_buf, gate_buf, rgate_buf);
+        }
+        return ZEBRA_RIB_FOUND_NOGATE;
+      }
+    }
+
+  return ZEBRA_RIB_NOTFOUND;
+}
+
 #ifdef HAVE_IPV6
 struct rib *
 rib_match_ipv6 (struct in6_addr *addr)
@@ -694,6 +770,16 @@ rib_match_ipv6 (struct in6_addr *addr)
 #define RIB_SYSTEM_ROUTE(R) \
         ((R)->type == ZEBRA_ROUTE_KERNEL || (R)->type == ZEBRA_ROUTE_CONNECT)
 
+/* This function verifies reachability of one given nexthop, which can be
+ * numbered or unnumbered, IPv4 or IPv6. The result is unconditionally stored
+ * in nexthop->flags field. If the 4th parameter, 'set', is non-zero,
+ * nexthop->ifindex will be updated appropriately as well.
+ * An existing route map can turn (otherwise active) nexthop into inactive, but
+ * not vice versa.
+ *
+ * The return value is the final value of 'ACTIVE' flag.
+ */
+
 static int
 nexthop_active_check (struct route_node *rn, struct rib *rib,
 		      struct nexthop *nexthop, int set)
@@ -839,6 +925,7 @@ rib_install_kernel (struct route_node *rn, struct rib *rib)
 #endif /* HAVE_IPV6 */
     }
 
+  /* This condition is never met, if we are using rt_socket.c */
   if (ret < 0)
     {
       for (nexthop = rib->nexthop; nexthop; nexthop = nexthop->next)
@@ -860,6 +947,8 @@ rib_uninstall_kernel (struct route_node *rn, struct rib *rib)
       break;
 #ifdef HAVE_IPV6
     case AF_INET6:
+      if (IS_ZEBRA_DEBUG_RIB)
+        zlog_debug ("%s: calling kernel_delete_ipv4 (%p, %p)", __func__, rn, rib);
       ret = kernel_delete_ipv6 (&rn->p, rib);
       break;
 #endif /* HAVE_IPV6 */
@@ -907,6 +996,9 @@ rib_process (struct work_queue *wq, void *data)
 
   for (rib = rn->info; rib; rib = next)
     {
+      /* The next pointer is saved, because current pointer
+       * may be passed to rib_unlink() in the middle of iteration.
+       */
       next = rib->next;
       
       /* Currently installed rib. */
@@ -983,9 +1075,16 @@ rib_process (struct work_queue *wq, void *data)
       /* metric tie-breaks equal distance */
       if (rib->metric <= select->metric)
         select = rib;
-    }
-  
-  /* Same route is selected. */
+    } /* for (rib = rn->info; rib; rib = next) */
+
+  /* After the cycle is finished, the following pointers will be set:
+   * select --- the winner RIB entry, if any was found, otherwise NULL
+   * fib    --- the SELECTED RIB entry, if any, otherwise NULL
+   * del    --- equal to fib, if fib is queued for deletion, NULL otherwise
+   * rib    --- NULL
+   */
+
+  /* Same RIB entry is selected. Update FIB and finish. */
   if (select && select == fib)
     {
       if (IS_ZEBRA_DEBUG_RIB)
@@ -1024,7 +1123,10 @@ rib_process (struct work_queue *wq, void *data)
       goto end;
     }
 
-  /* Uninstall old rib from forwarding table. */
+  /* At this point we either haven't found the best RIB entry or it is
+   * different from what we currently intend to flag with SELECTED. In both
+   * cases, if a RIB block is present in FIB, it should be withdrawn.
+   */
   if (fib)
     {
       if (IS_ZEBRA_DEBUG_RIB)
@@ -1039,7 +1141,10 @@ rib_process (struct work_queue *wq, void *data)
       nexthop_active_update (rn, fib, 1);
     }
 
-  /* Install new rib into forwarding table. */
+  /* Regardless of some RIB entry being SELECTED or not before, now we can
+   * tell, that if a new winner exists, FIB is still not updated with this
+   * data, but ready to be.
+   */
   if (select)
     {
       if (IS_ZEBRA_DEBUG_RIB)
@@ -1382,16 +1487,127 @@ rib_add_ipv4 (int type, int flags, struct prefix_ipv4 *p,
       SET_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB);
 
   /* Link new rib to node.*/
+  if (IS_ZEBRA_DEBUG_RIB)
+    zlog_debug ("%s: calling rib_addnode (%p, %p)", __func__, rn, rib);
   rib_addnode (rn, rib);
   
   /* Free implicit route.*/
   if (same)
+  {
+    if (IS_ZEBRA_DEBUG_RIB)
+      zlog_debug ("%s: calling rib_delnode (%p, %p)", __func__, rn, rib);
     rib_delnode (rn, same);
+  }
   
   route_unlock_node (rn);
   return 0;
 }
 
+/* This function dumps the contents of a given RIB entry into
+ * standard debug log. Calling function name and IP prefix in
+ * question are passed as 1st and 2nd arguments.
+ */
+
+void rib_dump (const char * func, const struct prefix_ipv4 * p, const struct rib * rib)
+{
+  char straddr1[INET_ADDRSTRLEN], straddr2[INET_ADDRSTRLEN];
+  struct nexthop *nexthop;
+
+  inet_ntop (AF_INET, &p->prefix, straddr1, INET_ADDRSTRLEN);
+  zlog_debug ("%s: dumping RIB entry %p for %s/%d", func, rib, straddr1, p->prefixlen);
+  zlog_debug
+  (
+    "%s: refcnt == %lu, uptime == %u, type == %u, table == %d",
+    func,
+    rib->refcnt,
+    rib->uptime,
+    rib->type,
+    rib->table
+  );
+  zlog_debug
+  (
+    "%s: metric == %u, distance == %u, flags == %u, status == %u",
+    func,
+    rib->metric,
+    rib->distance,
+    rib->flags,
+    rib->status
+  );
+  zlog_debug
+  (
+    "%s: nexthop_num == %u, nexthop_active_num == %u, nexthop_fib_num == %u",
+    func,
+    rib->nexthop_num,
+    rib->nexthop_active_num,
+    rib->nexthop_fib_num
+  );
+  for (nexthop = rib->nexthop; nexthop; nexthop = nexthop->next)
+  {
+    inet_ntop (AF_INET, &nexthop->gate.ipv4.s_addr, straddr1, INET_ADDRSTRLEN);
+    inet_ntop (AF_INET, &nexthop->rgate.ipv4.s_addr, straddr2, INET_ADDRSTRLEN);
+    zlog_debug
+    (
+      "%s: NH %s (%s) with flags %s%s%s",
+      func,
+      straddr1,
+      straddr2,
+      (CHECK_FLAG (nexthop->flags, NEXTHOP_FLAG_ACTIVE) ? "ACTIVE " : ""),
+      (CHECK_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB) ? "FIB " : ""),
+      (CHECK_FLAG (nexthop->flags, NEXTHOP_FLAG_RECURSIVE) ? "RECURSIVE" : "")
+    );
+  }
+  zlog_debug ("%s: dump complete", func);
+}
+
+/* This is an exported helper to rtm_read() to dump the strange
+ * RIB entry found by rib_lookup_ipv4_route()
+ */
+
+void rib_lookup_and_dump (struct prefix_ipv4 * p)
+{
+  struct route_table *table;
+  struct route_node *rn;
+  struct rib *rib;
+  char prefix_buf[INET_ADDRSTRLEN];
+
+  /* Lookup table.  */
+  table = vrf_table (AFI_IP, SAFI_UNICAST, 0);
+  if (! table)
+  {
+    zlog_err ("%s: vrf_table() returned NULL", __func__);
+    return;
+  }
+
+  inet_ntop (AF_INET, &p->prefix.s_addr, prefix_buf, INET_ADDRSTRLEN);
+  /* Scan the RIB table for exactly matching RIB entry. */
+  rn = route_node_lookup (table, (struct prefix *) p);
+
+  /* No route for this prefix. */
+  if (! rn)
+  {
+    zlog_debug ("%s: lookup failed for %s/%d", __func__, prefix_buf, p->prefixlen);
+    return;
+  }
+
+  /* Unlock node. */
+  route_unlock_node (rn);
+
+  /* let's go */
+  for (rib = rn->info; rib; rib = rib->next)
+  {
+    zlog_debug
+    (
+      "%s: rn %p, rib %p: %s, %s",
+      __func__,
+      rn,
+      rib,
+      (CHECK_FLAG (rib->status, RIB_ENTRY_REMOVED) ? "removed" : "NOT removed"),
+      (CHECK_FLAG (rib->flags, ZEBRA_FLAG_SELECTED) ? "selected" : "NOT selected")
+    );
+    rib_dump (__func__, p, rib);
+  }
+}
+
 int
 rib_add_ipv4_multipath (struct prefix_ipv4 *p, struct rib *rib)
 {
@@ -1440,10 +1656,24 @@ rib_add_ipv4_multipath (struct prefix_ipv4 *p, struct rib *rib)
 
   /* Link new rib to node.*/
   rib_addnode (rn, rib);
+  if (IS_ZEBRA_DEBUG_RIB)
+  {
+    zlog_debug ("%s: called rib_addnode (%p, %p) on new RIB entry",
+      __func__, rn, rib);
+    rib_dump (__func__, p, rib);
+  }
 
   /* Free implicit route.*/
   if (same)
+  {
+    if (IS_ZEBRA_DEBUG_RIB)
+    {
+      zlog_debug ("%s: calling rib_delnode (%p, %p) on existing RIB entry",
+        __func__, rn, same);
+      rib_dump (__func__, p, same);
+    }
     rib_delnode (rn, same);
+  }
   
   route_unlock_node (rn);
   return 0;