Fix Bug 2158 and Bug 2254 by arranging exception handling
[osm/RO.git] / NG-RO / osm_ng_ro / ns_thread.py
index cb52d77..e64db28 100644 (file)
@@ -17,7 +17,7 @@
 #
 ##
 
-""""
+"""
 This is thread that interacts with a VIM. It processes TASKs sequentially against a single VIM.
 The tasks are stored at database in table ro_tasks
 A single ro_task refers to a VIM element (flavor, image, network, ...).
@@ -27,9 +27,9 @@ A ro_task can contain several 'tasks', each one with a target, where to store th
 from copy import deepcopy
 from http import HTTPStatus
 import logging
-from os import mkdir
+from os import makedirs
+from os import path
 import queue
-from shutil import rmtree
 import threading
 import time
 import traceback
@@ -39,7 +39,8 @@ from unittest.mock import Mock
 from importlib_metadata import entry_points
 from osm_common.dbbase import DbException
 from osm_ng_ro.vim_admin import LockRenew
-from osm_ro_plugin import sdnconn, vimconn
+from osm_ro_plugin import sdnconn
+from osm_ro_plugin import vimconn
 from osm_ro_plugin.sdn_dummy import SdnDummyConnector
 from osm_ro_plugin.vim_dummy import VimDummyConnector
 import yaml
@@ -55,7 +56,7 @@ def deep_get(target_dict, *args, **kwargs):
     :param target_dict: dictionary to be read
     :param args: list of keys to read from  target_dict
     :param kwargs: only can contain default=value to return if key is not present in the nested dictionary
