From 2d2749ab77ea0cfb9b1a9a0a5c7eeffbde9daed8 Mon Sep 17 00:00:00 2001 From: vdahiya12 <67608553+vdahiya12@users.noreply.github.com> Date: Thu, 24 Jun 2021 09:28:24 -0700 Subject: [PATCH] [xcvrd] add debug logs for y_cable change events/probes (#195) This PR adds support for logging required in debugging events for change/probe requests received by xcvrd from swss and linkmgr into state DB. a typical log would look like this: Jun 17 05:55:39.302379 NOTICE pmon#xcvrd[33]: Y_CABLE_DEBUG: trying to enable/disable debug logs Jun 17 05:55:39.302379 NOTICE pmon#xcvrd[33]: Y_CABLE_DEBUG: received an event for port transition Ethernet4 Jun 17 05:55:39.302575 NOTICE pmon#xcvrd[33]: Y_CABLE_DEBUG: xcvrd trying to transition port Ethernet4 from standby to active Jun 17 05:55:39.307872 NOTICE pmon#xcvrd[33]: Y_CABLE_DEBUG: Successful in toggling mux to ToR A for port 2 where both probe events and change events are logged inside xcvrd. Motivation and Context This is required for xcvrd to log the events which it receives from other modules when we want to see the completion of events as to what triggered the event and at which stage it failed without restarting pmon/xcvrd Signed-off-by: vaibhav-dahiya --- .../xcvrd/xcvrd_utilities/y_cable_helper.py | 51 ++++++++++++++++++- 1 file changed, 50 insertions(+), 1 deletion(-) diff --git a/sonic-xcvrd/xcvrd/xcvrd_utilities/y_cable_helper.py b/sonic-xcvrd/xcvrd/xcvrd_utilities/y_cable_helper.py index 0857d8323a49..4ac4b4de034b 100644 --- a/sonic-xcvrd/xcvrd/xcvrd_utilities/y_cable_helper.py +++ b/sonic-xcvrd/xcvrd/xcvrd_utilities/y_cable_helper.py @@ -68,6 +68,8 @@ def update_table_mux_status_for_response_tbl(table_name, status, logical_port_na fvs = swsscommon.FieldValuePairs([('response', status)]) table_name.set(logical_port_name, fvs) + helper_logger.log_debug("Y_CABLE_DEBUG: Successful in returning probe port status {}".format(logical_port_name)) + def update_table_mux_status_for_statedb_port_tbl(table_name, status, read_side, active_side, logical_port_name): fvs = swsscommon.FieldValuePairs([('state', status), @@ -78,6 +80,8 @@ def update_table_mux_status_for_statedb_port_tbl(table_name, status, read_side, def y_cable_toggle_mux_torA(physical_port): update_status = y_cable.toggle_mux_to_torA(physical_port) + + helper_logger.log_debug("Y_CABLE_DEBUG: Status of toggling mux to ToR A for port {} {}".format(physical_port, update_status)) if update_status is True: return 1 else: @@ -88,6 +92,8 @@ def y_cable_toggle_mux_torA(physical_port): def y_cable_toggle_mux_torB(physical_port): update_status = y_cable.toggle_mux_to_torB(physical_port) + + helper_logger.log_debug("Y_CABLE_DEBUG: Status of toggling mux to ToR B for port {} {}".format(physical_port, update_status)) if update_status is True: return 2 else: @@ -173,6 +179,8 @@ def update_appdb_port_mux_cable_response_table(logical_port_name, asic_index, ap helper_logger.log_warning( "Error: Could not get state for mux cable port probe command logical port {} and physical port {}".format(logical_port_name, physical_port)) + helper_logger.log_debug("Y_CABLE_DEBUG: notifying a probe for port status {} {}".format(logical_port_name, status)) + update_table_mux_status_for_response_tbl(y_cable_response_tbl[asic_index], status, logical_port_name) else: @@ -347,10 +355,12 @@ def init_ports_status_for_y_cable(platform_sfp, platform_chassis, y_cable_presen config_db, state_db, port_tbl, y_cable_tbl = {}, {}, {}, {} static_tbl, mux_tbl = {}, {} port_table_keys = {} + xcvrd_log_tbl = {} y_cable_platform_sfputil = platform_sfp y_cable_platform_chassis = platform_chassis + fvs_updated = swsscommon.FieldValuePairs([('enable_log', 'false')]) # Get the namespaces in the platform namespaces = multi_asic.get_front_end_namespaces() for namespace in namespaces: @@ -358,6 +368,8 @@ def init_ports_status_for_y_cable(platform_sfp, platform_chassis, y_cable_presen config_db[asic_id] = daemon_base.db_connect("CONFIG_DB", namespace) port_tbl[asic_id] = swsscommon.Table(config_db[asic_id], "MUX_CABLE") port_table_keys[asic_id] = port_tbl[asic_id].getKeys() + xcvrd_log_tbl[asic_id] = swsscommon.Table(config_db[asic_id], "XCVRD_LOG") + xcvrd_log_tbl[asic_id].set("Y_CABLE", fvs_updated ) # Init PORT_STATUS table if ports are on Y cable logical_port_list = y_cable_platform_sfputil.logical @@ -996,10 +1008,11 @@ def __init__(self): def task_worker(self): # Connect to STATE_DB and APPL_DB and get both the HW_MUX_STATUS_TABLE info - appl_db, state_db, status_tbl, y_cable_tbl = {}, {}, {}, {} + appl_db, state_db, config_db, status_tbl, y_cable_tbl = {}, {}, {}, {}, {} y_cable_tbl_keys = {} mux_cable_command_tbl, y_cable_command_tbl = {}, {} mux_metrics_tbl = {} + xcvrd_log_tbl = {} sel = swsscommon.Select() @@ -1009,6 +1022,7 @@ def task_worker(self): # Open a handle to the Application database, in all namespaces asic_id = multi_asic.get_asic_index_from_namespace(namespace) appl_db[asic_id] = daemon_base.db_connect("APPL_DB", namespace) + config_db[asic_id] = daemon_base.db_connect("CONFIG_DB", namespace) status_tbl[asic_id] = swsscommon.SubscriberStateTable( appl_db[asic_id], swsscommon.APP_HW_MUX_CABLE_TABLE_NAME) mux_cable_command_tbl[asic_id] = swsscommon.SubscriberStateTable( @@ -1020,9 +1034,12 @@ def task_worker(self): state_db[asic_id], swsscommon.STATE_HW_MUX_CABLE_TABLE_NAME) mux_metrics_tbl[asic_id] = swsscommon.Table( state_db[asic_id], swsscommon.STATE_MUX_METRICS_TABLE_NAME) + xcvrd_log_tbl[asic_id] = swsscommon.SubscriberStateTable( + config_db[asic_id], "XCVRD_LOG") y_cable_tbl_keys[asic_id] = y_cable_tbl[asic_id].getKeys() sel.addSelectable(status_tbl[asic_id]) sel.addSelectable(mux_cable_command_tbl[asic_id]) + sel.addSelectable(xcvrd_log_tbl[asic_id]) # Listen indefinitely for changes to the HW_MUX_CABLE_TABLE in the Application DB's while True: @@ -1048,9 +1065,12 @@ def task_worker(self): while True: (port, op, fvp) = status_tbl[asic_index].pop() + if not port: break + helper_logger.log_debug("Y_CABLE_DEBUG: received an event for port transition {}".format(port)) + # entering this section signifies a start for xcvrd state # change request from swss so initiate recording in mux_metrics table time_start = datetime.datetime.utcnow().strftime("%Y-%b-%d %H:%M:%S.%f") @@ -1075,6 +1095,7 @@ def task_worker(self): old_status = mux_port_dict.get("state") read_side = mux_port_dict.get("read_side") # Now whatever is the state requested, toggle the mux appropriately + helper_logger.log_debug("Y_CABLE_DEBUG: xcvrd trying to transition port {} from {} to {}".format(port, old_status, new_status)) active_side = update_tor_active_side(read_side, new_status, port) if active_side == -1: helper_logger.log_warning("ERR: Got a change event for toggle but could not toggle the mux-direction for port {} state from {} to {}, writing unknown".format( @@ -1085,6 +1106,7 @@ def task_worker(self): ('read_side', read_side), ('active_side', str(active_side))]) y_cable_tbl[asic_index].set(port, fvs_updated) + helper_logger.log_debug("Y_CABLE_DEBUG: xcvrd successful to transition port {} from {} to {} and write back to the DB".format(port, old_status, new_status)) helper_logger.log_info("Got a change event for toggle the mux-direction active side for port {} state from {} to {}".format( port, old_status, new_status)) time_end = datetime.datetime.utcnow().strftime("%Y-%b-%d %H:%M:%S.%f") @@ -1097,8 +1119,11 @@ def task_worker(self): while True: (port_m, op_m, fvp_m) = mux_cable_command_tbl[asic_index].pop() + if not port_m: break + helper_logger.log_debug("Y_CABLE_DEBUG: received a probe for port status {}".format(port_m)) + if fvp_m: if port_m not in y_cable_tbl_keys[asic_index]: @@ -1120,6 +1145,30 @@ def task_worker(self): read_side = mux_port_dict.get("read_side") update_appdb_port_mux_cable_response_table(port_m, asic_index, appl_db, int(read_side)) + while True: + (key, op_m, fvp_m) = xcvrd_log_tbl[asic_index].pop() + + if not key: + break + + helper_logger.log_notice("Y_CABLE_DEBUG: trying to enable/disable debug logs") + if fvp_m: + + if key is "Y_CABLE": + continue + + fvp_dict = dict(fvp_m) + if "log_verbosity" in fvp_dict: + # check if xcvrd got a probe command + probe_identifier = fvp_dict["log_verbosity"] + + if probe_identifier == "debug": + helper_logger.set_min_log_priority_debug() + + elif probe_identifier == "notice": + helper_logger.set_min_log_priority_notice() + + def task_run(self): self.task_thread = threading.Thread(target=self.task_worker) self.task_thread.start()