refactor test_swss_neighbor_syncup test

- add log marker to mark starting point for grep
- subscribe asic db changes
- use neighbor add/change based on whether neighbor is deleted or not

Signed-off-by: Guohan Lu <gulv@microsoft.com>

tests/conftest.py

@@ -10,6 +10,7 @@
 import tarfile
 import StringIO
 import subprocess
+from datetime import datetime
 from swsscommon import swsscommon
 
 def ensure_system(cmd):
@@ -242,6 +243,10 @@ def check_ready(self, timeout=30):
                 except KeyError:
                     ready = False
 
+            # check if start.sh exited
+            if process_status["start.sh"] != "EXITED":
+                ready = False
+
             if ready == True:
                 break
 
@@ -276,6 +281,36 @@ def copy_file(self, path, filename):
         self.ctn.put_archive(path, tarstr.getvalue())
         tarstr.close()
 
+    def add_log_marker(self):
+        marker = "=== start marker {} ===".format(datetime.now().isoformat())
+        self.ctn.exec_run("logger {}".format(marker))
+        return marker
+
+    def SubscribeAsicDbObject(self, objpfx):
+        r = redis.Redis(unix_socket_path=self.redis_sock, db=swsscommon.ASIC_DB)
+        pubsub = r.pubsub()
+        pubsub.psubscribe("__keyspace@1__:ASIC_STATE:%s*" % objpfx)
+        return pubsub
+
+    def CountSubscribedObjects(self, pubsub, timeout=10):
+        nadd = 0
+        ndel = 0
+        idle = 0
+        while True and idle < timeout:
+            message = pubsub.get_message()
+            if message:
+                print message
+                if message['data'] == 'hset':
+                    nadd += 1
+                elif message['data'] == 'del':
+                    ndel += 1
+                idle = 0
+            else:
+                time.sleep(1)
+                idle += 1
+
+        return (nadd, ndel)
+
     def get_map_iface_bridge_port_id(self, asic_db):
         port_id_2_iface = self.asicdb.portoidmap
         tbl = swsscommon.Table(asic_db, "ASIC_STATE:SAI_OBJECT_TYPE_BRIDGE_PORT")

tests/test_warm_reboot.py

@@ -114,15 +114,6 @@ def how_many_entries_exist(db, table):
     tbl =  swsscommon.Table(db, table)
     return len(tbl.getKeys())
 