-    :return: The wanted value if exist, None or default otherwise
+    :return: The wanted value if exists, None or default otherwise
     """
     for key in args:
         if not isinstance(target_dict, dict) or key not in target_dict:
@@ -344,9 +345,7 @@ class VimInteractionVdu(VimInteractionBase):
         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:
             created = True
             params = task["params"]
@@ -388,7 +387,6 @@ class VimInteractionVdu(VimInteractionBase):
                         )
 
                     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"]]
 
@@ -644,8 +642,11 @@ class VimInteractionImage(VimInteractionBase):
 
         try:
             # FIND
+            vim_image_id = ""
             if task.get("find_params"):
-                vim_images = target_vim.get_image_list(**task["find_params"])
+                vim_images = target_vim.get_image_list(
+                    task["find_params"].get("filter_dict", {})
+                )
 
                 if not vim_images:
                     raise NsWorkerExceptionNotFound(
@@ -664,7 +665,7 @@ class VimInteractionImage(VimInteractionBase):
 
             ro_vim_item_update = {
                 "vim_id": vim_image_id,
-                "vim_status": "DONE",
+                "vim_status": "ACTIVE",
                 "created": created,
                 "created_items": created_items,
                 "vim_details": None,
@@ -690,6 +691,112 @@ class VimInteractionImage(VimInteractionBase):
             return "FAILED", ro_vim_item_update
 
 
+class VimInteractionSharedVolume(VimInteractionBase):
+    def delete(self, ro_task, task_index):
+        task = ro_task["tasks"][task_index]
+        task_id = task["task_id"]
+        shared_volume_vim_id = ro_task["vim_info"]["vim_id"]
+        created_items = ro_task["vim_info"]["created_items"]
+        ro_vim_item_update_ok = {
+            "vim_status": "DELETED",
+            "created": False,
+            "vim_message": "DELETED",
+            "vim_id": None,
+        }
+        if created_items and created_items.get(shared_volume_vim_id).get("keep"):
+            ro_vim_item_update_ok = {
+                "vim_status": "ACTIVE",
+                "created": False,
+                "vim_message": None,
+            }
+            return "DONE", ro_vim_item_update_ok
+        try:
+            if shared_volume_vim_id:
+                target_vim = self.my_vims[ro_task["target_id"]]
+                target_vim.delete_shared_volumes(shared_volume_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-shared-volume={}: {}".format(
+                    ro_task["_id"], ro_task["target_id"], shared_volume_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-shared-volume={} {}".format(
+                task_id,
+                ro_task["target_id"],
+                shared_volume_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:
+            shared_volume_vim_id = None
+            shared_volume_data = None
+
+            if task.get("params"):
+                shared_volume_data = task["params"]
+
+            if shared_volume_data:
+                self.logger.info(
+                    f"Creating the new shared_volume for {shared_volume_data}\n"
+                )
+                (
+                    shared_volume_name,
+                    shared_volume_vim_id,
+                ) = target_vim.new_shared_volumes(shared_volume_data)
+                created = True
+                created_items[shared_volume_vim_id] = {
+                    "name": shared_volume_name,
+                    "keep": shared_volume_data.get("keep"),
+                }
+
+            ro_vim_item_update = {
+                "vim_id": shared_volume_vim_id,
+                "vim_status": "ACTIVE",
+                "created": created,
+                "created_items": created_items,
+                "vim_details": None,
+                "vim_message": None,
+            }
+            self.logger.debug(
+                "task={} {} new-shared-volume={} created={}".format(
+                    task_id, ro_task["target_id"], shared_volume_vim_id, created
+                )
+            )
+
+            return "DONE", ro_vim_item_update
+        except (vimconn.VimConnException, NsWorkerException) as e:
+            self.logger.error(
+                "task={} vim={} new-shared-volume:"
+                " {}".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
+
+
 class VimInteractionFlavor(VimInteractionBase):
     def delete(self, ro_task, task_index):
         task = ro_task["tasks"][task_index]
@@ -738,17 +845,20 @@ class VimInteractionFlavor(VimInteractionBase):
         created = False
         created_items = {}
         target_vim = self.my_vims[ro_task["target_id"]]
-
         try:
             # FIND
             vim_flavor_id = None
 
-            if task.get("find_params"):
+            if task.get("find_params", {}).get("vim_flavor_id"):
+                vim_flavor_id = task["find_params"]["vim_flavor_id"]
+            elif task.get("find_params", {}).get("flavor_data"):
                 try:
                     flavor_data = task["find_params"]["flavor_data"]
                     vim_flavor_id = target_vim.get_flavor_id_from_data(flavor_data)
-                except vimconn.VimConnNotFoundException:
-                    self.logger.exception("VimConnNotFoundException occured.")
+                except vimconn.VimConnNotFoundException as flavor_not_found_msg:
+                    self.logger.warning(
+                        f"VimConnNotFoundException occured: {flavor_not_found_msg}"
+                    )
 
             if not vim_flavor_id and task.get("params"):
                 # CREATE
@@ -758,7 +868,7 @@ class VimInteractionFlavor(VimInteractionBase):
 
             ro_vim_item_update = {
                 "vim_id": vim_flavor_id,
-                "vim_status": "DONE",
+                "vim_status": "ACTIVE",
                 "created": created,
                 "created_items": created_items,
                 "vim_details": None,
@@ -836,6 +946,7 @@ class VimInteractionAffinityGroup(VimInteractionBase):
         try:
             affinity_group_vim_id = None
             affinity_group_data = None
+            param_affinity_group_id = ""
 
             if task.get("params"):
                 affinity_group_data = task["params"].get("affinity_group_data")
@@ -864,7 +975,7 @@ class VimInteractionAffinityGroup(VimInteractionBase):
 
             ro_vim_item_update = {
                 "vim_id": affinity_group_vim_id,
-                "vim_status": "DONE",
+                "vim_status": "ACTIVE",
                 "created": created,
                 "created_items": created_items,
                 "vim_details": None,
@@ -901,6 +1012,7 @@ class VimInteractionUpdateVdu(VimInteractionBase):
         target_vim = self.my_vims[ro_task["target_id"]]
 
         try:
+            vim_vm_id = ""
             if task.get("params"):
                 vim_vm_id = task["params"].get("vim_vm_id")
                 action = task["params"].get("action")
@@ -909,7 +1021,7 @@ class VimInteractionUpdateVdu(VimInteractionBase):
                 # created = True
             ro_vim_item_update = {
                 "vim_id": vim_vm_id,
-                "vim_status": "DONE",
+                "vim_status": "ACTIVE",
                 "created": created,
                 "created_items": created_items,
                 "vim_details": None,
@@ -937,8 +1049,8 @@ class VimInteractionSdnNet(VimInteractionBase):
     @staticmethod
     def _match_pci(port_pci, mapping):
         """
-        Check if port_pci matches with mapping
-        mapping can have brackets to indicate that several chars are accepted. e.g
+        Check if port_pci matches with mapping.
+        The mapping can have brackets to indicate that several chars are accepted. e.g
         pci '0000:af:10.1' matches with '0000:af:1[01].[1357]'
         :param port_pci: text
         :param mapping: text, can contain brackets to indicate several chars are available
@@ -1037,7 +1149,6 @@ class VimInteractionSdnNet(VimInteractionBase):
         return self.new(ro_task, task_create_index, None)
 
     def new(self, ro_task, task_index, task_depends):
