[ovs-dev] [PATCH 4/4] [RFC] ofproto-dpif: Make ofproto/trace output easier to read.

Ben Pfaff blp at ovn.org
Wed Dec 7 07:28:43 UTC 2016


"ovs-appctl ofproto/trace" is invaluable for debugging, but as the users of
Open vSwitch have evolved it has failed to keep up with the times.  It's
pretty easy to design OpenFlow tables and pipelines that resubmit dozens of
times.  Each resubmit causes an additional tab of indentation, so the
output wraps around, sometimes again and again, and makes the output close
to unreadable.

ovn-trace pioneered better formatting for tracing in OVN logical datapaths,
mostly by not increasing indentation for tail recursion, which in practice
gets rid of almost all indentation.

This commit experiments with redoing ofproto/trace the same way.  Try
looking at, for example, the testsuite output for test 2280 "ovn -- 3 HVs,
3 LRs connected via LS, source IP based routes".  Without this commit, it
indents 61 levels (488 spaces!).  With this commit, it indents 1 level
(4 spaces) and it's possible to actually understand what's going on almost
at a glance.

To see this for yourself, try the following command either with or without
this commit (but be sure to keep the change to ovn.at that adds an
ofproto/trace to the test):
make check TESTSUITEFLAGS='-d 2280' && less tests/testsuite.dir/2280/testsuite.log

Here's a to-do list before this can be applied:
- Add back support for showing megaflows and other information that
  ofproto/trace formerly had.
- Make all the unit tests pass (previous item ought to help since some
  tests use that info).
- Add some annotations to the output for showing what "set_field",
  "copy_field", etc. are actually doing to fields.
- Update sample output in the tutorial, etc. to show the new output
  format.
- Possibly, implemented shorter output formats (like ovn-trace).
- Possibly, document the output format.

Signed-off-by: Ben Pfaff <blp at ovn.org>
---
 ofproto/ofproto-dpif-trace.c | 263 +++++++++++++------------------------
 ofproto/ofproto-dpif-trace.h |  29 +++++
 ofproto/ofproto-dpif-xlate.c | 300 +++++++++++++++++++++++++++----------------
 ofproto/ofproto-dpif-xlate.h |  25 +---
 tests/ovn.at                 |   2 +-
 5 files changed, 313 insertions(+), 306 deletions(-)

diff --git a/ofproto/ofproto-dpif-trace.c b/ofproto/ofproto-dpif-trace.c
index 52c1758..4e6293c 100644
--- a/ofproto/ofproto-dpif-trace.c
+++ b/ofproto/ofproto-dpif-trace.c
@@ -23,165 +23,72 @@
 #include "openvswitch/ofp-parse.h"
 #include "unixctl.h"
 
-struct trace_ctx {
-    struct xlate_out xout;
-    struct xlate_in xin;
-    const struct flow *key;
-    struct flow flow;
-    struct ds *result;
-    struct flow_wildcards wc;
-    struct ofpbuf odp_actions;
-};
-
 static void ofproto_trace(struct ofproto_dpif *, struct flow *,
                           const struct dp_packet *packet,
                           const struct ofpact[], size_t ofpacts_len,
                           struct ds *);
 
-static void
-trace_format_rule(struct ofproto *ofproto, struct ds *result, int level,
-                  const struct rule_dpif *rule)
-{
-    const struct rule_actions *actions;
-    ovs_be64 cookie;
-
-    ds_put_char_multiple(result, '\t', level);
-    if (!rule) {
-        ds_put_cstr(result, "No match\n");
-        return;
-    }
-
-    ovs_mutex_lock(&rule->up.mutex);
-    cookie = rule->up.flow_cookie;
-    ovs_mutex_unlock(&rule->up.mutex);
-
-    ds_put_format(result, "Rule: table=%"PRIu8" cookie=%#"PRIx64" ",
-                  rule ? rule->up.table_id : 0, ntohll(cookie));
-    cls_rule_format(&rule->up.cr, ofproto_get_tun_tab(ofproto), result);
-    ds_put_char(result, '\n');
-
-    actions = rule_get_actions(&rule->up);
-
-    ds_put_char_multiple(result, '\t', level);
-    ds_put_cstr(result, "OpenFlow actions=");
-    ofpacts_format(actions->ofpacts, actions->ofpacts_len, result);
-    ds_put_char(result, '\n');
-}
-
-static void
-trace_format_flow(struct ds *result, int level, const char *title,
-                  struct trace_ctx *trace)
+struct oftrace_node *
+oftrace_report(struct ovs_list *super, enum oftrace_node_type type,
+               const char *text)
 {
-    ds_put_char_multiple(result, '\t', level);
-    ds_put_format(result, "%s: ", title);
-    /* Do not report unchanged flows for resubmits. */
-    if ((level > 0 && flow_equal(&trace->xin.flow, &trace->flow))
-        || (level == 0 && flow_equal(&trace->xin.flow, trace->key))) {
-        ds_put_cstr(result, "unchanged");
-    } else {
-        flow_format(result, &trace->xin.flow);
-        trace->flow = trace->xin.flow;
-    }
-    ds_put_char(result, '\n');
+    struct oftrace_node *node = xmalloc(sizeof *node);
+    ovs_list_push_back(super, &node->node);
+    node->type = type;
+    node->name = xstrdup(text);
+    node->always_indent = false;
+    ovs_list_init(&node->subs);
+
+    return node;
 }
 
