Replace logging.xxx with logger.xxx in common libs (sonic-net#7450)

What is the motivation for this PR?
The devutils script supports output results to a json. To ensure that json output is not polluted by error messages, we need to redirect error messages to /dev/null.

The devutils script called library code in snmp_pdu_controller.py in multiple threads.

The library uses logging.error() to log error messages. Somehow, the error messages are output to stdout instead of stderr. If we run the devutils script with bash option 2>/dev/null to hide error messages, it does not work. The error messages are still output to stdout.

After changed logging.error() to logger.error(), then redirecting stderr to /dev/null works.

This change also updated some other libraries to use logger.xxx instead of logging.xxx.

How did you do it?
This change updated some common libraries to use logger.xxx instead of logging.xxx.

Signed-off-by: Xin Wang <[email protected]>

tests/common/devices/base.py

@@ -20,7 +20,7 @@
     from ansible.executor import task_result
     task_result._IGNORE = ('skipped', )
 except Exception as e:
-    logging.error("Hack for https://github.com/ansible/pytest-ansible/issues/47 failed: {}".format(repr(e)))
+    logger.error("Hack for https://github.com/ansible/pytest-ansible/issues/47 failed: {}".format(repr(e)))
 
 
 class AnsibleHostBase(object):
@@ -58,11 +58,11 @@ def _run(self, *module_args, **complex_args):
         verbose = complex_args.pop('verbose', True)
 
         if verbose:
-            logging.debug("{}::{}#{}: [{}] AnsibleModule::{}, args={}, kwargs={}"
+            logger.debug("{}::{}#{}: [{}] AnsibleModule::{}, args={}, kwargs={}"
                           .format(filename, function_name, line_number, self.hostname,
                                   self.module_name, json.dumps(module_args), json.dumps(complex_args)))
         else:
-            logging.debug("{}::{}#{}: [{}] AnsibleModule::{} executing..."
+            logger.debug("{}::{}#{}: [{}] AnsibleModule::{} executing..."
                           .format(filename, function_name, line_number, self.hostname, self.module_name))
 
         module_ignore_errors = complex_args.pop('module_ignore_errors', False)
@@ -78,11 +78,11 @@ def run_module(module_args, complex_args):
         res = self.module(*module_args, **complex_args)[self.hostname]
 
         if verbose:
-            logging.debug("{}::{}#{}: [{}] AnsibleModule::{} Result => {}"
+            logger.debug("{}::{}#{}: [{}] AnsibleModule::{} Result => {}"
                           .format(filename, function_name, line_number,
                                   self.hostname, self.module_name, json.dumps(res)))
         else:
-            logging.debug("{}::{}#{}: [{}] AnsibleModule::{} done, is_failed={}, rc={}"
+            logger.debug("{}::{}#{}: [{}] AnsibleModule::{} done, is_failed={}, rc={}"
                           .format(filename, function_name, line_number, self.hostname,
                                   self.module_name, res.is_failed, res.get('rc', None)))
 

tests/common/dualtor/nic_simulator_control.py

@@ -52,14 +52,14 @@ def call_grpc(func, args=None, kwargs=None, timeout=5, retries=3, ignore_errors=
             response = func(*args, **kwargs)
         except grpc.RpcError as e:
             # first retries - 1 tries errors are all ignored
-            logging.debug("Calling %s %dth time results error(%r)" % (func, i + 1, e))
+            logger.debug("Calling %s %dth time results error(%r)" % (func, i + 1, e))
         else:
             return response
 
     try:
         response = func(*args, **kwargs)
     except grpc.RpcError as e:
-        logging.debug("Calling %s %dth time results error(%r)" % (func, retries, e))
+        logger.debug("Calling %s %dth time results error(%r)" % (func, retries, e))
         if not ignore_errors:
             raise
 
@@ -277,7 +277,7 @@ def _set_drop_active_active(interface_names, portids, directions):
         nic_addresses = []
         for interface_name, portid, direction in zip(interface_names, portids, directions):
             nic_address = mux_config[interface_name]["SERVER"]["soc_ipv4"].split("/")[0]
-            logging.debug(
+            logger.debug(
                 "Set drop on port %s, mux server %s, portid %s, direction %s",
                 interface_name, nic_address, portid, direction
             )
@@ -293,7 +293,7 @@ def _set_drop_active_active(interface_names, portids, directions):
     yield _set_drop_active_active
 
     for (interface_name, nic_address, portid, _) in zip(_interface_names, _nic_addresses, _portids, _directions):
-        logging.debug(
+        logger.debug(
             "Set drop recover on port %s, mux server %s, portid %s",
             interface_name, nic_address, portid,
         )
@@ -305,7 +305,7 @@ def toggle_active_active_simulator_ports(active_active_ports_config, nic_simulat
     """Toggle nic_simulator forwarding state."""
 
     def _toggle_active_active_simulator_ports(mux_ports, portid, state):
-        logging.info("Toggle simulator ports %s to %s", mux_ports, state)
+        logger.info("Toggle simulator ports %s to %s", mux_ports, state)
         if not mux_ports:
             return
 

tests/common/fixtures/ptfhost_utils.py

@@ -81,7 +81,7 @@ def set_ptf_port_mapping_mode(ptfhost, request, tbinfo):
         ptf_port_mapping_mode = getattr(request.module, "PTF_PORT_MAPPING_MODE", constants.PTF_PORT_MAPPING_MODE_DEFAULT)
     else:
         ptf_port_mapping_mode = "use_orig_interface"
-    logging.info("Set ptf port mapping mode: %s", ptf_port_mapping_mode)
+    logger.info("Set ptf port mapping mode: %s", ptf_port_mapping_mode)
     data = {
         "PTF_PORT_MAPPING_MODE": ptf_port_mapping_mode
     }
@@ -126,7 +126,7 @@ def change_mac_addresses(ptfhost):
     # socket read/write operations, so let's restart icmp_responder if it is running
     icmp_responder_status = ptfhost.shell("supervisorctl status icmp_responder", module_ignore_errors=True)
     if icmp_responder_status["rc"] == 0 and "RUNNING" in icmp_responder_status["stdout"]:
-        logging.debug("restart icmp_responder after change ptf port mac addresses")
+        logger.debug("restart icmp_responder after change ptf port mac addresses")
         ptfhost.shell("supervisorctl restart icmp_responder", module_ignore_errors=True)
 
 
@@ -238,7 +238,7 @@ def run_icmp_responder_session(duthosts, duthost, ptfhost, tbinfo):
     logger.debug("Copy icmp_responder.py to ptfhost '{0}'".format(ptfhost.hostname))
     ptfhost.copy(src=os.path.join(SCRIPTS_SRC_DIR, ICMP_RESPONDER_PY), dest=OPT_DIR)
 
-    logging.info("Start running icmp_responder")
+    logger.info("Start running icmp_responder")
     templ = Template(open(os.path.join(TEMPLATES_DIR, ICMP_RESPONDER_CONF_TEMPL)).read())
     ptf_indices = duthost.get_extended_minigraph_facts(tbinfo)["minigraph_ptf_indices"]
     vlan_intfs = duthost.get_vlan_intfs()
@@ -286,7 +286,7 @@ def run_icmp_responder(duthosts, rand_one_dut_hostname, ptfhost, tbinfo, request
     logger.debug("Copy icmp_responder.py to ptfhost '{0}'".format(ptfhost.hostname))
     ptfhost.copy(src=os.path.join(SCRIPTS_SRC_DIR, ICMP_RESPONDER_PY), dest=OPT_DIR)
 
-    logging.info("Start running icmp_responder")
+    logger.info("Start running icmp_responder")
     templ = Template(open(os.path.join(TEMPLATES_DIR, ICMP_RESPONDER_CONF_TEMPL)).read())
     ptf_indices = duthost.get_extended_minigraph_facts(tbinfo)["minigraph_ptf_indices"]
     vlan_intfs = duthost.get_vlan_intfs()
@@ -304,9 +304,9 @@ def run_icmp_responder(duthosts, rand_one_dut_hostname, ptfhost, tbinfo, request
 
     yield
 
-    logging.info("Stop running icmp_responder")
+    logger.info("Stop running icmp_responder")
     ptfhost.shell("supervisorctl stop icmp_responder")
-    logging.info("Recover linkmgrd probe interval")
+    logger.info("Recover linkmgrd probe interval")
     recover_linkmgrd_probe_interval(duthosts, tbinfo)
     duthosts.shell("config save -y")
 

tests/common/helpers/pfc_gen.py

@@ -11,8 +11,8 @@
 import logging.handlers
 from socket import socket, AF_PACKET, SOCK_RAW
 
-my_logger = logging.getLogger('MyLogger')
-my_logger.setLevel(logging.DEBUG)
+logger = logging.getLogger('MyLogger')
+logger.setLevel(logging.DEBUG)
 
 
 def checksum(msg):
@@ -83,7 +83,7 @@ def main():
 
     # Configure logging
     handler = logging.handlers.SysLogHandler(address=(options.rsyslog_server, 514))
-    my_logger.addHandler(handler)
+    logger.addHandler(handler)
 
     for s, interface in zip(sockets, interfaces):
         s.bind((interface, 0))
@@ -152,13 +152,13 @@ def main():
 
     pre_str = 'GLOBAL_PF' if options.global_pf else 'PFC'
     print("Generating %s Packet(s)" % options.num)
-    my_logger.debug(pre_str + '_STORM_START')
+    logger.debug(pre_str + '_STORM_START')
     iteration = options.num
     while iteration > 0:
         for s in sockets:
             s.send(packet)
         iteration -= 1
-    my_logger.debug(pre_str + '_STORM_END')
+    logger.debug(pre_str + '_STORM_END')
 
 
 if __name__ == "__main__":

tests/common/plugins/pdu_controller/snmp_pdu_controllers.py

@@ -113,7 +113,7 @@ def _probe_lane(self, lane_id, cmdGen, snmp_auth):
             cmdgen.MibVariable(query_oid)
         )
         if errorIndication:
-            logging.debug("Failed to get ports controlling PSUs of DUT, exception: " + str(errorIndication))
+            logger.debug("Failed to get ports controlling PSUs of DUT, exception: " + str(errorIndication))
         else:
             for varBinds in varTable:
                 for oid, val in varBinds:
@@ -131,7 +131,7 @@ def _get_pdu_ports(self):
         This method depends on this configuration to find out the PDU ports connected to PSUs of specific DUT.
         """
         if not self.pduType:
-            logging.error('PDU type is unknown: pdu_ip {}'.format(self.controller))
+            logger.error('PDU type is unknown: pdu_ip {}'.format(self.controller))
             return
 
         cmdGen = cmdgen.CommandGenerator()
@@ -141,7 +141,7 @@ def _get_pdu_ports(self):
             self._probe_lane(lane_id, cmdGen, snmp_auth)
 
     def __init__(self, controller, pdu, hwsku):
-        logging.info("Initializing " + self.__class__.__name__)
+        logger.info("Initializing " + self.__class__.__name__)
         PduControllerBase.__init__(self)
         self.controller = controller
         self.snmp_rocommunity = pdu['snmp_rocommunity']
@@ -151,7 +151,7 @@ def __init__(self, controller, pdu, hwsku):
         self.port_label_dict = {}
         self.pduCntrlOid()
         self._get_pdu_ports()
-        logging.info("Initialized " + self.__class__.__name__)
+        logger.info("Initialized " + self.__class__.__name__)
 
     def turn_on_outlet(self, outlet):
         """
@@ -167,7 +167,7 @@ def turn_on_outlet(self, outlet):
         @return: Return true if successfully execute the command for turning on power. Otherwise return False.
         """
         if not self.pduType:
-            logging.error('Unable to turn on: PDU type is unknown: pdu_ip {}'.format(self.controller))
+            logger.error('Unable to turn on: PDU type is unknown: pdu_ip {}'.format(self.controller))
             return False
 
         port_oid = '.' + self.PORT_CONTROL_BASE_OID + outlet
@@ -178,7 +178,7 @@ def turn_on_outlet(self, outlet):
                 (port_oid, rfc1902.Integer(self.CONTROL_ON))
             )
         if errorIndication or errorStatus != 0:
-            logging.debug("Failed to turn on outlet %s, exception: %s" % (str(outlet), str(errorStatus)))
+            logger.debug("Failed to turn on outlet %s, exception: %s" % (str(outlet), str(errorStatus)))
             return False
         return True
 
@@ -196,7 +196,7 @@ def turn_off_outlet(self, outlet):
         @return: Return true if successfully execute the command for turning off power. Otherwise return False.
         """
         if not self.pduType:
-            logging.error('Unable to turn off: PDU type is unknown: pdu_ip {}'.format(self.controller))
+            logger.error('Unable to turn off: PDU type is unknown: pdu_ip {}'.format(self.controller))
             return False
 
         port_oid = '.' + self.PORT_CONTROL_BASE_OID + outlet
@@ -207,7 +207,7 @@ def turn_off_outlet(self, outlet):
                 (port_oid, rfc1902.Integer(self.CONTROL_OFF))
             )
         if errorIndication or errorStatus != 0:
-            logging.debug("Failed to turn off outlet %s, exception: %s" % (str(outlet), str(errorStatus)))
+            logger.debug("Failed to turn off outlet %s, exception: %s" % (str(outlet), str(errorStatus)))
             return False
         return True
 
@@ -222,7 +222,7 @@ def _get_one_outlet_power(self, cmdGen, snmp_auth, port_id, status):
             cmdgen.MibVariable(query_id)
         )
         if errorIndication:
-            logging.debug("Failed to get outlet power level of DUT outlet, exception: " + str(errorIndication))
+            logger.debug("Failed to get outlet power level of DUT outlet, exception: " + str(errorIndication))
 
         for oid, val in varBinds:
             oid = oid.getOid() if hasattr(oid, 'getoid') else oid
@@ -241,7 +241,7 @@ def _get_one_outlet_status(self, cmdGen, snmp_auth, port_id):
             cmdgen.MibVariable(query_id)
         )
         if errorIndication:
-            logging.debug("Failed to outlet status of PDU, exception: " + str(errorIndication))
+            logger.debug("Failed to outlet status of PDU, exception: " + str(errorIndication))
 
         for oid, val in varBinds:
             oid = oid.getOid() if hasattr(oid, 'getoid') else oid
@@ -273,7 +273,7 @@ def get_outlet_status(self, outlet=None, hostname=None):
         """
         results = []
         if not self.pduType:
-            logging.error('Unable to retrieve status: PDU type is unknown: pdu_ip {}'.format(self.controller))
+            logger.error('Unable to retrieve status: PDU type is unknown: pdu_ip {}'.format(self.controller))
             return results
 
         if not outlet and not hostname:
@@ -282,12 +282,12 @@ def get_outlet_status(self, outlet=None, hostname=None):
         elif outlet:
             ports = [oid for oid in self.port_oid_dict.keys() if oid.endswith(outlet)]
             if not ports:
-                logging.error("Outlet ID {} doesn't belong to PDU {}".format(outlet, self.controller))
+                logger.error("Outlet ID {} doesn't belong to PDU {}".format(outlet, self.controller))
         elif hostname:
             hn = hostname.lower()
             ports = [self.port_label_dict[label]['port_oid'] for label in self.port_label_dict.keys() if hn in label]
             if not ports:
-                logging.error("{} device is not attached to any outlet of PDU {}".format(hn, self.controller))
+                logger.error("{} device is not attached to any outlet of PDU {}".format(hn, self.controller))
 
         cmdGen = cmdgen.CommandGenerator()
         snmp_auth = cmdgen.CommunityData(self.snmp_rocommunity)
@@ -297,7 +297,7 @@ def get_outlet_status(self, outlet=None, hostname=None):
             if status:
                 results.append(status)
 
-        logging.info("Got outlet status: %s" % str(results))
+        logger.info("Got outlet status: %s" % str(results))
         return results
 
     def close(self):