-
         task = ro_task["tasks"][task_index]
         task_id = task["task_id"]
         target_vim = self.my_vims[ro_task["target_id"]]
@@ -1054,12 +1165,17 @@ class VimInteractionSdnNet(VimInteractionBase):
 
         try:
             # CREATE
+            db_vim = {}
             params = task["params"]
-            vlds_to_connect = params["vlds"]
-            associated_vim = params["target_vim"]
+            vlds_to_connect = params.get("vlds", [])
+            associated_vim = params.get("target_vim")
             # external additional ports
             additional_ports = params.get("sdn-ports") or ()
-            _, _, vim_account_id = associated_vim.partition(":")
+            _, _, vim_account_id = (
+                (None, None, None)
+                if associated_vim is None
+                else associated_vim.partition(":")
+            )
 
             if associated_vim:
                 # get associated VIM
@@ -1337,6 +1453,7 @@ class VimInteractionMigration(VimInteractionBase):
         refreshed_vim_info = {}
 
         try:
+            vim_vm_id = ""
             if task.get("params"):
                 vim_vm_id = task["params"].get("vim_vm_id")
                 migrate_host = task["params"].get("migrate_host")
@@ -1418,6 +1535,7 @@ class VimInteractionResize(VimInteractionBase):
         target_vim = self.my_vims[ro_task["target_id"]]
 
         try:
+            vim_vm_id = ""
             if task.get("params"):
                 vim_vm_id = task["params"].get("vim_vm_id")
                 flavor_dict = task["params"].get("flavor_dict")
@@ -1445,7 +1563,7 @@ class VimInteractionResize(VimInteractionBase):
 
             ro_vim_item_update = {
                 "vim_id": vim_vm_id,
-                "vim_status": "DONE",
+                "vim_status": "ACTIVE",
                 "created": created,
                 "created_items": created_items,
                 "vim_details": None,
@@ -1534,6 +1652,9 @@ class NsWorker(threading.Thread):
         self.db = db
         self.item2class = {
             "net": VimInteractionNet(self.db, self.my_vims, self.db_vims, self.logger),
+            "shared-volumes": VimInteractionSharedVolume(
+                self.db, self.my_vims, self.db_vims, self.logger
+            ),
             "vdu": VimInteractionVdu(self.db, self.my_vims, self.db_vims, self.logger),
             "image": VimInteractionImage(
                 self.db, self.my_vims, self.db_vims, self.logger
@@ -1583,7 +1704,7 @@ class NsWorker(threading.Thread):
                 self.task_lock.release()
                 return False
 
-    def _process_vim_config(self, target_id, db_vim):
+    def _process_vim_config(self, target_id: str, db_vim: dict) -> None:
         """
         Process vim config, creating vim configuration files as ca_cert
         :param target_id: vim/sdn/wim + id
@@ -1594,17 +1715,14 @@ class NsWorker(threading.Thread):
             return
 
         file_name = ""
+        work_dir = "/app/osm_ro/certs"
 
         try:
             if db_vim["config"].get("ca_cert_content"):
-                file_name = "{}:{}".format(target_id, self.worker_index)
+                file_name = f"{work_dir}/{target_id}:{self.worker_index}"
 
-                try:
-                    mkdir(file_name)
-                except FileExistsError:
-                    self.logger.exception(
-                        "FileExistsError occured while processing vim_config."
-                    )
+                if not path.isdir(file_name):
+                    makedirs(file_name)
 
                 file_name = file_name + "/ca_cert"
 
@@ -1655,10 +1773,6 @@ class NsWorker(threading.Thread):
                 self.vim_targets.remove(target_id)
 
             self.logger.info("Unloaded {}".format(target_id))
-            rmtree("{}:{}".format(target_id, self.worker_index))
-        except FileNotFoundError:
-            # This is raised by rmtree if folder does not exist.
-            self.logger.exception("FileNotFoundError occured while unloading VIM.")
         except Exception as e:
             self.logger.error("Cannot unload {}: {}".format(target_id, e))
 
@@ -1682,6 +1796,7 @@ class NsWorker(threading.Thread):
             if target == "wim"
             else "sdns"
         )
+        error_text = ""
 
         try:
             step = "Getting {} from db".format(target_id)
@@ -1776,7 +1891,7 @@ class NsWorker(threading.Thread):
         """
         Load or reload a vim_account, sdn_controller or wim_account.
         Read content from database, load the plugin if not loaded.
-        In case of error loading the plugin, it load a failing VIM_connector
+        In case of error loading the plugin, it loads a failing VIM_connector
         It fills self db_vims dictionary, my_vims dictionary and vim_targets list
         :param target_id: Contains type:_id; where type can be 'vim', ...
         :return: None if ok, descriptive text if error
@@ -1791,9 +1906,9 @@ class NsWorker(threading.Thread):
         )
         plugin_name = ""
         vim = None
+        step = "Getting {}={} from db".format(target, _id)
 
         try:
-            step = "Getting {}={} from db".format(target, _id)
             # TODO process for wim, sdnc, ...
             vim = self.db.get_one(target_database, {"_id": _id})
 
@@ -1830,14 +1945,17 @@ class NsWorker(threading.Thread):
                     persistent_info={},
                 )
             else:  # sdn
-                plugin_name = "rosdn_" + vim["type"]
+                plugin_name = "rosdn_" + (vim.get("type") or vim.get("wim_type"))
                 step = "Loading plugin '{}'".format(plugin_name)
                 vim_module_conn = self._load_plugin(plugin_name, "sdn")
                 step = "Loading {}'".format(target_id)
                 wim = deepcopy(vim)
                 wim_config = wim.pop("config", {}) or {}
                 wim["uuid"] = wim["_id"]
-                wim["wim_url"] = wim["url"]
+                if "url" in wim and "wim_url" not in wim:
+                    wim["wim_url"] = wim["url"]
+                elif "url" not in wim and "wim_url" in wim:
+                    wim["url"] = wim["wim_url"]
 
                 if wim.get("dpid"):
                     wim_config["dpid"] = wim.pop("dpid")
@@ -1940,128 +2058,6 @@ 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
@@ -2073,7 +2069,7 @@ class NsWorker(threading.Thread):
             "created_items", False
         )
 