-static void
-trace_format_regs(struct ds *result, int level, const char *title,
-                  struct trace_ctx *trace)
+static bool
+oftrace_node_type_is_terminal(enum oftrace_node_type type)
 {
-    size_t i;
-
-    ds_put_char_multiple(result, '\t', level);
-    ds_put_format(result, "%s:", title);
-    for (i = 0; i < FLOW_N_REGS; i++) {
-        ds_put_format(result, " reg%"PRIuSIZE"=0x%"PRIx32, i, trace->flow.regs[i]);
+    switch (type) {
+    case OFT_OUTPUT:
+    case OFT_MODIFY:
+    case OFT_ACTION:
+    case OFT_WARN:
+    case OFT_ERROR:
+        return true;
+
+    case OFT_BRIDGE:
+    case OFT_TABLE:
+    case OFT_THAW:
+    case OFT_TRANSFORMATION:
+        return false;
     }
-    ds_put_char(result, '\n');
-}
 
-static void
-trace_format_odp(struct ds *result, int level, const char *title,
-                 struct trace_ctx *trace)
-{
-    struct ofpbuf *odp_actions = &trace->odp_actions;
-
-    ds_put_char_multiple(result, '\t', level);
-    ds_put_format(result, "%s: ", title);
-    format_odp_actions(result, odp_actions->data, odp_actions->size);
-    ds_put_char(result, '\n');
+    OVS_NOT_REACHED();
 }
 
 static void
-trace_format_megaflow(struct ds *result, int level, const char *title,
-                      struct trace_ctx *trace)
+oftrace_node_print_details(struct ds *output,
+                            const struct ovs_list *nodes, int level)
 {
-    struct match match;
-
-    ds_put_char_multiple(result, '\t', level);
-    ds_put_format(result, "%s: ", title);
-    match_init(&match, trace->key, &trace->wc);
-    match_format(&match, result, OFP_DEFAULT_PRIORITY);
-    ds_put_char(result, '\n');
-}
-
-static void trace_report(struct xlate_in *, int indentation,
-                         const char *format, ...)
-    OVS_PRINTF_FORMAT(3, 4);
-static void trace_report_valist(struct xlate_in *, int indentation,
-                                const char *format, va_list args)
-    OVS_PRINTF_FORMAT(3, 0);
+    const struct oftrace_node *sub;
+    LIST_FOR_EACH (sub, node, nodes) {
+        if (sub->type == OFT_MODIFY) {
+            continue;
+        }
 
-static void
-trace_resubmit(struct xlate_in *xin, struct rule_dpif *rule, int indentation)
-{
-    struct trace_ctx *trace = CONTAINER_OF(xin, struct trace_ctx, xin);
-    struct ds *result = trace->result;
-
-    if (!indentation) {
-        if (rule == xin->ofproto->miss_rule) {
-            trace_report(xin, indentation,
-                         "No match, flow generates \"packet in\"s.");
-        } else if (rule == xin->ofproto->no_packet_in_rule) {
-            trace_report(xin, indentation, "No match, packets dropped because "
-                         "OFPPC_NO_PACKET_IN is set on in_port.");
-        } else if (rule == xin->ofproto->drop_frags_rule) {
-            trace_report(xin, indentation,
-                         "Packets dropped because they are IP fragments and "
-                         "the fragment handling mode is \"drop\".");
+        bool more = sub->node.next != nodes || sub->always_indent || oftrace_node_type_is_terminal(sub->type);
+        bool title = (sub->type == OFT_BRIDGE ||
+                      sub->type == OFT_TRANSFORMATION);
+        if (title) {
+            ds_put_char(output, '\n');
+        }
+        ds_put_char_multiple(output, ' ', (level + more) * 4);
+        ds_put_format(output, "%s\n", sub->name);
+        if (title) {
+            ds_put_char_multiple(output, ' ', (level + more) * 4);
+            ds_put_char_multiple(output, '-', strlen(sub->name));
+            ds_put_char(output, '\n');
         }
-    }
 
-    ds_put_char(result, '\n');
-    if (indentation) {
-        trace_format_flow(result, indentation, "Resubmitted flow", trace);
-        trace_format_regs(result, indentation, "Resubmitted regs", trace);
-        trace_format_odp(result,  indentation, "Resubmitted  odp", trace);
-        trace_format_megaflow(result, indentation, "Resubmitted megaflow",
-                              trace);
+        oftrace_node_print_details(output, &sub->subs, level + more + more);
     }
-    trace_format_rule(&xin->ofproto->up, result, indentation, rule);
-}
-
-static void
-trace_report_valist(struct xlate_in *xin, int indentation,
-                    const char *format, va_list args)
-{
-    struct trace_ctx *trace = CONTAINER_OF(xin, struct trace_ctx, xin);
-    struct ds *result = trace->result;
-
-    ds_put_char_multiple(result, '\t', indentation);
-    ds_put_format_valist(result, format, args);
-    ds_put_char(result, '\n');
-}
-
-static void
-trace_report(struct xlate_in *xin, int indentation, const char *format, ...)
-{
-    va_list args;
-
-    va_start(args, format);
-    trace_report_valist(xin, indentation, format, args);
-    va_end(args);
 }
 
 /* Parses the 'argc' elements of 'argv', ignoring argv[0].  The following
@@ -466,7 +373,7 @@ exit:
 }
 
 /* Implements a "trace" through 'ofproto''s flow table, appending a textual
- * description of the results to 'ds'.
+ * description of the results to 'output'.
  *
  * The trace follows a packet with the specified 'flow' through the flow
  * table.  'packet' may be nonnull to trace an actual packet, with consequent
@@ -478,61 +385,71 @@ static void
 ofproto_trace(struct ofproto_dpif *ofproto, struct flow *flow,
               const struct dp_packet *packet,
               const struct ofpact ofpacts[], size_t ofpacts_len,
-              struct ds *ds)
+              struct ds *output)
 {
-    struct trace_ctx trace;
-    enum xlate_error error;
-
-    ds_put_format(ds, "Bridge: %s\n", ofproto->up.name);
-    ds_put_cstr(ds, "Flow: ");
-    flow_format(ds, flow);
-    ds_put_char(ds, '\n');
+    ds_put_cstr(output, "Flow: ");
+    flow_format(output, flow);
+    ds_put_char(output, '\n');
 
-    ofpbuf_init(&trace.odp_actions, 0);
+    struct ofpbuf odp_actions;
+    ofpbuf_init(&odp_actions, 0);
 
-    trace.result = ds;
-    trace.key = flow; /* Original flow key, used for megaflow. */
-    trace.flow = *flow; /* May be modified by actions. */
-    xlate_in_init(&trace.xin, ofproto,
+    struct xlate_in xin;
+    struct flow_wildcards wc;
+    struct ovs_list trace = OVS_LIST_INITIALIZER(&trace);
+    xlate_in_init(&xin, ofproto,
                   ofproto_dpif_get_tables_version(ofproto), flow,
                   flow->in_port.ofp_port, NULL, ntohs(flow->tcp_flags),
-                  packet, &trace.wc, &trace.odp_actions);
-    trace.xin.ofpacts = ofpacts;
-    trace.xin.ofpacts_len = ofpacts_len;
-    trace.xin.resubmit_hook = trace_resubmit;
-    trace.xin.report_hook = trace_report_valist;
+                  packet, &wc, &odp_actions);
+    xin.ofpacts = ofpacts;
+    xin.ofpacts_len = ofpacts_len;
+    xin.trace = &trace;
 
-    error = xlate_actions(&trace.xin, &trace.xout);
-    ds_put_char(ds, '\n');
-    trace.xin.flow.actset_output = 0;
-    trace_format_flow(ds, 0, "Final flow", &trace);
-    trace_format_megaflow(ds, 0, "Megaflow", &trace);
+    struct xlate_out xout;
+    enum xlate_error error = xlate_actions(&xin, &xout);
+
+    oftrace_node_print_details(output, &trace, 0);
+
+    ds_put_cstr(output, "Final flow: ");
+    if (flow_equal(flow, &xin.flow)) {
+        ds_put_cstr(output, "unchanged");
+    } else {
+        flow_format(output, &xin.flow);
+    }
+    ds_put_char(output, '\n');
+
+    ds_put_cstr(output, "Megaflow: ");
+    struct match match;
+    match_init(&match, flow, &wc);
+    match_format(&match, output, OFP_DEFAULT_PRIORITY);
+    ds_put_char(output, '\n');
 
-    ds_put_cstr(ds, "Datapath actions: ");
-    format_odp_actions(ds, trace.odp_actions.data, trace.odp_actions.size);
+    ds_put_cstr(output, "Datapath actions: ");
+    format_odp_actions(output, odp_actions.data, odp_actions.size);
 
     if (error != XLATE_OK) {
-        ds_put_format(ds, "\nTranslation failed (%s), packet is dropped.\n",
+        ds_put_format(output,
+                      "\nTranslation failed (%s), packet is dropped.\n",
                       xlate_strerror(error));
-    } else if (trace.xout.slow) {
+    } else if (xout.slow) {
         enum slow_path_reason slow;
 
-        ds_put_cstr(ds, "\nThis flow is handled by the userspace "
+        ds_put_cstr(output, "\nThis flow is handled by the userspace "
                     "slow path because it:");
 
-        slow = trace.xout.slow;
+        slow = xout.slow;
         while (slow) {
             enum slow_path_reason bit = rightmost_1bit(slow);
 
-            ds_put_format(ds, "\n\t- %s.",
+            ds_put_format(output, "\n\t- %s.",
                           slow_path_reason_to_explanation(bit));
 
             slow &= ~bit;
         }
     }
 
-    xlate_out_uninit(&trace.xout);
-    ofpbuf_uninit(&trace.odp_actions);
+    xlate_out_uninit(&xout);
+    ofpbuf_uninit(&odp_actions);
 }
 
 void
diff --git a/ofproto/ofproto-dpif-trace.h b/ofproto/ofproto-dpif-trace.h
index 06d63f8..f863eeb 100644
--- a/ofproto/ofproto-dpif-trace.h
+++ b/ofproto/ofproto-dpif-trace.h
@@ -15,6 +15,35 @@
 #ifndef OFPROTO_DPIF_TRACE_H
 #define OFPROTO_DPIF_TRACE_H 1
 
+#include "openvswitch/compiler.h"
+#include "openvswitch/list.h"
+
+enum oftrace_node_type {
+    OFT_BRIDGE,                 /* Packet travel through an OpenFlow switch. */
+    OFT_TABLE,                  /* Packet travel through a flow table. */
+    OFT_THAW,                   /* Thawing a frozen state. */
+
+    OFT_ACTION,                 /* Something that an action does. */
+    OFT_WARN,                   /* A worrisome situation. */
+    OFT_ERROR,                  /* An erroneous situation, worth logging. */
+
+    OFT_OUTPUT,
+    OFT_MODIFY,
+    OFT_TRANSFORMATION
+};
+
+struct oftrace_node {
+    struct ovs_list node;       /* In parent. */
+
+    enum oftrace_node_type type;
+    const char *name;
+    bool always_indent;
+    struct ovs_list subs;       /* List of "struct oftrace_node" children. */
+};
+
 void ofproto_dpif_trace_init(void);
 
+struct oftrace_node *oftrace_report(struct ovs_list *, enum oftrace_node_type,
+                                    const char *text);
+
 #endif /* ofproto-dpif-trace.h */
diff --git a/ofproto/ofproto-dpif-xlate.c b/ofproto/ofproto-dpif-xlate.c
index 6d508c2..2a5cee3 100644
--- a/ofproto/ofproto-dpif-xlate.c
+++ b/ofproto/ofproto-dpif-xlate.c
@@ -46,6 +46,7 @@
 #include "ofproto/ofproto-dpif-mirror.h"
 #include "ofproto/ofproto-dpif-monitor.h"
 #include "ofproto/ofproto-dpif-sflow.h"
+#include "ofproto/ofproto-dpif-trace.h"
 #include "ofproto/ofproto-dpif-xlate-cache.h"
 #include "ofproto/ofproto-dpif.h"
 #include "ofproto/ofproto-provider.h"
@@ -483,8 +484,6 @@ static bool may_receive(const struct xport *, struct xlate_ctx *);
 static void do_xlate_actions(const struct ofpact *, size_t ofpacts_len,
                              struct xlate_ctx *);
 static void xlate_normal(struct xlate_ctx *);
-static inline void xlate_report(struct xlate_ctx *, const char *, ...)
-    OVS_PRINTF_FORMAT(2, 3);
 static void xlate_table_action(struct xlate_ctx *, ofp_port_t in_port,
                                uint8_t table_id, bool may_packet_in,
                                bool honor_table_miss);
@@ -552,45 +551,87 @@ static void xlate_xport_copy(struct xbridge *, struct xbundle *,
                              struct xport *);
 static void xlate_xcfg_free(struct xlate_cfg *);
 
-static inline void
-xlate_report(struct xlate_ctx *ctx, const char *format, ...)
+static struct ovs_list * OVS_PRINTF_FORMAT(3, 4)
+xlate_report(struct xlate_ctx *ctx, enum oftrace_node_type type,
+             const char *format, ...)
 {
-    if (OVS_UNLIKELY(ctx->xin->report_hook)) {
+    struct ovs_list *subtrace = NULL;
+    if (OVS_UNLIKELY(ctx->xin->trace)) {
         va_list args;
-
         va_start(args, format);
-        ctx->xin->report_hook(ctx->xin, ctx->indentation, format, args);
+        char *text = xvasprintf(format, args);
+        subtrace = &oftrace_report(ctx->xin->trace, type, text)->subs;
         va_end(args);
     }
+    return subtrace;
 }
 
-static struct vlog_rate_limit error_report_rl = VLOG_RATE_LIMIT_INIT(1, 5);
+/* This is like xlate_report() for errors that are serious enough that we
+ * should log them even if we are not tracing. */
+static void OVS_PRINTF_FORMAT(2, 3)
+xlate_report_error(struct xlate_ctx *ctx, const char *format, ...)
+{
+    static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
+    if (!OVS_UNLIKELY(ctx->xin->trace) && VLOG_DROP_ERR(&rl)) {
+        return;
+    }
 
-#define XLATE_REPORT_ERROR(CTX, ...)                            \
-    do {                                                        \
-        if (OVS_UNLIKELY((CTX)->xin->report_hook)) {            \
-            xlate_report(CTX, __VA_ARGS__);                     \
-        } else {                                                \
-            struct ds ds = DS_EMPTY_INITIALIZER;                \
-                                                                \
-            ds_put_format(&ds, __VA_ARGS__);                    \
-            ds_put_cstr(&ds, ": ");                             \
-            flow_format(&ds, &(CTX)->base_flow);                \
-            VLOG_ERR_RL(&error_report_rl, "%s", ds_cstr(&ds));  \
-            ds_destroy(&ds);                                    \
-        }                                                       \
-    } while (0)
+    struct ds s = DS_EMPTY_INITIALIZER;
+    va_list args;
+    va_start(args, format);
+    ds_put_format_valist(&s, format, args);
+    va_end(args);
+
+    if (OVS_UNLIKELY(ctx->xin->trace)) {
+        oftrace_report(ctx->xin->trace, OFT_ERROR, ds_cstr(&s));
+    } else {
+        ds_put_cstr(&s, ": ");
+        flow_format(&s, &ctx->base_flow);
+        VLOG_ERR("%s", ds_cstr(&s));
+    }
+    ds_destroy(&s);
+}
 
-static inline void
-xlate_report_actions(struct xlate_ctx *ctx, const char *title,
+static struct ovs_list *
+xlate_report_actions(struct xlate_ctx *ctx, enum oftrace_node_type type,
+                     const char *title,
                      const struct ofpact *ofpacts, size_t ofpacts_len)
 {
-    if (OVS_UNLIKELY(ctx->xin->report_hook)) {
+    struct ovs_list *subtrace = NULL;
+    if (OVS_UNLIKELY(ctx->xin->trace)) {
         struct ds s = DS_EMPTY_INITIALIZER;
+        ds_put_format(&s, "%s: ", title);
         ofpacts_format(ofpacts, ofpacts_len, &s);
-        xlate_report(ctx, "%s: %s", title, ds_cstr(&s));
+        subtrace = &oftrace_report(ctx->xin->trace, type, ds_cstr(&s))->subs;
         ds_destroy(&s);
     }
+    return subtrace;
+}
+
+static void
+xlate_report_table(struct xlate_ctx *ctx, struct rule_dpif *rule,
+                   uint8_t table_id)
+{
+    if (OVS_LIKELY(!ctx->xin->trace)) {
+        return;
+    }
+
+    struct ds s = DS_EMPTY_INITIALIZER;
+    ds_put_format(&s, "%2d. ", table_id);
+    minimatch_format(&rule->up.cr.match,
+                     ofproto_get_tun_tab(&ctx->xin->ofproto->up),
+                     &s, OFP_DEFAULT_PRIORITY);
+    if (ds_last(&s) != ' ') {
+        ds_put_cstr(&s, ", ");
+    }
+    ds_put_format(&s, "priority %d", rule->up.cr.priority);
+    if (rule->up.flow_cookie) {
+        ds_put_format(&s, ", cookie %#"PRIx64,
+                      ntohll(rule->up.flow_cookie));
+    }
+    ctx->xin->trace = &oftrace_report(ctx->xin->trace, OFT_TABLE,
+                                      ds_cstr(&s))->subs;
+    ds_destroy(&s);
 }
 
 static void
@@ -1946,7 +1987,8 @@ is_admissible(struct xlate_ctx *ctx, struct xport *in_port,
     /* Drop frames for reserved multicast addresses
      * only if forward_bpdu option is absent. */
     if (!xbridge->forward_bpdu && eth_addr_is_reserved(flow->dl_dst)) {
-        xlate_report(ctx, "packet has reserved destination MAC, dropping");
+        xlate_report(ctx, OFT_ACTION,
+                     "packet has reserved destination MAC, dropping");
         return false;
     }
 
@@ -1959,7 +2001,8 @@ is_admissible(struct xlate_ctx *ctx, struct xport *in_port,
             break;
 
         case BV_DROP:
-            xlate_report(ctx, "bonding refused admissibility, dropping");
+            xlate_report(ctx, OFT_ACTION,
+                         "bonding refused admissibility, dropping");
             return false;
 
         case BV_DROP_IF_MOVED:
@@ -1970,7 +2013,8 @@ is_admissible(struct xlate_ctx *ctx, struct xport *in_port,
                 && (!is_gratuitous_arp(flow, ctx->wc)
                     || mac_entry_is_grat_arp_locked(mac))) {
                 ovs_rwlock_unlock(&xbridge->ml->rwlock);
-                xlate_report(ctx, "SLB bond thinks this packet looped back, "
+                xlate_report(ctx, OFT_ACTION,
+                             "SLB bond thinks this packet looped back, "
                              "dropping");
                 return false;
             }
@@ -2144,12 +2188,14 @@ xlate_normal_mcast_send_group(struct xlate_ctx *ctx,
     LIST_FOR_EACH(b, bundle_node, &grp->bundle_lru) {
         mcast_xbundle = xbundle_lookup(xcfg, b->port);
         if (mcast_xbundle && mcast_xbundle != in_xbundle) {
-            xlate_report(ctx, "forwarding to mcast group port");
+            xlate_report(ctx, OFT_ACTION, "forwarding to mcast group port");
             output_normal(ctx, mcast_xbundle, vlan);
         } else if (!mcast_xbundle) {
-            xlate_report(ctx, "mcast group port is unknown, dropping");
+            xlate_report(ctx, OFT_WARN,
+                         "mcast group port is unknown, dropping");
         } else {
-            xlate_report(ctx, "mcast group port is input port, dropping");
+            xlate_report(ctx, OFT_ACTION,
+                         "mcast group port is input port, dropping");
         }
     }
 }
@@ -2170,14 +2216,17 @@ xlate_normal_mcast_send_mrouters(struct xlate_ctx *ctx,
         mcast_xbundle = xbundle_lookup(xcfg, mrouter->port);
         if (mcast_xbundle && mcast_xbundle != in_xbundle
             && mrouter->vlan == vlan) {
-            xlate_report(ctx, "forwarding to mcast router port");
+            xlate_report(ctx, OFT_ACTION, "forwarding to mcast router port");
             output_normal(ctx, mcast_xbundle, vlan);
         } else if (!mcast_xbundle) {
-            xlate_report(ctx, "mcast router port is unknown, dropping");
+            xlate_report(ctx, OFT_WARN,
+                         "mcast router port is unknown, dropping");
         } else if (mrouter->vlan != vlan) {
-            xlate_report(ctx, "mcast router is on another vlan, dropping");
+            xlate_report(ctx, OFT_ACTION,
+                         "mcast router is on another vlan, dropping");
         } else {
-            xlate_report(ctx, "mcast router port is input port, dropping");
+            xlate_report(ctx, OFT_ACTION,
+                         "mcast router port is input port, dropping");
         }
     }
 }
@@ -2197,12 +2246,14 @@ xlate_normal_mcast_send_fports(struct xlate_ctx *ctx,
     LIST_FOR_EACH(fport, node, &ms->fport_list) {
         mcast_xbundle = xbundle_lookup(xcfg, fport->port);
         if (mcast_xbundle && mcast_xbundle != in_xbundle) {
-            xlate_report(ctx, "forwarding to mcast flood port");
+            xlate_report(ctx, OFT_ACTION, "forwarding to mcast flood port");
             output_normal(ctx, mcast_xbundle, vlan);
         } else if (!mcast_xbundle) {
-            xlate_report(ctx, "mcast flood port is unknown, dropping");
+            xlate_report(ctx, OFT_WARN,
+                         "mcast flood port is unknown, dropping");
         } else {
-            xlate_report(ctx, "mcast flood port is input port, dropping");
+            xlate_report(ctx, OFT_ACTION,
+                         "mcast flood port is input port, dropping");
         }
     }
 }
@@ -2222,12 +2273,15 @@ xlate_normal_mcast_send_rports(struct xlate_ctx *ctx,
     LIST_FOR_EACH(rport, node, &ms->rport_list) {
         mcast_xbundle = xbundle_lookup(xcfg, rport->port);
         if (mcast_xbundle && mcast_xbundle != in_xbundle) {
-            xlate_report(ctx, "forwarding Report to mcast flagged port");
+            xlate_report(ctx, OFT_ACTION,
+                         "forwarding report to mcast flagged port");
             output_normal(ctx, mcast_xbundle, vlan);
         } else if (!mcast_xbundle) {
-            xlate_report(ctx, "mcast port is unknown, dropping the Report");
+            xlate_report(ctx, OFT_WARN,
+                         "mcast port is unknown, dropping the report");
         } else {
-            xlate_report(ctx, "mcast port is input port, dropping the Report");
+            xlate_report(ctx, OFT_ACTION,
+                         "mcast port is input port, dropping the Report");
         }
     }
 }
@@ -2282,7 +2336,7 @@ xlate_normal(struct xlate_ctx *ctx)
     in_xbundle = lookup_input_bundle(ctx->xbridge, flow->in_port.ofp_port,
                                      ctx->xin->packet != NULL, &in_port);
     if (!in_xbundle) {
-        xlate_report(ctx, "no input bundle, dropping");
+        xlate_report(ctx, OFT_WARN, "no input bundle, dropping");
         return;
     }
 
@@ -2295,7 +2349,7 @@ xlate_normal(struct xlate_ctx *ctx)
                          "VLAN tag received on port %s",
                          ctx->xbridge->name, in_xbundle->name);
         }
-        xlate_report(ctx, "partial VLAN tag, dropping");
+        xlate_report(ctx, OFT_WARN, "partial VLAN tag, dropping");
         return;
     }
 
@@ -2307,14 +2361,16 @@ xlate_normal(struct xlate_ctx *ctx)
                          "%s, which is reserved exclusively for mirroring",
                          ctx->xbridge->name, in_xbundle->name);
         }
-        xlate_report(ctx, "input port is mirror output port, dropping");
+        xlate_report(ctx, OFT_WARN,
+                     "input port is mirror output port, dropping");
         return;
     }
 
     /* Check VLAN. */
     vid = vlan_tci_to_vid(flow->vlan_tci);
     if (!input_vid_is_valid(vid, in_xbundle, ctx->xin->packet != NULL)) {
-        xlate_report(ctx, "disallowed VLAN VID for this input port, dropping");
+        xlate_report(ctx, OFT_WARN,
+                     "disallowed VLAN VID for this input port, dropping");
         return;
     }
     vlan = input_vid_to_vlan(in_xbundle, vid);
@@ -2380,7 +2436,7 @@ xlate_normal(struct xlate_ctx *ctx)
                 xlate_normal_mcast_send_rports(ctx, ms, in_xbundle, vlan);
                 ovs_rwlock_unlock(&ms->rwlock);
             } else {
-                xlate_report(ctx, "multicast traffic, flooding");
+                xlate_report(ctx, OFT_ACTION, "multicast traffic, flooding");
                 xlate_normal_flood(ctx, in_xbundle, vlan);
             }
             return;
@@ -2396,7 +2452,7 @@ xlate_normal(struct xlate_ctx *ctx)
                 xlate_normal_mcast_send_rports(ctx, ms, in_xbundle, vlan);
                 ovs_rwlock_unlock(&ms->rwlock);
             } else {
-                xlate_report(ctx, "MLD query, flooding");
+                xlate_report(ctx, OFT_ACTION, "MLD query, flooding");
                 xlate_normal_flood(ctx, in_xbundle, vlan);
             }
         } else {
@@ -2404,7 +2460,8 @@ xlate_normal(struct xlate_ctx *ctx)
                 /* RFC4541: section 2.1.2, item 2: Packets with a dst IP
                  * address in the 224.0.0.x range which are not IGMP must
                  * be forwarded on all ports */
-                xlate_report(ctx, "RFC4541: section 2.1.2, item 2, flooding");
+                xlate_report(ctx, OFT_ACTION,
+                             "RFC4541: section 2.1.2, item 2, flooding");
                 xlate_normal_flood(ctx, in_xbundle, vlan);
                 return;
             }
@@ -2423,7 +2480,8 @@ xlate_normal(struct xlate_ctx *ctx)
             xlate_normal_mcast_send_mrouters(ctx, ms, in_xbundle, vlan);
         } else {
             if (mcast_snooping_flood_unreg(ms)) {
-                xlate_report(ctx, "unregistered multicast, flooding");
+                xlate_report(ctx, OFT_ACTION,
+                             "unregistered multicast, flooding");
                 xlate_normal_flood(ctx, in_xbundle, vlan);
             } else {
                 xlate_normal_mcast_send_mrouters(ctx, ms, in_xbundle, vlan);
@@ -2441,15 +2499,18 @@ xlate_normal(struct xlate_ctx *ctx)
             struct xlate_cfg *xcfg = ovsrcu_get(struct xlate_cfg *, &xcfgp);
             struct xbundle *mac_xbundle = xbundle_lookup(xcfg, mac_port);
             if (mac_xbundle && mac_xbundle != in_xbundle) {
-                xlate_report(ctx, "forwarding to learned port");
+                xlate_report(ctx, OFT_ACTION, "forwarding to learned port");
                 output_normal(ctx, mac_xbundle, vlan);
             } else if (!mac_xbundle) {
-                xlate_report(ctx, "learned port is unknown, dropping");
+                xlate_report(ctx, OFT_WARN,
+                             "learned port is unknown, dropping");
             } else {
-                xlate_report(ctx, "learned port is input port, dropping");
+                xlate_report(ctx, OFT_ACTION,
+                             "learned port is input port, dropping");
             }
         } else {
-            xlate_report(ctx, "no learned MAC for destination, flooding");
+            xlate_report(ctx, OFT_ACTION,
+                         "no learned MAC for destination, flooding");
             xlate_normal_flood(ctx, in_xbundle, vlan);
         }
     }
