FIB: use vlib-log for debugging

Change-Id: I9052202b8cbcf656e61d635253d515f0f3a8d145
Signed-off-by: Neale Ranns <nranns@cisco.com>

11 files changed, 186 insertions, 96 deletions

diff --git a/src/vnet/fib/fib_entry.c b/src/vnet/fib/fib_entry.c
index 8d7ce00b9c0..7de521336b8 100644
--- a/src/vnet/fib/fib_entry.c
+++ b/src/vnet/fib/fib_entry.c
@@ -41,6 +41,11 @@ static const char *fib_src_attribute_names[] = FIB_ENTRY_SRC_ATTRIBUTES;
  */
 static fib_entry_t *fib_entry_pool;
 
+/**
+ * the logger
+ */
+vlib_log_class_t fib_entry_logger;
+
 fib_entry_t *
 fib_entry_get (fib_node_index_t index)
 {
@@ -101,11 +106,39 @@ format_fib_source (u8 * s, va_list * args)
 }
 
 u8 *
-format_fib_entry (u8 * s, va_list * args)
+format_fib_entry_flags (u8 *s, va_list *args)
+{
+    fib_entry_attribute_t attr;
+    fib_entry_flag_t flag = va_arg(*args, int);
+
+    FOR_EACH_FIB_ATTRIBUTE(attr) {
+        if ((1<<attr) & flag) {
+            s = format (s, "%s,", fib_attribute_names[attr]);
+        }
+    }
+
+    return (s);
+}
+
+u8 *
+format_fib_entry_src_flags (u8 *s, va_list *args)
 {
     fib_entry_src_attribute_t sattr;
+    fib_entry_src_flag_t flag = va_arg(*args, int);
+
+    FOR_EACH_FIB_SRC_ATTRIBUTE(sattr) {
+        if ((1<<sattr) & flag) {
+            s = format (s, "%s,", fib_src_attribute_names[sattr]);
+        }
+    }
+
+    return (s);
+}
+
+u8 *
+format_fib_entry (u8 * s, va_list * args)
+{
     fib_forward_chain_type_t fct;
-    fib_entry_attribute_t attr;
     fib_entry_t *fib_entry;
     fib_entry_src_t *src;
     fib_node_index_t fei;
@@ -129,20 +162,12 @@ format_fib_entry (u8 * s, va_list * args)
 	    s = format (s, "\n  %U", format_fib_source, source);
 	    s = format (s, " refs:%d", src->fes_ref_count);
 	    if (FIB_ENTRY_FLAG_NONE != src->fes_entry_flags) {
-		s = format(s, " entry-flags:");
-		FOR_EACH_FIB_ATTRIBUTE(attr) {
-		    if ((1<<attr) & src->fes_entry_flags) {
-			s = format (s, "%s,", fib_attribute_names[attr]);
-		    }
-		}
+		s = format(s, " entry-flags:%U",
+                           format_fib_entry_flags, src->fes_entry_flags);
 	    }
 	    if (FIB_ENTRY_SRC_FLAG_NONE != src->fes_flags) {
-		s = format(s, " src-flags:");
-		FOR_EACH_FIB_SRC_ATTRIBUTE(sattr) {
-		    if ((1<<sattr) & src->fes_flags) {
-			s = format (s, "%s,", fib_src_attribute_names[sattr]);
-		    }
-		}
+		s = format(s, " src-flags:%U",
+                           format_fib_entry_src_flags, src->fes_flags);
 	    }
             s = fib_entry_src_format(fib_entry, source, s);
 	    s = format (s, "\n");
@@ -316,6 +341,9 @@ fib_entry_back_walk_notify (fib_node_t *node,
      */
     ctx->fnbw_flags &= ~FIB_NODE_BW_FLAG_FORCE_SYNC;
 
+    FIB_ENTRY_DBG(fib_entry, "bw:%U",
+                  format_fib_node_bw_reason, ctx->fnbw_reason);
+
     /*
      * propagate the backwalk further if we haven't already reached the
      * maximum depth.
@@ -601,8 +629,6 @@ fib_entry_alloc (u32 fib_index,
 
     *fib_entry_index = fib_entry_get_index(fib_entry);
 
-    FIB_ENTRY_DBG(fib_entry, "alloc");
-
     return (fib_entry);
 }
 
@@ -719,6 +745,8 @@ fib_entry_create (u32 fib_index,
 
     fib_entry_post_install_actions(fib_entry, source, FIB_ENTRY_FLAG_NONE);
 
+    FIB_ENTRY_DBG(fib_entry, "create");
+
     return (fib_entry_index);
 }
 
@@ -745,6 +773,8 @@ fib_entry_create_special (u32 fib_index,
 
     fib_entry_post_install_actions(fib_entry, source, FIB_ENTRY_FLAG_NONE);
 
+    FIB_ENTRY_DBG(fib_entry, "create-special");
+
     return (fib_entry_index);
 }
 
@@ -850,6 +880,7 @@ fib_entry_special_add (fib_node_index_t fib_entry_index,
 
     fib_entry = fib_entry_src_action_add(fib_entry, source, flags, dpo);
     fib_entry_source_change(fib_entry, best_source, source);
+    FIB_ENTRY_DBG(fib_entry, "special-add:%U", format_fib_source, source);
 }
 
 void
@@ -866,6 +897,8 @@ fib_entry_special_update (fib_node_index_t fib_entry_index,
 
     fib_entry = fib_entry_src_action_update(fib_entry, source, flags, dpo);
     fib_entry_source_change(fib_entry, best_source, source);
+
+    FIB_ENTRY_DBG(fib_entry, "special-updated:%U", format_fib_source, source);
 }
 
 
@@ -890,6 +923,8 @@ fib_entry_path_add (fib_node_index_t fib_entry_index,
     fib_entry = fib_entry_src_action_path_add(fib_entry, source, flags, rpath);
 
     fib_entry_source_change(fib_entry, best_source, source);
+
+    FIB_ENTRY_DBG(fib_entry, "path add:%U", format_fib_source, source);
 }
 
 static fib_entry_src_flag_t
@@ -987,6 +1022,8 @@ fib_entry_path_remove (fib_node_index_t fib_entry_index,
 
     sflag = fib_entry_src_action_path_remove(fib_entry, source, rpath);
 
+    FIB_ENTRY_DBG(fib_entry, "path remove:%U", format_fib_source, source);
+
     /*
      * if the path list for the source passed is invalid,
      * then we need to create a new one. else we are updating
@@ -1076,6 +1113,8 @@ fib_entry_special_remove (fib_node_index_t fib_entry_index,
 
     sflag = fib_entry_src_action_remove_or_update_inherit(fib_entry, source);
 
+    FIB_ENTRY_DBG(fib_entry, "special remove:%U", format_fib_source, source);
+
     /*
      * if the path list for the source passed is invalid,
      * then we need to create a new one. else we are updating
@@ -1206,6 +1245,7 @@ fib_entry_update (fib_node_index_t fib_entry_index,
                                                paths);
 
     fib_entry_source_change_w_flags(fib_entry, best_source, bflags, source);
+    FIB_ENTRY_DBG(fib_entry, "update");
 }
 
 
@@ -1279,6 +1319,7 @@ fib_entry_cover_changed (fib_node_index_t fib_entry_index)
 
 	fib_walk_sync(FIB_NODE_TYPE_ENTRY, fib_entry_index, &bw_ctx);
     }
+    FIB_ENTRY_DBG(fib_entry, "cover-changed");
 }
 
 /*
@@ -1352,6 +1393,7 @@ fib_entry_cover_updated (fib_node_index_t fib_entry_index)
 
 	fib_walk_sync(FIB_NODE_TYPE_ENTRY, fib_entry_index, &bw_ctx);
     }
+    FIB_ENTRY_DBG(fib_entry, "cover-updated");
 }
 
 int
@@ -1602,7 +1644,8 @@ fib_entry_unlock (fib_node_index_t fib_entry_index)
 void
 fib_entry_module_init (void)
 {
-    fib_node_register_type (FIB_NODE_TYPE_ENTRY, &fib_entry_vft);
+    fib_node_register_type(FIB_NODE_TYPE_ENTRY, &fib_entry_vft);
+    fib_entry_logger = vlib_log_register_class("fib", "entry");
 }
 
 void
diff --git a/src/vnet/fib/fib_entry.h b/src/vnet/fib/fib_entry.h
index 9175a571032..8ede39c1e9d 100644
--- a/src/vnet/fib/fib_entry.h
+++ b/src/vnet/fib/fib_entry.h
@@ -286,6 +286,8 @@ typedef enum fib_entry_flag_t_ {
     FIB_ENTRY_FLAG_INTERPOSE = (1 << FIB_ENTRY_ATTRIBUTE_INTERPOSE),
 } __attribute__((packed)) fib_entry_flag_t;
 
+extern u8 * format_fib_entry_flags(u8 *s, va_list *args);
+
 /**
  * Flags for the source data
  */
@@ -337,6 +339,8 @@ typedef enum fib_entry_src_flag_t_ {
     FIB_ENTRY_SRC_FLAG_INHERITED = (1 << FIB_ENTRY_SRC_ATTRIBUTE_INHERITED),
 } __attribute__ ((packed)) fib_entry_src_flag_t;
 
+extern u8 * format_fib_entry_src_flags(u8 *s, va_list *args);
+
 /*
  * Keep the size of the flags field to 2 bytes, so it
  * can be placed next to the 2 bytes reference count
diff --git a/src/vnet/fib/fib_entry_src.c b/src/vnet/fib/fib_entry_src.c
index 1b2d7161060..6868da613e0 100644
--- a/src/vnet/fib/fib_entry_src.c
+++ b/src/vnet/fib/fib_entry_src.c
@@ -692,8 +692,7 @@ fib_entry_src_action_uninstall (fib_entry_t *fib_entry)
     /*
      * uninstall the forwarding chain from the forwarding tables
      */
-    FIB_ENTRY_DBG(fib_entry, "uninstall: %d",
-		  fib_entry->fe_adj_index);
+    FIB_ENTRY_DBG(fib_entry, "uninstall");
 
     if (dpo_id_is_valid(&fib_entry->fe_lb))
     {
diff --git a/src/vnet/fib/fib_entry_src.h b/src/vnet/fib/fib_entry_src.h
index 61740201eb7..1d5f252eb87 100644
--- a/src/vnet/fib/fib_entry_src.h
+++ b/src/vnet/fib/fib_entry_src.h
@@ -23,24 +23,21 @@
 /**
  * Debug macro
  */
-#ifdef FIB_DEBUG
+extern vlib_log_class_t fib_entry_logger;
+
 #define FIB_ENTRY_DBG(_e, _fmt, _args...)		\
 {   		          				\
-    u8*__tmp = NULL;					\
-    __tmp = format(__tmp, "e:[%d:%U",			\
-		   fib_entry_get_index(_e),		\
-		   format_ip46_address,			\
-		   &_e->fe_prefix.fp_addr,		\
-		   IP46_TYPE_ANY);			\
-    __tmp = format(__tmp, "/%d]:",			\
-		   _e->fe_prefix.fp_len);		\
-    __tmp = format(__tmp, _fmt, ##_args);		\
-    clib_warning("%s", __tmp);				\
-    vec_free(__tmp);					\
+    vlib_log_debug(fib_entry_logger,                    \
+                   "[@%d:[%U]:%U:%U]: " _fmt,           \
+                   fib_entry_get_index(_e),		\
+                   format_fib_prefix,                   \
+                   &_e->fe_prefix,                      \
+                   format_fib_entry_flags,              \
+                    _e->fe_srcs[0].fes_entry_flags,     \
+                   format_fib_source,                   \
+                   _e->fe_srcs[0].fes_src,              \
+                   ##_args);                            \
 }
-#else
-#define FIB_ENTRY_DBG(_e, _fmt, _args...)
-#endif
 
 /**
  * Source initialisation Function 
diff --git a/src/vnet/fib/fib_entry_src_adj.c b/src/vnet/fib/fib_entry_src_adj.c
index e43e36ee4e5..8c343051e8f 100644
--- a/src/vnet/fib/fib_entry_src_adj.c
+++ b/src/vnet/fib/fib_entry_src_adj.c
@@ -348,6 +348,7 @@ fib_entry_src_adj_cover_change (fib_entry_src_t *src,
         res.bw_reason = FIB_NODE_BW_REASON_FLAG_EVALUATE;
     }
 
+    FIB_ENTRY_DBG(fib_entry, "adj-src-cover-changed");
     return (res);
 }
 
@@ -375,6 +376,8 @@ fib_entry_src_adj_cover_update (fib_entry_src_t *src,
 
     res.install = (FIB_ENTRY_FLAG_ATTACHED & fib_entry_get_flags_i(cover));
 
+    FIB_ENTRY_DBG(fib_entry, "adj-src-cover-updated");
+
     return (res);
 }
 
diff --git a/src/vnet/fib/fib_internal.h b/src/vnet/fib/fib_internal.h
index 8abc0e07313..a60ad26dc64 100644
--- a/src/vnet/fib/fib_internal.h
+++ b/src/vnet/fib/fib_internal.h
@@ -19,11 +19,6 @@
 #include <vnet/ip/ip.h>
 #include <vnet/dpo/dpo.h>
 
-/**
- * Big train switch; FIB debugs on or off
- */
-#undef FIB_DEBUG
-
 extern void fib_prefix_from_mpls_label(mpls_label_t label,
                                        mpls_eos_bit_t eos,
 				       fib_prefix_t *prf);
diff --git a/src/vnet/fib/fib_node.h b/src/vnet/fib/fib_node.h
index 3a4ba8470bc..1179dfc0a50 100644
--- a/src/vnet/fib/fib_node.h
+++ b/src/vnet/fib/fib_node.h
@@ -156,6 +156,8 @@ typedef enum fib_node_bw_reason_flag_t_ {
 STATIC_ASSERT(sizeof(fib_node_bw_reason_flag_t) < 2,
 	      "BW Reason enum < 2 byte. Consequences for cover_upd_res_t");
 
+extern u8 *format_fib_node_bw_reason(u8 *s, va_list *args);
+
 /**
  * Flags on the walk
  */
diff --git a/src/vnet/fib/fib_path.c b/src/vnet/fib/fib_path.c
index 4ec04f5b950..e37d47482db 100644
--- a/src/vnet/fib/fib_path.c
+++ b/src/vnet/fib/fib_path.c
@@ -409,22 +409,22 @@ static const char *fib_path_cfg_attribute_names[]  = FIB_PATH_CFG_ATTRIBUTES;
  */
 static fib_path_t *fib_path_pool;
 
+/**
+ * the logger
+ */
+vlib_log_class_t fib_path_logger;
+
 /*
  * Debug macro
  */
-#ifdef FIB_DEBUG
-#define FIB_PATH_DBG(_p, _fmt, _args...)			\
-{       		          				\
-    u8 *_tmp = NULL;						\
-    _tmp = fib_path_format(fib_path_get_index(_p), _tmp);	\
-    clib_warning("path:[%d:%U]:" _fmt,				\
-		 fib_path_get_index(_p), format_fib_path, _p, 0,\
-		 ##_args);					\
-    vec_free(_tmp);						\
+#define FIB_PATH_DBG(_p, _fmt, _args...)                                \
+{                                                                       \
+    vlib_log_debug (fib_path_logger,                                    \
+                    "[%U]: " _fmt,                                      \
+                    format_fib_path, fib_path_get_index(_p), 0,         \
+                    FIB_PATH_FORMAT_FLAGS_ONE_LINE,                     \
+                    ##_args);                                           \
 }
-#else
-#define FIB_PATH_DBG(_p, _fmt, _args...)
-#endif
 
 static fib_path_t *
 fib_path_get (fib_node_index_t index)
@@ -456,10 +456,21 @@ format_fib_path (u8 * s, va_list * args)
 {
     fib_node_index_t path_index = va_arg (*args, fib_node_index_t);
     u32 indent = va_arg (*args, u32);
+    fib_format_path_flags_t flags =  va_arg (*args, fib_format_path_flags_t);
     vnet_main_t * vnm = vnet_get_main();
     fib_path_oper_attribute_t oattr;
     fib_path_cfg_attribute_t cattr;
     fib_path_t *path;
+    const char *eol;
+
+    if (flags & FIB_PATH_FORMAT_FLAGS_ONE_LINE)
+    {
+        eol = "";
+    }
+    else
+    {
+        eol = "\n";
+    }
 
     path = fib_path_get(path_index);
 
@@ -486,7 +497,8 @@ format_fib_path (u8 * s, va_list * args)
 	    }
 	}
     }
-    s = format(s, "\n%U", format_white_space, indent+2);
+    if (!(flags & FIB_PATH_FORMAT_FLAGS_ONE_LINE))
+        s = format(s, "\n%U", format_white_space, indent+2);
 
     switch (path->fp_type)
     {
@@ -514,11 +526,11 @@ format_fib_path (u8 * s, va_list * args)
 	}
 	if (!dpo_id_is_valid(&path->fp_dpo))
 	{
-	    s = format(s, "\n%Uunresolved", format_white_space, indent+2);
+	    s = format(s, "%s%Uunresolved", eol, format_white_space, indent+2);
 	}
 	else
 	{
-	    s = format(s, "\n%U%U",
+	    s = format(s, "%s%U%U", eol,
 		       format_white_space, indent,
                        format_dpo_id,
 		       &path->fp_dpo, 13);
@@ -608,17 +620,6 @@ format_fib_path (u8 * s, va_list * args)
     return (s);
 }
 
-u8 *
-fib_path_format (fib_node_index_t pi, u8 *s)
-{
-    fib_path_t *path;
-
-    path = fib_path_get(pi);
-    ASSERT(NULL != path);
-
-    return (format (s, "%U", format_fib_path, path));
-}
-
 /*
  * fib_path_last_lock_gone
  *
@@ -966,6 +967,9 @@ fib_path_back_walk_notify (fib_node_t *node,
 
     path = fib_path_from_fib_node(node);
 
+    FIB_PATH_DBG(path, "bw:%U",
+                 format_fib_node_bw_reason, ctx->fnbw_reason);
+
     switch (path->fp_type)
     {
     case FIB_PATH_TYPE_RECURSIVE:
@@ -2311,8 +2315,6 @@ fib_path_contribute_forwarding (fib_node_index_t path_index,
     ASSERT(path);
     ASSERT(FIB_FORW_CHAIN_TYPE_MPLS_EOS != fct);
 
-    FIB_PATH_DBG(path, "contribute");
-
     /*
      * The DPO stored in the path was created when the path was resolved.
      * This then represents the path's 'native' protocol; IP.
@@ -2667,6 +2669,7 @@ void
 fib_path_module_init (void)
 {
     fib_node_register_type (FIB_NODE_TYPE_PATH, &fib_path_vft);
+    fib_path_logger = vlib_log_register_class ("fib", "path");
 }
 
 static clib_error_t *
@@ -2685,7 +2688,8 @@ show_fib_path_command (vlib_main_t * vm,
 	if (!pool_is_free_index(fib_path_pool, pi))
 	{
 	    path = fib_path_get(pi);
-	    u8 *s = format(NULL, "%U", format_fib_path, pi, 1);
+	    u8 *s = format(NULL, "%U", format_fib_path, pi, 1,
+                           FIB_PATH_FORMAT_FLAGS_NONE);
 	    s = format(s, "children:");
 	    s = fib_node_children_format(path->fp_node.fn_children, s);
 	    vlib_cli_output (vm, "%s", s);
@@ -2701,7 +2705,8 @@ show_fib_path_command (vlib_main_t * vm,
 	vlib_cli_output (vm, "FIB Paths");
 	pool_foreach_index (pi, fib_path_pool,
 	({
-	    vlib_cli_output (vm, "%U", format_fib_path, pi, 0);
+	    vlib_cli_output (vm, "%U", format_fib_path, pi, 0,
+                             FIB_PATH_FORMAT_FLAGS_NONE);
 	}));
     }
 
diff --git a/src/vnet/fib/fib_path.h b/src/vnet/fib/fib_path.h
index 28ec10a98d5..e162f4dad3a 100644
--- a/src/vnet/fib/fib_path.h
+++ b/src/vnet/fib/fib_path.h
@@ -127,6 +127,11 @@ typedef enum fib_path_cfg_flags_t_ {
     FIB_PATH_CFG_FLAG_DEAG_SRC = (1 << FIB_PATH_CFG_ATTRIBUTE_DEAG_SRC),
 } __attribute__ ((packed)) fib_path_cfg_flags_t;
 
+typedef enum fib_path_format_flags_t_
+{
+    FIB_PATH_FORMAT_FLAGS_NONE = 0,
+    FIB_PATH_FORMAT_FLAGS_ONE_LINE = (1 << 0),
+} fib_format_path_flags_t;
 
 extern u8 *format_fib_path(u8 *s, va_list *args);
 
diff --git a/src/vnet/fib/fib_path_list.c b/src/vnet/fib/fib_path_list.c
index d830eaa3667..4655c687427 100644
--- a/src/vnet/fib/fib_path_list.c
+++ b/src/vnet/fib/fib_path_list.c
@@ -82,24 +82,22 @@ static fib_path_list_t * fib_path_list_pool;
  */
 static uword *fib_path_list_db;
 
+/**
+ * the logger
+ */
+vlib_log_class_t fib_path_list_logger;
+
 /*
  * Debug macro
  */
-#ifdef FIB_DEBUG
-#define FIB_PATH_LIST_DBG(_pl, _fmt, _args...)		  \
-{   		            				  \
-    u8 *_tmp = 0;					  \
-    _tmp = fib_path_list_format(			  \
-	fib_path_list_get_index(_pl), _tmp);		  \
-    clib_warning("pl:[%d:%p:%p:%s]:" _fmt,		  \
-		 fib_path_list_get_index(_pl),		  \
-		 _pl, _pl->fpl_paths, _tmp,		  \
-		 ##_args);				  \
-    vec_free(_tmp);					  \
+#define FIB_PATH_LIST_DBG(_pl, _fmt, _args...)                  \
+{                                                               \
+    vlib_log_debug(fib_path_list_logger,                        \
+                   "[%U]:" _fmt,                                \
+                   format_fib_path_list,                        \
+                   fib_path_list_get_index(_pl), 0,             \
+                   ##_args);                                    \
 }
-#else
-#define FIB_PATH_LIST_DBG(_pl, _fmt, _args...)
-#endif
 
 static fib_path_list_t *
 fib_path_list_get (fib_node_index_t index)
@@ -158,7 +156,8 @@ format_fib_path_list (u8 * s, va_list * args)
 
     vec_foreach (path_index, path_list->fpl_paths)
     {
-	s = format(s, "%U", format_fib_path, *path_index, indent+2);
+	s = format(s, "%U", format_fib_path, *path_index, indent+2,
+                   FIB_PATH_FORMAT_FLAGS_NONE);
 	s = format(s, "\n");
     }
 
@@ -470,6 +469,9 @@ fib_path_list_back_walk (fib_node_index_t path_list_index,
 
     fib_path_list_mk_urpf(path_list);
 
+    FIB_PATH_LIST_DBG(path_list, "bw:%U",
+                      format_fib_node_bw_reason, ctx->fnbw_reason);
+
     /*
      * propagate the backwalk further
      */
@@ -839,7 +841,7 @@ fib_path_list_path_add (fib_node_index_t path_list_index,
     ASSERT(1 == vec_len(rpaths));
     ASSERT(!(path_list->fpl_flags & FIB_PATH_LIST_FLAG_SHARED));
 
-    FIB_PATH_LIST_DBG(orig_path_list, "path-add");
+    FIB_PATH_LIST_DBG(path_list, "path-add");
 
     new_path_index = fib_path_create(path_list_index,
                                      rpaths);
@@ -986,7 +988,7 @@ fib_path_list_path_remove (fib_node_index_t path_list_index,
     ASSERT(1 == vec_len(rpaths));
     ASSERT(!(path_list->fpl_flags & FIB_PATH_LIST_FLAG_SHARED));
 
-    FIB_PATH_LIST_DBG(orig_path_list, "path-remove");
+    FIB_PATH_LIST_DBG(path_list, "path-remove");
 
     /*
      * create a representation of the path to be removed, so it
@@ -1222,7 +1224,7 @@ fib_path_list_recursive_loop_detect (fib_node_index_t path_list_index,
         vec_free(copy);
     }
 
-    FIB_PATH_LIST_DBG(path_list, "loop-detect: eval:%d", eval);
+    FIB_PATH_LIST_DBG(path_list, "loop-detect: eval:%d", list_looped);
 
     if (list_looped)
     {
@@ -1294,7 +1296,6 @@ fib_path_list_lock(fib_node_index_t path_list_index)
 	path_list = fib_path_list_get(path_list_index);
 
 	fib_node_lock(&path_list->fpl_node);
-	FIB_PATH_LIST_DBG(path_list, "lock");
     }
 }
 
@@ -1306,7 +1307,6 @@ fib_path_list_unlock (fib_node_index_t path_list_index)
     if (FIB_NODE_INDEX_INVALID != path_list_index)
     {
 	path_list = fib_path_list_get(path_list_index);
-	FIB_PATH_LIST_DBG(path_list, "unlock");
     
 	fib_node_unlock(&path_list->fpl_node);
     }
@@ -1356,6 +1356,7 @@ fib_path_list_module_init (void)
     				     fib_path_list_db_hash_key_equal,
     				     /* format pair/arg */
     				     0, 0);
+    fib_path_list_logger = vlib_log_register_class("fib", "path-list");
 }
 
 static clib_error_t *
diff --git a/src/vnet/fib/fib_walk.c b/src/vnet/fib/fib_walk.c
index d0942401153..6a64d554f98 100644
--- a/src/vnet/fib/fib_walk.c
+++ b/src/vnet/fib/fib_walk.c
@@ -16,6 +16,8 @@
 #include <vnet/fib/fib_walk.h>
 #include <vnet/fib/fib_node_list.h>
 
+vlib_log_class_t fib_walk_logger;
+
 /**
  * The flags on a walk
  */
@@ -184,6 +186,17 @@ typedef struct fib_walk_history_t_ {
 } fib_walk_history_t;
 static fib_walk_history_t fib_walk_history[HISTORY_N_WALKS];
 
+static u8* format_fib_walk (u8* s, va_list *ap);
+
+#define FIB_WALK_DBG(_walk, _fmt, _args...)                     \
+{                                                               \
+    vlib_log_debug(fib_walk_logger,                             \
+                   "[%U]:" _fmt,                                \
+                   format_fib_walk,                             \
+                   fib_walk_get_index(_walk),                   \
+                   ##_args);                                    \
+}
+
 u8*
 format_fib_walk_priority (u8 *s, va_list *ap)
 {
@@ -714,6 +727,9 @@ fib_walk_async (fib_node_type_t parent_type,
 					       fib_walk_get_index(fwalk));
 
     fwalk->fw_prio_sibling = fib_walk_prio_queue_enquue(prio, fwalk);
+
+    FIB_WALK_DBG(fwalk, "async-start: %U",
+                 format_fib_node_bw_reason, ctx->fnbw_reason);
 }
 
 /**
@@ -759,6 +775,8 @@ fib_walk_sync (fib_node_type_t parent_type,
 					       FIB_NODE_TYPE_WALK,
 					       fib_walk_get_index(fwalk));
     fwi = fib_walk_get_index(fwalk);
+    FIB_WALK_DBG(fwalk, "sync-start: %U",
+                 format_fib_node_bw_reason, ctx->fnbw_reason);
 
     while (1)
     {
@@ -812,6 +830,10 @@ fib_walk_sync (fib_node_type_t parent_type,
 		 * continue with it now, but let the stack unwind and along the
 		 * appropriate frame to read the depth count and bail.
 		 */
+                FIB_WALK_DBG(fwalk, "sync-stop: %U",
+                             format_fib_node_bw_reason,
+                             ctx->fnbw_reason);
+
 		fwalk = NULL;
 		break;
 	    }
@@ -827,6 +849,9 @@ fib_walk_sync (fib_node_type_t parent_type,
 
     if (NULL != fwalk)
     {
+        FIB_WALK_DBG(fwalk, "sync-stop: %U",
+                     format_fib_node_bw_reason,
+                     ctx->fnbw_reason);
 	fib_walk_destroy(fwi);
     }
 }
@@ -924,6 +949,7 @@ fib_walk_module_init (void)
     }
 
     fib_node_register_type(FIB_NODE_TYPE_WALK, &fib_walk_vft);
+    fib_walk_logger = vlib_log_register_class("fib", "walk");
 }
 
 static u8*
@@ -934,13 +960,27 @@ format_fib_walk (u8* s, va_list *ap)
 
     fwalk = fib_walk_get(fwi);
 
-    return (format(s, "  parent:{%s:%d} visits:%d flags:%d",
+    return (format(s, "[@%d] parent:{%s:%d} visits:%d flags:%d", fwi,
 		   fib_node_type_get_name(fwalk->fw_parent.fnp_type),
 		   fwalk->fw_parent.fnp_index,
 		   fwalk->fw_n_visits,
 		   fwalk->fw_flags));
 }
 
+u8 *
+format_fib_node_bw_reason (u8 *s, va_list *args)
+{
+    fib_node_bw_reason_flag_t flag = va_arg (*args, int);
+    fib_node_back_walk_reason_t reason;
+
+    FOR_EACH_FIB_NODE_BW_REASON(reason) {
+        if ((1<<reason) & flag)
+            s = format(s, "%s", fib_node_bw_reason_names[reason]);
+    }
+
+    return (s);
+}
+
 static clib_error_t *
 fib_walk_show (vlib_main_t * vm,
 	       unformat_input_t * input,
@@ -1045,7 +1085,6 @@ fib_walk_show (vlib_main_t * vm,
     {
 	if (0 != fib_walk_history[ii].fwh_reason[0])
 	{
-            fib_node_back_walk_reason_t reason;
             u8 *s = NULL;
             u32 jj;
 
@@ -1064,11 +1103,8 @@ fib_walk_show (vlib_main_t * vm,
             jj = 0;
             while (0 != fib_walk_history[ii].fwh_reason[jj])
             {
-                FOR_EACH_FIB_NODE_BW_REASON(reason) {
-                    if ((1<<reason) & fib_walk_history[ii].fwh_reason[jj]) {
-                        s = format (s, "%s,", fib_node_bw_reason_names[reason]);
-                    }
-                }
+                s = format (s, "%U,", format_fib_node_bw_reason,
+                            fib_walk_history[ii].fwh_reason[jj]);
                 jj++;
             }
             vlib_cli_output(vm, "%v", s);