-        self.logger.warning("Needed delete: {}".format(needed_delete))
+        self.logger.debug("Needed delete: {}".format(needed_delete))
         if my_task["status"] == "FAILED":
             return None, None  # TODO need to be retry??
 
@@ -2097,7 +2093,7 @@ class NsWorker(threading.Thread):
                     needed_delete = False
 
             if needed_delete:
-                self.logger.warning(
+                self.logger.debug(
                     "Deleting ro_task={} task_index={}".format(ro_task, task_index)
                 )
                 return self.item2class[my_task["item"]].delete(ro_task, task_index)
@@ -2121,7 +2117,6 @@ class NsWorker(threading.Thread):
         """
         my_task = ro_task["tasks"][task_index]
         task_id = my_task["task_id"]
-        task_status = None
 
         if my_task["status"] == "FAILED":
             return None, None  # TODO need to be retry??
@@ -2202,25 +2197,22 @@ class NsWorker(threading.Thread):
                 fail_on_empty=False,
             )
 
-            self.logger.warning("ro_task_dependency={}".format(ro_task_dependency))
+            self.logger.debug("ro_task_dependency={}".format(ro_task_dependency))
             if ro_task_dependency:
                 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))
 
-    def update_vm_refresh(self):
+    def update_vm_refresh(self, ro_task):
         """Enables the VM status updates if self.refresh_config.active parameter
-        is not -1 and than updates the DB accordingly
+        is not -1 and then updates the DB accordingly
 
         """
         try:
             self.logger.debug("Checking if VM status update config")
             next_refresh = time.time()
-            if self.refresh_config.active == -1:
-                next_refresh = -1
-            else:
-                next_refresh += self.refresh_config.active
+            next_refresh = self._get_next_refresh(ro_task, next_refresh)
 
             if next_refresh != -1:
                 db_ro_task_update = {}
@@ -2255,6 +2247,23 @@ class NsWorker(threading.Thread):
         except Exception as e:
             self.logger.error(f"Error updating tasks to enable VM status updates: {e}")
 
+    def _get_next_refresh(self, ro_task: dict, next_refresh: float):
+        """Decide the next_refresh according to vim type and refresh config period.
+        Args:
+            ro_task (dict):             ro_task details
+            next_refresh    (float):    next refresh time as epoch format
+
+        Returns:
+            next_refresh    (float)     -1 if vm updates are disabled or vim type is openstack.
+        """
+        target_vim = ro_task["target_id"]
+        vim_type = self.db_vims[target_vim]["vim_type"]
+        if self.refresh_config.active == -1 or vim_type == "openstack":
+            next_refresh = -1
+        else:
+            next_refresh += self.refresh_config.active
+        return next_refresh
+
     def _process_pending_tasks(self, ro_task):
         ro_task_id = ro_task["_id"]
         now = time.time()
@@ -2276,10 +2285,7 @@ class NsWorker(threading.Thread):
             elif new_status == "BUILD":
                 next_refresh += self.refresh_config.build
             elif new_status == "DONE":
-                if self.refresh_config.active == -1:
-                    next_refresh = -1
-                else:
-                    next_refresh += self.refresh_config.active
+                next_refresh = self._get_next_refresh(ro_task, next_refresh)
             else:
                 next_refresh += self.refresh_config.error
 
@@ -2294,7 +2300,7 @@ class NsWorker(threading.Thread):
                 self._log_ro_task(ro_task, None, None, "TASK_WF", "GET_TASK")
             """
             # Check if vim status refresh is enabled again
-            self.update_vm_refresh()
+            self.update_vm_refresh(ro_task)
             # 0: get task_status_create
             lock_object = None
             task_status_create = None
@@ -2340,6 +2346,7 @@ class NsWorker(threading.Thread):
                     task_path = "tasks.{}.status".format(task_index)
                     try:
                         db_vim_info_update = None
+                        dependency_ro_task = {}
 
                         if task["status"] == "SCHEDULED":
                             # check if tasks that this depends on have been completed
@@ -2355,7 +2362,7 @@ class NsWorker(threading.Thread):
                                 dependency_task = dependency_ro_task["tasks"][
                                     dependency_task_index
                                 ]
-                                self.logger.warning(
+                                self.logger.debug(
                                     "dependency_ro_task={} dependency_task_index={}".format(
                                         dependency_ro_task, dependency_task_index
                                     )
@@ -2410,9 +2417,11 @@ class NsWorker(threading.Thread):
                             lock_object = LockRenew.add_lock_object(
                                 "ro_tasks", ro_task, self
                             )
-
                         if task["action"] == "DELETE":
-                            (new_status, db_vim_info_update,) = self._delete_task(
+                            (
+                                new_status,
+                                db_vim_info_update,
+                            ) = self._delete_task(
                                 ro_task, task_index, task_depends, db_ro_task_update
                             )
                             new_status = (
@@ -2455,12 +2464,14 @@ class NsWorker(threading.Thread):
                                     new_status, db_vim_info_update = self.item2class[
                                         task["item"]
                                     ].new(ro_task, task_index, task_depends)
-                                    # self._create_task(ro_task, task_index, task_depends, db_ro_task_update)
                                     _update_refresh(new_status)
                             else:
                                 refresh_at = ro_task["vim_info"]["refresh_at"]
                                 if refresh_at and refresh_at != -1 and now > refresh_at:
-                                    (new_status, db_vim_info_update,) = self.item2class[
+                                    (
+                                        new_status,
+                                        db_vim_info_update,
+                                    ) = self.item2class[
                                         task["item"]
                                     ].refresh(ro_task)
                                     _update_refresh(new_status)
@@ -2536,7 +2547,7 @@ class NsWorker(threading.Thread):
                     lock_object["locked_at"],
                     lock_object["locked_at"] + self.task_locked_time,
                 ]
-                # locked_at contains two times to avoid race condition. In case the lock has been renew, it will
+                # locked_at contains two times to avoid race condition. In case the lock has been renewed, it will
                 # contain exactly locked_at + self.task_locked_time
                 LockRenew.remove_lock_object(lock_object)
 
@@ -2548,7 +2559,7 @@ class NsWorker(threading.Thread):
             # modify own task. Try filtering by to_next_check. For race condition if to_check_at has been modified,
             # outside this task (by ro_nbi) do not update it
             db_ro_task_update["locked_by"] = None
-            # locked_at converted to int only for debugging. When has not decimals it means it has been unlocked
+            # locked_at converted to int only for debugging. When it is not decimals it means it has been unlocked
             db_ro_task_update["locked_at"] = int(now - self.task_locked_time)
             db_ro_task_update["modified_at"] = now
             db_ro_task_update["to_check_at"] = next_check_at
@@ -2824,7 +2835,7 @@ class NsWorker(threading.Thread):
                 """
                 ro_task = self._get_db_task()
                 if ro_task:
-                    self.logger.warning("Task to process: {}".format(ro_task))
+                    self.logger.debug("Task to process: {}".format(ro_task))
                     time.sleep(1)
                     self._process_pending_tasks(ro_task)
                     busy = True