[ovs-dev] xlate: auto ofproto trace when recursion too deep

Usually ofproto/trace is used to debug the flow translation error.
When translation error such as recursion too deep or too many resubmit,
the issue might happen momentary; flows causing the recursion expire
when users try to debug it.  This patch enables the ofproto trace
automatically when recursion is too deep or too many resubmit, by
invoking the translation again, and log the ofproto trace as warnings.

VMWare-BZ: #2054659
Signed-off-by: William Tu <u9012063@gmail.com>
---
 ofproto/ofproto-dpif-trace.c  |  7 +------
 ofproto/ofproto-dpif-trace.h  |  6 ++++++
 ofproto/ofproto-dpif-upcall.c | 19 ++++++++++++++++++-
 tests/ofproto-dpif.at         | 22 ++++++++++++++++++++++
 4 files changed, 47 insertions(+), 7 deletions(-)

On 2/8/2018 10:16 PM, William Tu wrote:
> Usually ofproto/trace is used to debug the flow translation error.
> When translation error such as recursion too deep or too many resubmit,
> the issue might happen momentary; flows causing the recursion expire
> when users try to debug it.  This patch enables the ofproto trace
> automatically when recursion is too deep or too many resubmit, by
> invoking the translation again, and log the ofproto trace as warnings.
>
> VMWare-BZ: #2054659
> Signed-off-by: William Tu <u9012063@gmail.com>
> ---
>   ofproto/ofproto-dpif-trace.c  |  7 +------
>   ofproto/ofproto-dpif-trace.h  |  6 ++++++
>   ofproto/ofproto-dpif-upcall.c | 19 ++++++++++++++++++-
>   tests/ofproto-dpif.at         | 22 ++++++++++++++++++++++
>   4 files changed, 47 insertions(+), 7 deletions(-)
>
> diff --git a/ofproto/ofproto-dpif-trace.c b/ofproto/ofproto-dpif-trace.c
> index 3811e03b106d..25b018d48207 100644
> --- a/ofproto/ofproto-dpif-trace.c
> +++ b/ofproto/ofproto-dpif-trace.c
> @@ -24,11 +24,6 @@
>   #include "openvswitch/ofp-parse.h"
>   #include "unixctl.h"
>   
> -static void ofproto_trace(struct ofproto_dpif *, const struct flow *,
> -                          const struct dp_packet *packet,
> -                          const struct ofpact[], size_t ofpacts_len,
> -                          struct ovs_list *next_ct_states,
> -                          struct ds *);
>   static void oftrace_node_destroy(struct oftrace_node *);
>   
>   /* Creates a new oftrace_node, populates it with the given 'type' and a copy of
> @@ -662,7 +657,7 @@ ofproto_trace__(struct ofproto_dpif *ofproto, const struct flow *flow,
>    *
>    * If 'ofpacts' is nonnull then its 'ofpacts_len' bytes specify the actions to
>    * trace, otherwise the actions are determined by a flow table lookup. */
> -static void
> +void
>   ofproto_trace(struct ofproto_dpif *ofproto, const struct flow *flow,
>                 const struct dp_packet *packet,
>                 const struct ofpact ofpacts[], size_t ofpacts_len,
> diff --git a/ofproto/ofproto-dpif-trace.h b/ofproto/ofproto-dpif-trace.h
> index 5e51771b19b0..ea6cb3fc01ac 100644
> --- a/ofproto/ofproto-dpif-trace.h
> +++ b/ofproto/ofproto-dpif-trace.h
> @@ -28,6 +28,8 @@
>    * each action (OFT_ACTION) executed in the table.
>    */
>   
> +#include "openvswitch/dynamic-string.h"
> +#include "ofproto/ofproto-dpif.h"
>   #include "openvswitch/compiler.h"
>   #include "openvswitch/list.h"
>   #include "flow.h"
> @@ -79,6 +81,10 @@ struct oftrace_next_ct_state {
>   };
>   
>   void ofproto_dpif_trace_init(void);
> +void ofproto_trace(struct ofproto_dpif *ofproto, const struct flow *flow,
> +              const struct dp_packet *packet,
> +              const struct ofpact *, size_t ofpacts_len,
> +              struct ovs_list *next_ct_states, struct ds *output);
>   
>   struct oftrace_node *oftrace_report(struct ovs_list *, enum oftrace_node_type,
>                                       const char *text);
> diff --git a/ofproto/ofproto-dpif-upcall.c b/ofproto/ofproto-dpif-upcall.c
> index 035233d5adc8..05064c8b85fa 100644
> --- a/ofproto/ofproto-dpif-upcall.c
> +++ b/ofproto/ofproto-dpif-upcall.c
> @@ -34,6 +34,7 @@
>   #include "ofproto-dpif-sflow.h"
>   #include "ofproto-dpif-xlate.h"
>   #include "ofproto-dpif-xlate-cache.h"
> +#include "ofproto-dpif-trace.h"
>   #include "ovs-rcu.h"
>   #include "packets.h"
>   #include "openvswitch/poll-loop.h"
> @@ -1128,7 +1129,9 @@ upcall_xlate(struct udpif *udpif, struct upcall *upcall,
>                struct ofpbuf *odp_actions, struct flow_wildcards *wc)
>   {
>       struct dpif_flow_stats stats;
> +    enum xlate_error xerr;
>       struct xlate_in xin;
> +    struct ds output;
>   
>       stats.n_packets = 1;
>       stats.n_bytes = dp_packet_size(upcall->packet);
> @@ -1163,7 +1166,21 @@ upcall_xlate(struct udpif *udpif, struct upcall *upcall,
>       upcall->dump_seq = seq_read(udpif->dump_seq);
>       upcall->reval_seq = seq_read(udpif->reval_seq);
>   
> -    xlate_actions(&xin, &upcall->xout);
> +    xerr = xlate_actions(&xin, &upcall->xout);
> +
> +    /* Translate again and log the ofproto trace for
> +     * these two error types. */
> +    if (xerr == XLATE_RECURSION_TOO_DEEP ||
> +        xerr == XLATE_TOO_MANY_RESUBMITS) {
> +        static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5);
> +
> +        ds_init(&output);
> +        ofproto_trace(upcall->ofproto, upcall->flow,
> +                      upcall->packet, NULL, 0, NULL, &output);
> +        VLOG_WARN_RL(&rl, "%s", ds_cstr(&output));
> +        ds_destroy(&output);
> +    }
> +
>       if (wc) {
>           /* Convert the input port wildcard from OFP to ODP format. There's no
>            * real way to do this for arbitrary bitmasks since the numbering spaces
> diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at
> index 600afdda8528..776c5d34fae2 100644
> --- a/tests/ofproto-dpif.at
> +++ b/tests/ofproto-dpif.at
> @@ -8473,6 +8473,28 @@ AT_CHECK([grep -c 'over max translation depth 64' stdout],
>   OVS_VSWITCHD_STOP(["/resubmit actions recursed/d"])
>   AT_CLEANUP
>   
> +dnl Without using ofproto/trace, make sure the
> +dnl ofproto trace is still logged
> +AT_SETUP([ofproto-dpif - backward resubmit without trace])
> +OVS_VSWITCHD_START
> +(echo "table=0, actions=resubmit(,66)"
> + for i in `seq 2 66`; do
> +    j=`expr $i - 1`
> +    echo "table=$i, actions=resubmit(,$j)"
> + done
> + echo "table=1, actions=local") > flows
> +AT_CHECK([ovs-ofctl add-flows br0 flows])
> +
> +AT_CHECK([ovs-appctl netdev-dummy/receive br0 'in_port(1),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x1234)'], [0], [stdout])
> +
> +AT_CHECK([grep -c "^ *resubmit" ovs-vswitchd.log],
> +  [0], [66
> +])
> +
> +OVS_VSWITCHD_STOP(["/over max translation depth/d
> +/ofproto_dpif_upcall/d"])
> +AT_CLEANUP
> +
>   AT_SETUP([ofproto-dpif - exponential resubmit chain])
>   OVS_VSWITCHD_START
>   add_of_ports br0 1

I tested this with make check on a Ubuntu 4.4-104-generic kernel. The 
test passes and the code looks fine to me.

Tested-by: Greg Rose <gvrose8192@gmail.com>
Reviewed-by: Greg Rose <gvrose8192@gmail.com>