ofproto-dpif: Make ofproto/trace output easier to read.

"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 2282 "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 2282' && less tests/testsuite.dir/2282/testsuite.log

Signed-off-by: Ben Pfaff <blp@ovn.org>
Acked-by: Lance Richardson <lrichard@redhat.com>
Acked-by: Justin Pettit <jpettit@ovn.org>

4 files changed, 28 insertions, 25 deletions

diff --git a/tests/ofproto-dpif.at b/tests/ofproto-dpif.at
index 4d0f93563..a4bf5a3f2 100644
--- a/tests/ofproto-dpif.at
+++ b/tests/ofproto-dpif.at
@@ -3823,7 +3823,7 @@ do
     AT_CHECK([ovs-appctl ofproto/trace ovs-dummy "$flow"], [0], [stdout])
     : > expout
     if test $mode = drop && test $type != no; then
-        echo 'Packets dropped because they are IP fragments and the fragment handling mode is "drop".' >> expout
+        echo ' 0. Packets are IP fragments and the fragment handling mode is "drop".' >> expout
         echo "Datapath actions: $exp_output" >> expout
     elif test $type = later; then
         echo "Datapath actions: $exp_output" >> expout
@@ -4873,9 +4873,10 @@ AT_CHECK([ovs-appctl ofproto/trace \
 AT_CHECK([tail -1 stdout], [0], [dnl
 Datapath actions: 2
 ])
-AT_CHECK([head -n 2 stdout], [0], [dnl
-Bridge: br0
+AT_CHECK([head -n 3 stdout], [0], [dnl
 Flow: pkt_mark=0x2,skb_priority=0x1,arp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:01,dl_dst=50:54:00:00:00:02,arp_spa=0.0.0.0,arp_tpa=0.0.0.0,arp_op=0,arp_sha=00:00:00:00:00:00,arp_tha=00:00:00:00:00:00
+
+bridge("br0")
 ])
 
 # Test command: ofproto/trace dp_name odp_flow packet
@@ -4884,9 +4885,10 @@ AT_CHECK([ovs-appctl ofproto/trace ovs-dummy \
 AT_CHECK([tail -1 stdout], [0], [dnl
 Datapath actions: 2
 ])
-AT_CHECK([head -n 2 stdout], [0], [dnl
-Bridge: br0
+AT_CHECK([head -n 3 stdout], [0], [dnl
 Flow: pkt_mark=0x2,skb_priority=0x1,arp,in_port=1,vlan_tci=0x0000,dl_src=50:54:00:00:00:01,dl_dst=50:54:00:00:00:02,arp_spa=0.0.0.0,arp_tpa=0.0.0.0,arp_op=0,arp_sha=00:00:00:00:00:00,arp_tha=00:00:00:00:00:00
+
+bridge("br0")
 ])
 
 # Test command: ofproto/trace br_name br_flow packet
@@ -4895,9 +4897,10 @@ AT_CHECK([ovs-appctl ofproto/trace br0 \
 AT_CHECK([tail -1 stdout], [0], [dnl
 Datapath actions: 1
 ])
-AT_CHECK([head -n 2 stdout], [0], [dnl
-Bridge: br0
+AT_CHECK([head -n 3 stdout], [0], [dnl
 Flow: pkt_mark=0x1,skb_priority=0x2,arp,in_port=2,vlan_tci=0x0000,dl_src=50:54:00:00:00:02,dl_dst=50:54:00:00:00:01,arp_spa=0.0.0.0,arp_tpa=0.0.0.0,arp_op=0,arp_sha=00:00:00:00:00:00,arp_tha=00:00:00:00:00:00
+
+bridge("br0")
 ])
 
 OVS_VSWITCHD_STOP
@@ -5032,12 +5035,12 @@ AT_CHECK([ovs-appctl dpif/dump-flows -m br0 | sed 's/, packets.*$//' > dp_flows1
 
 odp_flow=`cat dp_flows1.txt`
 AT_CHECK([ovs-appctl ofproto/trace "$odp_flow" | sed 's/\([[Ff]]low:\).*/\1 <cleared>/'], [0], [dnl
-Bridge: br0
 Flow: <cleared>
-No match, packets dropped because OFPPC_NO_PACKET_IN is set on in_port.
 
-Rule: table=254 cookie=0 priority=0,reg0=0x2
-OpenFlow actions=drop
+bridge("br0")
+-------------
+ 0. No match.
+    drop
 
 Final flow: <cleared>
 Megaflow: <cleared>
@@ -5053,12 +5056,12 @@ AT_CHECK([ovs-appctl dpif/dump-flows -m br0 | sed 's/, packets.*$//' > dp_flows2
 
 odp_flow=`cat dp_flows2.txt`
 AT_CHECK([ovs-appctl ofproto/trace "$odp_flow" | sed 's/\([[Ff]]low:\).*/\1 <cleared>/'], [0], [dnl
-Bridge: br0
 Flow: <cleared>
-No match, packets dropped because OFPPC_NO_PACKET_IN is set on in_port.
 
-Rule: table=254 cookie=0 priority=0,reg0=0x2
-OpenFlow actions=drop
+bridge("br0")
+-------------
+ 0. No match.
+    drop
 
 Final flow: <cleared>
 Megaflow: <cleared>
@@ -5728,7 +5731,7 @@ AT_CHECK([ovs-appctl ofproto/trace br0 in_port=LOCAL,dl_src=10:20:30:40:50:60],
 AT_CHECK([tail -1 stdout], [0], [Datapath actions: 2
 ])
 dnl the output(port=1,max_len=100) fails the translation, only output:2 in datapath
-AT_CHECK([grep "output_trunc does not support port: [[0-9]]*" stdout], [0], [stdout])
+AT_CHECK([grep "output_trunc does not support patch port [[0-9]]*" stdout], [0], [stdout])
 
 OVS_VSWITCHD_STOP
 AT_CLEANUP
@@ -7125,11 +7128,11 @@ AT_CHECK([strip_ufid < ovs-vswitchd.log | filter_flow_install | strip_used], [0]
 recirc_id(0),in_port(100),eth_type(0x0800),ipv4(src=192.168.0.1,frag=no), actions:101,set(ipv4(src=255.255.255.254)),2
 ])
 
-AT_CHECK([grep -e '|nx_match|WARN|' ovs-vswitchd.log | sed "s/^.*|WARN|//"], [0], [dnl
-Failed to pop from an empty stack. On flow
+AT_CHECK([grep -e '|ofproto_dpif_xlate|WARN|' ovs-vswitchd.log | sed "s/^.*|WARN|//"], [0], [dnl
+stack underflow while processing icmp,in_port=LOCAL,vlan_tci=0x0000,dl_src=50:54:00:00:00:05,dl_dst=50:54:00:00:00:07,nw_src=192.168.0.1,nw_dst=192.168.0.2,nw_tos=0,nw_ecn=0,nw_ttl=64,icmp_type=8,icmp_code=0 on bridge br1
 ])
 
-OVS_VSWITCHD_STOP(["/Failed to pop from an empty stack/d"])
+OVS_VSWITCHD_STOP(["/stack underflow/d"])
 AT_CLEANUP
 
 AT_SETUP([ofproto-dpif - port duration])
diff --git a/tests/ovn.at b/tests/ovn.at
index 65f97768a..8cbd06aba 100644
--- a/tests/ovn.at
+++ b/tests/ovn.at
@@ -2301,7 +2301,7 @@ test_arp() {
     local request=ffffffffffff${sha}08060001080006040001${sha}${spa}ffffffffffff${tpa}
     hv=hv`vif_to_hv $inport`
     as $hv ovs-appctl netdev-dummy/receive vif$inport $request
-    #as $hv ovs-appctl ofproto/trace br-int in_port=$inport $request
+    as $hv ovs-appctl ofproto/trace br-int in_port=$inport $request
 
     # Expect to receive the broadcast ARP on the other logical switch ports if
     # IP address is not configured to the switch patch port.
@@ -6074,7 +6074,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"
diff --git a/tests/rstp.at b/tests/rstp.at
index ba48c0a71..600e85dab 100644
--- a/tests/rstp.at
+++ b/tests/rstp.at
@@ -213,10 +213,10 @@ port p2: RSTP state changed from Disabled to Discarding
 ])
 
 AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(7),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.0.0.2,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep STP], [0], [dnl
-RSTP not in forwarding state, skipping output
+     >> RSTP not in forwarding state, skipping output
 ])
 AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(8),eth(src=50:54:00:00:00:0b,dst=50:54:00:00:00:0c),eth_type(0x0800),ipv4(src=10.0.0.3,dst=10.0.0.4,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep STP], [0], [dnl
-RSTP not in forwarding state, skipping output
+     >> RSTP not in forwarding state, skipping output
 ])
 
 #
diff --git a/tests/stp.at b/tests/stp.at
index c01ad81e3..8b6421824 100644
--- a/tests/stp.at
+++ b/tests/stp.at
@@ -428,10 +428,10 @@ port p2: STP state changed from disabled to listening
 ])
 
 AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(7),eth(src=50:54:00:00:00:09,dst=50:54:00:00:00:0a),eth_type(0x0800),ipv4(src=10.0.0.2,dst=10.0.0.1,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep STP], [0], [dnl
-STP not in forwarding state, skipping output
+     >> STP not in forwarding state, skipping output
 ])
 AT_CHECK([ovs-appctl ofproto/trace ovs-dummy 'in_port(8),eth(src=50:54:00:00:00:0b,dst=50:54:00:00:00:0c),eth_type(0x0800),ipv4(src=10.0.0.3,dst=10.0.0.4,proto=1,tos=0,ttl=64,frag=no),icmp(type=8,code=0)' | grep STP], [0], [dnl
-STP not in forwarding state, skipping output
+     >> STP not in forwarding state, skipping output
 ])
 
 # give time for STP to synchronize