From 5e2c1de0206d034a6e51d8408c170b03e7e926ac Mon Sep 17 00:00:00 2001 From: Guohan Lu Date: Sat, 20 Oct 2018 09:33:41 +0000 Subject: [PATCH] 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 --- tests/conftest.py | 35 +++++++++ tests/test_warm_reboot.py | 148 +++++++++++++++++++------------------- 2 files changed, 111 insertions(+), 72 deletions(-) diff --git a/tests/conftest.py b/tests/conftest.py index 3afd6fb43550..9e28703c3429 100644 --- a/tests/conftest.py +++ b/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") diff --git a/tests/test_warm_reboot.py b/tests/test_warm_reboot.py index 3757aa756246..7db91e40a757 100644 --- a/tests/test_warm_reboot.py +++ b/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")