-# No create/set/remove operations should be passed down to syncd for vlanmgr/portsyncd warm restart
-def checkCleanSaiRedisCSR(dvs):
-    (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep \|c\| /var/log/swss/sairedis.rec | wc -l'])
-    assert num == '0\n'
-    (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep \|s\| /var/log/swss/sairedis.rec | wc -l'])
-    assert num == '0\n'
-    (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep \|r\| /var/log/swss/sairedis.rec | wc -l'])
-    assert num == '0\n'
-
 def test_PortSyncdWarmRestart(dvs):
 
     conf_db = swsscommon.DBConnector(swsscommon.CONFIG_DB, dvs.redis_sock, 0)
@@ -169,11 +160,14 @@ def test_PortSyncdWarmRestart(dvs):
     restore_count = swss_get_RestoreCount(state_db)
 
     # restart portsyncd
-    dvs.runcmd(['sh', '-c', 'pkill -x portsyncd; cp /var/log/swss/sairedis.rec /var/log/swss/sairedis.rec.b; echo > /var/log/swss/sairedis.rec'])
+    dvs.runcmd(['sh', '-c', 'pkill -x portsyncd'])
+
+    pubsub = dvs.SubscribeAsicDbObject("SAI_OBJECT_TYPE")
     dvs.runcmd(['sh', '-c', 'supervisorctl start portsyncd'])
-    time.sleep(2)
 
-    checkCleanSaiRedisCSR(dvs)
+    (nadd, ndel) = dvs.CountSubscribedObjects(pubsub)
+    assert nadd == 0
+    assert ndel == 0
 
     #new ip on server 5
     dvs.servers[5].runcmd("ifconfig eth0 11.0.0.11/29")
@@ -276,14 +270,19 @@ def test_VlanMgrdWarmRestart(dvs):
 
     restore_count = swss_get_RestoreCount(state_db)
 
-    dvs.runcmd(['sh', '-c', 'pkill -x vlanmgrd; cp /var/log/swss/sairedis.rec /var/log/swss/sairedis.rec.b; echo > /var/log/swss/sairedis.rec'])
+    dvs.runcmd(['sh', '-c', 'pkill -x vlanmgrd'])
+
+    pubsub = dvs.SubscribeAsicDbObject("SAI_OBJECT_TYPE")
+
     dvs.runcmd(['sh', '-c', 'supervisorctl start vlanmgrd'])
     time.sleep(2)
 
     (exitcode, bv_after) = dvs.runcmd("bridge vlan")
     assert bv_after == bv_before
 
-    checkCleanSaiRedisCSR(dvs)
+    (nadd, ndel) = dvs.CountSubscribedObjects(pubsub)
+    assert nadd == 0
+    assert ndel == 0
 
     #new ip on server 5
     dvs.servers[5].runcmd("ifconfig eth0 11.0.0.11/29")
@@ -297,13 +296,8 @@ def test_VlanMgrdWarmRestart(dvs):
 
     swss_app_check_RestoreCount_single(state_db, restore_count, "vlanmgrd")
 
-# function to stop neighsyncd service and clear syslog and sairedis records
-def stop_neighsyncd_clear_syslog_sairedis(dvs, save_number):
+def stop_neighsyncd(dvs):
     dvs.runcmd(['sh', '-c', 'pkill -x neighsyncd'])
-    dvs.runcmd("cp /var/log/swss/sairedis.rec /var/log/swss/sairedis.rec.back{}".format(save_number))
-    dvs.runcmd(['sh', '-c', '> /var/log/swss/sairedis.rec'])
-    dvs.runcmd("cp /var/log/syslog /var/log/syslog.back{}".format(save_number))
-    dvs.runcmd(['sh', '-c', '> /var/log/syslog'])
 
 def start_neighsyncd(dvs):
     dvs.runcmd(['sh', '-c', 'supervisorctl start neighsyncd'])
@@ -313,37 +307,20 @@ def check_no_neighsyncd_timer(dvs):
     assert string.strip() != ""
 
 def check_neighsyncd_timer(dvs, timer_value):
-    (exitcode, num) = dvs.runcmd(['sh', '-c', "grep getWarmStartTimer /var/log/syslog | grep neighsyncd | rev | cut -d ' ' -f 1 | rev"])
+    (exitcode, num) = dvs.runcmd(['sh', '-c', "grep getWarmStartTimer /var/log/syslog | grep neighsyncd | tail -n 1 | rev | cut -d ' ' -f 1 | rev"])
     assert num.strip() == timer_value
 
 # function to check neighbor entry reconciliation status written in syslog
-def check_syslog_for_neighbor_entry(dvs, new_cnt, delete_cnt, iptype):
+def check_syslog_for_neighbor_entry(dvs, marker, new_cnt, delete_cnt, iptype):
     # check reconciliation results (new or delete entries) for ipv4 and ipv6
-    if iptype == "ipv4":
-        (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep neighsyncd /var/log/syslog| grep cache-state:NEW | grep IPv4 | wc -l'])
+    if iptype == "ipv4" or iptype == "ipv6":
+        (exitcode, num) = dvs.runcmd(['sh', '-c', "awk \'/%s/,ENDFILE {print;}\' /var/log/syslog | grep neighsyncd | grep cache-state:NEW | grep -i %s | wc -l" % (marker, iptype)])
         assert num.strip() == str(new_cnt)
-        (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep neighsyncd /var/log/syslog| grep cache-state:DELETE | grep IPv4 | wc -l'])
-        assert num.strip() == str(delete_cnt)
-    elif iptype == "ipv6":
-        (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep neighsyncd /var/log/syslog| grep cache-state:NEW | grep IPv6 | wc -l'])
-        assert num.strip() == str(new_cnt)
-        (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep neighsyncd /var/log/syslog| grep cache-state:DELETE | grep IPv6 | wc -l'])
+        (exitcode, num) = dvs.runcmd(['sh', '-c', "awk \'/%s/,ENDFILE {print;}\' /var/log/syslog | grep neighsyncd | grep -E \"cache-state:(DELETE|STALE)\" | grep -i %s | wc -l" % (marker, iptype)])
         assert num.strip() == str(delete_cnt)
     else:
         assert "iptype is unknown" == ""
 
-
-# function to check sairedis record for neighbor entries
-def check_sairedis_for_neighbor_entry(dvs, create_cnt, set_cnt, remove_cnt):
-    # check create/set/remove operations for neighbor entries during warm restart
-    (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep \|c\| /var/log/swss/sairedis.rec | grep NEIGHBOR_ENTRY | wc -l'])
-    assert num.strip() == str(create_cnt)
-    (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep \|s\| /var/log/swss/sairedis.rec | grep NEIGHBOR_ENTRY | wc -l'])
-    assert num.strip() == str(set_cnt)
-    (exitcode, num) = dvs.runcmd(['sh', '-c', 'grep \|r\| /var/log/swss/sairedis.rec | grep NEIGHBOR_ENTRY | wc -l'])
-    assert num.strip() == str(remove_cnt)
-
-
 def test_swss_neighbor_syncup(dvs):
 
     appl_db = swsscommon.DBConnector(swsscommon.APPL_DB, dvs.redis_sock, 0)
@@ -414,9 +391,10 @@ def test_swss_neighbor_syncup(dvs):
     # get restore_count
     restore_count = swss_get_RestoreCount(state_db)
 
-    # stop neighsyncd and clear syslog and sairedis.rec
-    stop_neighsyncd_clear_syslog_sairedis(dvs, 1)
-
+    # stop neighsyncd and sairedis.rec
+    stop_neighsyncd(dvs)
+    marker = dvs.add_log_marker()
+    pubsub = dvs.SubscribeAsicDbObject("SAI_OBJECT_TYPE_NEIGHBOR_ENTRY")
     start_neighsyncd(dvs)
     time.sleep(10)
 
@@ -442,9 +420,11 @@ def test_swss_neighbor_syncup(dvs):
                 assert v[1] == "IPv6"
 
     # check syslog and sairedis.rec file for activities
-    check_syslog_for_neighbor_entry(dvs, 0, 0, "ipv4")
-    check_syslog_for_neighbor_entry(dvs, 0, 0, "ipv6")
-    check_sairedis_for_neighbor_entry(dvs, 0, 0, 0)
+    check_syslog_for_neighbor_entry(dvs, marker, 0, 0, "ipv4")
+    check_syslog_for_neighbor_entry(dvs, marker, 0, 0, "ipv6")
+    (nadd, ndel) = dvs.CountSubscribedObjects(pubsub)
+    assert nadd == 0
+    assert ndel == 0
 
     # check restore Count
     swss_app_check_RestoreCount_single(state_db, restore_count, "neighsyncd")
@@ -460,8 +440,9 @@ def test_swss_neighbor_syncup(dvs):
     # get restore_count
     restore_count = swss_get_RestoreCount(state_db)
 
-    # stop neighsyncd and clear syslog and sairedis.rec
-    stop_neighsyncd_clear_syslog_sairedis(dvs, 2)
+    # stop neighsyncd
+    stop_neighsyncd(dvs)
+    marker = dvs.add_log_marker()
 
     # delete even nummber of ipv4/ipv6 neighbor entries from each interface
     for i in range(0, len(ips), 2):
@@ -509,33 +490,48 @@ def test_swss_neighbor_syncup(dvs):
 
     # check syslog and sairedis.rec file for activities
     # 2 deletes each for ipv4 and ipv6
-    # 4 remove actions in sairedis
-    check_syslog_for_neighbor_entry(dvs, 0, 2, "ipv4")
-    check_syslog_for_neighbor_entry(dvs, 0, 2, "ipv6")
-    check_sairedis_for_neighbor_entry(dvs, 0, 0, 4)
+    # 4 neighbor removal in asic db
+    check_syslog_for_neighbor_entry(dvs, marker, 0, 2, "ipv4")
+    check_syslog_for_neighbor_entry(dvs, marker, 0, 2, "ipv6")
+    (nadd, ndel) = dvs.CountSubscribedObjects(pubsub)
+    assert nadd == 0
+    assert ndel == 4
+
     # check restore Count
     swss_app_check_RestoreCount_single(state_db, restore_count, "neighsyncd")
 
 
     #
     # Testcase 4:
-    # Stop neighsyncd, add even nummber of ipv4/ipv6 neighbor entries to each interface again,
-    # use "change" due to the kernel behaviour, start neighsyncd.
+    # Stop neighsyncd, add even nummber of ipv4/ipv6 neighbor entries to each interface again, 
+    # Start neighsyncd
     # The neighsyncd is supposed to sync up the entries from kernel after warm restart
     # Check the timer is not retrieved from configDB since it is not configured
 
     # get restore_count
     restore_count = swss_get_RestoreCount(state_db)
 
-    # stop neighsyncd and clear syslog and sairedis.rec
-    stop_neighsyncd_clear_syslog_sairedis(dvs, 3)
+    # stop neighsyncd
+    stop_neighsyncd(dvs)
+    marker = dvs.add_log_marker()
 
     # add even nummber of ipv4/ipv6 neighbor entries to each interface
+    # use "change" if neighbor is in FAILED state
     for i in range(0, len(ips), 2):
-        dvs.runcmd("ip neigh change {} dev {} lladdr {}".format(ips[i], intfs[i%2], macs[i]))
+        (rc, output) = dvs.runcmd(['sh', '-c', "ip -4 neigh | grep {}".format(ips[i])])
+        print output
+        if rc == 0:
+            dvs.runcmd("ip neigh change {} dev {} lladdr {}".format(ips[i], intfs[i%2], macs[i]))
+        else:
+            dvs.runcmd("ip neigh add {} dev {} lladdr {}".format(ips[i], intfs[i%2], macs[i]))
 
     for i in range(0, len(v6ips), 2):
-        dvs.runcmd("ip -6 neigh change {} dev {} lladdr {}".format(v6ips[i], intfs[i%2], macs[i]))
+        (rc, output) = dvs.runcmd(['sh', '-c', "ip -6 neigh | grep {}".format(v6ips[i])])
+        print output
+        if rc == 0:
+            dvs.runcmd("ip -6 neigh change {} dev {} lladdr {}".format(v6ips[i], intfs[i%2], macs[i]))
+        else:
+            dvs.runcmd("ip -6 neigh add {} dev {} lladdr {}".format(v6ips[i], intfs[i%2], macs[i]))
 
     # start neighsyncd again
     start_neighsyncd(dvs)
@@ -563,12 +559,15 @@ def test_swss_neighbor_syncup(dvs):
             if v[0] == "family":
                 assert v[1] == "IPv6"
 
-    # check syslog and sairedis.rec file for activities
+    # check syslog and asic db for activities
     # 2 news entries for ipv4 and ipv6 each
-    # 4 create actions for sairedis
-    check_syslog_for_neighbor_entry(dvs, 2, 0, "ipv4")
-    check_syslog_for_neighbor_entry(dvs, 2, 0, "ipv6")
-    check_sairedis_for_neighbor_entry(dvs, 4, 0, 0)
+    # 4 neighbor creation in asic db
+    check_syslog_for_neighbor_entry(dvs, marker, 2, 0, "ipv4")
+    check_syslog_for_neighbor_entry(dvs, marker, 2, 0, "ipv6")
+    (nadd, ndel) = dvs.CountSubscribedObjects(pubsub)
+    assert nadd == 4
+    assert ndel == 0
+
     # check restore Count
     swss_app_check_RestoreCount_single(state_db, restore_count, "neighsyncd")
 
@@ -587,8 +586,9 @@ def test_swss_neighbor_syncup(dvs):
     # get restore_count
     restore_count = swss_get_RestoreCount(state_db)
 
-    # stop neighsyncd and clear syslog and sairedis.rec
-    stop_neighsyncd_clear_syslog_sairedis(dvs, 4)
+    # stop neighsyncd
+    stop_neighsyncd(dvs)
+    marker = dvs.add_log_marker()
 
     # Even number of ip4/6 neigbors updated with new mac.
     # Odd number of ipv4/6 neighbors removed and added to different interfaces.
@@ -656,12 +656,16 @@ def test_swss_neighbor_syncup(dvs):
                 if v[0] == "family":
                     assert v[1] == "IPv6"
 
-    # check syslog and sairedis.rec file for activities
+    time.sleep(2)
+
+    # check syslog and asic db for activities
     # 4 news, 2 deletes for ipv4 and ipv6 each
-    # 8 create, 4 set, 4 removes for sairedis
-    check_syslog_for_neighbor_entry(dvs, 4, 2, "ipv4")
-    check_syslog_for_neighbor_entry(dvs, 4, 2, "ipv6")
-    check_sairedis_for_neighbor_entry(dvs, 4, 4, 4)
+    # 4 create, 4 set, 4 removes for neighbor in asic db
+    check_syslog_for_neighbor_entry(dvs, marker, 4, 2, "ipv4")
+    check_syslog_for_neighbor_entry(dvs, marker, 4, 2, "ipv6")
+    (nadd, ndel) = dvs.CountSubscribedObjects(pubsub)
+    assert nadd == 8
+    assert ndel == 4
 
     # check restore Count
     swss_app_check_RestoreCount_single(state_db, restore_count, "neighsyncd")