[QoS] DSCP Queue IP-IP Packet Mapping Logging Fix (sonic-net#10172)

Improve logging visibility on dscp to queue mapping test, while also improving test stability by adding several checkers such as bgp up/down visibility.

tests/common/config_reload.py

@@ -63,13 +63,14 @@ def config_force_option_supported(duthost):
 
 @ignore_loganalyzer
 def config_reload(sonic_host, config_source='config_db', wait=120, start_bgp=True, start_dynamic_buffer=True,
-                  safe_reload=False, wait_before_force_reload=0,
+                  safe_reload=False, wait_before_force_reload=0, wait_for_bgp=False,
                   check_intf_up_ports=False, traffic_shift_away=False, override_config=False, is_dut=True):
     """
     reload SONiC configuration
     :param sonic_host: SONiC host object
     :param config_source: configuration source is 'config_db', 'minigraph' or 'running_golden_config'
     :param wait: wait timeout for sonic_host to initialize after configuration reload
+    :param wait_for_bgp: True to wait for all BGP connections to come up after configuration reload
     :param override_config: override current config with '/etc/sonic/golden_config_db.json'
     :param is_dut: True if the host is DUT, False if the host may be neighbor device.
                     To the non-DUT host, it may lack of some runtime variables like `topo_type`
@@ -151,3 +152,8 @@ def _config_reload_cmd_wrapper(cmd, executable):
                           "Not all ports that are admin up on are operationally up")
     else:
         time.sleep(wait)
+
+    if wait_for_bgp:
+        bgp_neighbors = sonic_host.get_bgp_neighbors().keys()
+        pytest_assert(wait_until(120, 10, 0, sonic_host.check_bgp_session_state, bgp_neighbors),
+                      "Not all bgp sessions are established after config reload")

tests/common/helpers/ptf_tests_helper.py

@@ -5,10 +5,13 @@
 import pytest
 import random
 import os
+import logging
 
 from ipaddress import ip_address, IPv4Address
 from tests.common.config_reload import config_reload
 
+logger = logging.getLogger(__name__)
+
 
 @pytest.fixture(scope="module")
 def downstream_links(duthost, tbinfo):
@@ -86,21 +89,26 @@ def apply_dscp_cfg_setup(duthost, dscp_mode):
     """
 
     default_decap_mode = duthost.shell("redis-cli -n 0 hget 'TUNNEL_DECAP_TABLE:IPINIP_TUNNEL' 'dscp_mode'")["stdout"]
+    logger.info("Current DSCP decap mode: {}".format(default_decap_mode))
 
     if default_decap_mode == dscp_mode:
+        logger.info("Current DSCP decap mode: {} matches required decap mode - no reload required"
+                    .format(default_decap_mode))
         return
 
     for asic_id in duthost.get_frontend_asic_ids():
         swss = "swss{}".format(asic_id if asic_id is not None else '')
-        cmds = [
-            "docker exec {} cp /usr/share/sonic/templates/ipinip.json.j2 /usr/share/sonic/templates/ipinip.json.j2.tmp"
-            .format(swss),
-            "docker exec {} sed -i 's/{}/{}/g' /usr/share/sonic/templates/ipinip.json.j2 "
-            .format(swss, default_decap_mode, dscp_mode)
-        ]
+        logger.info("DSCP decap mode required to be changed to {} on asic {}".format(dscp_mode, asic_id))
+        cmds = ["docker exec {} cp /usr/share/sonic/templates/ipinip.json.j2 ".format(swss) +
+                "/usr/share/sonic/templates/ipinip.json.j2.tmp",
+                "docker exec {} sed -i 's/\"dscp_mode\":\"{}\"/\"dscp_mode\":\"{}\"/g\' ".
+                format(swss, default_decap_mode, dscp_mode) + "/usr/share/sonic/templates/ipinip.json.j2"]
+        # sed -i 's/"dscp_mode":"uniform"/"dscp_mode":"pipe"/g' ipinip.json.j2 - this is the command to change
         duthost.shell_cmds(cmds=cmds)
+        logger.info("DSCP decap mode changed from {} to {} on asic {}".format(default_decap_mode, dscp_mode, asic_id))
 
-    config_reload(duthost, config_source='minigraph', safe_reload=True)
+    logger.info("SETUP: Reload required for dscp decap mode changes to take effect.")
+    config_reload(duthost, safe_reload=True, wait_for_bgp=True)
 
 
 def apply_dscp_cfg_teardown(duthost):
@@ -118,15 +126,15 @@ def apply_dscp_cfg_teardown(duthost):
         except Exception:
             continue
         if file_out["rc"] == 0:
-            cmds = [
-                'docker exec {} cp /usr/share/sonic/templates/ipinip.json.j2.tmp '.format(swss) +
-                '/usr/share/sonic/templates/ipinip.json.j2'
-                ]
+            cmd1 = "docker exec {} cp /usr/share/sonic/templates/ipinip.json.j2.tmp ".format(swss) + \
+                "/usr/share/sonic/templates/ipinip.json.j2"
             reload_required = True
-            duthost.shell_cmds(cmds=cmds)
+            logger.info("DSCP decap mode required to be changed to default on asic {}".format(asic_id))
+            duthost.shell(cmd1)
 
     if reload_required:
-        config_reload(duthost, config_source='minigraph', safe_reload=True)
+        logger.info("TEARDOWN: Reload required for dscp decap mode changes to take effect.")
+        config_reload(duthost, safe_reload=True)
 
 
 def find_links(duthost, tbinfo, filter):

tests/common/snappi_tests/common_helpers.py

@@ -885,8 +885,8 @@ def get_egress_queue_count(duthost, port, priority):
         tuple (int, int): total count of packets and bytes in the queue
     """
     raw_out = duthost.shell("show queue counters {} | sed -n '/UC{}/p'".format(port, priority))['stdout']
-    total_pkts = raw_out.split()[2]
-    total_bytes = raw_out.split()[3]
+    total_pkts = "0" if raw_out.split()[2] == "N/A" else raw_out.split()[2]
+    total_bytes = "0" if raw_out.split()[3] == "N/A" else raw_out.split()[3]
     return int(total_pkts.replace(',', '')), int(total_bytes.replace(',', ''))
 
 

tests/common/utilities.py

@@ -1017,3 +1017,55 @@ def get_dscp_to_queue_value(dscp_value, dscp_to_tc_map, tc_to_queue_map):
         return None
 
     return int(tc_to_queue_map[tc_value])
+
+
+def find_egress_queue(all_queue_pkts, exp_queue_pkts, tolerance=0.05):
+    """
+    Given the number of packets egressing out of each queue and an expected number of packets to
+    egress out of ONE of the queues, this function returns which queue it is. If no such queue exists, it returns -1.
+
+    Args:
+        all_queue_pkts ([int]): egress queue counts for all queues where packets are expected to egress from
+                                in array form ex. [0, 0, 100, 0, 0, 0, 0]
+        exp_queue_pkts (int): expected number of packets to egress from port
+        tolerance (float): packet tolerance to expected queue packets - only followed if atleast 100 packets are
+                           expected this accounts for background traffic
+    Returns:
+        queue_val (int): egress queue if found, else -1
+    """
+    pytest_assert(exp_queue_pkts >= 1, "At least one packet is expected to egress from the queue")
+    for queue_pkt_index in range(len(all_queue_pkts)):
+        if all_queue_pkts[queue_pkt_index] == 0:
+            continue
+        elif all_queue_pkts[queue_pkt_index] == exp_queue_pkts and exp_queue_pkts < 100:
+            return queue_pkt_index
+        elif (abs(all_queue_pkts[queue_pkt_index] - exp_queue_pkts)/exp_queue_pkts < tolerance) and \
+             (exp_queue_pkts >= 100):
+            # tolerance only followed if atleast 100 packets are expected
+            return queue_pkt_index
+
+    return -1
+
+
+def get_egress_queue_pkt_count_all_prio(duthost, port):
+    """
+    Get the egress queue count in packets for a given port and all priorities from SONiC CLI.
+    This is the equivalent of the "queuestat -j" command.
+    Args:
+        duthost (Ansible host instance): device under test
+        port (str): port name
+    Returns:
+        array [int]: total count of packets in the queue for all priorities
+    """
+    raw_out = duthost.shell("queuestat -jp {}".format(port))['stdout']
+    raw_json = json.loads(raw_out)
+    intf_queue_stats = raw_json.get(port)
+    queue_stats = []
+
+    for prio in range(8):
+        total_pkts_str = intf_queue_stats.get("UC{}".format(prio)).get("totalpacket")
+        if total_pkts_str == "N/A" or total_pkts_str is None:
+            total_pkts_str = "0"
+        queue_stats.append(int(total_pkts_str.replace(',', '')))
+
+    return queue_stats

tests/qos/test_qos_dscp_mapping.py

@@ -13,10 +13,10 @@
 
 from tests.common.helpers.ptf_tests_helper import downstream_links, upstream_links, select_random_link,\
     get_stream_ptf_ports, get_dut_pair_port_from_ptf_port, apply_dscp_cfg_setup, apply_dscp_cfg_teardown # noqa F401
-from tests.common.utilities import get_ipv4_loopback_ip, get_dscp_to_queue_value
+from tests.common.utilities import get_ipv4_loopback_ip, get_dscp_to_queue_value, find_egress_queue,\
+    get_egress_queue_pkt_count_all_prio
 from tests.common.helpers.assertions import pytest_assert
 from tests.common.fixtures.duthost_utils import dut_qos_maps_module # noqa F401
-from tests.common.snappi_tests.common_helpers import get_egress_queue_count
 
 logger = logging.getLogger(__name__)
 
@@ -28,11 +28,12 @@
 DEFAULT_TTL = 64
 DEFAULT_ECN = 1
 DEFAULT_PKT_COUNT = 10000
-TOLERANCE = 0.02 * DEFAULT_PKT_COUNT
+TOLERANCE = 0.05 * DEFAULT_PKT_COUNT  # Account for noise and polling delays
 DUMMY_OUTER_SRC_IP = '8.8.8.8'
 DUMMY_INNER_SRC_IP = '9.9.9.9'
 DUMMY_INNER_DST_IP = '10.10.10.10'
 output_table = []
+packet_egressed_success = False
 
 
 def create_ipip_packet(outer_src_mac,
@@ -118,19 +119,29 @@ def send_and_verify_traffic(ptfadapter,
     """
 
     ptfadapter.dataplane.flush()
-    logger.info("Send packet from port {} upstream".format(ptf_src_port_id))
+    logger.info("Send packet(s) from port {} upstream".format(ptf_src_port_id))
     testutils.send(ptfadapter, ptf_src_port_id, pkt, count=DEFAULT_PKT_COUNT)
 
     try:
         port_index, _ = testutils.verify_packet_any_port(ptfadapter, exp_pkt, ports=ptf_dst_port_ids)
-        logger.info("Received packet on port {}".format(ptf_dst_port_ids[port_index]))
-        time.sleep(5)
+        logger.info("Received packet(s) on port {}".format(ptf_dst_port_ids[port_index]))
+        global packet_egressed_success
+        packet_egressed_success = True
+        # Wait for packets to be processed by the DUT
+        time.sleep(7)
         return ptf_dst_port_ids[port_index]
 
     except AssertionError as detail:
         if "Did not receive expected packet on any of ports" in str(detail):
-            logger.error("Expected packet was not received")
-        raise
+            logger.error("Expected packet(s) was not received on any of the ports -> {}".format(ptf_dst_port_ids))
+
+
+def find_queue_count_and_value(duthost, queue_val, dut_egress_port):
+    egress_queue_counts_all_queues = get_egress_queue_pkt_count_all_prio(duthost, dut_egress_port)
+    egress_queue_count = egress_queue_counts_all_queues[queue_val]
+    egress_queue_val = find_egress_queue(egress_queue_counts_all_queues, DEFAULT_PKT_COUNT)
+
+    return egress_queue_count, egress_queue_val
 
 
 class TestQoSSaiDSCPQueueMapping_IPIP_Base():
@@ -208,16 +219,26 @@ def _run_test(self,
         ptf_src_mac = ptfadapter.dataplane.get_mac(0, ptf_src_port_id)
         failed_once = False
 
+        # Log packet information
+        logger.info("Outer Pkt Src IP: {}".format(outer_src_pkt_ip))
+        logger.info("Outer Pkt Dst IP: {}".format(outer_dst_pkt_ip))
+        logger.info("Inner Pkt Src IP: {}".format(inner_src_pkt_ip))
+        logger.info("Inner Pkt Dst IP: {}".format(inner_dst_pkt_ip))
+        logger.info("Pkt Src MAC: {}".format(ptf_src_mac))
+        logger.info("Pkt Dst MAC: {}".format(router_mac))
+
         pytest_assert(dut_qos_maps_module.get("dscp_to_tc_map") and dut_qos_maps_module.get("tc_to_queue_map"),
                       "No QoS map found on DUT")
 
         for rotating_dscp in range(0, 64):
             if decap_mode == "uniform":
                 outer_dscp = rotating_dscp
                 inner_dscp = DEFAULT_DSCP
+                logger.info("Uniform mode: outer_dscp = {}, inner_dscp = {}".format(outer_dscp, inner_dscp))
             elif decap_mode == "pipe":
                 outer_dscp = DEFAULT_DSCP
                 inner_dscp = rotating_dscp
+                logger.info("Pipe mode: outer_dscp = {}, inner_dscp = {}".format(outer_dscp, inner_dscp))
 
             pkt, exp_pkt = create_ipip_packet(outer_src_mac=ptf_src_mac,
                                               outer_dst_mac=router_mac,
@@ -251,29 +272,55 @@ def _run_test(self,
                                                           ptf_dst_port_ids=ptf_dst_port_ids)
 
             except Exception as e:
-                raise (e)
-
-            dut_egress_port = get_dut_pair_port_from_ptf_port(duthost, tbinfo, dst_ptf_port_id)
-            pytest_assert(dut_egress_port, "No egress port on DUT found for ptf port {}".format(dst_ptf_port_id))
-
-            egress_queue_count, _ = get_egress_queue_count(duthost, dut_egress_port, queue_val)
-            verification_success = abs(egress_queue_count - DEFAULT_PKT_COUNT) < TOLERANCE
+                logger.error(str(e))
+                failed_once = True
 
-            if verification_success:
-                logger.info("Received expected number of packets on queue {}".format(queue_val))
-                output_table.append([rotating_dscp, queue_val, egress_queue_count, "SUCCESS"])
+            global packet_egressed_success
+            if packet_egressed_success:
+                dut_egress_port = get_dut_pair_port_from_ptf_port(duthost, tbinfo, dst_ptf_port_id)
+                pytest_assert(dut_egress_port, "No egress port on DUT found for ptf port {}".format(dst_ptf_port_id))
+                egress_queue_count, egress_queue_val = find_queue_count_and_value(duthost, queue_val, dut_egress_port)
+                # Re-poll DUT if queue value could not be accurately found
+                if egress_queue_val == -1:
+                    time.sleep(2)
+                    egress_queue_count, egress_queue_val = find_queue_count_and_value(duthost, queue_val,
+                                                                                      dut_egress_port)
+                verification_success = abs(egress_queue_count - DEFAULT_PKT_COUNT) < TOLERANCE
+
+                if verification_success:
+                    logger.info("SUCCESS: Received expected number of packets on queue {}".format(queue_val))
+                    output_table.append([rotating_dscp, queue_val, egress_queue_count, "SUCCESS", queue_val])
+                else:
+                    if queue_val == egress_queue_val:
+                        # If the queue value is correct, but the packet count is incorrect, then the DUT poll failed
+                        logger.info("FAILURE: Not all packets received on queue {}. DUT poll failure."
+                                    .format(queue_val))
+                        logger.info("Received {} packets instead".format(egress_queue_count))
+                        output_table.append([rotating_dscp, queue_val, egress_queue_count,
+                                             "FAILURE - INCORRECT PACKET COUNT", egress_queue_val])
+                    else:
+                        if egress_queue_val == -1:
+                            logger.info("FAILURE: Packets not received on any queue. DUT poll failure.")
+                            output_table.append([rotating_dscp, queue_val, egress_queue_count,
+                                                 "FAILURE - DUT POLL FAILURE", egress_queue_val])
+                        else:
+                            logger.info("FAILURE: Received {} packets on queue {} instead of queue {}."
+                                        .format(DEFAULT_PKT_COUNT, egress_queue_val, queue_val))
+                            output_table.append([rotating_dscp, queue_val, egress_queue_count,
+                                                 "FAILURE - INCORRECT QUEUE", egress_queue_val])
+                    failed_once = True
             else:
-                failed_once = True
-                logger.info("Received {} packets on queue {} instead of {}".format(egress_queue_count, queue_val,
-                                                                                   DEFAULT_PKT_COUNT))
-                output_table.append([rotating_dscp, queue_val, egress_queue_count, "FAILURE"])
+                output_table.append([rotating_dscp, queue_val, 0, "FAILURE - NO PACKETS EGRESSED", "N/A"])
+
+            # Reset packet egress status
+            packet_egressed_success = False
 
         logger.info("DSCP to queue mapping test results:\n{}"
                     .format(tabulate(output_table,
-                                     headers=["Inner Packet DSCP Value", "Egress Queue",
-                                              "Egress Queue Count", "Result"])))
-        pytest_assert(not failed_once, "Received {} packets on queue {} instead of {}".format(
-                    egress_queue_count, queue_val, DEFAULT_PKT_COUNT))
+                                     headers=["Inner Packet DSCP Value", "Expected Egress Queue",
+                                              "Egress Queue Count", "Result", "Actual Egress Queue"])))
+
+        pytest_assert(not failed_once, "FAIL: Test failed. Please check table for details.")
 
     def _teardown_test(self, duthost):
         """