Feature/alex 202 add logs

drivers/deployment_drivers/openstack_nova_image_instance/driver.py

@@ -35,9 +35,9 @@ def Deploy(self, context, Name=None):
         with LoggingSessionContext(context) as logger:
             with ErrorHandlingContext(logger):
                 with CloudShellSessionContext(context) as session:
-                    logger.debug("Deploy Called for Reservation: {0}".format(context.reservation.reservation_id))
+                    logger.info("Deploy Called for Reservation: {0}".format(context.reservation.reservation_id))
                     # Get CS Session we are going to make an API call using this session
-                    logger.debug("creating session: {0}, {1}, {2}".format(context.connectivity.server_address,
+                    logger.info("creating session: {0}, {1}, {2}".format(context.connectivity.server_address,
                                                                           context.connectivity.admin_auth_token,
                                                                           context.reservation.domain))
 
@@ -48,17 +48,17 @@ def Deploy(self, context, Name=None):
                     app_name = context_json_decoded['name']
                     cloud_provider_name = context_json_decoded["deploymentService"].get("cloudProviderName")
 
-                    logger.debug("cloud_provider_name from context = {0}".format(cloud_provider_name))
+                    logger.info("cloud_provider_name from context = {0}".format(cloud_provider_name))
 
                     if cloud_provider_name:
                         deploy_service_res_model.cloud_provider = str(cloud_provider_name)
 
                     deploy_req = DeployDataHolder({self.APP_NAME: app_name,
                                                    self.IMAGE_PARAM: deploy_service_res_model})
 
-                    logger.debug("Calling the Shell Driver's Deploy method for app: {0}".format(app_name))
+                    logger.info("Calling the Shell Driver's Deploy method for app: {0}".format(app_name))
 
-                    logger.debug("cloud_provider = {0}".format(deploy_service_res_model.cloud_provider))
+                    logger.info("cloud_provider = {0}".format(deploy_service_res_model.cloud_provider))
                     # Calls command on the OpenStack cloud provider
                     result = session.ExecuteCommand(context.reservation.reservation_id,
                                                     deploy_service_res_model.cloud_provider,

package/cloudshell/cp/openstack/command/operations/connectivity_operation.py

@@ -17,7 +17,7 @@ def apply_connectivity(self, openstack_session, cp_resource_model, conn_request,
         :param keystoneauth1.session.Session openstack_session:
         :param OpenStackResourceModel cp_resource_model:
         :param str conn_request: Connectivty Request JSON
-        :param LoggingSessionContext logger:
+        :param logging.Logger logger:
         :return DriverResponseRoot:
         """
 

package/cloudshell/cp/openstack/domain/services/connectivity/vlan_connectivity_service.py

@@ -32,7 +32,7 @@ def perform_apply_connectivity(self, openstack_session, cp_resource_model, conne
         :param keystoneauth1.session.Session openstack_session:
         :param OpenStackResourceModel cp_resource_model:
         :param str connection_request:
-        :param LoggingSessionContext logger:
+        :param logging.Logger logger:
         :return:
         """
 
@@ -48,8 +48,9 @@ def perform_apply_connectivity(self, openstack_session, cp_resource_model, conne
         set_vlan_actions_dict = {}
         remove_vlan_actions_dict = {}
 
+        logger.info("Processing {0} actions and creating mapping between vlan ids to actions".format(len(actions)))
+
         # Add more description
-        # TODO : implement remove actions dict
         for action in actions:
 
             curr_dict = self._get_curr_actions_dict(action_type=action.type,
@@ -58,9 +59,11 @@ def perform_apply_connectivity(self, openstack_session, cp_resource_model, conne
             if curr_dict is None:
                 raise ValueError("Unknown action: Action not one of 'setVlan' or 'removeVlan'.")
 
-            actionid = action.actionId
+            action_id = action.actionId
             deployed_app_res_name = action.actionTarget.fullName
-            action_resource_info = self.get_action_resource_info(deployed_app_res_name, actionid, action)
+            logger.info("Processing action id {0} for target {1}".format(action_id, deployed_app_res_name))
+            action_resource_info = self.get_action_resource_info(deployed_app_res_name, action_id, action)
+            logger.info("Action resource info: {}".format(action_resource_info))
 
             action_vlanid = action.connectionParams.vlanId
             if action_vlanid in curr_dict.keys():
@@ -89,6 +92,8 @@ def perform_apply_connectivity(self, openstack_session, cp_resource_model, conne
         driver_response_root = DriverResponseRoot()
         driver_response_root.driverResponse = driver_response
 
+        logger.info(jsonpickle.dumps(driver_response, unpicklable=False))
+
         return driver_response_root
 
     def _format_err_msg_for_exception(self, e):
@@ -106,17 +111,20 @@ def set_vlan_actions(self, openstack_session, cp_resource_model, vlan_actions, l
         :param keystoneauth1.session.Session openstack_session:
         :param OpenStackResourceModel cp_resource_model:
         :param dict vlan_actions:
-        :param LoggingSessionContext logger:
-        :return ConnectivityActionResult List :
+        :param logging.Logger logger:
+        :rtype: ConnectivityActionResult[]
         """
 
         # For each VLAN ID (create VLAN network)
         results = []
 
+        logger.info("We have {0} 'set vlan' actions to process".format(len(vlan_actions)))
+
         for vlan_id, values in vlan_actions.iteritems():
             net = None
             net_err_msg = ''
             try:
+                logger.info("creating or getting network with segmentation id {}".format(vlan_id))
                 net = self.network_service.create_or_get_network_with_segmentation_id(
                     openstack_session=openstack_session,
                     cp_resource_model=cp_resource_model,
@@ -125,6 +133,7 @@ def set_vlan_actions(self, openstack_session, cp_resource_model, vlan_actions, l
             except Exception as e:
                 logger.error(traceback.format_exc())
                 net_err_msg = self._format_err_msg_for_exception(e)
+
             if not net:
                 fail_results = self.set_fail_results(values=values,
                                                      action_type='setVlan',
@@ -138,6 +147,7 @@ def set_vlan_actions(self, openstack_session, cp_resource_model, vlan_actions, l
                     net_id = net['id']
                     subnet = net['subnets']
                     if not subnet:
+                        logger.info("Its a new network without a subnet so will allocate new CIDR")
                         with self.subnet_lock:
                             subnet = self.network_service.create_and_attach_subnet_to_net(
                                 openstack_session=openstack_session,
@@ -150,6 +160,7 @@ def set_vlan_actions(self, openstack_session, cp_resource_model, vlan_actions, l
                 except Exception as e:
                     logger.error(traceback.format_exc())
                     subnet_err_msg = self._format_err_msg_for_exception(e)
+
                 if not subnet:
                     fail_results = self.set_fail_results(values=values,
                                                          action_type='setVlan',
@@ -158,6 +169,7 @@ def set_vlan_actions(self, openstack_session, cp_resource_model, vlan_actions, l
                     results += fail_results
                 else:
                     attach_results = []
+                    logger.info("Attaching nics to instances")
                     for val in values:
                         action_result = self.attach_nic_to_instance_action_result(openstack_session=openstack_session,
                                                                                   action_resource_info=val,
@@ -173,24 +185,28 @@ def remove_vlan_actions(self, openstack_session, cp_resource_model, vlan_actions
         :param keystoneauth1.session.Session openstack_session:
         :param OpenStckResourceModel cp_resource_model:
         :param dict vlan_actions:
-        :param LoggingSessionContext logger:
+        :param logging.Logger logger:
         :return:
         """
 
+        logger.info("We have {0} 'remove vlan' actions to process".format(len(vlan_actions)))
+
         results = []
 
-        for k, values in vlan_actions.iteritems():
+        for vlan_id, values in vlan_actions.iteritems():
+            logger.info("Finding network with segmentation id {}".format(vlan_id))
             net = self.network_service.get_network_with_segmentation_id(openstack_session=openstack_session,
-                                                                        segmentation_id=int(k), logger=logger)
+                                                                        segmentation_id=int(vlan_id), logger=logger)
             if not net:
                 fail_results = self.set_fail_results(values=values,
                                                      action_type='removeVlan',
-                                                     failure_text="Failed to get Network with VLAN ID {0}".format(k))
+                                                     failure_text="Failed to get Network with VLAN ID {0}".format(vlan_id))
                 results += fail_results
             else:
                 net_id = net['id']
 
                 remove_results = []
+                logger.info("Detaching nics from network {}".format(net_id))
                 for val in values:
                     action_result = self.detach_nic_from_instance_action_result(openstack_session=openstack_session,
                                                                                 action_resource_info=val,
@@ -250,7 +266,7 @@ def get_action_resource_info(self, deployed_app_resource_name, actionid, action)
         :param str deployed_app_resource_name:
         :param str actionid:
         :param action: action obtained from JSON
-        :return ConnectivityActionResourceInfo:
+        :rtype: ConnectivityActionResourceInfo
 
         """
 
@@ -288,7 +304,7 @@ def attach_nic_to_instance_action_result(self, openstack_session, action_resourc
         :param keystoneauth1.session.Session openstack_session:
         :param ConnectivityActionResourceInfo action_resource_info:
         :param str net_id:
-        :param LoggingSessionContext logger:
+        :param logging.Logger logger:
         :return ConnectivityActionResultModel:
         """
         action_result = ConnectivityActionResultModel()
@@ -297,11 +313,13 @@ def attach_nic_to_instance_action_result(self, openstack_session, action_resourc
         result_err_msg = ''
         try:
             instance_id = action_resource_info.vm_uuid
+            logger.info("Attaching instance {0} to net {1}".format(instance_id, net_id))
             result = self.instance_service.attach_nic_to_net(openstack_session=openstack_session,
                                                              instance_id=instance_id, net_id=net_id, logger=logger)
         except Exception as e:
             result_err_msg = self._format_err_msg_for_exception(e)
             logger.error(result_err_msg)
+
         if not result:
             action_result.success = "False"
             action_result.actionId = action_resource_info.actionid

package/cloudshell/cp/openstack/domain/services/neutron/neutron_network_service.py

@@ -21,7 +21,7 @@ def create_or_get_network_with_segmentation_id(self, openstack_session, cp_resou
         :param keystoneauth1.session.Session openstack_session:
         :param OpenStackResourceModel cp_resource_model:
         :param int segmentation_id:
-        :param LoggingSessionContext logger:
+        :param logging.Logger logger:
         :return dict :
         """
 
@@ -40,16 +40,21 @@ def create_or_get_network_with_segmentation_id(self, openstack_session, cp_resou
             create_nw_json.update({'provider:physical_network': interface_name})
 
         try:
-            new_net = client.create_network({'network': create_nw_json})
+            request = {'network': create_nw_json}
+            logger.info("Calling neutron client create_network with request: {}".format(request))
+            new_net = client.create_network(request)
             new_net = new_net['network']
         except NetCreateConflict as e:
             logger.error(traceback.format_exc())
             networks_res = client.list_networks(**{'provider:segmentation_id': segmentation_id})
             networks = networks_res['networks']
             if not networks:
+                logger.error("Network with segmentation id {0} not found and couldnt be created".format(segmentation_id))
                 raise
             new_net = networks_res['networks'][0]
 
+        logger.info("Got network: {}".format(new_net))
+
         return new_net
 
     def get_network_with_segmentation_id(self, openstack_session, segmentation_id, logger):
@@ -76,6 +81,7 @@ def create_and_attach_subnet_to_net(self, openstack_session, cp_resource_model,
         :param keystoneauth1.session.Session openstack_session:
         :param OpenStackResourceModel cp_resource_model:
         :param str net_id: UUID string
+        :param logging.Logger logger:
         :return dict:
         """
 
@@ -93,8 +99,11 @@ def create_and_attach_subnet_to_net(self, openstack_session, cp_resource_model,
                               'name': subnet_name,
                               'gateway_ip': None}
 
-        new_subnet = client.create_subnet({'subnet':create_subnet_json})
+        request = {'subnet': create_subnet_json}
+        logger.info("Calling neutron client create_subnet with request: {}".format(request))
+        new_subnet = client.create_subnet(request)
         new_subnet = new_subnet['subnet']
+        logger.info("Created new subnet: {}".format(new_subnet))
 
         return new_subnet
 
@@ -103,16 +112,13 @@ def remove_subnet_and_net(self, openstack_session, network, logger):
 
         :param keystoneauth1.session.Session openstack_session:
         :param dict network:
-        :param LoggingSessionContext logger:
+        :param logging.Logger logger:
         :return:
         """
 
-        # FIXME: What happens if multiple threads call this?
         client = neutron_client.Client(session=openstack_session)
 
         try:
-            #  FIXME: This whole block should be synchronized.
-
             # Get a list of all ports for this network. If there's any port with device owner other than DHCP,
             # You won't be able to delete the network or subnet. Retry it a few times (sometimes seen that when
             # this call happens, some 'ports' are still there.
@@ -128,11 +134,13 @@ def remove_subnet_and_net(self, openstack_session, network, logger):
                 else:
                     break
 
-            logger.debug("Found {0} ports".format(network_ports))
+            logger.info("Found {0} ports: {1}".format(len(network_ports), network_ports))
             if len(network_ports) <= 1:
                 for subnet in network['subnets']:
+                    logger.info("Deleting subnet {}".format(subnet))
                     client.delete_subnet(subnet)
 
+                logger.info("Deleting network {}".format(network))
                 client.delete_network(network['id'])
 
             else:
@@ -158,7 +166,7 @@ def _get_unused_cidr(self, client, cp_resvd_cidrs, logger):
         # We basically start with a 10.0. network to find a subnet that does not overlap with
         # either the reserved_cidrs or currently allocated CIDRs
         # currently supports /24 subnets
-        logger.debug("reserved CIDRs: {0}".format(cp_resvd_cidrs))
+        logger.info("reserved CIDRs: {0}".format(cp_resvd_cidrs))
 
         # Empty reserved_addresses generates a list with single empty string
         blacklist_cidrs = filter(lambda x: len(x) > 0, map(lambda x: x.strip(), cp_resvd_cidrs.split(",")))
@@ -170,6 +178,7 @@ def _get_unused_cidr(self, client, cp_resvd_cidrs, logger):
 
         blacklist_cidrs += current_subnets_cidrs
         blacklist_cidrs = map(lambda x: unicode(x), blacklist_cidrs)
+        logger.info("blacklist CIDRs: {0}".format(blacklist_cidrs))
         blacklist_subnets = map(lambda x: ipaddress.IPv4Network(x), blacklist_cidrs)
 
         # start with a 10 subnet
@@ -220,6 +229,7 @@ def _get_unused_cidr(self, client, cp_resvd_cidrs, logger):
             return None
 
         cidr = str(found_subnet)
+        logger.info("Resolved CIDR: {}".format(cidr))
 
         return cidr
 

package/cloudshell/cp/openstack/domain/services/nova/nova_instance_service.py

@@ -207,7 +207,8 @@ def get_instance_from_instance_id(self, openstack_session, instance_id, logger,
         :param str instance_id:
         :param LoggingSessionContext logger:
         :param novaclient.Client client: client (optional)
-        :rtype novaclient.Client.servers.Server instance:
+        :return: instance
+        :rtype: novaclient.Client.servers.Server
         """
         if client is None:
             client = novaclient.Client(self.API_VERSION, session=openstack_session)
@@ -229,14 +230,14 @@ def attach_nic_to_net(self, openstack_session, instance_id, net_id, logger):
         :param openstack_session:
         :param instance_id:
         :param net_id:
-        :param logger:
+        :param logging.Logger logger:
         :return:
         """
 
         instance = self.get_instance_from_instance_id(openstack_session=openstack_session,
                                                       instance_id=instance_id,
                                                       logger=logger)
-        if instance is None :
+        if instance is None:
             return None
 
         try:
@@ -251,8 +252,6 @@ def attach_nic_to_net(self, openstack_session, instance_id, net_id, logger):
             logger.error("Exception: {0} during interface attach.".format(e))
             raise
 
-        return None
-
     def detach_nic_from_instance(self, openstack_session, instance_id, port_id, logger):
         """
 
@@ -267,7 +266,7 @@ def detach_nic_from_instance(self, openstack_session, instance_id, port_id, logg
         instance = self.get_instance_from_instance_id(openstack_session=openstack_session,
                                                       instance_id=instance_id,
                                                       logger=logger)
-        logger.info("Returned instance {0}".format(instance))
+        logger.info("Returned instance {0}".format(instance.name))
         if instance is None:
             return False
 

package/cloudshell/cp/openstack/models/connectivity_action_resource_info.py

@@ -1,4 +1,3 @@
-
 class ConnectivityActionResourceInfo:
     def __init__(self, deployed_app_resource_name, actionid, vm_uuid, interface_ip, interface_port_id, interface_mac):
         self.deployed_app_resource_name = deployed_app_resource_name
@@ -7,3 +6,8 @@ def __init__(self, deployed_app_resource_name, actionid, vm_uuid, interface_ip,
         self.iface_ip = interface_ip
         self.interface_port_id = interface_port_id
         self.interface_mac = interface_mac
+
+    def __str__(self):
+        return "deployed_app_resource_name: {0}, vm_uuid: {1}, actionid: {2}, iface_ip: {3}, interface_port_id: {4}, " \
+               "interface_mac: {5}".format(self.deployed_app_resource_name, self.vm_uuid, self.actionid, self.iface_ip,
+                                           self.interface_port_id, self.interface_mac)