@@ -2767,18 +2828,19 @@ build_tunnel_send(struct xlate_ctx *ctx, const struct xport *xport,
 
     err = tnl_route_lookup_flow(flow, &d_ip6, &s_ip6, &out_dev);
     if (err) {
-        xlate_report(ctx, "native tunnel routing failed");
+        xlate_report(ctx, OFT_WARN, "native tunnel routing failed");
         return err;
     }
 
-    xlate_report(ctx, "tunneling to %s via %s",
+    xlate_report(ctx, OFT_ACTION, "tunneling to %s via %s",
                  ipv6_string_mapped(buf_dip6, &d_ip6),
                  netdev_get_name(out_dev->netdev));
 
     /* Use mac addr of bridge port of the peer. */
     err = netdev_get_etheraddr(out_dev->netdev, &smac);
     if (err) {
-        xlate_report(ctx, "tunnel output device lacks Ethernet address");
+        xlate_report(ctx, OFT_WARN,
+                     "tunnel output device lacks Ethernet address");
         return err;
     }
 
@@ -2789,7 +2851,8 @@ build_tunnel_send(struct xlate_ctx *ctx, const struct xport *xport,
 
     err = tnl_neigh_lookup(out_dev->xbridge->name, &d_ip6, &dmac);
     if (err) {
-        xlate_report(ctx, "neighbor cache miss for %s on bridge %s, "
+        xlate_report(ctx, OFT_ACTION,
+                     "neighbor cache miss for %s on bridge %s, "
                      "sending %s request",
                      buf_dip6, out_dev->xbridge->name, d_ip ? "ARP" : "ND");
         if (d_ip) {
@@ -2809,7 +2872,7 @@ build_tunnel_send(struct xlate_ctx *ctx, const struct xport *xport,
         entry->tnl_neigh_cache.d_ipv6 = d_ip6;
     }
 
-    xlate_report(ctx, "tunneling from "ETH_ADDR_FMT" %s"
+    xlate_report(ctx, OFT_ACTION, "tunneling from "ETH_ADDR_FMT" %s"
                  " to "ETH_ADDR_FMT" %s",
                  ETH_ADDR_ARGS(smac), ipv6_string_mapped(buf_sip6, &s_ip6),
                  ETH_ADDR_ARGS(dmac), buf_dip6);
@@ -2881,38 +2944,42 @@ compose_output_action__(struct xlate_ctx *ctx, ofp_port_t ofp_port,
     memset(&flow_tnl, 0, sizeof flow_tnl);
 
     if (!xport) {
-        xlate_report(ctx, "Nonexistent output port");
+        xlate_report(ctx, OFT_WARN, "Nonexistent output port");
         return;
     } else if (xport->config & OFPUTIL_PC_NO_FWD) {
-        xlate_report(ctx, "OFPPC_NO_FWD set, skipping output");
+        xlate_report(ctx, OFT_ACTION, "OFPPC_NO_FWD set, skipping output");
         return;
     } else if (ctx->mirror_snaplen != 0 && xport->odp_port == ODPP_NONE) {
-        xlate_report(ctx, "Mirror truncate to ODPP_NONE, skipping output");
+        xlate_report(ctx, OFT_WARN,
+                     "Mirror truncate to ODPP_NONE, skipping output");
         return;
     } else if (xlate_flow_is_protected(ctx, flow, xport)) {
-        xlate_report(ctx, "Flow is between protected ports, skipping output.");
+        xlate_report(ctx, OFT_WARN,
+                     "Flow is between protected ports, skipping output.");
         return;
     } else if (check_stp) {
         if (is_stp(&ctx->base_flow)) {
             if (!xport_stp_should_forward_bpdu(xport) &&
                 !xport_rstp_should_manage_bpdu(xport)) {
                 if (ctx->xbridge->stp != NULL) {
-                    xlate_report(ctx, "STP not in listening state, "
-                            "skipping bpdu output");
+                    xlate_report(ctx, OFT_WARN,
+                                 "STP not in listening state, "
+                                 "skipping bpdu output");
                 } else if (ctx->xbridge->rstp != NULL) {
-                    xlate_report(ctx, "RSTP not managing BPDU in this state, "
-                            "skipping bpdu output");
+                    xlate_report(ctx, OFT_WARN,
+                                 "RSTP not managing BPDU in this state, "
+                                 "skipping bpdu output");
                 }
                 return;
             }
         } else if (!xport_stp_forward_state(xport) ||
                    !xport_rstp_forward_state(xport)) {
             if (ctx->xbridge->stp != NULL) {
-                xlate_report(ctx, "STP not in forwarding state, "
-                        "skipping output");
+                xlate_report(ctx, OFT_WARN,
+                             "STP not in forwarding state, skipping output");
             } else if (ctx->xbridge->rstp != NULL) {
-                xlate_report(ctx, "RSTP not in forwarding state, "
-                        "skipping output");
+                xlate_report(ctx, OFT_WARN,
+                             "RSTP not in forwarding state, skipping output");
             }
             return;
         }
@@ -2928,6 +2995,7 @@ compose_output_action__(struct xlate_ctx *ctx, ofp_port_t ofp_port,
         struct ofpbuf old_stack = ctx->stack;
         union mf_subvalue new_stack[1024 / sizeof(union mf_subvalue)];
         struct ofpbuf old_action_set = ctx->action_set;
+        struct ovs_list *old_trace = ctx->xin->trace;
         uint64_t actset_stub[1024 / 8];
 
         ofpbuf_use_stub(&ctx->stack, new_stack, sizeof new_stack);
@@ -2942,6 +3010,8 @@ compose_output_action__(struct xlate_ctx *ctx, ofp_port_t ofp_port,
         flow->actset_output = OFPP_UNSET;
         ctx->conntracked = false;
         clear_conntrack(flow);
+        ctx->xin->trace = xlate_report(ctx, OFT_BRIDGE,
+                                       "bridge(\"%s\")", peer->xbridge->name);
 
         /* When the patch port points to a different bridge, then the mirrors
          * for that bridge clearly apply independently to the packet, so we
@@ -2993,6 +3063,7 @@ compose_output_action__(struct xlate_ctx *ctx, ofp_port_t ofp_port,
             }
         }
 
+        ctx->xin->trace = old_trace;
         if (independent_mirrors) {
             ctx->mirrors = old_mirrors;
         }
@@ -3072,12 +3143,12 @@ compose_output_action__(struct xlate_ctx *ctx, ofp_port_t ofp_port,
         flow_tnl = flow->tunnel;
         odp_port = tnl_port_send(xport->ofport, flow, ctx->wc);
         if (odp_port == ODPP_NONE) {
-            xlate_report(ctx, "Tunneling decided against output");
+            xlate_report(ctx, OFT_WARN, "Tunneling decided against output");
             goto out; /* restore flow_nw_tos */
         }
         dst = flow_tnl_dst(&flow->tunnel);
         if (ipv6_addr_equals(&dst, &ctx->orig_tunnel_ipv6_dst)) {
-            xlate_report(ctx, "Not tunneling to our own address");
+            xlate_report(ctx, OFT_WARN, "Not tunneling to our own address");
             goto out; /* restore flow_nw_tos */
         }
         if (ctx->xin->resubmit_stats) {
@@ -3091,10 +3162,10 @@ compose_output_action__(struct xlate_ctx *ctx, ofp_port_t ofp_port,
         }
         out_port = odp_port;
         if (ovs_native_tunneling_is_on(ctx->xbridge->ofproto)) {
-            xlate_report(ctx, "output to native tunnel");
+            xlate_report(ctx, OFT_ACTION, "output to native tunnel");
             tnl_push_pop_send = true;
         } else {
-            xlate_report(ctx, "output to kernel tunnel");
+            xlate_report(ctx, OFT_ACTION, "output to kernel tunnel");
             commit_odp_tunnel_action(flow, &ctx->base_flow, ctx->odp_actions);
             flow->tunnel = flow_tnl; /* Restore tunnel metadata */
         }
@@ -3219,17 +3290,17 @@ static bool
 xlate_resubmit_resource_check(struct xlate_ctx *ctx)
 {
     if (ctx->depth >= MAX_DEPTH) {
-        XLATE_REPORT_ERROR(ctx, "over max translation depth %d", MAX_DEPTH);
+        xlate_report_error(ctx, "over max translation depth %d", MAX_DEPTH);
         ctx->error = XLATE_RECURSION_TOO_DEEP;
     } else if (ctx->resubmits >= MAX_RESUBMITS) {
-        XLATE_REPORT_ERROR(ctx, "over %d resubmit actions", MAX_RESUBMITS);
+        xlate_report_error(ctx, "over %d resubmit actions", MAX_RESUBMITS);
         ctx->error = XLATE_TOO_MANY_RESUBMITS;
     } else if (ctx->odp_actions->size > UINT16_MAX) {
-        XLATE_REPORT_ERROR(ctx, "resubmits yielded over 64 kB of actions");
+        xlate_report_error(ctx, "resubmits yielded over 64 kB of actions");
         /* NOT an error, as we'll be slow-pathing the flow in this case? */
         ctx->exit = true; /* XXX: translation still terminated! */
     } else if (ctx->stack.size >= 65536) {
-        XLATE_REPORT_ERROR(ctx, "resubmits yielded over 64 kB of stack");
+        xlate_report_error(ctx, "resubmits yielded over 64 kB of stack");
         ctx->error = XLATE_STACK_TOO_DEEP;
     } else {
         return true;
@@ -3260,9 +3331,6 @@ xlate_table_action(struct xlate_ctx *ctx, ofp_port_t in_port, uint8_t table_id,
                                            &ctx->table_id, in_port,
                                            may_packet_in, honor_table_miss,
                                            ctx->xin->xcache);
-        if (OVS_UNLIKELY(ctx->xin->resubmit_hook)) {
-            ctx->xin->resubmit_hook(ctx->xin, rule, ctx->indentation + 1);
-        }
 
         if (rule) {
             /* Fill in the cache entry here instead of xlate_recursively
@@ -3276,7 +3344,11 @@ xlate_table_action(struct xlate_ctx *ctx, ofp_port_t in_port, uint8_t table_id,
                 entry->rule = rule;
                 ofproto_rule_ref(&rule->up);
             }
+
+            struct ovs_list *old_trace = ctx->xin->trace;
+            xlate_report_table(ctx, rule, table_id);
             xlate_recursively(ctx, rule, table_id <= old_table_id);
+            ctx->xin->trace = old_trace;
         }
 
         ctx->table_id = old_table_id;
@@ -3744,7 +3816,7 @@ finish_freezing__(struct xlate_ctx *ctx, uint8_t table)
          * with the udpif key ('ukey') created for each new datapath flow. */
         uint32_t id = recirc_alloc_id_ctx(&state);
         if (!id) {
-            XLATE_REPORT_ERROR(ctx, "Failed to allocate recirculation id");
+            xlate_report_error(ctx, "Failed to allocate recirculation id");
             ctx->error = XLATE_NO_RECIRCULATION_CONTEXT;
             return;
         }
@@ -3799,7 +3871,7 @@ compose_mpls_push_action(struct xlate_ctx *ctx, struct ofpact_push_mpls *mpls)
         xlate_commit_actions(ctx);
     } else if (n >= FLOW_MAX_MPLS_LABELS) {
         if (ctx->xin->packet != NULL) {
-            XLATE_REPORT_ERROR(ctx, "bridge %s: dropping packet on which an "
+            xlate_report_error(ctx, "bridge %s: dropping packet on which an "
                          "MPLS push action can't be performed as it would "
                          "have more MPLS LSEs than the %d supported.",
                          ctx->xbridge->name, FLOW_MAX_MPLS_LABELS);
@@ -3824,7 +3896,7 @@ compose_mpls_pop_action(struct xlate_ctx *ctx, ovs_be16 eth_type)
         }
     } else if (n >= FLOW_MAX_MPLS_LABELS) {
         if (ctx->xin->packet != NULL) {
-            XLATE_REPORT_ERROR(ctx, "bridge %s: dropping packet on which an "
+            xlate_report_error(ctx, "bridge %s: dropping packet on which an "
                          "MPLS pop action can't be performed as it has "
                          "more MPLS LSEs than the %d supported.",
                          ctx->xbridge->name, FLOW_MAX_MPLS_LABELS);
@@ -3949,7 +4021,7 @@ xlate_output_action(struct xlate_ctx *ctx,
         if (port != ctx->xin->flow.in_port.ofp_port) {
             compose_output_action(ctx, port, NULL);
         } else {
-            xlate_report(ctx, "skipping output to input port");
+            xlate_report(ctx, OFT_WARN, "skipping output to input port");
         }
         break;
     }
@@ -3995,7 +4067,8 @@ xlate_output_trunc_action(struct xlate_ctx *ctx,
     case OFPP_CONTROLLER:
     case OFPP_NONE:
         ofputil_port_to_string(port, name, sizeof name);
-        xlate_report(ctx, "output_trunc does not support port: %s", name);
+        xlate_report(ctx, OFT_WARN,
+                     "output_trunc does not support port: %s", name);
         break;
     case OFPP_LOCAL:
     case OFPP_IN_PORT:
@@ -4008,7 +4081,7 @@ xlate_output_trunc_action(struct xlate_ctx *ctx,
                  * the output port is a patch port, the behavior is somehow
                  * unpredicable. For simpilicity, disallow this case. */
                 ofputil_port_to_string(port, name, sizeof name);
-                XLATE_REPORT_ERROR(ctx, "bridge %s: "
+                xlate_report_error(ctx, "bridge %s: "
                          "output_trunc does not support port: %s",
                          ctx->xbridge->name, name);
                 break;
@@ -4023,7 +4096,7 @@ xlate_output_trunc_action(struct xlate_ctx *ctx,
                 ctx->xout->slow |= SLOW_ACTION;
             }
         } else {
-            xlate_report(ctx, "skipping output to input port");
+            xlate_report(ctx, OFT_WARN, "skipping output to input port");
         }
         break;
     }
@@ -4733,6 +4806,13 @@ do_xlate_actions(const struct ofpact *ofpacts, size_t ofpacts_len,
             break;
         }
 
+        if (OVS_UNLIKELY(ctx->xin->trace)) {
+            struct ds s = DS_EMPTY_INITIALIZER;
+            ofpacts_format(a, OFPACT_ALIGN(a->len), &s);
+            xlate_report(ctx, OFT_ACTION, "%s", ds_cstr(&s));
+            ds_destroy(&s);
+        }
+
         switch (a->type) {
         case OFPACT_OUTPUT:
             xlate_output_action(ctx, ofpact_get_OUTPUT(a)->port,
@@ -5084,8 +5164,7 @@ xlate_in_init(struct xlate_in *xin, struct ofproto_dpif *ofproto,
     xin->ofpacts = NULL;
     xin->ofpacts_len = 0;
     xin->tcp_flags = tcp_flags;
-    xin->resubmit_hook = NULL;
-    xin->report_hook = NULL;
+    xin->trace = NULL;
     xin->resubmit_stats = NULL;
     xin->indentation = 0;
     xin->depth = 0;
@@ -5389,17 +5468,17 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
 
     COVERAGE_INC(xlate_actions);
 
+    xin->trace = xlate_report(&ctx, OFT_BRIDGE, "bridge(\"%s\")",
+                              xbridge->name);
     if (xin->frozen_state) {
         const struct frozen_state *state = xin->frozen_state;
 
-        xlate_report(&ctx, "Thawing frozen state:");
+        struct ovs_list *old_trace = xin->trace;
+        xin->trace = xlate_report(&ctx, OFT_THAW, "thaw");
 
         if (xin->ofpacts_len > 0 || ctx.rule) {
-            static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 1);
-            const char *conflict = xin->ofpacts_len ? "actions" : "rule";
-
-            VLOG_WARN_RL(&rl, "Recirculation conflict (%s)!", conflict);
-            xlate_report(&ctx, "- Recirculation conflict (%s)!", conflict);
+            xlate_report_error(&ctx, "Recirculation conflict (%s)!",
+                               xin->ofpacts_len ? "actions" : "rule");
             ctx.error = XLATE_RECIRCULATION_CONFLICT;
             goto exit;
         }
@@ -5412,10 +5491,9 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
 
             if (OVS_UNLIKELY(!new_bridge)) {
                 /* Drop the packet if the bridge cannot be found. */
-                static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 1);
-                VLOG_WARN_RL(&rl, "Frozen bridge no longer exists.");
-                xlate_report(&ctx, "- Frozen bridge no longer exists.");
+                xlate_report_error(&ctx, "Frozen bridge no longer exists.");
                 ctx.error = XLATE_BRIDGE_NOT_FOUND;
+                xin->trace = old_trace;
                 goto exit;
             }
             ctx.xbridge = new_bridge;
@@ -5427,7 +5505,8 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
         /* Set the thawed table id.  Note: A table lookup is done only if there
          * are no frozen actions. */
         ctx.table_id = state->table_id;
-        xlate_report(&ctx, "- Resuming from table %"PRIu8, ctx.table_id);
+        xlate_report(&ctx, OFT_ACTION,
+                     "Resuming from table %"PRIu8, ctx.table_id);
 
         if (!state->conntracked) {
             clear_conntrack(flow);
@@ -5448,7 +5527,7 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
 
         /* Restore action set, if any. */
         if (state->action_set_len) {
-            xlate_report_actions(&ctx, "- Restoring action set",
+            xlate_report_actions(&ctx, OFT_ACTION, "Restoring action set",
                                  state->action_set, state->action_set_len);
 
             flow->actset_output = OFPP_UNSET;
@@ -5461,14 +5540,15 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
         xin->ofpacts = state->ofpacts;
         xin->ofpacts_len = state->ofpacts_len;
         if (state->ofpacts_len) {
-            xlate_report_actions(&ctx, "- Restoring actions",
+            xlate_report_actions(&ctx, OFT_ACTION, "Restoring actions",
                                  xin->ofpacts, xin->ofpacts_len);
         }
-    } else if (OVS_UNLIKELY(flow->recirc_id)) {
-        static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 1);
 
-        VLOG_WARN_RL(&rl, "Recirculation context not found for ID %"PRIx32,
-                     flow->recirc_id);
+        xin->trace = old_trace;
+    } else if (OVS_UNLIKELY(flow->recirc_id)) {
+        xlate_report_error(&ctx,
+                           "Recirculation context not found for ID %"PRIx32,
+                           flow->recirc_id);
         ctx.error = XLATE_NO_RECIRCULATION_CONTEXT;
         goto exit;
     }
@@ -5483,7 +5563,7 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
                                              &xin->upcall_flow->tunnel,
                                              &flow->tunnel);
         if (err) {
-            XLATE_REPORT_ERROR(&ctx, "Invalid Geneve tunnel metadata");
+            xlate_report_error(&ctx, "Invalid Geneve tunnel metadata");
             ctx.error = XLATE_INVALID_TUNNEL_METADATA;
             goto exit;
         }
@@ -5511,9 +5591,7 @@ xlate_actions(struct xlate_in *xin, struct xlate_out *xout)
             ofproto_rule_ref(&ctx.rule->up);
         }
 
-        if (OVS_UNLIKELY(ctx.xin->resubmit_hook)) {
-            ctx.xin->resubmit_hook(ctx.xin, ctx.rule, 0);
-        }
+        xlate_report_table(&ctx, ctx.rule, ctx.table_id);
     }
 
     /* Get the proximate input port of the packet.  (If xin->frozen_state,
diff --git a/ofproto/ofproto-dpif-xlate.h b/ofproto/ofproto-dpif-xlate.h
index 51c05ac..bf3f684 100644
--- a/ofproto/ofproto-dpif-xlate.h
+++ b/ofproto/ofproto-dpif-xlate.h
@@ -83,27 +83,10 @@ struct xlate_in {
      * timeouts.) */
     uint16_t tcp_flags;
 
-    /* If nonnull, flow translation calls this function just before executing a
-     * resubmit or OFPP_TABLE action.  In addition, disables logging of traces
-     * when the recursion depth is exceeded.
-     *
-     * 'rule' is the rule being submitted into.  It will be null if the
-     * resubmit or OFPP_TABLE action didn't find a matching rule.
-     *
-     * 'indentation' is the resubmit recursion depth at time of invocation,
-     * suitable for indenting the output.
-     *
-     * This is normally null so the client has to set it manually after
-     * calling xlate_in_init(). */
-    void (*resubmit_hook)(struct xlate_in *, struct rule_dpif *rule,
-                          int indentation);
-
-    /* If nonnull, flow translation calls this function to report some
-     * significant decision, e.g. to explain why OFPP_NORMAL translation
-     * dropped a packet.  'indentation' is the resubmit recursion depth at time
-     * of invocation, suitable for indenting the output. */
-    void (*report_hook)(struct xlate_in *, int indentation,
-                        const char *format, va_list args);
+    /* If nonnull, this indicates that the translation is being traced.  It
+     * points to the list of oftrace nodes to which the translation should add
+     * tracing information (with oftrace_node_append()). */
+    struct ovs_list *trace;
 
     /* If nonnull, flow translation credits the specified statistics to each
      * rule reached through a resubmit or OFPP_TABLE action.
diff --git a/tests/ovn.at b/tests/ovn.at
index 38fd1e5..30e80f4 100644
--- a/tests/ovn.at
+++ b/tests/ovn.at
@@ -5964,7 +5964,7 @@ src_ip=`ip_to_hex 192 168 1 2`
 dst_ip=`ip_to_hex 172 16 1 3`
 packet=${dst_mac}${src_mac}08004500001c0000000040110000${src_ip}${dst_ip}0035111100080000
 as hv1 ovs-appctl netdev-dummy/receive hv1-vif1 $packet
-#as hv1 ovs-appctl ofproto/trace br-int in_port=1 $packet
+as hv1 ovs-appctl ofproto/trace br-int in_port=1 $packet
 
 # Send ip packets between bar1 and bob1
 src_mac="f00000010204"
-- 
2.10.2



More information about the dev mailing list