X-Git-Url: https://osm.etsi.org/gitweb/?p=osm%2FRO.git;a=blobdiff_plain;f=NG-RO%2Fosm_ng_ro%2Fns_thread.py;h=d728d7024659d425cfe98c471f459f47bbb0348c;hp=01c894ddefb4a06fe0ee3b3e009864667d53340d;hb=79ac6df793d0c47de98f6b3a57026aef6bdbb1f3;hpb=049cbb1b256805f589c24776dcf092c77fefec6a diff --git a/NG-RO/osm_ng_ro/ns_thread.py b/NG-RO/osm_ng_ro/ns_thread.py index 01c894dd..d728d702 100644 --- a/NG-RO/osm_ng_ro/ns_thread.py +++ b/NG-RO/osm_ng_ro/ns_thread.py @@ -123,6 +123,8 @@ class VimInteractionNet(VimInteractionBase): created = False created_items = {} target_vim = self.my_vims[ro_task["target_id"]] + mgmtnet = False + mgmtnet_defined_in_vim = False try: # FIND @@ -130,13 +132,15 @@ class VimInteractionNet(VimInteractionBase): # if management, get configuration of VIM if task["find_params"].get("filter_dict"): vim_filter = task["find_params"]["filter_dict"] - # mamagement network + # management network elif task["find_params"].get("mgmt"): + mgmtnet = True if deep_get( self.db_vims[ro_task["target_id"]], "config", "management_network_id", ): + mgmtnet_defined_in_vim = True vim_filter = { "id": self.db_vims[ro_task["target_id"]]["config"][ "management_network_id" @@ -147,6 +151,7 @@ class VimInteractionNet(VimInteractionBase): "config", "management_network_name", ): + mgmtnet_defined_in_vim = True vim_filter = { "name": self.db_vims[ro_task["target_id"]]["config"][ "management_network_name" @@ -161,11 +166,29 @@ class VimInteractionNet(VimInteractionBase): vim_nets = target_vim.get_network_list(vim_filter) if not vim_nets and not task.get("params"): - raise NsWorkerExceptionNotFound( - "Network not found with this criteria: '{}'".format( - task.get("find_params") + # If there is mgmt-network in the descriptor, + # there is no mapping of that network to a VIM network in the descriptor, + # also there is no mapping in the "--config" parameter or at VIM creation; + # that mgmt-network will be created. + if mgmtnet and not mgmtnet_defined_in_vim: + net_name = ( + vim_filter.get("name") + if vim_filter.get("name") + else vim_filter.get("id")[:16] + ) + vim_net_id, created_items = target_vim.new_network( + net_name, None + ) + self.logger.debug( + "Created mgmt network vim_net_id: {}".format(vim_net_id) + ) + created = True + else: + raise NsWorkerExceptionNotFound( + "Network not found with this criteria: '{}'".format( + task.get("find_params") + ) ) - ) elif len(vim_nets) > 1: raise NsWorkerException( "More than one network found with this criteria: '{}'".format( @@ -187,6 +210,7 @@ class VimInteractionNet(VimInteractionBase): "created": created, "created_items": created_items, "vim_details": None, + "vim_message": None, } self.logger.debug( "task={} {} new-net={} created={}".format( @@ -202,7 +226,7 @@ class VimInteractionNet(VimInteractionBase): ro_vim_item_update = { "vim_status": "VIM_ERROR", "created": created, - "vim_details": str(e), + "vim_message": str(e), } return "FAILED", ro_vim_item_update @@ -242,11 +266,11 @@ class VimInteractionNet(VimInteractionBase): ro_vim_item_update["vim_name"] = vim_info.get("name") if vim_info["status"] in ("ERROR", "VIM_ERROR"): - if ro_task["vim_info"]["vim_details"] != vim_info.get("error_msg"): - ro_vim_item_update["vim_details"] = vim_info.get("error_msg") + if ro_task["vim_info"]["vim_message"] != vim_info.get("error_msg"): + ro_vim_item_update["vim_message"] = vim_info.get("error_msg") elif vim_info["status"] == "DELETED": ro_vim_item_update["vim_id"] = None - ro_vim_item_update["vim_details"] = "Deleted externally" + ro_vim_item_update["vim_message"] = "Deleted externally" else: if ro_task["vim_info"]["vim_details"] != vim_info["vim_info"]: ro_vim_item_update["vim_details"] = vim_info["vim_info"] @@ -258,7 +282,7 @@ class VimInteractionNet(VimInteractionBase): ro_task["target_id"], vim_id, ro_vim_item_update.get("vim_status"), - ro_vim_item_update.get("vim_details") + ro_vim_item_update.get("vim_message") if ro_vim_item_update.get("vim_status") != "ACTIVE" else "", ) @@ -273,7 +297,7 @@ class VimInteractionNet(VimInteractionBase): ro_vim_item_update_ok = { "vim_status": "DELETED", "created": False, - "vim_details": "DELETED", + "vim_message": "DELETED", "vim_id": None, } @@ -284,7 +308,7 @@ class VimInteractionNet(VimInteractionBase): net_vim_id, ro_task["vim_info"]["created_items"] ) except vimconn.VimConnNotFoundException: - ro_vim_item_update_ok["vim_details"] = "already deleted" + ro_vim_item_update_ok["vim_message"] = "already deleted" except vimconn.VimConnException as e: self.logger.error( "ro_task={} vim={} del-net={}: {}".format( @@ -293,7 +317,7 @@ class VimInteractionNet(VimInteractionBase): ) ro_vim_item_update = { "vim_status": "VIM_ERROR", - "vim_details": "Error while deleting: {}".format(e), + "vim_message": "Error while deleting: {}".format(e), } return "FAILED", ro_vim_item_update @@ -303,7 +327,7 @@ class VimInteractionNet(VimInteractionBase): task_id, ro_task["target_id"], net_vim_id, - ro_vim_item_update_ok.get("vim_details", ""), + ro_vim_item_update_ok.get("vim_message", ""), ) ) @@ -346,6 +370,23 @@ class VimInteractionVdu(VimInteractionBase): if params_copy["flavor_id"].startswith("TASK-"): params_copy["flavor_id"] = task_depends[params_copy["flavor_id"]] + affinity_group_list = params_copy["affinity_group_list"] + for affinity_group in affinity_group_list: + # change task_id into affinity_group_id + if "affinity_group_id" in affinity_group and affinity_group[ + "affinity_group_id" + ].startswith("TASK-"): + affinity_group_id = task_depends[ + affinity_group["affinity_group_id"] + ] + + if not affinity_group_id: + raise NsWorkerException( + "found for {}".format(affinity_group["affinity_group_id"]) + ) + + affinity_group["affinity_group_id"] = affinity_group_id + vim_vm_id, created_items = target_vim.new_vminstance(**params_copy) interfaces = [iface["vim_id"] for iface in params_copy["net_list"]] @@ -355,6 +396,7 @@ class VimInteractionVdu(VimInteractionBase): "created": created, "created_items": created_items, "vim_details": None, + "vim_message": None, "interfaces_vim_ids": interfaces, "interfaces": [], } @@ -372,7 +414,7 @@ class VimInteractionVdu(VimInteractionBase): ro_vim_item_update = { "vim_status": "VIM_ERROR", "created": created, - "vim_details": str(e), + "vim_message": str(e), } return "FAILED", ro_vim_item_update @@ -384,18 +426,25 @@ class VimInteractionVdu(VimInteractionBase): ro_vim_item_update_ok = { "vim_status": "DELETED", "created": False, - "vim_details": "DELETED", + "vim_message": "DELETED", "vim_id": None, } try: + self.logger.debug( + "delete_vminstance: vm_vim_id={} created_items={}".format( + vm_vim_id, ro_task["vim_info"]["created_items"] + ) + ) if vm_vim_id or ro_task["vim_info"]["created_items"]: target_vim = self.my_vims[ro_task["target_id"]] target_vim.delete_vminstance( - vm_vim_id, ro_task["vim_info"]["created_items"] + vm_vim_id, + ro_task["vim_info"]["created_items"], + ro_task["vim_info"].get("volumes_to_hold", []), ) except vimconn.VimConnNotFoundException: - ro_vim_item_update_ok["vim_details"] = "already deleted" + ro_vim_item_update_ok["vim_message"] = "already deleted" except vimconn.VimConnException as e: self.logger.error( "ro_task={} vim={} del-vm={}: {}".format( @@ -404,7 +453,7 @@ class VimInteractionVdu(VimInteractionBase): ) ro_vim_item_update = { "vim_status": "VIM_ERROR", - "vim_details": "Error while deleting: {}".format(e), + "vim_message": "Error while deleting: {}".format(e), } return "FAILED", ro_vim_item_update @@ -414,7 +463,7 @@ class VimInteractionVdu(VimInteractionBase): task_id, ro_task["target_id"], vm_vim_id, - ro_vim_item_update_ok.get("vim_details", ""), + ro_vim_item_update_ok.get("vim_message", ""), ) ) @@ -502,11 +551,11 @@ class VimInteractionVdu(VimInteractionBase): ro_vim_item_update["vim_name"] = vim_info.get("name") if vim_info["status"] in ("ERROR", "VIM_ERROR"): - if ro_task["vim_info"]["vim_details"] != vim_info.get("error_msg"): - ro_vim_item_update["vim_details"] = vim_info.get("error_msg") + if ro_task["vim_info"]["vim_message"] != vim_info.get("error_msg"): + ro_vim_item_update["vim_message"] = vim_info.get("error_msg") elif vim_info["status"] == "DELETED": ro_vim_item_update["vim_id"] = None - ro_vim_item_update["vim_details"] = "Deleted externally" + ro_vim_item_update["vim_message"] = "Deleted externally" else: if ro_task["vim_info"]["vim_details"] != vim_info["vim_info"]: ro_vim_item_update["vim_details"] = vim_info["vim_info"] @@ -518,7 +567,7 @@ class VimInteractionVdu(VimInteractionBase): ro_task["target_id"], vim_id, ro_vim_item_update.get("vim_status"), - ro_vim_item_update.get("vim_details") + ro_vim_item_update.get("vim_message") if ro_vim_item_update.get("vim_status") != "ACTIVE" else "", ) @@ -568,7 +617,7 @@ class VimInteractionVdu(VimInteractionBase): self.logger.error( "task={} {} inject-ssh-key: {}".format(task_id, ro_task["target_id"], e) ) - ro_vim_item_update = {"vim_details": str(e)} + ro_vim_item_update = {"vim_message": str(e)} return "FAILED", ro_vim_item_update, db_task_update @@ -607,6 +656,7 @@ class VimInteractionImage(VimInteractionBase): "created": created, "created_items": created_items, "vim_details": None, + "vim_message": None, } self.logger.debug( "task={} {} new-image={} created={}".format( @@ -622,7 +672,7 @@ class VimInteractionImage(VimInteractionBase): ro_vim_item_update = { "vim_status": "VIM_ERROR", "created": created, - "vim_details": str(e), + "vim_message": str(e), } return "FAILED", ro_vim_item_update @@ -636,7 +686,7 @@ class VimInteractionFlavor(VimInteractionBase): ro_vim_item_update_ok = { "vim_status": "DELETED", "created": False, - "vim_details": "DELETED", + "vim_message": "DELETED", "vim_id": None, } @@ -645,7 +695,7 @@ class VimInteractionFlavor(VimInteractionBase): target_vim = self.my_vims[ro_task["target_id"]] target_vim.delete_flavor(flavor_vim_id) except vimconn.VimConnNotFoundException: - ro_vim_item_update_ok["vim_details"] = "already deleted" + ro_vim_item_update_ok["vim_message"] = "already deleted" except vimconn.VimConnException as e: self.logger.error( "ro_task={} vim={} del-flavor={}: {}".format( @@ -654,7 +704,7 @@ class VimInteractionFlavor(VimInteractionBase): ) ro_vim_item_update = { "vim_status": "VIM_ERROR", - "vim_details": "Error while deleting: {}".format(e), + "vim_message": "Error while deleting: {}".format(e), } return "FAILED", ro_vim_item_update @@ -664,7 +714,7 @@ class VimInteractionFlavor(VimInteractionBase): task_id, ro_task["target_id"], flavor_vim_id, - ro_vim_item_update_ok.get("vim_details", ""), + ro_vim_item_update_ok.get("vim_message", ""), ) ) @@ -700,6 +750,7 @@ class VimInteractionFlavor(VimInteractionBase): "created": created, "created_items": created_items, "vim_details": None, + "vim_message": None, } self.logger.debug( "task={} {} new-flavor={} created={}".format( @@ -715,7 +766,114 @@ class VimInteractionFlavor(VimInteractionBase): ro_vim_item_update = { "vim_status": "VIM_ERROR", "created": created, - "vim_details": str(e), + "vim_message": str(e), + } + + return "FAILED", ro_vim_item_update + + +class VimInteractionAffinityGroup(VimInteractionBase): + def delete(self, ro_task, task_index): + task = ro_task["tasks"][task_index] + task_id = task["task_id"] + affinity_group_vim_id = ro_task["vim_info"]["vim_id"] + ro_vim_item_update_ok = { + "vim_status": "DELETED", + "created": False, + "vim_message": "DELETED", + "vim_id": None, + } + + try: + if affinity_group_vim_id: + target_vim = self.my_vims[ro_task["target_id"]] + target_vim.delete_affinity_group(affinity_group_vim_id) + except vimconn.VimConnNotFoundException: + ro_vim_item_update_ok["vim_message"] = "already deleted" + except vimconn.VimConnException as e: + self.logger.error( + "ro_task={} vim={} del-affinity-or-anti-affinity-group={}: {}".format( + ro_task["_id"], ro_task["target_id"], affinity_group_vim_id, e + ) + ) + ro_vim_item_update = { + "vim_status": "VIM_ERROR", + "vim_message": "Error while deleting: {}".format(e), + } + + return "FAILED", ro_vim_item_update + + self.logger.debug( + "task={} {} del-affinity-or-anti-affinity-group={} {}".format( + task_id, + ro_task["target_id"], + affinity_group_vim_id, + ro_vim_item_update_ok.get("vim_message", ""), + ) + ) + + return "DONE", ro_vim_item_update_ok + + def new(self, ro_task, task_index, task_depends): + task = ro_task["tasks"][task_index] + task_id = task["task_id"] + created = False + created_items = {} + target_vim = self.my_vims[ro_task["target_id"]] + + try: + affinity_group_vim_id = None + affinity_group_data = None + + if task.get("params"): + affinity_group_data = task["params"].get("affinity_group_data") + + if affinity_group_data and affinity_group_data.get("vim-affinity-group-id"): + try: + param_affinity_group_id = task["params"]["affinity_group_data"].get( + "vim-affinity-group-id" + ) + affinity_group_vim_id = target_vim.get_affinity_group( + param_affinity_group_id + ).get("id") + except vimconn.VimConnNotFoundException: + self.logger.error( + "task={} {} new-affinity-or-anti-affinity-group. Provided VIM Affinity Group ID {}" + "could not be found at VIM. Creating a new one.".format( + task_id, ro_task["target_id"], param_affinity_group_id + ) + ) + + if not affinity_group_vim_id and affinity_group_data: + affinity_group_vim_id = target_vim.new_affinity_group( + affinity_group_data + ) + created = True + + ro_vim_item_update = { + "vim_id": affinity_group_vim_id, + "vim_status": "DONE", + "created": created, + "created_items": created_items, + "vim_details": None, + "vim_message": None, + } + self.logger.debug( + "task={} {} new-affinity-or-anti-affinity-group={} created={}".format( + task_id, ro_task["target_id"], affinity_group_vim_id, created + ) + ) + + return "DONE", ro_vim_item_update + except (vimconn.VimConnException, NsWorkerException) as e: + self.logger.error( + "task={} vim={} new-affinity-or-anti-affinity-group:" + " {}".format(task_id, ro_task["target_id"], e) + ) + ro_vim_item_update = { + "vim_status": "VIM_ERROR", + "created": created, + "vim_message": str(e), } return "FAILED", ro_vim_item_update @@ -1041,6 +1199,7 @@ class VimInteractionSdnNet(VimInteractionBase): "created_items": created_items, "connected_ports": connected_ports, "vim_details": sdn_info, + "vim_message": None, "last_update": last_update, } @@ -1055,7 +1214,7 @@ class VimInteractionSdnNet(VimInteractionBase): ro_vim_item_update = { "vim_status": "VIM_ERROR", "created": created, - "vim_details": str(e), + "vim_message": str(e), } return "FAILED", ro_vim_item_update @@ -1067,7 +1226,7 @@ class VimInteractionSdnNet(VimInteractionBase): ro_vim_item_update_ok = { "vim_status": "DELETED", "created": False, - "vim_details": "DELETED", + "vim_message": "DELETED", "vim_id": None, } @@ -1083,7 +1242,7 @@ class VimInteractionSdnNet(VimInteractionBase): isinstance(e, sdnconn.SdnConnectorError) and e.http_code == HTTPStatus.NOT_FOUND.value ): - ro_vim_item_update_ok["vim_details"] = "already deleted" + ro_vim_item_update_ok["vim_message"] = "already deleted" else: self.logger.error( "ro_task={} vim={} del-sdn-net={}: {}".format( @@ -1095,7 +1254,7 @@ class VimInteractionSdnNet(VimInteractionBase): ) ro_vim_item_update = { "vim_status": "VIM_ERROR", - "vim_details": "Error while deleting: {}".format(e), + "vim_message": "Error while deleting: {}".format(e), } return "FAILED", ro_vim_item_update @@ -1105,7 +1264,7 @@ class VimInteractionSdnNet(VimInteractionBase): task_id, ro_task["target_id"], sdn_vim_id, - ro_vim_item_update_ok.get("vim_details", ""), + ro_vim_item_update_ok.get("vim_message", ""), ) ) @@ -1156,6 +1315,9 @@ class NsWorker(threading.Thread): "sdn_net": VimInteractionSdnNet( self.db, self.my_vims, self.db_vims, self.logger ), + "affinity-or-anti-affinity-group": VimInteractionAffinityGroup( + self.db, self.my_vims, self.db_vims, self.logger + ), } self.time_last_task_processed = None # lists of tasks to delete because nsrs or vnfrs has been deleted from db @@ -1478,6 +1640,24 @@ class NsWorker(threading.Thread): try: while True: + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + self._log_ro_task( + None, + None, + None, + "TASK_WF", + "task_locked_time=" + + str(self.task_locked_time) + + " " + + "time_last_task_processed=" + + str(self.time_last_task_processed) + + " " + + "now=" + + str(now), + ) + """ locked = self.db.set_one( "ro_tasks", q_filter={ @@ -1518,6 +1698,128 @@ class NsWorker(threading.Thread): return None + def _get_db_all_tasks(self): + """ + Read all content of table ro_tasks to log it + :return: None + """ + try: + # Checking the content of the BD: + + # read and return + ro_task = self.db.get_list("ro_tasks") + for rt in ro_task: + self._log_ro_task(rt, None, None, "TASK_WF", "GET_ALL_TASKS") + return ro_task + + except DbException as e: + self.logger.error("Database exception at _get_db_all_tasks: {}".format(e)) + except Exception as e: + self.logger.critical( + "Unexpected exception at _get_db_all_tasks: {}".format(e), exc_info=True + ) + + return None + + def _log_ro_task(self, ro_task, db_ro_task_update, db_ro_task_delete, mark, event): + """ + Generate a log with the following format: + + Mark;Event;ro_task_id;locked_at;modified_at;created_at;to_check_at;locked_by; + target_id;vim_info.refresh_at;vim_info;no_of_tasks;task_status;action_id; + task_array_index;task_id;task_action;task_item;task_args + + Example: + + TASK_WF;GET_TASK;888f1864-749a-4fc2-bc1a-97c0fffd6a6f:2;1642158724.8210013; + 1642158640.7986135;1642158640.7986135;1642158640.7986135;b134c9494e75:0a + ;vim:b7ff9e24-8868-4d68-8a57-a59dc11d0327;None;{'created': False, + 'created_items': None, 'vim_id': None, 'vim_name': None, 'vim_status': None, + 'vim_details': None, 'vim_message': None, 'refresh_at': None};1;SCHEDULED; + 888f1864-749a-4fc2-bc1a-97c0fffd6a6f;0;888f1864-749a-4fc2-bc1a-97c0fffd6a6f:2; + CREATE;image;{'filter_dict': {'name': 'ubuntu-os-cloud:image-family:ubuntu-1804-lts'}} + """ + try: + line = [] + i = 0 + if ro_task is not None and isinstance(ro_task, dict): + for t in ro_task["tasks"]: + line.clear() + line.append(mark) + line.append(event) + line.append(ro_task.get("_id", "")) + line.append(str(ro_task.get("locked_at", ""))) + line.append(str(ro_task.get("modified_at", ""))) + line.append(str(ro_task.get("created_at", ""))) + line.append(str(ro_task.get("to_check_at", ""))) + line.append(str(ro_task.get("locked_by", ""))) + line.append(str(ro_task.get("target_id", ""))) + line.append(str(ro_task.get("vim_info", {}).get("refresh_at", ""))) + line.append(str(ro_task.get("vim_info", ""))) + line.append(str(ro_task.get("tasks", ""))) + if isinstance(t, dict): + line.append(str(t.get("status", ""))) + line.append(str(t.get("action_id", ""))) + line.append(str(i)) + line.append(str(t.get("task_id", ""))) + line.append(str(t.get("action", ""))) + line.append(str(t.get("item", ""))) + line.append(str(t.get("find_params", ""))) + line.append(str(t.get("params", ""))) + else: + line.extend([""] * 2) + line.append(str(i)) + line.extend([""] * 5) + + i += 1 + self.logger.debug(";".join(line)) + elif db_ro_task_update is not None and isinstance(db_ro_task_update, dict): + i = 0 + while True: + st = "tasks.{}.status".format(i) + if st not in db_ro_task_update: + break + line.clear() + line.append(mark) + line.append(event) + line.append(db_ro_task_update.get("_id", "")) + line.append(str(db_ro_task_update.get("locked_at", ""))) + line.append(str(db_ro_task_update.get("modified_at", ""))) + line.append("") + line.append(str(db_ro_task_update.get("to_check_at", ""))) + line.append(str(db_ro_task_update.get("locked_by", ""))) + line.append("") + line.append(str(db_ro_task_update.get("vim_info.refresh_at", ""))) + line.append("") + line.append(str(db_ro_task_update.get("vim_info", ""))) + line.append(str(str(db_ro_task_update).count(".status"))) + line.append(db_ro_task_update.get(st, "")) + line.append("") + line.append(str(i)) + line.extend([""] * 3) + i += 1 + self.logger.debug(";".join(line)) + + elif db_ro_task_delete is not None and isinstance(db_ro_task_delete, dict): + line.clear() + line.append(mark) + line.append(event) + line.append(db_ro_task_delete.get("_id", "")) + line.append("") + line.append(db_ro_task_delete.get("modified_at", "")) + line.extend([""] * 13) + self.logger.debug(";".join(line)) + + else: + line.clear() + line.append(mark) + line.append(event) + line.extend([""] * 16) + self.logger.debug(";".join(line)) + + except Exception as e: + self.logger.error("Error logging ro_task: {}".format(e)) + def _delete_task(self, ro_task, task_index, task_depends, db_update): """ Determine if this task need to be done or superseded @@ -1529,6 +1831,7 @@ class NsWorker(threading.Thread): "created_items", False ) + self.logger.warning("Needed delete: {}".format(needed_delete)) if my_task["status"] == "FAILED": return None, None # TODO need to be retry?? @@ -1552,6 +1855,9 @@ class NsWorker(threading.Thread): needed_delete = False if needed_delete: + self.logger.warning( + "Deleting ro_task={} task_index={}".format(ro_task, task_index) + ) return self.item2class[my_task["item"]].delete(ro_task, task_index) else: return "SUPERSEDED", None @@ -1564,7 +1870,7 @@ class NsWorker(threading.Thread): exc_info=True, ) - return "FAILED", {"vim_status": "VIM_ERROR", "vim_details": str(e)} + return "FAILED", {"vim_status": "VIM_ERROR", "vim_message": str(e)} def _create_task(self, ro_task, task_index, task_depends, db_update): """ @@ -1602,7 +1908,7 @@ class NsWorker(threading.Thread): ) task_status = "FAILED" - ro_vim_item_update = {"vim_status": "VIM_ERROR", "vim_details": str(e)} + ro_vim_item_update = {"vim_status": "VIM_ERROR", "vim_message": str(e)} # TODO update ro_vim_item_update return task_status, ro_vim_item_update @@ -1654,8 +1960,9 @@ class NsWorker(threading.Thread): fail_on_empty=False, ) + self.logger.warning("ro_task_dependency={}".format(ro_task_dependency)) if ro_task_dependency: - for task_index, task in ro_task_dependency["tasks"]: + for task_index, task in enumerate(ro_task_dependency["tasks"]): if task["task_id"] == task_id: return ro_task_dependency, task_index raise NsWorkerException("Cannot get depending task {}".format(task_id)) @@ -1690,6 +1997,11 @@ class NsWorker(threading.Thread): ro_task["vim_info"]["refresh_at"] = next_refresh try: + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + self._log_ro_task(ro_task, None, None, "TASK_WF", "GET_TASK") + """ # 0: get task_status_create lock_object = None task_status_create = None @@ -1750,6 +2062,11 @@ class NsWorker(threading.Thread): dependency_task = dependency_ro_task["tasks"][ dependency_task_index ] + self.logger.warning( + "dependency_ro_task={} dependency_task_index={}".format( + dependency_ro_task, dependency_task_index + ) + ) if dependency_task["status"] == "SCHEDULED": dependency_not_completed = True @@ -1770,7 +2087,7 @@ class NsWorker(threading.Thread): dependency_task["item"], dependency_task_id, dependency_ro_task["vim_info"].get( - "vim_details" + "vim_message" ), ) self.logger.error( @@ -1786,6 +2103,11 @@ class NsWorker(threading.Thread): ] = dependency_ro_task["vim_info"]["vim_id"] if dependency_not_completed: + self.logger.warning( + "DEPENDENCY NOT COMPLETED {}".format( + dependency_ro_task["vim_info"]["vim_id"] + ) + ) # TODO set at vim_info.vim_details that it is waiting continue @@ -1851,12 +2173,17 @@ class NsWorker(threading.Thread): task["item"] ].refresh(ro_task) _update_refresh(new_status) + else: + # The refresh is updated to avoid set the value of "refresh_at" to + # default value (next_check_at = now + (24 * 60 * 60)) when status is BUILD, + # because it can happen that in this case the task is never processed + _update_refresh(task["status"]) except Exception as e: new_status = "FAILED" db_vim_info_update = { "vim_status": "VIM_ERROR", - "vim_details": str(e), + "vim_message": str(e), } if not isinstance( @@ -1935,6 +2262,14 @@ class NsWorker(threading.Thread): db_ro_task_update["modified_at"] = now db_ro_task_update["to_check_at"] = next_check_at + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + db_ro_task_update_log = db_ro_task_update.copy() + db_ro_task_update_log["_id"] = q_filter["_id"] + self._log_ro_task(None, db_ro_task_update_log, None, "TASK_WF", "SET_TASK") + """ + if not self.db.set_one( "ro_tasks", update_dict=db_ro_task_update, @@ -1943,6 +2278,17 @@ class NsWorker(threading.Thread): ): del db_ro_task_update["to_check_at"] del q_filter["to_check_at"] + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + self._log_ro_task( + None, + db_ro_task_update_log, + None, + "TASK_WF", + "SET_TASK " + str(q_filter), + ) + """ self.db.set_one( "ro_tasks", q_filter=q_filter, @@ -1971,7 +2317,14 @@ class NsWorker(threading.Thread): path_vim_status + "." + k: v for k, v in ro_vim_item_update.items() if k - in ("vim_id", "vim_details", "vim_name", "vim_status", "interfaces") + in ( + "vim_id", + "vim_details", + "vim_message", + "vim_name", + "vim_status", + "interfaces", + ) } if path_vim_status.startswith("vdur."): @@ -2157,8 +2510,15 @@ class NsWorker(threading.Thread): if self.tasks_to_delete: self._process_delete_db_tasks() busy = False + """ + # Log RO tasks only when loglevel is DEBUG + if self.logger.getEffectiveLevel() == logging.DEBUG: + _ = self._get_db_all_tasks() + """ ro_task = self._get_db_task() if ro_task: + self.logger.warning("Task to process: {}".format(ro_task)) + time.sleep(1) self._process_pending_tasks(ro_task) busy = True if not busy: